1070066 - [Dialer] The call screen does not display call info and shows a black background after repeatedly placing calls

Status: RESOLVED DUPLICATE of bug 1068109

(Firefox OS Graveyard :: Gaia::Dialer, defect)

Description

[Seth Miko [:SMiko]]

Attachment: NoInfo.txt

Description: After repeatedly calling and hanging up, the call screen will display a black background and the call information will not display.

Repro Steps:
1: Update a Flame to 20140919000204
2: Open Dialer and use keypad to type in a valid 10 digit number
3: Place the call and immediately hang up.
4: Press the dial button on the keypad screen to redial the number. 
5: Immediately hang up
6: Repeat steps 4 and 5 up to 10 times

Actual:
The call screen displays a black background. The number calling does not appear.

Expected:
The home wallpaper is shown as well as the number dialed.

Flame 2.1(319mb)

Environmental Variables:
Device: Flame 2.1 (319mb)
Build ID: 20140919000204
Gaia: 2a612867039a7cfb3af6e692bfae4482b06705e9
Gecko: 004bc0d262e5
Version: 34.0a2 (Master)
Firmware Version: v123
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0

Notes:
1: Once this issue occurs, the black screen will be displayed when calling until rebooting the phone.
2: Calls made with the black screen displayed do not appear in the call log.
3: May be related to Bug 819467

Repro frequency: 100%

See attached: logcat

Video clip: http://youtu.be/RqE-LNfUOj4

Comment 1

[Seth Miko [:SMiko]]

This issue DOES occur on Flame 2.2(319mb), Open C 2.2, Flame 2.1(512mb), Flame 2.1 KK base(319mb), and Open C 2.1

Actual Result: The call screen displays a black background. The number calling does not appear.

Flame 2.2 (319mb)

Environmental Variables:
Device: Flame 2.2 
Build ID: 20140919040205
Gaia: bc2da39ccd2b82b67773f10c8da8fc8eedc483ab
Gecko: c8e325eee9e1
Version: 35.0a1 
Firmware Version: v123
User Agent: Mozilla/5.0 (Mobile; rv:35.0) Gecko/35.0 Firefox/35.0

Open C 2.2

Environmental Variables:
Device: Open_C 2.2
Build ID: 20140919040205
Gaia: bc2da39ccd2b82b67773f10c8da8fc8eedc483ab
Gecko: c8e325eee9e1
Version: 35.0a1 
Firmware: P821A10v1.0.0B06_LOG_DL
User Agent: Mozilla/5.0 (Mobile; rv:35.0) Gecko/35.0 Firefox/35.0

Flame 2.1 (512 mb)

Environmental Variables:
Device: Flame 2.1
BuildID: 20140919000204
Gaia: 2a612867039a7cfb3af6e692bfae4482b06705e9
Gecko: 004bc0d262e5
Version: 34.0a2 (2.1) 
Firmware Version:  v123
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0

Flame 2.1 KitKat Base (319mb)

Environmental Variables:
Device: Flame 2.1 (319mb)
Build ID: 20140919063003
Gaia: f0f22bb46c881e02524b3991c2587ff8c0a9fc37
Gecko: ab2a88c05a4b
Version: 34.0a2 
Firmware Version: v180
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0

Open C 2.1

Environmental Variables:
Device: Open_C 2.1
Build ID: 20140919000204
Gaia: 2a612867039a7cfb3af6e692bfae4482b06705e9
Gecko: 004bc0d262e5
Version: 34.0a2 (Master)
Firmware Version: P821A10V1.0.0B06_LOG_DL
User Agent: Mozilla/5.0 (Mobile; rv:34.0) Gecko/34.0 Firefox/34.0

This issue does NOT occur on Flame 2.0(319mb) JB base, Flame 2.0(319mb) KK base, or Open C 2.0

Actual Result: The screen displays the home wallpaper and the number calling

Flame 2.0 (319mb)

Environmental Variables:
Device: Flame 2.0 (319mb)
Build ID: 20140919000204
Gaia: 31434a3949556171f3565ca47ac2b44e810e95e6
Gecko: a10034c1964f
Version: 32.0 (2.0)
Firmware Version: v123
User Agent: Mozilla/5.0 (Mobile; rv:32.0) Gecko/32.0 Firefox/32.0

