Closed
Bug 1509434
Opened 6 years ago
Closed 5 years ago
Intermittent testAudioFocus | Exception caught - java.lang.NullPointerException
Categories
(Firefox for Android Graveyard :: Testing, defect, P1)
Firefox for Android Graveyard
Testing
Tracking
(firefox64 wontfix, firefox65 fixed, firefox66 fixed)
RESOLVED
FIXED
Firefox 66
People
(Reporter: intermittent-bug-filer, Assigned: petru)
References
Details
(Keywords: crash, intermittent-failure, Whiteboard: [stockwell fixed])
Attachments
(2 files)
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
Comment 1•6 years ago
|
||
Retries were inconclusive: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=robocop&tochange=a773a42f4c001614c4ae826bc8ada7de29cea3e6&fromchange=ac1c8b26e69085a1ce075939533eb081b9e997ce&selectedJob=213503250 but bug 1505972 is the earliest testAudioFocus failure that I can find. Related?
Flags: needinfo?(alwu)
Comment hidden (Intermittent Failures Robot) |
Comment 3•6 years ago
|
||
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)
Comment hidden (Intermittent Failures Robot) |
Comment 5•6 years ago
|
||
This has 29 failures in the last 7 days, all on android-em-4-3-armv7-api16 opt. Went with the retriggers up until here: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Csuccess%2Crunning%2Cpending%2Crunnable&searchStr=android%2C4.3%2Capi16%2B%2Copt%2Cmochitests%2Ctest-android-em-4.3-arm7-api-16%2Fopt-robocop-1%2Cm%28rc1%29&fromchange=023c546c01cd2d3c4d382ab5e9245a48f138e934&group_state=expanded&tochange=6893246437a24a624ba3876c518ec82ba09e995d&selectedJob=215876161 Taking a bit of a wild guess here but maybe https://hg.mozilla.org/integration/autoland/rev/f3f2be0cb3a6 has something to do with this. Retriggered - http://tinyurl.com/ybvkatca Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=215845849&repo=autoland&lineNumber=1497
Comment hidden (Intermittent Failures Robot) |
Comment 7•5 years ago
|
||
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 | ||
Updated•5 years ago
|
Assignee: nobody → petru.lingurar
Status: NEW → ASSIGNED
Assignee | ||
Comment 8•5 years ago
|
||
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.
Assignee | ||
Comment 9•5 years ago
|
||
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
Assignee | ||
Comment 10•5 years ago
|
||
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)
Comment hidden (typo) |
Assignee | ||
Comment 12•5 years ago
|
||
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
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Updated•5 years ago
|
Keywords: checkin-needed
Comment 14•5 years ago
|
||
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
Comment 15•5 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/f525a4f572f6 https://hg.mozilla.org/mozilla-central/rev/4b128c704ca6
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox66:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 66
Updated•5 years ago
|
Comment 16•5 years ago
|
||
bugherder uplift |
https://hg.mozilla.org/releases/mozilla-beta/rev/4d21abcabd2a https://hg.mozilla.org/releases/mozilla-beta/rev/73c6129bfe79
Flags: in-testsuite+
Whiteboard: [stockwell needswork:owner] → [stockwell fixed]
Comment hidden (Intermittent Failures Robot) |
Comment 18•5 years ago
|
||
Is manual QE needed to verify the issue here?
Assignee | ||
Comment 19•5 years ago
|
||
(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.
Updated•5 years ago
|
Priority: -- → P1
Updated•3 years ago
|
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in
before you can comment on or make changes to this bug.
Description
•