Open Bug 1595343 Opened 5 years ago Updated 2 years ago

C-C TB: nsMsgAttachment::DeleteAttachment fails to delete attachment file occasionally during shutdown, possibily leaving orphaned files in temp/tmp directory

Categories

(Thunderbird :: General, defect)

Product:
Thunderbird
Component:
General
Type:
defect

Tracking

(Not tracked)

People

(Reporter: ishikawa, Unassigned)

References

Details

Attachments

(1 file)

Log from make mozmill-one SOLO_TEST=attachment
164.56 KB, text/plain
Details

I noticed strange errors reported by the following ASSERTION
during the run of |make mozmill| of C-C TB (FULL DEBUG version).

###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp, line 213

Strange still is that they are sporadic.

The bug appeared sporadically in |make mozmill|. Number of
appearances, one or two, differs from time time.

On my local log, it started to appear in February 2016.

  • Feb 2016

/FF-NEW/log780-mozmill.txt.gz
[29790] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/comm-central/mailnews/compose/src/nsMsgAttachment.cpp, line 244
[29790] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/comm-central/mailnews/compose/src/nsMsgAttachment.cpp, line 244

/FF-NEW/log782-mozmill.txt.gz
[27271] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/comm-central/mailnews/compose/src/nsMsgAttachment.cpp, line 244
[27271] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/comm-central/mailnews/compose/src/nsMsgAttachment.cpp, line 244
/FF-NEW/log783-xpcshell.txt.gz

  • July 2017
    /FF-NEW/log960-mozmill.txt:27493:[6655] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/comm-central/mailnews/compose/src/nsMsgAttachment.cpp, line 244
    /FF-NEW/log960-mozmill.txt:27538:[6655] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/comm-central/mailnews/compose/src/nsMsgAttachment.cpp, line 244

/FF-NEW/log967-mozmill.txt:27712:[17157] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/comm-central/mailnews/compose/src/nsMsgAttachment.cpp, line 244

August 2019
/FF-NEW/log1055-mozmill-fixed-stack.txt:7702:[9326, Main Thread] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp, line 214

.... some omissions from the summer to now.

Nov 2019
/FF-NEW/log1115-mozmill-fixedstack.txt:8186:[16433, Main Thread] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp, line 213
/FF-NEW/log1115-mozmill-fixedstack.txt:8229:[16433, Main Thread] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp, line 213

The bug comes from the following test:

TEST-START | /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/test-attachment-size.js | test_attached_message_with_attachment

I checked the code. The message is printed by NS_ERROR() in Full
Debug build of C-C TB.

mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp

nsresult nsMsgAttachment::DeleteAttachment() {
  nsresult rv;
  bool isAFile = false;

  nsCOMPtr<nsIFile> urlFile;
  rv = NS_GetFileFromURLSpec(mUrl, getter_AddRefs(urlFile));
  NS_ASSERTION(NS_SUCCEEDED(rv), "Can't nsIFile from URL string"); <== THIS
  if (NS_SUCCEEDED(rv)) {
    bool bExists = false;
    rv = urlFile->Exists(&bExists);
    NS_ASSERTION(NS_SUCCEEDED(rv), "Exists() call failed!");
    if (NS_SUCCEEDED(rv) && bExists) {
      rv = urlFile->IsFile(&isAFile);
      NS_ASSERTION(NS_SUCCEEDED(rv), "IsFile() call failed!");
    }
  }

  // remove it if it's a valid file
  if (isAFile) rv = urlFile->Remove(false);

  return rv;
}

I found that there is a problem here. The assertion is triggered by
the failure of a call to |NS_GetFileFromURLSpec()|. And when that call
fails, the removal of the attachment file does not happen.
|isAFile| is initialized to |false| and does not change the value when
the call to |NS_GetFileFromURLSpec()| fails. Thus file |Remove()| call
never takes place.

In any case, this is possibly a serious bug.
We do not want to leave
an attachment hanging around in temporary directory randomly (even if
the permission is set to user RW only).