Flame 2.0 KitKat Base (319mb)

Environmental Variables:
Device: Flame 2.0 
Build ID: 20140919063017
Gaia: 31434a3949556171f3565ca47ac2b44e810e95e6
Gecko: fb1589259e4f
Version: 32.0 (2.0)
Firmware Version: v180
User Agent: Mozilla/5.0 (Mobile; rv:32.0) Gecko/32.0 Firefox/32.0

Open_C 2.0

Enviromental Variables:
Device: Open_C 2.0
Build ID: 20140919000204
Gaia: 31434a3949556171f3565ca47ac2b44e810e95e6
Gecko: a10034c1964f
Version: 32.0 (2.0)
Firmware: P821A10v1.0.0B06_LOG_DL
User Agent: Mozilla/5.0 (Mobile; rv:32.0) Gecko/32.0 Firefox/32.0

Comment 2

[Anthony Ricaud (:rik)]

I think this could be related to the attention window changes. That's bug 927862.

Bug 1068109 will probably fix this by re-introducing a 2s delay that we lost.

Comment 3

[Derek Harris [:DerekH] - Dont need info. Last day 6/5/15]

Please note that the Environmental Variables from comment 0 are for Flame 2.1 (319mb) and not master.

Comment 4

[Derek Harris [:DerekH] - Dont need info. Last day 6/5/15]

[Blocking Requested - why for this release]:

Nominating this because it is a regression, and the UI can become unusable

Comment 5

[Wesley Huang [:wesley_huang] (EPM) (NI me)]

triage: regression

Comment 6

[Seth Miko [:SMiko]]

Initial Regression Window: mozilla-central-flame

Last Working

Device: Flame Master
BuildID: 20140830094116
Gaia: c05ee27dd1f39e0f1cceb8bc7706e20f297cd9df
Gecko: 82e1c0a8c589
Version: 34.0a1

First Broken 

Device: Flame Master
BuildID: 20140830195315
Gaia: 2be78d83a760fa3b9638fe51c266b442d14597f1
Gecko: 1db35d2c9a2f
Version: 34.0a1

1st Broken Gaia/Last Working Gecko- Issue does NOT repro
Gaia: 2be78d83a760fa3b9638fe51c266b442d14597f1
Gecko: 82e1c0a8c589

Last working Gaia/First Broken Gecko- Issue DOES repro = gecko issue
Gaia: c05ee27dd1f39e0f1cceb8bc7706e20f297cd9df
Gecko: 1db35d2c9a2f

1st Push Log
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=82e1c0a8c589&tochange=1db35d2c9a2f
----------------------------------------------------------------------
B2G Inbound 

Last Working
BuildID: 20140829133157
Gaia: 3a95ab1c33084d110351a39eb86d49a18bcf39f3
Gecko: 6dc0a998af58

First Broken
BuildID: 20140829140157
Gaia: 3a95ab1c33084d110351a39eb86d49a18bcf39f3
Gecko: 6b1690ad2cf5

B2G Inbound Push Log
hg.mozilla.org/integration/b2g-inbound/pushloghtml?fromchange=6dc0a998af58&tochange=6b1690ad2cf5

Comment 7

[Joshua Mitchell (Inactive)]

Kyle - the pushlog has only 2 patches, both yours - could you investigate? 

http://hg.mozilla.org/integration/b2g-inbound/pushloghtml?fromchange=6dc0a998af58&tochange=6b1690ad2cf5

Comment 8

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Not reproducable on 2.2 built yesterday, and STR was done before a bunch of settings patches landed to both 2.1 and 2.2. Requesting qa reverification on current build.

Comment 9

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Actually, half the STR works (tried again a couple of times after posting last comment). I don't get a black background, but call info does still disappear. Closing and reopening dialer app still shows no call info.

Comment 10

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Ok. The patches that I mentioned earlier added some error messages, I'm now seeing

W/GeckoConsole(  205): [JavaScript Error: "TypeError: this._settingsManager._window is null" {file: "jar:file:///system/b2g/omni.ja!/components/SettingsManager.js" line: 118}]
W/GeckoConsole(  205): [JavaScript Error: "NS_ERROR_UNEXPECTED: " {file: "app://callscreen.gaiamobile.org/shared/js/dialer/voicemail.js" line: 18}]

