1211266 - Occasional missing icons after flashing homescreen

Status: VERIFIED FIXED

(Core :: IPC, defect, P1)

Description

[Kevin Grandon :kgrandon]

This happens with the homescreen app and not verticalhome. I think this is a race condition with using the homescreen-webapps-manage permission and privileged icon APIs.

Noticed this on a flame.

This is possibly the same issue as: https://bugzilla.mozilla.org/show_bug.cgi?id=1042807#c22

Comment 1

[[:fabrice] Fabrice Desré]

I get the same behavior on b2gdroid.  These errors in logcat seem related:

0-03 17:02:51.893 I/Gecko   ( 5452): ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x18001D,name=PBackground::Msg_PBlobConstructor) Value error: message was deserialized, but contained an illegal value
10-03 17:02:51.893 I/Gecko   ( 5452): 
10-03 17:02:51.893 I/Gecko   ( 5452): 
10-03 17:02:51.893 I/Gecko   ( 5452): ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x1E0003,name=???) Route error: message sent to unknown actor ID
10-03 17:02:51.893 I/Gecko   ( 5452): 
10-03 17:02:51.893 I/Gecko   ( 5452): 
10-03 17:02:51.893 I/Gecko   ( 5452): ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x18001D,name=PBackground::Msg_PBlobConstructor) Value error: message was deserialized, but contained an illegal value
10-03 17:02:51.893 I/Gecko   ( 5452): 
10-03 17:02:51.893 I/Gecko   ( 5452): 
10-03 17:02:51.893 I/Gecko   ( 5452): ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x1E0003,name=???) Route error: message sent to unknown actor ID
10-03 17:02:51.893 I/Gecko   ( 5452): 
10-03 17:02:51.906 I/Gecko   ( 5452): 
10-03 17:02:51.906 I/Gecko   ( 5452): ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x18001D,name=PBackground::Msg_PBlobConstructor) Value error: message was deserialized, but contained an illegal value
10-03 17:02:51.906 I/Gecko   ( 5452): 
10-03 17:02:51.906 I/Gecko   ( 5452): 
10-03 17:02:51.906 I/Gecko   ( 5452): ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x1E0003,name=???) Route error: message sent to unknown actor ID
10-03 17:02:51.906 I/Gecko   ( 5452):

Comment 2

[Gregor Wagner [:gwagner]]

Ted, can you help out here?

Comment 3

[:gerard-majax]

I'll try to play with that. It's been something we have been spotting a couple of times already ... on several devices

Comment 4

[:gerard-majax]

Kevin, can you provide STRs ?

Comment 5

[Kevin Grandon :kgrandon]

(In reply to Alexandre LISSY :gerard-majax from comment #4)
> Kevin, can you provide STRs ?

The STR is: 
1) Flash device with make reset-gaia
2) Scroll down the entire app list until you see an empty space with no icon (the app name will be there).
3) If all icons are present, repeat from 1. 


There's ~50 icons installed in an engineering build, and I saw it happen to a single icon in the grid about ~50% of the time. The reproduction of this is only 1% or so per icon.

Comment 6

[:gerard-majax]

Ok, I did:
 0. make NOFTU=1 reset-gaia
 1. Settings, Homescreens, select "New Home Screen"

This changed my homescreen and I have three missing icons: Camera, Twitter and FM Radio. Logcat confirms what Fabrice said:
10-09 13:59:10.959  3595  3595 E GeckoConsole: [JavaScript Error: "ConstraintError" {file: "jar:file:///system/b2g/omni.ja!/components/DataStoreImpl.js" line: 233}]
10-09 13:59:11.029   212   212 V WLAN_PSA: NL MSG, len[048], NL type[0x11] WNI type[0x5050] len[028]
10-09 13:59:15.229  3595  3632 I Gecko   : 
10-09 13:59:15.229  3595  3632 I Gecko   : ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x18001D,name=PBackground::Msg_PBlobConstructor) Value error: message was deserialized, but contained an illegal value
10-09 13:59:15.229  3595  3632 I Gecko   : 
10-09 13:59:15.229  3595  3632 I Gecko   : 
10-09 13:59:15.229  3595  3632 I Gecko   : ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x1E0003,name=???) Route error: message sent to unknown actor ID
10-09 13:59:15.229  3595  3632 I Gecko   : 
10-09 13:59:15.759  3595  3632 I Gecko   : 
10-09 13:59:15.759  3595  3632 I Gecko   : ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x18001D,name=PBackground::Msg_PBlobConstructor) Value error: message was deserialized, but contained an illegal value
10-09 13:59:15.759  3595  3632 I Gecko   : 
10-09 13:59:15.759  3595  3632 I Gecko   : 
10-09 13:59:15.759  3595  3632 I Gecko   : ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x1E0003,name=???) Route error: message sent to unknown actor ID
10-09 13:59:15.759  3595  3632 I Gecko   : 
10-09 13:59:15.919  3595  3632 I Gecko   : 
10-09 13:59:15.919  3595  3632 I Gecko   : ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x18001D,name=PBackground::Msg_PBlobConstructor) Value error: message was deserialized, but contained an illegal value
10-09 13:59:15.919  3595  3632 I Gecko   : 
10-09 13:59:15.919  3595  3632 I Gecko   : 
10-09 13:59:15.919  3595  3632 I Gecko   : ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x1E0003,name=???) Route error: message sent to unknown actor ID
10-09 13:59:15.919  3595  3632 I Gecko   : 
10-09 13:59:16.039   212   212 V WLAN_PSA: NL MSG, len[048], NL type[0x11] WNI type[0x5050] len[028]
10-09 13:59:16.859  4289  4289 E New Home Screen: Content JS ERROR: Failed to retrieve icon [object DOMError] 
10-09 13:59:16.859  4289  4289 E New Home Screen:     at proto.refresh/< (app://homescreen.gaiamobile.org/bower_components/gaia-app-icon/script.js:552:13)
10-09 13:59:17.659  4477  4520 I (Preallocated app): PAC file installed from data: URI
10-09 13:59:17.829  3595  3632 I Gecko   : 
10-09 13:59:17.829  3595  3632 I Gecko   : ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x18001D,name=PBackground::Msg_PBlobConstructor) Value error: message was deserialized, but contained an illegal value
10-09 13:59:17.829  3595  3632 I Gecko   : 
10-09 13:59:17.829  3595  3632 I Gecko   : 
10-09 13:59:17.829  3595  3632 I Gecko   : ###!!! [Parent][DispatchAsyncMessage] Error: (msgtype=0x1E0003,name=???) Route error: message sent to unknown actor ID

