1786237 - nsIMessenger.detachAttachmentsWOPrompts() listener callback is invoked before the detach is completed.

Status: RESOLVED FIXED

(MailNews Core :: Backend, defect)

Description

[Ben Campbell]

I just discovered that nsIMessenger.detachAttachmentsWOPrompts() calls OnStopRunningUrl() on the passed-in listener before the detach has completed.

The timing of the current code is such that this doesn't seem to cause any problems... but as part of Bug 1733849, I started hitting unit test failures. After a couple of days (!) of printf debugging, I figured out that it's a timing issue - the current code doesn't notice that the listener fires prematurely but my modified mbox streaming code changes the timing and causes some unit test fails.

The unit tests I've been looking at are test_detachToFile.js, test_mimemaltdetach.js. Both of them start working fine with my modified mbox code if I add an arbitrary few seconds delay when they waiting for the listener passed into the detach op.

Looking through the detach code, it works roughly like this:

1. stream out the message to a temporary file, stripping out the targeted attachement (and replacing that Mime part with a message saying the attachement has been stripped out).
2. Do a CopyFileMessage() to load the temp file into the msgStore, replacing the old message (well. on mbox, that means appending the new message, then marking the old message as deleted).

It's really hard code to follow - it uses Mime code and message copy code, both particularly gnarly systems.
But what seems to be happening that the temporary message is being written out correctly (step 1, above), but the listener OnStopRunningUrl is called before step 2 is finished.

Comment 1

[Ben Campbell]

Attachment: bug_1786237_debug_attachment_detach.diff

(feel free to ignore this - just for completeness, and to get it all straight in my own head ;- )

Here's a diff with some of my printf debugging.
And an example with run without my mbox modifications - so it runs, but the printfs still highlight the issue:

$ ./mach xpcshell-test comm/mailnews/base/test/unit/test_detachToFile.js

...
...
...

 0:00.75 pid:37428 XXXXXXXXXXXXXXXXXXX begin startDetach
 0:00.75 pid:37428 XYZZY nsMailboxProtocol::Initialize : 0x0x7f4ad6b99f40 key=1 tok=0 flags=0x10000000 off=0
 0:00.75 INFO (xpcshell/head.js) | test run_next_test 3 finished (2)
 0:00.77 pid:37428 XYZZY StartProcessing : 0x0x7f4ad6b99f40 key=1 tok=0 flags=0x10000000 off=0
 0:00.77 pid:37428 XYZZY nsMailboxProtocol::Initialize : 0x0x7f4ad6b99f40 key=1 tok=0 flags=0x10000000 off=0
 0:00.77 pid:37428 XXXXXXXXXXXXXXXXXXX exit startDetach

At this point, the listener has fired... and testDetach should start running. BUT... you see the calls to CopyFileMesssage() and DeleteOriginalMessage() below... these should have completed before the listener fired.

 0:00.77 INFO (xpcshell/head.js) | test run_next_test 4 pending (2)
 0:00.77 INFO (xpcshell/head.js) | test startDetach finished (2)
 0:00.77 pid:37428 XYZZY OnStopRequest calling CopyFileMessage: 0x0x7f4ad6b99f40 key=1 tok=0 flags=0x10000000 off=0
 0:00.77 pid:37428 XYZZY CopyFileMessage start: 0x0x7f4ad6b99f40 key=1 tok=0 flags=0x10000000 off=0
 0:00.77 pid:37428 GetDiskSpaceAvailable returned: 32709562368 bytes
 0:00.77 pid:37428 XYZZY InternalGetNewMsgOutputStream : 0x0x7f4ad695b9a0 key=2 tok=3513 flags=0x0 off=3513
 0:00.77 pid:37428 XYZZY DeleteOriginalMessage : 0x0x7f4ad6b99f40 key=1 tok=0 flags=0x10000000 off=0
 0:00.77 pid:37428 XYZZY DeleteHeader before: 0x0x7f4ad6b99f40 key=1 tok=0 flags=0x10000000 off=0
 0:00.77 pid:37428 XYZZY DeleteHeader deleted: 0x0x7f4ad6b99f40 key=1 tok=0 flags=0x10000008 off=0
 0:00.77 INFO xpcshell.ini:comm/mailnews/base/test/unit/test_detachToFile.js | Starting testDetach
 0:00.77 INFO (xpcshell/head.js) | test testDetach pending (2)
 0:00.77 pid:37428 XXXXXXXXXXXXXXXXXXX begin testDetach
 0:00.78 PASS testDetach - [testDetach : 114] true == true
 0:00.78 pid:37428 XYZZY nsMailboxProtocol::Initialize : 0x0x7f4ad695b9a0 key=2 tok=3513 flags=0x10000000 off=3513
 0:00.78 PASS testDetach - [testDetach : 123] true == true
 0:00.78 pid:37428 XXXXXXXXXXXXXXXXXXX exit testDetach

The timing doesn't screw up this run (it was without my mbox modifications), but is definitely all wrong.

Comment 2

[Ben Campbell]

Attachment: Bug 1786237 - Tidy up leftover void* param in nsMessenger::SaveAttachment(). r=mkmelin

Comment 3

[Ben Campbell]

(that patch isn't a fix BTW - just some incidental leftover oddness I discovered in the code that merited a quick cleanup)

Comment 4

[Ben Campbell]

Some notes to myself:

DetachAttachmentsWOPrompt() performs these steps:

1. Save out each attachment to a file (using nsMessenger::SaveAttachment())
2. When all are saved, call nsMessenger::DetachAttachments() to strip the attachments out of the message.

The problem is that nsMessenger::DetachAttachments() has no listener mechanism, so there's no way a caller can ask to be informed when the detach operation is completed. So DetachAttachmentsWOPrompt() calls it's listener.OnStopRunningUrl() when it starts the detach part of the operation. Which is what this bug is all about.

It's made more complicated by the way the save and detach operations are chained together - there's a custom nsSaveMsgListener class which has a 'detach' flag. So when the save finishes, the detach can be kicked off.

Out of interest, nsMessenger::DetachAttachments() works by:

1. setting up a mime streamconverter which will strip out targeted attachments as the message is streamed through it.
2. stream the message from the msgStore, through the streamconverter, and out to a temporary file
3. load the message back using nsIMsgCopyService.copyFileMessage().
   Lots of intricate details skipped here, but that's the gist.

THE SOLUTION:

Add a listener param to internal nsMessenger::DetachAttachments() function, which is informed when the detach is completed.
Need to figure out how to propagate the original listener passed in to DetachAttachmentsWOPrompt() all the way through the SaveAttachments() calls, then the DetachAttachments() call (and it's streamconverter and copyFileMessage() shenanigans)... so that the original listener is called when the DetachAttachments() is all done.

It's tricky, as the nsSaveMsgListener is used to chain together Save and Detach sequences... and there are lots of cases that I don't want to screw up.
Really, the Save and Detach functions should be totally separate operations, both accepting listeners, then we can just chain them together using newfangled C++ closures. Not quite as nice as javascript async/await, but at least the overall sequence will be in one single place rather than scattered all over the code as it is right now...

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/52bbd98b6a3f
Tidy up leftover void* param in nsMessenger::SaveAttachment(). r=mkmelin

Comment 6

[Ben Campbell]

Attachment: Bug 1786237 - Add a nsIUrlListener callback to the internal nsMessenger::DetachAttachments(). r=mkmelin

Also renames nsDelAttachListener to AttachmentDeleter. The old name is
technically accurate, but it derives from nsIUrlListener purely as an
implementation detail, rather than something a caller should need to be aware
of.

Comment 7

[Ben Campbell]

Attachment: Bug 1786237 - Make sure listener passed to nsMessenger.DetachAttachmentsWOPrompts() triggers at correct time. r=mkmelin

Depends on D157064

Comment 8

[Ben Campbell]

looks OK on try run:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=85a3d98d7db43f0006a4c8b9a124f8d621402b46

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/0d8cecc5d6c6
Add a nsIUrlListener callback to the internal nsMessenger::DetachAttachments(). r=mkmelin
https://hg.mozilla.org/comm-central/rev/ea2090b488da
Make sure listener passed to nsMessenger.DetachAttachmentsWOPrompts() triggers at correct time. r=mkmelin