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

RESOLVED DUPLICATE of bug 1068109

Status

RESOLVED DUPLICATE of bug 1068109
4 years ago
4 years ago

People

(Reporter: smiko, Assigned: thills)

Tracking

({regression})

unspecified
ARM
Gonk (Firefox OS)
regression
Dependency tree / graph

Firefox Tracking Flags

(blocking-b2g:2.1+, b2g-v2.0 unaffected, b2g-v2.1 affected, b2g-v2.2 affected)

Details

(Whiteboard: [2.1-flame-test-run-2], URL)

Attachments

(2 attachments)

(Reporter)

Description

4 years ago
Created attachment 8492297 [details]
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
(Reporter)

Comment 1

4 years ago
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
QA Whiteboard: [QAnalyst-Triage?]
status-b2g-v2.0: --- → unaffected
status-b2g-v2.1: --- → affected
status-b2g-v2.2: --- → affected
Flags: needinfo?(dharris)
Keywords: regression
Summary: [Dialer] The call screen does not display call info and shows a black background after repeatedly placing a calls → [Dialer] The call screen does not display call info and shows a black background after repeatedly placing calls
Whiteboard: [2.1-flame-test-run-2]
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.
Depends on: 927862, 1068109
Please note that the Environmental Variables from comment 0 are for Flame 2.1 (319mb) and not master.
[Blocking Requested - why for this release]:

Nominating this because it is a regression, and the UI can become unusable
blocking-b2g: --- → 2.1?
QA Whiteboard: [QAnalyst-Triage?]
Flags: needinfo?(dharris)
Keywords: regressionwindow-wanted
(Reporter)

Updated

4 years ago
QA Contact: smiko
triage: regression
blocking-b2g: 2.1? → 2.1+
Assignee: nobody → thills
(Reporter)

Comment 6

4 years ago
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
QA Whiteboard: [QAnalyst-Triage?]
Flags: needinfo?(jmitchell)
Keywords: regressionwindow-wanted
Kyle - the pushlog has only 2 patches, both yours - could you investigate? 

http://hg.mozilla.org/integration/b2g-inbound/pushloghtml?fromchange=6dc0a998af58&tochange=6b1690ad2cf5
QA Whiteboard: [QAnalyst-Triage?] → [QAnalyst-Triage+]
Flags: needinfo?(jmitchell) → needinfo?(kyle)
QA Contact: smiko
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.
Flags: needinfo?(kyle)
Keywords: qawanted
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.
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.
Keywords: qawanted
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.
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.
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?
Flags: needinfo?(bent.mozilla)
I'd ignore it for now... Warnings in the new IDB backend are a little too vocal. I will scale them back soon.
Flags: needinfo?(bent.mozilla)
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.
Created attachment 8498655 [details]
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.
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.
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?
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?
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?
ni'ing khuey for memory log translation
Flags: needinfo?(khuey)
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?
Flags: needinfo?(khuey)
We call window.close() from within the callscreen app.
And what does the system app do with that?
It wouldn't shock me if the mozbrowser code doesn't handle that correctly.
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.
Assignee: thills → drs+bugzilla
(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.
Flags: needinfo?(bugs)
is it oop mozbrowser? Then I'd expect bfcache, or at least I don't recall anything which would have
disabled bfcache in TabChild.
Flags: needinfo?(bugs)
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.
I believe it's a subframe of the system app, so no.  And it certainly appears that there's more than one entry.
QA: Can we test this bug with the patch from bug 1068109 applied? To see if it fixes the issue.
Keywords: qawanted
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.
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.
Correction of comment 33: Sorry, I meant testing with the patch from bug 1076597.
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.
Depends on: 1076597
Keywords: qawanted
See Also: → bug 1078448
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.
Status: NEW → RESOLVED
Last Resolved: 4 years ago
No longer depends on: 1076597
Resolution: --- → DUPLICATE
See Also: → bug 1076597
Duplicate of bug: 1068109
Assignee: drs+bugzilla → thills
You need to log in before you can comment on or make changes to this bug.