in the logs. I bet this is a settings race due to the new transaction system. Will take a look.

Comment 11

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

From build I just made with more debugging messages:

W/GeckoConsole(  206): [JavaScript Error: "SettingsManager window died, cannot run settings transaction." {file: "jar:file:///system/b2g/omni.ja!/components/SettingsManager.js" line: 116}]
W/GeckoConsole(  206): [JavaScript Error: "SettingsMessage: Settings:CreateLock" {file: "jar:file:///system/b2g/omni.ja!/components/SettingsManager.js" line: 117}]
W/GeckoConsole(  206): [JavaScript Error: "SettingsData: {"lockID":"{df433a21-d619-4db5-85da-bd902a793580}","isServiceLock":false}" {file: "jar:file:///system/b2g/omni.ja!/components/SettingsManager.js" line: 118}]
W/GeckoConsole(  206): [JavaScript Error: "NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIDOMRequestService.createRequest]" {file: "resource://gre/modules/DOMRequestHelper.jsm" line: 279}]
W/GeckoConsole(  206): [JavaScript Error: "NS_ERROR_UNEXPECTED: " {file: "app://callscreen.gaiamobile.org/shared/js/dialer/voicemail.js" line: 18}]


It looks like at some point, we're trying to check voicemail but failing because we no longer have an inner window. Trying to trace why that happens now.

Comment 12

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Talked to :thills on IRC, bug 1068109 should fix this, though it's still odd that settings wouldn't be able to reestablish a window after an app shut down like this. I'll take a look at that elsewhere.

Comment 13

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

I'm now seeing an IDB error whenever I try the repro steps. Even just once.

I/GeckoConsole(  205): Content JS LOG: Error handling bluetooth request 
I/GeckoConsole(  205):     at BluetoothHelper/_handleRequest/request.onerror (app://callscreen.gaiamobile.org/shared/js/bluetooth_helper.js:39:6)
W/GeckoConsole(  205): [JavaScript Error: "NS_ERROR_FAILURE: " {file: "chrome://global/content/BrowserElementChildPreload.js" line: 998}]
W/Usage   ( 3403): Content JS WARN: SimManager is not ready, waiting for initialized custom event 
W/Usage   ( 3403):     at _requestService (app://costcontrol.gaiamobile.org/js/sim_manager.js:86:0)
I/Gecko   ( 3428): ###################################### forms.js loaded
I/Gecko   ( 3428): ############################### browserElementPanning.js loaded
I/Gecko   ( 3428): ######################## BrowserElementChildPreload.js loaded
W/Usage   ( 3403): Content JS WARN: The setting ril.data.defaultServiceId does not exists, using default Slot (0) 
W/Usage   ( 3403):     at _onsuccesSlotId (app://costcontrol.gaiamobile.org/js/sim_manager.js:52:0)
W/Usage   ( 3403): [JavaScript Error: "IndexedDB UnknownErr: IDBDatabase.cpp:779"]

:bent, that last line is worrisome. It looks like IDB is dying in its AbortTransactions function. Any ideas?

Comment 14

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

I'd ignore it for now... Warnings in the new IDB backend are a little too vocal. I will scale them back soon.

Comment 15

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

I agree with :bent, still working on instrumenting this, but something weird is happening in callscreen (which runs as part of the parent process, which is where I'm seeing the error happen, so it's definitely callscreen, NOT dialer) trying to run Voicemail.check during the beginning of a call. Working on reproing it and getting a decent logcat now.

Comment 16

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Attachment: Logcat of Voicemail Failure

Here's a logcat of the voicemail failure, though it's kinda spammy because I had SettingsRequestManager debugging on to see if it was settings, plus some debug messages in to show where voicemail was being checked, and when that check returned.

So, as you can see, the voicemail failure happens in the process with pid 205. That's the system process, where the callscreen app is launched. We also request voicemail for one of the callscreen runs at the beginning of the log I pasted, but it never gets the return it expects.

Since voicemail is only checked in the updateCallNumber function of callscreen's handled_call.js, it seems like there's something that's taking a REALLY long time to get to that function. During execution of the STR, it seems like each successive loop of dial/hangup is a little slower than the last. So I'm guessing something is building up here, maybe a leak or something, but I'm not quite sure what.

Comment 17

[Anthony Ricaud (:rik)]

We check if a call is to a voicemail when we receive a call (in the callscreen app, so system process) and when a call has ended (in the dialer app, own process) to store this information in the call log.

The check first checks navigator.mozVoicemail (aka SIM card info) and then does a mozSettings query.

What I'm seeing in this log is that the query from 1440 (Dialer PID) fails in the 205 process.

Comment 18

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

On a flame with a debug build, I'm doing some dumb memory watching (basically running b2g-ps between every call/hangup loop) and it looks like memory is going up 300-500k per call in the SYSTEM process (meaning something's up with callscreen), and isn't being released when killing the dialer. Someone with more knowledge on how to profile memory in gaia apps might want to try the STR in Comment 0 and see if they can get more info?

Comment 19

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Ran get_about_memory real quick, looks like we're keeping a ton of cached callscreen objects around in the system process, hence the memory growth.

├──19.95 MB (24.87%) -- window-objects
│  ├──19.42 MB (24.20%) -- top(app://system.gaiamobile.org/index.html, id=3)
│  │  ├──12.28 MB (15.31%) -- cached
│  │  │  ├───0.89 MB (01.11%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268242884)
│  │  │  ├───0.89 MB (01.11%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268286937)
│  │  │  ├───0.89 MB (01.11%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268290378)
│  │  │  ├───0.89 MB (01.11%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268301149)
│  │  │  ├───0.89 MB (01.11%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412269759847)
│  │  │  ├───0.89 MB (01.11%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268257010)
│  │  │  ├───0.89 MB (01.11%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268231577)
│  │  │  ├───0.88 MB (01.10%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268235263)
│  │  │  ├───0.87 MB (01.09%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268246112)
│  │  │  ├───0.87 MB (01.09%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412269763650)
│  │  │  ├───0.87 MB (01.09%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268293766)
│  │  │  ├───0.85 MB (01.05%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268260071)
│  │  │  ├───0.85 MB (01.05%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412269770146)
│  │  │  └───0.84 MB (01.05%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268252785)


Dunno if that's bad or not?

Comment 20

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

Um. Ok. Closed dialer. No apps open.

├──20.13 MB (24.78%) -- window-objects
│  ├──19.60 MB (24.12%) -- top(app://system.gaiamobile.org/index.html, id=3)
│  │  ├──12.26 MB (15.09%) -- cached
│  │  │  ├───0.89 MB (01.10%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268257010)
│  │  │  ├───0.89 MB (01.10%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268242884)
│  │  │  ├───0.89 MB (01.10%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268286937)
│  │  │  ├───0.89 MB (01.10%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268290378)
│  │  │  ├───0.89 MB (01.10%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268301149)
│  │  │  ├───0.89 MB (01.10%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412269759847)
│  │  │  ├───0.89 MB (01.10%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268231577)
│  │  │  ├───0.88 MB (01.08%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268235263)
│  │  │  ├───0.87 MB (01.07%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268246112)
│  │  │  ├───0.87 MB (01.07%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412269763650)
│  │  │  ├───0.87 MB (01.07%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268293766)
│  │  │  ├───0.84 MB (01.04%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268260071)
│  │  │  ├───0.84 MB (01.04%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412269770146)
│  │  │  └───0.84 MB (01.03%) ++ window(app://callscreen.gaiamobile.org/index.html#&timestamp=1412268252785)
│  │  ├───5.59 MB (06.89%) -- active
│  │  │   ├──4.85 MB (05.97%) -- window(app://system.gaiamobile.org/index.html)
│  │  │   │  ├──2.33 MB (02.87%) -- js-compartment(app://system.gaiamobile.org/index.html)
│  │  │   │  │  ├──1.53 MB (01.89%) ++ classes
│  │  │   │  │  └──0.80 MB (00.98%) ++ (5 tiny)
│  │  │   │  ├──1.18 MB (01.45%) ++ layout
│  │  │   │  ├──0.85 MB (01.05%) ── style-sheets
│  │  │   │  └──0.49 MB (00.60%) ++ (2 tiny)
│  │  │   └──0.74 MB (00.91%) ++ window(app://callscreen.gaiamobile.org/index.html)
│  │  └───1.74 MB (02.15%) -- js-zone(0xaf24fc00)
│  │      ├──0.92 MB (01.13%) ++ (5 tiny)
│  │      └──0.82 MB (01.01%) ── unused-gc-things

Why is there still an active callscreen window in the system process? It was my understanding callscreen only existed when up, wasn't actually ever backgrounded?

Comment 21

[Kyle Machulis [:qdot] [:kmachulis] (INACTIVE)]

ni'ing khuey for memory log translation

Comment 22

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

The cached bit means that Gecko thinks the window is in the bfcache.  Do we remove the callscreen iframe entirely?  or do we navigate it to about:blank or something?

Comment 23

[Doug Sherk (:drs) (inactive)]

We call window.close() from within the callscreen app.

Comment 24

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

And what does the system app do with that?

Comment 25

[Doug Sherk (:drs) (inactive)]

It looks like we just reload it:
https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/callscreen_window.js#L126

Comment 26

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

It wouldn't shock me if the mozbrowser code doesn't handle that correctly.

Comment 27

[:gerard-majax]

Kyle, I can confirm the leaking of callscreen. It happens as soon as I place several calls.

STR:
 0. python tools/get_about_memory.py
 1. Place multiple calls
 2. python tools/get_about_memory.py

Expected:
 Same amount of callscreen in window-objects section for 0 and 2.

Actual:
 Memory report in 2 has much more callscreen window-objects than the one in 0.

Comment 28

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

(In reply to Alexandre LISSY :gerard-majax from comment #27)
> Kyle, I can confirm the leaking of callscreen. It happens as soon as I place
> several calls.
> 
> STR:
>  0. python tools/get_about_memory.py
>  1. Place multiple calls
>  2. python tools/get_about_memory.py
> 
> Expected:
>  Same amount of callscreen in window-objects section for 0 and 2.
> 
> Actual:
>  Memory report in 2 has much more callscreen window-objects than the one in
> 0.

Yep, me too.

Olli, are we expecting to bfcache mozbrowser frames on b2g?  This is quite surprising to me.

Comment 29

[Olli Pettay [:smaug][[e-mail]]]

is it oop mozbrowser? Then I'd expect bfcache, or at least I don't recall anything which would have
disabled bfcache in TabChild.

Comment 30

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

In-process.

Comment 31

[Olli Pettay [:smaug][[e-mail]]]

Is it top level iframe/xul:browser (under the very top level xul/chrome thing - I assume we still have that)? Such docshell would have a bfcache too, as expect. IIRC b2g limits cache to 1 entry though.

Comment 32

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

I believe it's a subframe of the system app, so no.  And it certainly appears that there's more than one entry.

Comment 33

[Anthony Ricaud (:rik)]

QA: Can we test this bug with the patch from bug 1068109 applied? To see if it fixes the issue.

Comment 34

[Anthony Ricaud (:rik)]

I seem to recall we had a BF cache issue earlier and we solved it by adding an empty unload handler. I think this was creating issues with System messages. I can't find this empty unload handler anymore in the code. I'll look into our git history to see if we were able to remove it.

Comment 35

[Anthony Ricaud (:rik)]

The BF cache issue was bug 1030550 and we only landed this in 2.0. For 2.1 and later, we fixed the platform directly in bug 1035074.

Comment 36

[Anthony Ricaud (:rik)]

Correction of comment 33: Sorry, I meant testing with the patch from bug 1076597.

Comment 37

[Johan Lorenzo [:jlorenzo]]

I am not able to reproduce this bug anymore by following the STR in comment 0 when I apply attachment 8498652 [details] [diff] [review]. Let's mark bug 1076597 as a dependency and clear the QA work here.

We should verify the fix once bug 1076597 is landed.

Comment 38

[Doug Sherk (:drs) (inactive)]

The original issue is now effectively fixed by bug 1068109, which just landed. Verifying that bug 1076597 fixes this is too complicated as it will require a backout of bug 1068109 first. On top of that, another related bug, bug 1074379 requires bug 1076597 and is not fixed by bug 1068109, so we'll get practical verification that bug 1076597 is effective there.

Comment 39

[Anthony Ricaud (:rik)]

We can verify without a backout, just by changing callEndPromptTime to 0 at https://github.com/mozilla-b2g/gaia/blob/83de447d9ae9a59459d7a445f9348a254c661850/apps/callscreen/js/call_screen.js#L11