The user may have thought that the particular sensitive attachment has
been sent and s/he may have deleted the original file and even from
the attachment of a e-mail copy in Sent folder to be sure. And yet
the copy may be left in the temporary directory from time to time. A
surprise, isn't it?

One possible reason for sporadic nature of this issue.:

Looking at the stack trace from NS_ERROR() [I will attach the log with additional dump], I see there is a gabarge
collection in the stacktrace before some Release calls are made to
release objects. Hmm...
So maybe this is one last call to GC before shutdown?

It seems that this DeleteAttachment is called by the releasing of an
object (Attachment?) due to the garbage collection and by the time
this release takes place, other internal infrastructure for the
successful execution of |NS_GetFileFromURLSpec()| may have disappeared
already. (Now come to think of it, depending on the runs of GC's
traversal when it is invoked and how long, the releasing order of
related object may be semi-random, for that matter.)

The developer may have thought the orphaned object will be reclaimed
eventually by GC, and destruction of object would take care of the
removal of an external file in temporary directory. However, as we
see here, the temporary file for creating attachment (presumably) is
left around sometimes.
Bad...

Note that I run C-C TB (FULL DEBUG VERSION) with additional dump added
for local debugging.

I added more info to the log to show the name of the URL, |mUrl|. :
they turned out to be files under temporary directory, |/tmp|.

I also added the directory listing of |/tmp| directory of my linux PC:
mozmill creates temporary files there.
I dumped the listing to learn if the attachment files
not deleted have strange permission, etc.: No. It is owned by my
account and has read/write permission.

I also added the return value of |NS_GetFileFromURLSpec()| in the log.
I was curious if esoteric error was returned.: No, it was
the generic 0x80004005 (NS_ERROR_FAILURE) .

Modification:

