Intermittent testAudioFocus | Exception caught - java.lang.NullPointerException

RESOLVED FIXED in Firefox 65

Status

()

defect
P1
normal
RESOLVED FIXED
8 months ago
6 months ago

People

(Reporter: intermittent-bug-filer, Assigned: petru)

Tracking

({crash, intermittent-failure})

unspecified
Firefox 66
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox64 wontfix, firefox65 fixed, firefox66 fixed)

Details

(Whiteboard: [stockwell fixed])

Attachments

(2 attachments)

Filed by: csabou [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=213499468&repo=autoland

https://queue.taskcluster.net/v1/task/JERF7bGjTb6uClWORoAk1g/runs/0/artifacts/public/logs/live_backing.log

[task 2018-11-23T04:04:43.209Z] 04:04:43     INFO -  TEST-PASS | testAudioFocus | Check audio focus state - Should own audio focus.
[task 2018-11-23T04:04:43.210Z] 04:04:43     INFO -  - simulate losing audio focus transiently -
[task 2018-11-23T04:04:43.210Z] 04:04:43     INFO -  Buffered messages logged at 04:04:34
[task 2018-11-23T04:04:43.211Z] 04:04:43     INFO -  0 ERROR Exception caught during test! - java.lang.NullPointerException
[task 2018-11-23T04:04:43.211Z] 04:04:43     INFO -  	at org.mozilla.gecko.media.AudioFocusAgent.changeAudioFocus(AudioFocusAgent.java:230)
[task 2018-11-23T04:04:43.212Z] 04:04:43     INFO -  	at org.mozilla.gecko.tests.testAudioFocus.testBasicAbility(testAudioFocus.java:51)
[task 2018-11-23T04:04:43.212Z] 04:04:43     INFO -  	at org.mozilla.gecko.tests.testAudioFocus.testAudioFocus(testAudioFocus.java:20)
[task 2018-11-23T04:04:43.213Z] 04:04:43     INFO -  	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-11-23T04:04:43.213Z] 04:04:43     INFO -  	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-11-23T04:04:43.214Z] 04:04:43     INFO -  	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:214)
[task 2018-11-23T04:04:43.214Z] 04:04:43     INFO -  	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:199)
[task 2018-11-23T04:04:43.215Z] 04:04:43     INFO -  	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:192)
[task 2018-11-23T04:04:43.216Z] 04:04:43     INFO -  	at org.mozilla.gecko.tests.BaseRobocopTest.runTest(BaseRobocopTest.java:188)
[task 2018-11-23T04:04:43.216Z] 04:04:43     INFO -  	at junit.framework.TestCase.runBare(TestCase.java:134)
[task 2018-11-23T04:04:43.217Z] 04:04:43     INFO -  	at junit.framework.TestResult$1.protect(TestResult.java:115)
[task 2018-11-23T04:04:43.217Z] 04:04:43     INFO -  	at junit.framework.TestResult.runProtected(TestResult.java:133)
[task 2018-11-23T04:04:43.218Z] 04:04:43     INFO -  	at junit.framework.TestResult.run(TestResult.java:118)
[task 2018-11-23T04:04:43.218Z] 04:04:43     INFO -  	at junit.framework.TestCase.run(TestCase.java:124)
[task 2018-11-23T04:04:43.219Z] 04:04:43     INFO -  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:191)
[task 2018-11-23T04:04:43.219Z] 04:04:43     INFO -  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:176)
[task 2018-11-23T04:04:43.220Z] 04:04:43     INFO -  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:554)
[task 2018-11-23T04:04:43.220Z] 04:04:43     INFO -  	at org.mozilla.gecko.FennecInstrumentationTestRunner.onStart(FennecInstrumentationTestRunner.java:66)
[task 2018-11-23T04:04:43.220Z] 04:04:43     INFO -  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1701)
[task 2018-11-23T04:04:43.222Z] 04:04:43     INFO -  Buffered messages finished
[task 2018-11-23T04:04:43.222Z] 04:04:43  WARNING -  TEST-UNEXPECTED-FAIL | testAudioFocus | Exception caught - java.lang.NullPointerException
[task 2018-11-23T04:04:43.223Z] 04:04:43     INFO -  TEST-OK | testAudioFocus | took 33071ms
[task 2018-11-23T04:04:43.224Z] 04:04:43     INFO -  TEST-START | Shutdown
[task 2018-11-23T04:04:43.224Z] 04:04:43     INFO -  Passed: 4
[task 2018-11-23T04:04:43.225Z] 04:04:43     INFO -  Failed: 1
[task 2018-11-23T04:04:43.225Z] 04:04:43     INFO -  Todo: 0
[task 2018-11-23T04:04:43.226Z] 04:04:43     INFO -  SimpleTest FINISHED
[task 2018-11-23T04:07:42.106Z] 04:07:42     INFO -  wait for org.mozilla.fennec_aurora complete; top activity=com.android.launcher
[task 2018-11-23T04:07:42.311Z] 04:07:42     INFO -  INFO | automation.py | Application ran for: 0:03:43.398838
[task 2018-11-23T04:07:42.311Z] 04:07:42     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmphusPa1pidlog
[task 2018-11-23T04:07:42.828Z] 04:07:42     INFO -  /data/tombstones does not exist; tombstone check skipped
[task 2018-11-23T04:07:44.164Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): StrictMode policy violation; ~duration=187 ms: android.os.StrictMode$StrictModeDiskReadViolation: policy=543 violation=2
[task 2018-11-23T04:07:44.164Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.os.StrictMode$AndroidBlockGuardPolicy.onReadFromDisk(StrictMode.java:1123)
[task 2018-11-23T04:07:44.165Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.SharedPreferencesImpl.awaitLoadedLocked(SharedPreferencesImpl.java:203)
[task 2018-11-23T04:07:44.165Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.SharedPreferencesImpl.contains(SharedPreferencesImpl.java:268)
[task 2018-11-23T04:07:44.166Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at org.mozilla.gecko.switchboard.Preferences.getOverrideValue(Preferences.java:70)
[task 2018-11-23T04:07:44.166Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at org.mozilla.gecko.switchboard.SwitchBoard.isInExperiment(SwitchBoard.java:154)
[task 2018-11-23T04:07:44.167Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at org.mozilla.gecko.mma.MmaDelegate.isMmaExperimentEnabled(MmaDelegate.java:246)
[task 2018-11-23T04:07:44.168Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at org.mozilla.gecko.preferences.GeckoPreferences.isMmaAvailableAndEnabled(GeckoPreferences.java:1513)
[task 2018-11-23T04:07:44.169Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at org.mozilla.gecko.mma.MmaDelegate.isMmaAllowed(MmaDelegate.java:258)
[task 2018-11-23T04:07:44.169Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at org.mozilla.gecko.mma.MmaDelegate.notifyDefaultBrowserStatus(MmaDelegate.java:150)
[task 2018-11-23T04:07:44.169Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at org.mozilla.gecko.BrowserApp.onStart(BrowserApp.java:1150)
[task 2018-11-23T04:07:44.169Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.Instrumentation.callActivityOnStart(Instrumentation.java:1171)
[task 2018-11-23T04:07:44.170Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.Activity.performStart(Activity.java:5143)
[task 2018-11-23T04:07:44.170Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2184)
[task 2018-11-23T04:07:44.171Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2261)
[task 2018-11-23T04:07:44.171Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.ActivityThread.access$600(ActivityThread.java:141)
[task 2018-11-23T04:07:44.171Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1256)
[task 2018-11-23T04:07:44.172Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.os.Handler.dispatchMessage(Handler.java:99)
[task 2018-11-23T04:07:44.172Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.os.Looper.loop(Looper.java:137)
[task 2018-11-23T04:07:44.173Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at android.app.ActivityThread.main(ActivityThread.java:5103)
[task 2018-11-23T04:07:44.173Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at java.lang.reflect.Method.invokeNative(Native Method)
[task 2018-11-23T04:07:44.174Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at java.lang.reflect.Method.invoke(Method.java:525)
[task 2018-11-23T04:07:44.174Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
[task 2018-11-23T04:07:44.174Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
[task 2018-11-23T04:07:44.174Z] 04:07:44     INFO -  11-22 20:04:05.220 D/StrictMode( 2149): 	at dalvik.system.NativeStart.main(Native Method)
[task 2018-11-23T04:07:44.175Z] 04:07:44     INFO -  11-22 20:04:05.250 I/dalvikvm( 2149): Could not find method android.content.Context.startForegroundService, referenced from method org.mozilla.mozstumbler.service.mainthread.LocalPreferenceReceiver.onReceive
[task 2018-11-23T04:07:44.175Z] 04:07:44     INFO -  11-22 20:04:05.250 W/dalvikvm( 2149): VFY: unable to resolve virtual method 864: Landroid/content/Context;.startForegroundService (Landroid/content/Intent;)Landroid/content/ComponentName;
[task 2018-11-23T04:07:44.175Z] 04:07:44     INFO -  11-22 20:04:05.250 D/StumblerSafeReceiver( 2149): Registered local preference listener
[task 2018-11-23T04:07:44.176Z] 04:07:44     INFO -  11-22 20:04:05.270 I/Choreographer( 2149): Skipped 70 frames!  The application may be doing too much work on its main thread.
[task 2018-11-23T04:07:44.176Z] 04:07:44     INFO -  11-22 20:04:05.410 I/dalvikvm( 2149): Could not find method android.view.Window.setStatusBarColor, referenced from method org.mozilla.gecko.util.WindowUtil.setStatusBarColor
[task 2018-11-23T04:07:44.177Z] 04:07:44     INFO -  11-22 20:04:05.410 W/dalvikvm( 2149): VFY: unable to resolve virtual method 20149: Landroid/view/Window;.setStatusBarColor (I)V
[task 2018-11-23T04:07:44.177Z] 04:07:44     INFO -  11-22 20:04:05.869 D/libEGL  ( 2149): loaded /system/lib/egl/libEGL_emulation.so
[task 2018-11-23T04:07:44.177Z] 04:07:44     INFO -  11-22 20:04:05.889 D/        ( 2149): HostConnection::get() New Host Connection established 0x2a202560, tid 2149
[task 2018-11-23T04:07:44.178Z] 04:07:44     INFO -  11-22 20:04:05.909 D/libEGL  ( 2149): loaded /system/lib/egl/libGLESv1_CM_emulation.so
[task 2018-11-23T04:07:44.178Z] 04:07:44     INFO -  11-22 20:04:05.939 D/libEGL  ( 2149): loaded /system/lib/egl/libGLESv2_emulation.so
No, bug 1505972 only modified internal decoding state which won't affect the high level test like this.

From the log [1], it seems Java part got a null ptr.

[1] https://treeherder.mozilla.org/logviewer.html#?job_id=213499468&repo=autoland&lineNumber=1480
Flags: needinfo?(alwu)
Picking up where Cosmin left off, I arrived at:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&searchStr=robocop&tochange=be4f0249121820f15551de0d21e6e3626526f997&fromchange=ab0dfc5b827dcc0a2eef87d8e9ccbf383a397f72

There were 4 testAudioFocus failures in approx 50 runs of rc1 on be4f0249121820f15551de0d21e6e3626526f997; there were no testAudioFocus failures in approx 50 runs of rc1 on the previous revision, suggesting this failure started with bug 1505685 (which appears related to android media).

:petru - Can you investigate?
Blocks: 1505685
Flags: needinfo?(petru.lingurar)
Assignee: nobody → petru.lingurar
Status: NEW → ASSIGNED
There is a small race between actually starting the test after Gecko:Ready and
having the AudioFocusAgent that the tests depend on initialized, which is also
done after Gecko:Ready.

To avoid this situation we will wait for Gecko:Ready and then for
AudioFocusAgent to complete it's initialization.
Inside the tests from testMediaControl audio focus is not immediately checked
as for the tests from testAudioFocus but nonetheless we should make sure
AudioFocusAgent is initialized before proceeding with the media tests.

Depends on D14417
To actually start the test we wait until Gecko is ready [1], event [2] that precedes [3] initializing AudioFocusAgent [4] and the instance of AudioManager[5] so it may be possible that when we requestAudioFocus() [6] the instance of AudioManager is not yet initialized and so we get that dreaded NullPointerException [7].

To fix this we will wait not only for Gecko to be ready but also for the AudioFocusAgent to finish it's initialization.
This is needed just for this media tests as IRL initializing the AudioManager is so close to Gecko being ready that until actually needing it, there will be other operations that will provide a more than enough timespan for the initialization to complete.


[1] https://searchfox.org/mozilla-central/rev/3160ddc1f0ab55d230c595366662c62950e5c785/mobile/android/tests/browser/robocop/src/org/mozilla/gecko/tests/testAudioFocus.java#17
[2] https://searchfox.org/mozilla-central/rev/3160ddc1f0ab55d230c595366662c62950e5c785/mobile/android/tests/browser/robocop/src/org/mozilla/gecko/tests/OldBaseTest.java#87
[3] https://searchfox.org/mozilla-central/rev/3160ddc1f0ab55d230c595366662c62950e5c785/mobile/android/base/java/org/mozilla/gecko/GeckoApp.java#679
[4] https://searchfox.org/mozilla-central/rev/3160ddc1f0ab55d230c595366662c62950e5c785/mobile/android/base/java/org/mozilla/gecko/GeckoApplication.java#448
[5] https://searchfox.org/mozilla-central/rev/3160ddc1f0ab55d230c595366662c62950e5c785/mobile/android/base/java/org/mozilla/gecko/media/AudioFocusAgent.java#71
[6] https://searchfox.org/mozilla-central/rev/3160ddc1f0ab55d230c595366662c62950e5c785/mobile/android/tests/browser/robocop/src/org/mozilla/gecko/tests/testAudioFocus.java#45
[7] https://searchfox.org/mozilla-central/rev/3160ddc1f0ab55d230c595366662c62950e5c785/mobile/android/base/java/org/mozilla/gecko/media/AudioFocusAgent.java#138
Flags: needinfo?(petru.lingurar)
A try build with the above patches applied to rerun the failing test a few times - https://treeherder.mozilla.org/#/jobs?repo=try&revision=3b49dfe20e385c7ab490c0665cd3f9a5033338ee
Keywords: checkin-needed
Pushed by ebalazs@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/f525a4f572f6
Part 1 - Wait for AudioFocusAgent to be initialized before starting testAudioFocus;r=JanH
https://hg.mozilla.org/integration/autoland/rev/4b128c704ca6
Part 2 - Wait for AudioFocusAgent to be initialized before starting testMediaControl;r=JanH
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/f525a4f572f6
https://hg.mozilla.org/mozilla-central/rev/4b128c704ca6
Status: ASSIGNED → RESOLVED
Closed: 7 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 66
Is manual QE needed to verify the issue here?
(In reply to Levente Sacal from comment #18)
> Is manual QE needed to verify the issue here?

Thanks Levente but I don't think manual testing could catch this.
For the issue to happen in the first place time is of the essence (time needed for some code initialization to happen) so it can only reasonably occur in automated tests, while IRL there would be enough time (because of accessing and loading a webpage before starting media playing) for this not to happen.
Priority: -- → P1
You need to log in before you can comment on or make changes to this bug.