Comment 7

[:gerard-majax]

DOMError is unrelated, it is always reproduced and concerns mochi.test app.

Comment 8

[[:fabrice] Fabrice Desré]

cc-ing Sam as he's been looking at a similar blob ipc issue when using device storage.

Comment 9

[:gerard-majax]

Unable to reproduce at all with a debug Gecko build on a Flame :(

Comment 10

[Kevin Grandon :kgrandon]

(In reply to Alexandre LISSY :gerard-majax from comment #9)
> Unable to reproduce at all with a debug Gecko build on a Flame :(

Are you able to reproduce with a normal build on a flame?

Comment 11

[:gerard-majax]

(In reply to Kevin Grandon :kgrandon from comment #10)
> (In reply to Alexandre LISSY :gerard-majax from comment #9)
> > Unable to reproduce at all with a debug Gecko build on a Flame :(
> 
> Are you able to reproduce with a normal build on a flame?

Yes. And on a Z3c non debug with lots of applications. No need to reset-gaia, on that profile, just switching homescreen is enough. And even after switching once, I still got occurrences of PBlob errors ...

Comment 12

[:gerard-majax]

And after a reboot there is no trace of the issue. Unable to reproduce also when installing Gecko as an update.

Comment 13

[:gerard-majax]

Attachment: gdb stacktrace

So I have been able to reproduce that on my first try with Z3c, Gecko built in debug and following the STRs of reset-gaia then switch to new homescreen.

Comment 14

[:gerard-majax]

> (gdb) print idTableEntry
> $1 = {mRawPtr = 0xb6f65050 <_pr_envLock>}

Comment 15

[:gerard-majax]

That assert comes from bug 1076975.

Comment 16

[:gerard-majax]

Attachment: homescreen_icons_0.log

logcat while reproducing

Comment 17

[sgiles]

Duplicates this (https://bugzilla.mozilla.org/show_bug.cgi?id=1209545) but this one is probably better for tracking it I think.

Comment 19

[:gerard-majax]

So it would look like we are calling |IDTableEntry::GetOrCreateInternal()| https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#4505 from https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#1412

Since the MOZ_ASSERT() is https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#3991 it means what we get from |IDTableEntry::Create| is wrong.

With gdb I could check:
> (gdb) print id
> $3 = {m0 = 0, m1 = 61615, m2 = 45716, m3 = "\000\000\000\000\000\000\000"}

I don't know if that value is a correct one though.

There are four ways to return null from that code:
 (1) https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#4523
 (2) https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#4535
 (3) https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#4539
 (4) https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#4543

We know we pass:
> /* aMayCreate */       true,
> /* aMayGet */          false,
> /* aIgnoreProcessID */ false

The logcat shows:
> 10-13 12:17:02.091  1525  1556 I Gecko   : [Parent 1525] WARNING: '!aMayCreate', file ../../../gecko/dom/ipc/Blob.cpp, line 4542
> 10-13 12:17:02.091  1525  1556 I Gecko   : [Parent 1525] WARNING: '!idTableEntry', file ../../../gecko/dom/ipc/Blob.cpp, line 3965
> 10-13 12:17:02.092  1525  1556 F MOZ_Assert: Assertion failure: false (), at ../../../gecko/dom/ipc/Blob.cpp:3966

So we are reaching condition (4) and issue the warning. And thus we fail at https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#3965 |NS_WARN_IF(!idTableEntry)|.

All those are in the |AnyBlobConstructorParams::TKnownBlobConstructorParams| case. Yet, we get a stack that is about assertion failure at https://dxr.mozilla.org/mozilla-central/rev/11ff0ccb7d59311df4c190d331c8b58c6e35a0c8/dom/ipc/Blob.cpp#3991 in |AnyBlobConstructorParams::TSameProcessBlobConstructorParams|

Comment 20

[:gerard-majax]

Fun fact: it looks like delaying the publication of "displayed" event in Gaia when switching homescreen makes the bug disappearing ...

Comment 21

[Candice Serran (:cserran)]

(In reply to Alexandre LISSY :gerard-majax from comment #20)
> Fun fact: it looks like delaying the publication of "displayed" event in
> Gaia when switching homescreen makes the bug disappearing ...

Hey Alex, since this bug is assigned to you, are you working on the fix for this? Or does this bug need to be addressed by the platform team? :)

Thanks!

Comment 22

[:gerard-majax]

(In reply to Alexandre LISSY :gerard-majax from comment #20)
> Fun fact: it looks like delaying the publication of "displayed" event in
> Gaia when switching homescreen makes the bug disappearing ...

It's not "displayed" but "changed".

Comment 23

[:gerard-majax]

(In reply to Candice Serran (:cserran) from comment #21)
> (In reply to Alexandre LISSY :gerard-majax from comment #20)
> > Fun fact: it looks like delaying the publication of "displayed" event in
> > Gaia when switching homescreen makes the bug disappearing ...
> 
> Hey Alex, since this bug is assigned to you, are you working on the fix for
> this? Or does this bug need to be addressed by the platform team? :)
> 
> Thanks!

I fear that is something platform will have to work on. So far everything I have been able to hack would point to some kind of race condition around Blob passing within process. That is triggered when we are changing the homescreen because at that moment we will kill the previous homescreen, instantiate the new one and then make it visible.

We do notify to start displaying it by publishing that "changed" event. By doing so, the homescreen code will start to fetch apps icons. Then it seems we have something bad happening at that time but as exposed in comment 19 it's unclear exactly where it is failing.

Comment 25

[Jan Varga [:janv]]

I'm going to take a look at the issue.

Comment 26

[:gerard-majax]

Attachment: homescreen_entry_get_put.log

Checking the IDTableEntry Get() and Put() calls. One thing that is interesting in that is the latest ID we manipulate before crashing is "61de7b13-54c2-4a44-8eba-4e59f6d30e95".

Now, just before we crash, we see:
> 10-16 16:40:12.562 18167 18198 I Gecko   : AllocPBlobParent:209 => AllocPBlobParent
> 10-16 16:40:12.562 18167 18198 I Gecko   : CreateFromParams:3960 => TKnownBlobConstructorParams: IN
> 10-16 16:40:12.562 18167 18198 I Gecko   : IDTableEntry::GetOrCreateInternal: aID={61de7b13-54c2-4a44-8eba-4e59f6d30e95} ->Get()
> 10-16 16:40:12.562 18167 18198 I Gecko   : IDTableEntry::GetOrCreateInternal: aID={61de7b13-54c2-4a44-8eba-4e59f6d30e95} ->Get() => entry NOK
> 10-16 16:40:12.562 18167 18198 I Gecko   : [Parent 18167] WARNING: '!aMayCreate', file ../../../gecko/dom/ipc/Blob.cpp, line 4551
> 10-16 16:40:12.562 18167 18198 I Gecko   : [Parent 18167] WARNING: '!idTableEntry', file ../../../gecko/dom/ipc/Blob.cpp, line 3966
> 10-16 16:40:12.562 18167 18198 F MOZ_Assert: Assertion failure: false (), at ../../../gecko/dom/ipc/Blob.cpp:3967

So we do not find an entry in IDTableEntry::GetOrCreateInternal, hence we are in https://dxr.mozilla.org/mozilla-central/rev/2387ada864282880d3a498d643abe3d8b887ee59/dom/ipc/Blob.cpp#4541

Yet, if you look earlier in that log for the same ID value, we get something different:
> 10-16 16:40:08.641 18167 18167 I Gecko   : IDTableEntry::GetOrCreateInternal: aID={61de7b13-54c2-4a44-8eba-4e59f6d30e95} ->Get()
> 10-16 16:40:08.641 18167 18167 I Gecko   : IDTableEntry::GetOrCreateInternal: aID={61de7b13-54c2-4a44-8eba-4e59f6d30e95} ->Get() => entry NOK
> 10-16 16:40:08.641 18167 18167 I Gecko   : IDTableEntry::GetOrCreateInternal: aID={61de7b13-54c2-4a44-8eba-4e59f6d30e95} ->Put()

On that call, we do have no entry, but we are able to reach the end of the method and to call Put() to populate the table.

Comment 27

[:gerard-majax]

Attachment: homescreen_entry_get_put_3_SUCCESS.log

Comment 28

[GitHub Autolander Bot]

Attachment: [gaia] Cwiiis:bug1211266-work-around-get-icon > mozilla-b2g:master

Comment 29

[Chris Lord [:cwiiis]]

Comment on attachment 8674985 [details] [review]
[gaia] Cwiiis:bug1211266-work-around-get-icon > mozilla-b2g:master

Got r=gmarty earlier, was leaving until the last minute in case the platform bug got fixed before now.

Comment 30

[:gerard-majax]

Attachment: homescreen_entry_get_put_4_FAIL.log

Comment 31

[:gerard-majax]

Can you have a look at comment 26 and attachment 8674919 [details] and attachment 8674998 [details] ? It seems that the sIDTable behavior is the a good root to the problem but I still suspect that this is just a symptom. How can we debug further?

Comment 32

[Chris Lord [:cwiiis]]

I've merged the work-around: https://github.com/mozilla-b2g/gaia/commit/4d592d4d385c85296511216e7c702c71bf2c9540

Not sure if we want to track the platform bug in this bug or not - I'll leave that up to others.

Comment 33

[:gerard-majax]

Attachment: homescreen_entry_get_put_7.log

Crash with Blob 5ee51033-aac4-4576-a673-d33884bfb6e1

Comment 34

[:gerard-majax]

Attachment: blob-ipc-homescreen.patch

Debugging patch

Comment 35

[:gerard-majax]

Attachment: gdb stacktrace with MOZ_ASSERT(false) added

This is the stack we get if we break when we are in the ::Get() call in the unexpected state: that matches the NS_WARN_IF(!aMayCreate).

Comment 36

[:gerard-majax]

Attachment: homescreen_get_put_assert.log

Log matching the attachment 8675309 [details]: gdb stacktrace with MOZ_ASSERT(false) added

Comment 37

[:gerard-majax]

(In reply to Alexandre LISSY :gerard-majax from comment #36)
> Created attachment 8675310 [details]
> homescreen_get_put_assert.log
> 
> Log matching the attachment 8675309 [details]: gdb stacktrace with
> MOZ_ASSERT(false) added

From that we know that ID "efa6019f-ccab-4b86-966c-26bbe2819e08" did propery got inserted with the Put() call and a subsequent Get() call did succeed. Now when we hit the failure, we do see that |entry| is a null:
> (gdb) f
> #0  0xb3794da8 in mozilla::dom::BlobParent::IDTableEntry::GetOrCreateInternal (aID=..., aProcessID=-1619102152, aBlobImpl=aBlobImpl@entry=0x0, aMayCreate=aMayCreate@entry=false, aMayGet=aMayGet@entry=true, 
    aIgnoreProcessID=aIgnoreProcessID@entry=false) at ../../../gecko/dom/ipc/Blob.cpp:4558
> 4558	        MOZ_ASSERT(false);
> (gdb) print entry
> $1 = {mRawPtr = 0x0}

Comment 38

[:gerard-majax]

Attachment: gdb sIDTable

Comment 39

[:gerard-majax]

Attachment: homescreen_entry_get_put_10.log

That log exposes the crash. And we can see the Blob ID "842b74dd-7a7a-431c-87aa-2e927f66af3f". That blob gets removed from the hashmap just before we try to do a Get(), because of IDTableEntry destructor being called.

Comment 40

[:gerard-majax]

Attachment: stacktrace of Remove()

Comment 41

[:gerard-majax]

Attachment: addr2line

That is the stack addr2line result of attachment 8675643 [details]

Comment 42

[:gerard-majax]

(In reply to Alexandre LISSY :gerard-majax from comment #41)
> Created attachment 8675644 [details]
> addr2line
> 
> That is the stack addr2line result of attachment 8675643 [details]

So we remove the entry after receiving an IPC "PBlob::Msg___delete__" message.

Comment 43

[:gerard-majax]

Attachment: homescreen_entry_get_put_18.log

More debugging, to try to identify if the IPC |Send::__delete__| call could come from |NoteDyingRemoteBlobImpl| but so far it's not very completely useful.

Comment 44

[:gerard-majax]

Attachment: blob-ipc-homescreen.patch

Comment 45

[:gerard-majax]

Hacked https://dxr.mozilla.org/mozilla-central/rev/d1a89632277fbaaf470c90a35573776048988f2d/dom/ipc/Blob.cpp#4111 and commented the |PBlobParent::Send__delete__()| statement, I am still hitting the issue. That answers comment 43: we are not receiving the bogus delete call from that call site but from somewhere else.

Comment 46

[:gerard-majax]

I have troubles explaining that set of calls that are part of attachment 8675644 [details]:
> mozilla::dom::PContentParent::RemoveManagee(int, mozilla::ipc::IProtocol*)
> /home/alex/codaz/Mozilla/b2g/devices/XperiaZ3c/B2G.L/objdir-gecko-dbg/ipc/ipdl/PContentParent.cpp:2579

> mozilla::dom::PBlobParent::OnMessageReceived(IPC::Message const&)
> /home/alex/codaz/Mozilla/b2g/devices/XperiaZ3c/B2G.L/objdir-gecko-dbg/ipc/ipdl/PBlobParent.cpp:252 (discriminator 1)

> mozilla::dom::PContentParent::OnMessageReceived(IPC::Message const&)
> /home/alex/codaz/Mozilla/b2g/devices/XperiaZ3c/B2G.L/objdir-gecko-dbg/ipc/ipdl/PContentParent.cpp:3366

The statement at |PContentParent.cpp:2579| is |DeallocPPresentationParent(actor);|, being part of |PPresentationMsgStart| case in |PContentParent::RemoveManagee|.
The statement at |PBlobParent.cpp:252|     is |return MsgProcessed;|, being part of |PBlob::Msg___delete____ID| case.
The statement at |PContentParent.cpp:3366| is |(routed__)->OnMessageReceived(msg__);|

So it looks like we reach the expected |PContentParent::RemoveManagee| method, but I cannot explain why we enter the |PPresentationMsgStart| case while we are manipulating blobs.

Comment 47

[:gerard-majax]

Attachment: focusing on delete and get operations

Here we can see that blob d756c688-b7a8-402c-91a1-d07be96798eb gets created by thread 13711 of process 13711. The same thread issues a Remove() operation. The subsequent CreateFromParams() and Get() calls that fails are in issued by thread 13742 from process 13711.

Comment 48

[:gerard-majax]

Attachment: process_log.sh to process logcat and add addr2line infos

Comment 49

[:gerard-majax]

Attachment: homescreen_entry_get_put_20_processed.log

Comment 50

[:gerard-majax]

Attachment: stack of Remove() with protocol dump

Log shows the correct PBlobMsgStart protocol id being used, but the stacktrace stil matches the RemoveManagee() call site of PPresentationMsgStart, so I'm a little bit lost. I would suspect that there's something wrong when collecting the stack itself and that we do indeed really trigger the correct path of PBlobMsgStart and its RemoveManagee() call. Said otherwise, we receive a legit delalloc request for the blob. Still have to track where this is coming from.

Comment 51

[:gerard-majax]

Attachment: blob-ipc-homescreen.patch

Comment 52

[Chris Lord [:cwiiis]]

This blocks replaceable homescreens, but not new homescreen (which is shipping a work-around currently).

Comment 53

[:gerard-majax]

Attachment: homescreen_entry_get_put_23.log

More logging, we see PBlob delete issued:

> 10-22 11:29:35.039 29908 29908 I GeckoIPC: [time:1445506175038996][29908->29441][PBlobChild] Sending Msg___delete__([TODO])
> 10-22 11:29:35.040 29908 29908 I GeckoIPC: [time:1445506175040093][29908->29441][PBlobChild] Sending Msg_PBlobStreamConstructor([TODO])
> 10-22 11:29:35.040 29441 29472 I GeckoIPC: [time:1445506175040311][29441<-29908][PBlobParent] Received Msg_PBlobStreamConstructor([TODO])
> 10-22 11:29:35.042 29908 29908 I GeckoIPC: [time:1445506175042367][29908->29441][PBlobChild] Sending Msg___delete__([TODO])
> 10-22 11:29:35.043 29908 29908 I GeckoIPC: [time:1445506175043300][29908->29441][PBlobChild] Sending Msg_PBlobStreamConstructor([TODO])
> 10-22 11:29:35.045 29441 29441 I GeckoIPC: [time:1445506175045524][29441<-29908][PBlobParent] Received Msg___delete__([TODO])
> 10-22 11:29:35.045 29441 29441 I Gecko   : RemoveManagee: aProtocolId:30
> 10-22 11:29:35.045 29441 29441 I Gecko   : RemoveManagee: aProtocolId:30 PBlobMsgStart
> 10-22 11:29:35.045 29441 29441 I GeckoIPC: [time:1445506175045645][29441<-29908][PBlobParent] Received Msg___delete__([TODO])
> 10-22 11:29:35.045 29441 29441 I Gecko   : RemoveManagee: aProtocolId:30
> 10-22 11:29:35.045 29441 29441 I Gecko   : RemoveManagee: aProtocolId:30 PBlobMsgStart

Comment 54

[:gerard-majax]

Attachment: homescreen_entry_get_put_24.log

That contains stack from PBlobChild::Send__delete__ call sites.

Comment 55

[:gerard-majax]

Attachment: stack of PBlobChild::Send__delete__() with protocol dump

Excerpt of the end of attachment 8677364 [details] before the crash

Comment 56

[:gerard-majax]

Attachment: temp5.txt

New stack after hacking StructuredCloneData() for Move constructor

Comment 57

[:gerard-majax]

Attachment: structuredcloned_move_ctor.patch

Comment 58

[:gerard-majax]

Good news/bad news, it's all so reproduced on B2G Desktop/Mulet build (debug or not)

Comment 59

[Jan Varga [:janv]]

(In reply to Alexandre LISSY :gerard-majax from comment #58)
> Good news/bad news, it's all so reproduced on B2G Desktop/Mulet build (debug
> or not)

I'm going to try that too.

Comment 60

[:gerard-majax]

I'm still struggling. Tried collecting nsHttp logs yesterday with Mulet build, in case the problems lies with the use of XHR (which produces the blob we send), but each time I enabled NSPR_LOG_MOULES this was not reproduced.

I still have some unanswered questions regarding attachment 8678120 [details]: it looks like we are releasing RemoteBlobImpl because of the StructuredCloneData destructor being called, and that comes from Release() on nsRefPtr<nsFrameMessageManager>. So: 
 - does that fact holds and matches the expected code path?

If so, then I guess it means the lack of reference is either against:
 - BlobChild::RemoteBlobImpl
 - StructuredCloneData

I'm out of ideas of where to check those two ideas :/

Comment 61

[Gregor Wagner [:gwagner]]

(In reply to Jan Varga [:janv] from comment #59)
> (In reply to Alexandre LISSY :gerard-majax from comment #58)
> > Good news/bad news, it's all so reproduced on B2G Desktop/Mulet build (debug
> > or not)
> 
> I'm going to try that too.

Jan, any update here?

Comment 62

[Andrea Marchesini [:baku]]

> Jan, any update here?

Yes. It's a regression introduced by StructuredCloneHolder. The problem is that when we retrieve data from a cloned buffer (child process), we create a new PBackground actor for any cloned BlobImpl. This is something that it was not done previously (wrongly), but doing this, when this PBackground Actor is released, it deletes the BlobParent on the parent process, and from here, the crash.

Finally we know where the bug is. Now we have to fix it :)

Comment 63

[:gerard-majax]

I guess it's time to switch assignee :)

Comment 64

[Andrea Marchesini [:baku]]

Attachment: patch

What I suspect it's happening here is that, racy, the constructor of the PBackground BlobParent is faster than then PContent one. This case it's the first one that has to keep the second one alive. khuey can you review this patch?

BTW, I also would like to have the move ctor patch landed.

Comment 65

[Andrea Marchesini [:baku]]

Comment on attachment 8680669 [details] [diff] [review]
patch

Review of attachment 8680669 [details] [diff] [review]:
-----------------------------------------------------------------

::: b2g/app/b2g.js
@@ +299,5 @@
>  // Layers Acceleration.  We can only have nice things on gonk, because
>  // they're not maintained anywhere else.
>  pref("layers.offmainthreadcomposition.enabled", true);
>  #ifndef MOZ_WIDGET_GONK
> +pref("dom.ipc.tabs.disabled", false);

Ignore this. This is just required to reproduce the issue.

Comment 66

[:gerard-majax]

Comment on attachment 8680669 [details] [diff] [review]
patch

More than 15 consecutive runs successfull, even with the workaround removed from homescreen.

As soon as I remove that patch, issue gets reproduced very easily again. Looks like you found the fix!

Comment 67

[Chris Lord [:cwiiis]]

Great - here's a PR for removing the work-around from gaia-site-icon: https://github.com/gaia-components/gaia-site-icon/pull/17

And n?me to test/merge that and then open a PR for Gaia once this is fixed.

Comment 68

[Andrea Marchesini [:baku]]

Attachment: crash.patch

Comment 69

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 8681199 [details] [diff] [review]
crash.patch

Review of attachment 8681199 [details] [diff] [review]:
-----------------------------------------------------------------

::: b2g/app/b2g.js
@@ +299,5 @@
>  // Layers Acceleration.  We can only have nice things on gonk, because
>  // they're not maintained anywhere else.
>  pref("layers.offmainthreadcomposition.enabled", true);
>  #ifndef MOZ_WIDGET_GONK
> +pref("dom.ipc.tabs.disabled", false);

uh, what is this about?

::: dom/base/StructuredCloneHolder.cpp
@@ +562,5 @@
> +
> +  // This is needed just for workers thread.
> +  if (NS_IsMainThread()) {
> +    return blobImpl.forget();
> +  }

Why?  Isn't this called when somebody takes a PContent blob and puts it in an IndexedDB?

Comment 70

[Andrea Marchesini [:baku]]

Bent, if you have time, can you tell me something more about EnsureBlobForBackgroundManager?
In your code, this was used only in workers when postMessage() was called. In my unification of the StructureClone use, I use this everywhere, and in general it works fine.

The issue we have here is a race condition created by the 2 BlobChild actors (1 from PContent and 1 from PBackground).
One of these 2 is released, and doing that, it calls __delete__. The BlobParent deletes the IDTableEntry.
But when the second BlobChild, finally, creates the BlobParent for the same RemoteBlob, this parent doesn't have a valid IDTableEntry anymore.

With my patch I don't called EnsureBlobForBackgroundManager when we are not in a worker thread. This works, but it's an hack :)

Comment 71

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Hm. I don't remember this code too well but it sounds like there's a refcount problem on the parent side? If you have two BlobChild actors that are referencing the same blob then when the first is released it shouldn't trigger the deletion of the IDTableEntry right?

Comment 72

[Andrea Marchesini [:baku]]

Attachment: patch

Ok, this is the _real_ fix for this bug. And here a quick description of what the bug is about:

1. When we transfer a Blob from parent to process, at some point, we create a BlobChild.
2. in StructuredCloneHolder we find out that this is a nsIRemoteBlob and we create a BlobChild for PBackground as well.
3. a SendPBlobConstructor is sent to the parent for the creation of a BlobParent in PBackground.
3. nsIRemoteBlob of the first BlobChild (created from nsIContent*) gets released because nothing is keeping it alive.
4. race condition: the Send__delete_ of BlobChild (nsIContent) is received before the CTOR for the BlobParent in PBackground.
5. we remove the entry of IDTableEntry.
6. When the BlobParent for PBackground is created, it finds the ID of the other BlobParent, but that has been deleted in point 4. IDTableEntry doesn't exist any more and we crash.

What this patch does is to keep alive the remoteBlob when we create the PBackground BlobParent from another BlobChild (nsIContent).

Comment 73

[Andrea Marchesini [:baku]]

Maybe bent, if you have time, you can give me a feedback for this patch.

Comment 74

[Ben Turner (not reading bugmail, use the needinfo flag!)]

(In reply to Andrea Marchesini (:baku) from comment #73)
> Maybe bent, if you have time, you can give me a feedback for this patch.

Sure, I'll look over the weekend.

Comment 75

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 8683264 [details] [diff] [review]
patch

Review of attachment 8683264 [details] [diff] [review]:
-----------------------------------------------------------------

I don't think this is what you really want to do. This holds the BlobImpl alive on the child side forever, right? The whole idea underlying this blob stuff is that when the BlobImpl refcount drops to 0 we destroy the actor. With this patch in some cases that will never happen.

I think what you probably want to do is AddRef the BlobImpl while your PBackground blob is being constructed. Then when it is you can drop the ref. This is basically the same problem we solved with WaitForSliceCreation (http://mxr.mozilla.org/mozilla-central/source/dom/ipc/Blob.cpp#3373) only for the main thread. We do that synchronously, but you could make an async version of that for the main thread:

  protocol PBlob {
    // ...
  child:
    Created();
  };

Then just send that message once the actor is created on PBackground in the parent process, and you can drop the extra ref there.

Comment 76

[Andrea Marchesini [:baku]]

Attachment: crash.patch

bent, I hope you can find time for this new patch!
This patch is exactly the same of before, but in addition it adds a "|child: CreatedFromKnownBlob()|". When the PBlobParent is created, we send a notification to the child in case that blob is built from a known blob.

When the child receives that call, it frees the mDifferentProcessRemoteBlob.

Comment 77

[Andrea Marchesini [:baku]]

Attachment: crash.patch

Here a new version. I changed 1 like to improve the check of the kind of blob constructor param we have.

Comment 78

[Andrea Marchesini [:baku]]

Andrew, how do we want to proceed with this bug? I'm sure bent will review this patch soon or late, but how urgent is this bug?

Comment 79

[Andrew Overholt [:overholt]]

Gregor, wdyt?

Comment 80

[Gregor Wagner [:gwagner]]

(In reply to Andrew Overholt [:overholt] from comment #79)
> Gregor, wdyt?

It's important that we fix it but we are not in a huge hurry. It should be fine if we can fix it in the next 1-2 weeks.

Comment 81

[:gerard-majax]

I'm rebuilding uptodate without the workaround from Cwiiis and I will be retesting the latest patch.

Comment 82

[:gerard-majax]

Comment on attachment 8688962 [details] [diff] [review]
crash.patch

So I have performed some testing using:
> for i in $(seq 60); do (echo "Making gaia ... "; make PRODUCTION=0 MOZILLA_OFFICIAL=0 NO_LOCK_SCREEN=1 NOFTU=1 reset-gaia 2>/dev/null 1>/dev/null; echo "Gaia booting #${i}, waiting 60 secs now ..."; sleep 60) | ts "%b %d %H:%M:%S |>"; done;

Over 42 runs with the fix, there was no IPC blob error in the logs.
Over 16 runs without the fix, there was 4 IPC blob errors in the logs. I am continuing the testing to assert the frequency, but so far it would confirm the fix is good.

Comment 83

[:gerard-majax]

After 42 retries without the fix, I got 10 IPC blob errors ...

Comment 84

[:gerard-majax]

Comment on attachment 8688962 [details] [diff] [review]
crash.patch

I could not reproduce the issue with that. Without, I get a IPC error in a reliable and reproductible way.

Comment 85

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Comment on attachment 8688962 [details] [diff] [review]
crash.patch

Review of attachment 8688962 [details] [diff] [review]:
-----------------------------------------------------------------

I think this is probably fine. Just make sure you test with artificial slowdowns on PBackground to be sure (e.g. play around with http://mxr.mozilla.org/mozilla-central/source/dom/indexedDB/ActorsParent.cpp#245).

::: dom/base/StructuredCloneHolder.cpp
@@ +562,5 @@
>  
>    if (!aManager) {
>      aManager = BackgroundChild::GetForCurrentThread();
> +    if (!aManager) {
> +      return blobImpl.forget();

It seems really weird to call a function named 'EnsureBlobForBackgroundManager' and expect it to do nothing if there's no PBackgroundChild available... Why make this change?

@@ +670,5 @@
>  
>    RefPtr<BlobImpl> blobImpl = EnsureBlobForBackgroundManager(aBlob->Impl());
>    MOZ_ASSERT(blobImpl);
>  
> +  if (NS_WARN_IF(NS_FAILED(blobImpl->SetMutable(false)))) {

This can be MOZ_ALWAYS_TRUE() right?

::: dom/ipc/Blob.cpp
@@ +1752,5 @@
>  
>    BlobChild* mActor;
>    nsCOMPtr<nsIEventTarget> mActorTarget;
>  
> +  RefPtr<BlobImpl> mDifferentProcessBlobImpl;

This needs a big comment explaining why this exists, how long it lives, etc., because this kinda goes against the whole design.

Comment 86

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/385c7069dca8

Comment 87

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

(In reply to Pulsebot from comment #86)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/385c7069dca8

This was a patch with the wrong bug number and has since been backed out. Please disregard. :)

Comment 88

[Andrea Marchesini [:baku]]

Wow, thanks bent.

> It seems really weird to call a function named
> 'EnsureBlobForBackgroundManager' and expect it to do nothing if there's no
> PBackgroundChild available... Why make this change?

This EnsureBlobForbackgroundManager can be called on the main-thread as well, but nothing guaranties that PBackground is set up there yet. Soon PBackground will be initialized by default on main-thread and this check will go away.

Comment 89

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/cbc2c8a24438

Comment 90

[Pulsebot]

Backout:
https://hg.mozilla.org/integration/mozilla-inbound/rev/6e50570f0782

Comment 91

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

(In reply to Pulsebot from comment #89)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/cbc2c8a24438

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/71ba07014e12 for asan m(1) failures

https://treeherder.mozilla.org/logviewer.html#?job_id=17775493&repo=mozilla-inbound

Comment 92

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Not just asan: https://treeherder.mozilla.org/logviewer.html#?job_id=17777505&repo=mozilla-inbound

Comment 94

[Andrea Marchesini [:baku]]

The bad news is that the patch has been backed out. But the good news is that this patch triggers bug 1226477 more frequently.

Comment 95

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/79004346238d

Comment 96

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8405467ea7ad

Comment 97

[Pulsebot]

Backout:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2ba34b52df6b

Comment 98

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Backed out for static analysis bustage on Linux and OS X (Windows has infrastructure issues at the moment):
Backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/3cec4367c10b

Bustage: https://treeherder.mozilla.org/logviewer.html#?job_id=17833382&repo=mozilla-inbound

/builds/slave/m-in-m64-st-an-d-0000000000000/build/src/dom/ipc/Blob.cpp:3044:3: error: 'AddRef' cannot be called on the return value of 'operator->'
make[5]: *** [Blob.o] Error 1
make[5]: *** Waiting for unfinished jobs....
make[4]: *** [dom/ipc/target] Error 2
make[4]: *** Waiting for unfinished jobs....
make[3]: *** [compile] Error 2
make[2]: *** [default] Error 2
make[1]: *** [realbuild] Error 2
make: *** [build] Error 2
Return code: 2

Comment 99

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c33072613b5e

Comment 100

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/c33072613b5e

Comment 101

[Adam Alldredge [:AdamA][Inactive]]

All icons were visible when switching between homescreens on Flame 2.6 and Aries 2.6.

Environmental Variables:
Device: Aries 2.6 [Full Flash]
BuildID: 20151201122021
Gaia: 59c8605876736b22acaaed25be00008e452149cb
Gecko: 89ae375e24d7560f613b75a585e9ed4238604494
Gonk: a19052e4389c3ae2d8fc3e7a74a475401baacc56
Version: 45.0a1 (2.6) 
Firmware Version: D5803_23.1.A.1.28_NCB.ftf
User Agent: Mozilla/5.0 (Mobile; rv:45.0) Gecko/45.0 Firefox/45.0

Device: FlameKK 2.6 [Full Flash][512mb]
BuildID: 20151201030222
Gaia: 59c8605876736b22acaaed25be00008e452149cb
Gecko: 66a6d7ec9534b9d7847b665142fef0dd87623768
Gonk: 205ac4204bbbb2098a8046444acba551ba5dc75a
Version: 45.0a1 (2.6) 
Firmware Version: v18D
User Agent: Mozilla/5.0 (Mobile; rv:45.0) Gecko/45.0 Firefox/45.0

Result:
All icons are visible.

Comment 102

[Chris Lord [:cwiiis]]

Attachment: Remove work-around

This removes the work-around from the component, I'll add a PR for gaia merge/uplift once this is merged.

Comment 103

[Guillaume Marty [:gmarty]]

Comment on attachment 8694847 [details] [review]
Remove work-around

r+. Glad we finally removed that hack.

Comment 104

[GitHub Autolander Bot]

Attachment: [gaia] Cwiiis:bug1211266-remove-workaround > mozilla-b2g:master

Comment 105

[Chris Lord [:cwiiis]]

Comment on attachment 8703593 [details] [review]
[gaia] Cwiiis:bug1211266-remove-workaround > mozilla-b2g:master

Update gaia-site-icon to remove bug work-around.

Comment 106

[Guillaume Marty [:gmarty]]

Comment on attachment 8703593 [details] [review]
[gaia] Cwiiis:bug1211266-remove-workaround > mozilla-b2g:master

Looks good!

Comment 107

[Chris Lord [:cwiiis]]

Quick, thanks! Merged: https://github.com/mozilla-b2g/gaia/commit/81511c721b1140f1ec261a27e44bea04c43e5b16

Comment 108

[Chris Lord [:cwiiis]]

Did the platform fix get uplifted to b2g-44?

Comment 109

[Andrea Marchesini [:baku]]

Comment on attachment 8688962 [details] [diff] [review]
crash.patch

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Cloning blobs between threads
User impact if declined: a crash
Testing completed: yes, but there is not a mochitest because this is a race condition
Risk to taking this patch (and alternatives if risky): no big risk. This patch has been tested for quite a while.
String or UUID changes made by this patch: none

Comment 110

[Chris Lord [:cwiiis]]

Comment on attachment 8703593 [details] [review]
[gaia] Cwiiis:bug1211266-remove-workaround > mozilla-b2g:master

This is actually a b2g-2.5 uplift request, but you can't do that on a Gecko bug. Assuming that the platform bug is uplifted (as it should, given this has long been nominated a 2.5 blocker), this should also be uplifted to Gaia.

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): The work-around for this bug can itself, rarely, cause missing icons, due to a small logic error.
User impact if declined: Occasionally missing bookmark icons.
Testing completed: On master, manually tested, this just removes a work-around in Gaia that is no longer necessary when the platform bug is fixed.
Risk to taking this patch (and alternatives if risky): Low
String or UUID changes made by this patch: None