nsresult nsMsgAttachment::DeleteAttachment() {
  nsresult rv;
  bool isAFile = false;

  nsCOMPtr<nsIFile> urlFile;
  rv = NS_GetFileFromURLSpec(mUrl, getter_AddRefs(urlFile));
  NS_ASSERTION(NS_SUCCEEDED(rv), "Can't nsIFile from URL string");
#ifdef DEBUG
  if (!NS_SUCCEEDED(rv)) {
    int rc = 0;
#ifdef linux
    rc = system("ls -ltr /tmp/");
#endif
    fprintf(stderr,
            "{debug} DeleteAttachment: rv = 0x%" PRIx32 ", mUrl.data()==<<%s>>, rc=%d\n",
            static_cast<uint32_t>(rv), mUrl.Data(), rc);
  }
#endif
  if (NS_SUCCEEDED(rv)) {
    bool bExists = false;
    rv = urlFile->Exists(&bExists);
    NS_ASSERTION(NS_SUCCEEDED(rv), "Exists() call failed!");

    ... [omission]...

Indeed, I believe this is part of final shutdown.:

#26: nsCycleCollector::FixGrayBits(bool, TimeLog&) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsCycleCollector.cpp:3284 (discriminator 4))
#27: nsCycleCollector::BeginCollection(ccType, nsICycleCollectorListener*) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsCycleCollector.cpp:3580 (discriminator 8))
#28: nsCycleCollector::Collect(ccType, js::SliceBudget&, nsICycleCollectorListener*, bool) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsCycleCollector.cpp:3444)
#29: nsCycleCollector::ShutdownCollect() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsCycleCollector.cpp:3357)
#30: nsCycleCollector::Shutdown(bool) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/nsCycleCollector.cpp:3645)
#31: nsCycleCollector_shutdown(bool) (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/mozilla/RefPtr.h:64)
#32: mozilla::ShutdownXPCOM(nsIServiceManager*) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/build/XPCOMInit.cpp:710)
#33: NS_ShutdownXPCOM (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/build/XPCOMInit.cpp:565)
#34: ScopedXPCOMStartup::~ScopedXPCOMStartup() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/toolkit/xre/nsAppRunner.cpp:1234)
#35: XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/mozilla/cxxalloc.h:51)
#36: XRE_main(int, char**, mozilla::BootstrapConfig const&) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/toolkit/xre/nsAppRunner.cpp:4802)
#37: mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/toolkit/xre/Bootstrap.cpp:46)

Also, the object that is released is nsMsgAttachment:

[5212, Main Thread] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp, line 213
#01: nsMsgAttachment::DeleteAttachment() (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/nsDebug.h:97 (discriminator 1))
#02: nsMsgAttachment::~nsMsgAttachment() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp:19 (discriminator 2))
#03: nsMsgAttachment::~nsMsgAttachment() (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/mozilla/cxxalloc.h:51)
#04: nsMsgAttachment::Release() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp:10 (discriminator 5))
#05: ReleaseObjects(nsTArray<nsISupports*>&) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/ds/nsTArray.h:348)
#06: nsCOMArray_base::Clear() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/ds/nsTArray.h:348)
#07: nsCOMArray_base::~nsCOMArray_base() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/ds/nsTArray.h:348)
#08: nsMsgCompFields::~nsMsgCompFields() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgCompFields.cpp:92)
#09: nsMsgCompFields::~nsMsgCompFields() (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/mozilla/cxxalloc.h:51)
#10: nsMsgCompFields::Release() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgCompFields.cpp:62 (discriminator 8))
#11: nsMsgComposeParams::~nsMsgComposeParams() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgComposeParams.cpp:17)
#12: nsMsgComposeParams::~nsMsgComposeParams() (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/mozilla/cxxalloc.h:51)
#13: nsMsgComposeParams::Release() (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgComposeParams.cpp:15 (discriminator 5))
#14: mozilla::dom::DeferredFinalizerImpl<nsISupports>::DeferredFinalize(unsigned int, void*) (/NEW-SSD/moz-obj-dir/objdir-tb3/dist/include/mozilla/SegmentedVector.h:73)
#15: mozilla::IncrementalFinalizeRunnable::ReleaseNow(bool) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/CycleCollectedJSRuntime.cpp:1283)
#16: mozilla::CycleCollectedJSRuntime::FinalizeDeferredThings(mozilla::CycleCollectedJSContext::DeferredFinalizeType) (/NEW-SSD/NREF-COMM-CENTRAL/mozilla/xpcom/base/CycleCollectedJSRuntime.cpp:1357)

I am afraid we need to call the "~nsMsgAttachment()" explicitly when we are done composing a message, but
that does not solve the issue of someone shutting down TB while the composition was started and the composition windows was kept open, I think.

BTW, despite the somewhat random behavior, the bug appeared every time I ran the test today.

Well, if NS_GetFileFromURLSpec() fails, urlFile is not populated, so we cannot possibly delete the file. We should investigate why that fails. You should dump out the spec of mUrl:

nsAutoCString spec;
mUrl->GetSpec(spec);
printf(" ... ", spec.get());

(In reply to Jorg K (GMT+2) from comment #4)

Well, if NS_GetFileFromURLSpec() fails, urlFile is not populated, so we cannot possibly delete the file. We should investigate why that fails. You should dump out the spec of mUrl:

nsAutoCString spec;
mUrl->GetSpec(spec);
printf(" ... ", spec.get());

String-wise, they look like this:

-rw-------  1 ishikawa ishikawa	    467 Nov 10 10:25 nsmail.tmp
-rw-------  1 ishikawa ishikawa	    467 Nov 10 10:25 nsmail-29.asc
drwxr-xr-x 11 ishikawa ishikawa	   4096 Nov 10 10:26 mozmillprofile
{debug} DeleteAttachment: rv = 0x80004005, mUrl.data()==<<file:///tmp/nsmail-29.asc>>, rc=0
[5212, Main Thread] ###!!! ASSERTION: Can't nsIFile from URL string: 'NS_SUCCEEDED(rv)', file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/compose/src/nsMsgAttachment.cpp, line 213

...


{debug} DeleteAttachment: rv = 0x80004005, mUrl.data()==<<file:///tmp/nsmail.tmp>>, rc=0
--DOCSHELL 0x557bb4cbbe90 == 2 [pid = 5212] [id = {3303fcbb-68d3-467c-b40b-fc4b2dba0082}] [url = mailbox:///NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mail/test/mozmill/attachment/bug1358565.eml?type=application/x-message-display&number=0]

file:///tmp/nsmail-29.asc
file:///tmp/nsmail.tmp

It was printed via |mUrl.Data()|.
It seems mUrl is a simple string type here. (No GetSpec member?).

nsresult NS_GetFileFromURLSpec(const nsACString& inURL, nsIFile** result,
                               nsIIOService* ioService /* = nullptr */) {
  nsresult rv;
  nsCOMPtr<nsIFileProtocolHandler> fileHandler;
  rv = NS_GetFileProtocolHandler(getter_AddRefs(fileHandler), ioService);
  if (NS_SUCCEEDED(rv)) rv = fileHandler->GetFileFromURLSpec(inURL, result);
  return rv;
}

So now we need to figure out where the simple call fails during shtudown, I suppose.

Sorry, mUrl was already the spec. It points to those files nsmail.tmp and nsmail-29.asc which are left over, right? So some parts of the underlying Mozilla platform have already shut down when we ask for the file corresponding to the spec. That's bad.

(In reply to Jorg K (GMT+2) from comment #7)

Sorry, mUrl was already the spec. It points to those files nsmail.tmp and nsmail-29.asc which are left over, right?

Yes, indeed.

So some parts of the underlying Mozilla platform have already shut down when we ask for the file corresponding to the spec. That's bad.

That's what I thought, too.

We need to escalate this to wider mozilla community including FF community because they may also be hit with this.

I think we need somehow to introduce some ordering of Release(s) artificially.
For example ( I am not sure if this is feasible ), but
say, if we shutdown the infrastructure for file handling, we first destroy object that depends on it, etc., THEN we destroy the infrastructure for file handling. Of course, unless we have some pointers linking these, it would be impossible.

I was checking the log for any new issues that my local patches may have introduced, but I am afraid there may be other potentially serious bugs lurking unbeknownst to us yet. Gasp.

That this bug only happens when some GC ordering causes it to be visible is indeed very difficult for us to spot the bug and figure out the cause.
But I think yesterday's bug is very clear on the cause.

Since GC is not a built-in feature of C++ and mozilla has its own implementation, maybe the folks who have been developing it may have an idea how to go about it.
After all, when some objects have runtime dependency to upper object (upper in the sense of object hierarchy),
at least there is an invisible (to the user) but traceable pointer (for the run-time) to upper objects, I think.
I am not sure if such references are resolved at link time, but GC folks will know for sure.
(No it can't be all done at link time. Wait, C++ is compiled and then, all the type dependencies are known and fixed at compile time. Hmm...)

Summary: C-C TB: nsMsgAttachment::DeleteAttachment fails to delete attachment file occasionally? → C-C TB: nsMsgAttachment::DeleteAttachment fails to delete attachment file occasionally during shutdown.

(In reply to ISHIKAWA, Chiaki from comment #8)

We need to escalate this to wider mozilla community including FF community because they may also be hit with this.

I suspect that FF developers may not be aware of or be affected by this issue since FF is unlikely to create files (aside from download) during its life time.

Summary: C-C TB: nsMsgAttachment::DeleteAttachment fails to delete attachment file occasionally during shutdown. → C-C TB: nsMsgAttachment::DeleteAttachment fails to delete attachment file occasionally during shutdown, possibily leaving orphaned files in temp/tmp directory
Version: unspecified → Trunk
See Also: → 1589890

Wayne, right, this is probably the cause of those strange files left hanging around under /tmp directory...
We need someone familiar with GC to come up with a clean solution.
OTOH, we may want to do some brute force solution such as trying to explicitly call nsMsgAttachment() as early as possible under programmer control.

Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: