981010 - [B2G][E-Mail] Unable to send an E-Mail with a picture attachment initiated from the Camera

Status: VERIFIED FIXED

(Firefox OS Graveyard :: Gaia::E-Mail, defect)

Description

[Tony Nguyen]

Attachment: logcat_sending

Description:
Device continues to display "Sending email" when trying to send an E-Mail, then tapping on the paperclip icon to add an attachment from Camera.

Repro Steps:
1) Updated Buri to BuildID: 20140307040203
2) Navigate to E-Mail and login with a valid account
3) Tap Compose > Enter in a valid recipient
4) Tap paper clip icon to add an attachment
5) Tap on Camera > Take a photo > Tap Select
6) Tap Send 

Actual Result: 
E-Mail continues to hang on "Sending email" message

Expected Result:
E-Mail is sent 

Environmental Variables:
Device: Buri Master M-C mozRIL
BuildID: 20140307040203
Gaia: 04eb7996543f114133d1367f834a4d88b68c60ac
Gecko: b0e7f63c2138
Version: 30.0a1
v1.2-device.cfg

Attached: logcat, YouTube link

Note: E-Mail App will crash sometimes instead of going to the looping "Sending email" message.

Comment 1

[Tony Nguyen]

Attachment: dmesg

As stated in comment 0, the E-Mail App will sometimes close after selecting the image captured with the camera or after sending the E-Mail, once the attachment has been added. I'm attaching the dmesg hoping to providing more information.

Comment 2

[Tony Nguyen]

This issue does not reproduce on the latest Buri v1.3 build.

Environmental Variables:
Device: Buri v1.3 mozRIL
BuildID: 20140307004004
Gaia: e8bf7326ce5ed63bc8ef8b2cff1eba094887b9bf
Gecko: 4efa30fe00e7
Version: 28.0
v1.2-device.cfg

Comment 3

[Andrew Sutherland [:asuth] (he/him)]

It's not immediately obvious from the log, but the (presumably remotely-stored memory-backed) Blob is apparently dying before we can finish using it.

I am currently investigating the platform issues, but it looks like there are a few things going on:
* Bug 968542 (landed for v1.4 AND v1.3) seems like it would have kept a remotely-stored/accessed memory-backed blob's owning process alive until we were done with the Blob.
** This of course means v1.3 should theoretically be affected, but reaping times could explain this, and reaping also depends on the system app to kill the iframe in the first place.  That may have changed in v1.4.
** So in general there may be a platform issue with Blob semantics.
* Camera should really be returning a disk-backed File instead of a memory-backed Blob (or File) since it is saving the file to DeviceStorage.  Camera bug 949941 appears to have grown in scope/purpose to encompass this.  I will re-nom that bug for blocking status since it's overall the best solution to this problem and allows us to make any platform issues a lower priority.

Comment 4

[Andrew Sutherland [:asuth] (he/him)]

I instrumented some IPC stuff in ContentParent.cpp with printf_error's of the same name.  Let us compare the good and the bad.

=== v1.3: The good.

03-12 14:26:28.957 I/GeckoDump(  561): LOG: compose: attach activity success: attachment1 [details] [diff] [review].jpg
03-12 14:26:28.977 I/Gecko   (  561): WLOG: queueOp 0 saveDraft
03-12 14:26:28.987 I/Gecko   (  561): WLOG: runOp(local_do: {"type":"saveDraft","longtermId":"0/5","lifecycle":"do","localStatus":"doing","serverStatus":"n/a","tryCount":0,"humanOp":"saveDraft","existingNamer":null,"newD)
03-12 14:26:28.997 I/Gecko   (  561): WLOG: runOp_end(local_do: {"type":"saveDraft","longtermId":"0/5","lifecycle":"do","localStatus":"doing","serverStatus":"n/a","tryCount":0,"humanOp":"saveDraft","existingNamer":null,"newD)
03-12 14:26:28.997 I/Gecko   (  561): 
03-12 14:26:29.037 I/Gecko   (  561): WLOG: queueOp 0 attachBlobToDraft
03-12 14:26:29.037 I/Gecko   (  561): WLOG: runOp(local_do: {"type":"attachBlobToDraft","longtermId":"0/6","lifecycle":"do","localStatus":"doing","serverStatus":"n/a","tryCount":0,"humanOp":"attachBlobToDraft","existingN)
03-12 14:26:29.037 I/Gecko   (  561): WLOG: attachBlobToDraft: retrieving message
03-12 14:26:29.147 I/Gecko   (  136): NotifyTabDestroying
03-12 14:26:29.147 I/Gecko   (  136): MarkAsDead
03-12 14:26:29.267 I/Gecko   (  561): WLOG: attachBlobToDraft: fetching 0 to 325576 of 325576
03-12 14:26:29.317 I/Gecko   (  561): WLOG: attachBlobToDraft: fetched
03-12 14:26:29.527 I/Gecko   (  561): WLOG: attachBlobToDraft: flushing
03-12 14:26:29.567 I/Gecko   (  136): NotifyTabDestroyed
03-12 14:26:29.567 I/Gecko   (  136): ShutDownProcess
03-12 14:26:29.567 I/Gecko   (  136): ActorDestroy
03-12 14:26:29.567 I/Gecko   (  136): MarkAsDead
03-12 14:26:29.577 I/Gecko   (  136): ShutDownProcess
03-12 14:26:29.577 I/Gecko   (  136): MarkAsDead
03-12 14:26:29.577 I/Gecko   (  136): MarkAsDead
03-12 14:26:29.577 I/Gecko   (  136): [Parent 136] WARNING: waitpid failed pid:581 errno:10: file /home/visbrero/rev_control/fgit/b2g-hamachi-v1.3/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-12 14:26:29.597 I/Gecko   (  581): 
03-12 14:26:29.597 I/Gecko   (  581): ###!!! [Child][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
03-12 14:26:29.597 I/Gecko   (  581): 
03-12 14:26:29.777 I/Gecko   (  561): WLOG: attachBlobToDraft: blob fully attached
03-12 14:26:29.777 I/Gecko   (  561): WLOG: runOp_end(local_do: {"type":"attachBlobToDraft","longtermId":"0/6","lifecycle":"do","localStatus":"doing","serverStatus":"n/a","tryCount":0,"humanOp":"attachBlobToDraft","existingN)
03-12 14:26:29.777 I/Gecko   (  561): 
03-12 14:26:31.587 I/Gecko   (  136): [Parent 136] WARNING: waitpid failed pid:581 errno:10: file /home/visbrero/rev_control/fgit/b2g-hamachi-v1.3/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-12 14:26:31.587 I/Gecko   (  136): [Parent 136] WARNING: Failed to deliver SIGKILL to 581!(3).: file /home/visbrero/rev_control/fgit/b2g-hamachi-v1.3/gecko/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc, line 118


=== v1.4: The very bad.  Because the email app now crashes.

03-12 13:27:18.599 I/GeckoDump( 1620): LOG: compose: attach activity success: attachment1 [details] [diff] [review].jpg
03-12 13:27:18.799 I/Gecko   ( 1410): NotifyTabDestroying
03-12 13:27:18.799 I/Gecko   ( 1410): MarkAsDead
03-12 13:27:18.849 E/GeckoConsole( 1410): Content JS WARN at app://system.gaiamobile.org/js/activity_window.js:233 in onClose: unknown window type of activity caller.
03-12 13:27:18.889 I/Gecko   ( 1620): WLOG: queueOp 2 saveDraft
03-12 13:27:18.889 I/Gecko   ( 1620): WLOG: runOp(local_do: {"type":"saveDraft","longtermId":"2/U","lifecycle":"do","localStatus":"doing","serverStatus":"n/a","tryCount":0,"humanOp":"saveDraft","existingNamer":null,"newD)
03-12 13:27:19.049 I/Gecko   ( 1620): WLOG: queueOp 2 attachBlobToDraft
03-12 13:27:19.099 I/Gecko   ( 1410): NotifyTabDestroyed
03-12 13:27:19.099 I/Gecko   ( 1410): ShutDownProcess
03-12 13:27:19.099 I/Gecko   ( 1410): ActorDestroy
03-12 13:27:19.099 I/Gecko   ( 1410): MarkAsDead
03-12 13:27:19.099 I/Gecko   ( 1659): 
03-12 13:27:19.099 I/Gecko   ( 1659): ###!!! [Child][OnMaybeDequeueOne] Error: Channel closing: too late to send/recv, messages will be lost
03-12 13:27:19.099 I/Gecko   ( 1659): 
03-12 13:27:19.129 I/Gecko   ( 1620): WLOG: runOp_end(local_do: {"type":"saveDraft","longtermId":"2/U","lifecycle":"do","localStatus":"doing","serverStatus":"n/a","tryCount":0,"humanOp":"saveDraft","existingNamer":null,"newD)
03-12 13:27:19.129 I/Gecko   ( 1620): 
03-12 13:27:19.179 I/Gecko   ( 1620): WLOG: runOp(local_do: {"type":"attachBlobToDraft","longtermId":"2/V","lifecycle":"do","localStatus":"doing","serverStatus":"n/a","tryCount":0,"humanOp":"attachBlobToDraft","existingN)
03-12 13:27:19.189 I/Gecko   ( 1620): WLOG: attachBlobToDraft: retrieving message
03-12 13:27:19.229 I/Gecko   ( 1410): ShutDownProcess
03-12 13:27:19.229 I/Gecko   ( 1410): MarkAsDead
03-12 13:27:19.229 I/Gecko   ( 1410): MarkAsDead
03-12 13:27:19.239 I/Gecko   ( 1410): [Parent 1410] WARNING: waitpid failed pid:1659 errno:10: file /home/visbrero/rev_control/fgit/b2g-hamachi/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-12 13:27:19.309 I/Gecko   ( 1620): WLOG: attachBlobToDraft: fetching 0 to 256852 of 256852
03-12 13:27:19.319 I/Gecko   ( 1410): 
03-12 13:27:19.319 I/Gecko   ( 1410): ###!!! [Parent][DispatchAsyncMessage] Error: Value error: message was deserialized, but contained an illegal value
03-12 13:27:19.319 I/Gecko   ( 1410): 
03-12 13:27:19.319 I/Gecko   ( 1410): [Parent 1410] WARNING: waitpid failed pid:1620 errno:10: file /home/visbrero/rev_control/fgit/b2g-hamachi/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-12 13:27:19.339 I/Gecko   ( 1410): 
03-12 13:27:19.339 I/Gecko   ( 1410): ###!!! [Parent][MessageChannel] Error: Channel error: cannot send/recv
03-12 13:27:19.339 I/Gecko   ( 1410): 
03-12 13:27:19.339 I/Gecko   ( 1410): NotifyTabDestroying
03-12 13:27:19.339 I/Gecko   ( 1410): MarkAsDead
03-12 13:27:19.349 I/Gecko   ( 1410): ############ ErrorPage.js
03-12 13:27:19.379 I/Gecko   ( 1410): ActorDestroy
03-12 13:27:19.389 I/Gecko   ( 1410): MarkAsDead
03-12 13:27:19.419 I/Gecko   ( 1410): ShutDownProcess
03-12 13:27:19.419 I/Gecko   ( 1410): MarkAsDead
03-12 13:27:19.419 I/Gecko   ( 1410): [Parent 1410] WARNING: waitpid failed pid:1620 errno:10: file /home/visbrero/rev_control/fgit/b2g-hamachi/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-12 13:27:19.719 I/Gecko   ( 1410): [Parent 1410] WARNING: waitpid failed pid:1726 errno:10: file /home/visbrero/rev_control/fgit/b2g-hamachi/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254


=== The analysis:

In v1.3, all that happens before we try to process the Blob is "NotifyTabDestroying" and "MarkAsDead".

In v1.4, we get "NotifyTabDestroying" and "MarkAsDead" but then you will note that we also manage to get in a "NotifyTabDestroyed", "ShutDownProcess", "ActorDestroy" and "MarkAsDead".  These all seem to be bad things to happen, but it would appear "ShutDownProcess" is the most bad since it calls mMessageManager->Disconnect() and nulls out the mMessageManager, and that seems to be some type of important thing in that we absolutely can't talk to the camera process and its memory-backed Blob after that disconnection.


=== Causes?  Not really sure...

Prior to the b2g instrumentation, I looked into changes in the system app on the v1.4 branch in case there was an obvious life-cycle change like v1.3 was holding onto the mozbrowser iframe much longer.  While some refactoring changes have landed, they haven't substantially changed the treatment of the iframe.  It still gets delinked via the same code-path.  This does seem to be borne out by the b2g instrumentation.

I'm about to file the platform bug about memory-back blobs being broke again and name-check it to/from here, but I'm still of the mind that fixing Camera to just return a File is the right way to go.

Comment 5

[Andrew Sutherland [:asuth] (he/him)]

I have implemented a fix for Camera on bug 949941 which makes us work and be happy.  There is currently no action to be taken on this bug inside the e-mail app itself.  Bug 949941 is not currently blocking 1.4+ but is 1.4? though, so hopefully it gets marked.

Also, in case it wasn't clear from the addition of the see also, bug 982779 is the bug I filed on the platform issue.

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

Attachment: logging patch I used: the printf_stderr stuff in ContentParent plus backout of Bug 968542

Comment 7

[Andrew Sutherland [:asuth] (he/him)]

This is fixed by the landing of the fix for bug 949941 for v1.4.  Uplift for utilization purposes including on Tarako will be addressed on that bug.

Comment 8

[Edward Chen[:edchen]]

[Environment]
Gaia      a2a88d0638594a6510f878d2c5e99a6ead7520ad
Gecko     https://hg.mozilla.org/releases/mozilla-aurora/rev/67bdb575d833
BuildID   20140324160201
Version   30.0a2

[Result]
PASS

I mark it to "VERIFIED"