Closed
Bug 1458697
Opened 4 years ago
Closed 4 years ago
Intermittent testSessionPrivateBrowsing | java-exception junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testSessionPrivateBrowsing | got expected no change event - null at junit.framework.Assert.fail(Assert.java:50)
Categories
(Firefox for Android Graveyard :: Awesomescreen, defect, P5)
Tracking
(firefox62 fixed)
RESOLVED
FIXED
Firefox 62
Tracking | Status | |
---|---|---|
firefox62 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: JanH)
References
Details
(Keywords: intermittent-failure)
Attachments
(3 files)
Filed by: apavel [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=176621836&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/L_3dfmyoQ52qfkR_EER2Nw/runs/0/artifacts/public/logs/live_backing.log [task 2018-05-02T20:06:19.033Z] 20:06:19 INFO - TEST-START | testSessionPrivateBrowsing [task 2018-05-02T20:06:50.900Z] 20:06:50 INFO - GECKO | EventExpecter: no longer listening for Gecko:DelayedStartup [task 2018-05-02T20:06:50.900Z] 20:06:50 INFO - Buffered messages logged at 20:06:28 [task 2018-05-02T20:06:50.901Z] 20:06:50 INFO - TEST-PASS | testSessionPrivateBrowsing | Robocop tests need the test device screen to be powered on. - [task 2018-05-02T20:06:50.901Z] 20:06:50 INFO - Buffered messages logged at 20:06:48 [task 2018-05-02T20:06:50.902Z] 20:06:50 INFO - TEST-PASS | testSessionPrivateBrowsing | Given message occurred for registered event: {type=null} - Gecko:DelayedStartup should equal Gecko:DelayedStartup [task 2018-05-02T20:06:50.902Z] 20:06:50 INFO - Buffered messages logged at 20:06:49 [task 2018-05-02T20:06:50.904Z] 20:06:50 INFO - TEST-PASS | testSessionPrivateBrowsing | received PrivateBrowsing:Data event - PrivateBrowsing:Data should equal PrivateBrowsing:Data [task 2018-05-02T20:06:50.904Z] 20:06:50 INFO - TEST-PASS | testSessionPrivateBrowsing | received PrivateBrowsing:Data event - PrivateBrowsing:Data should equal PrivateBrowsing:Data [task 2018-05-02T20:06:50.904Z] 20:06:50 INFO - Buffered messages finished [task 2018-05-02T20:06:50.904Z] 20:06:50 WARNING - TEST-UNEXPECTED-FAIL | testSessionPrivateBrowsing | got expected no change event - expected PASS [task 2018-05-02T20:07:11.949Z] 20:07:11 INFO - INFO | automation.py | Application ran for: 0:00:55.043708 [task 2018-05-02T20:07:11.950Z] 20:07:11 INFO - INFO | zombiecheck | Reading PID log: /tmp/tmplpFCbCpidlog [task 2018-05-02T20:07:12.573Z] 20:07:12 INFO - /data/tombstones does not exist; tombstone check skipped [task 2018-05-02T20:07:12.880Z] 20:07:12 WARNING - PROCESS-CRASH | testSessionPrivateBrowsing | java-exception junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testSessionPrivateBrowsing | got expected no change event - null at junit.framework.Assert.fail(Assert.java:50) [task 2018-05-02T20:07:12.881Z] 20:07:12 INFO - 0 ERROR runApp() exited with code 1 [task 2018-05-02T20:07:13.401Z] 20:07:13 WARNING - PROCESS-CRASH | Automation Error: Missing end of test marker (process crashed?) [task 2018-05-02T20:07:13.708Z] 20:07:13 INFO - 05-02 13:06:16.084 I/log ( 4681): logcat cleared [task 2018-05-02T20:07:13.709Z] 20:07:13 INFO - 05-02 13:06:16.594 D/AndroidRuntime( 4684): [task 2018-05-02T20:07:13.709Z] 20:07:13 INFO - 05-02 13:06:16.594 D/AndroidRuntime( 4684): >>>>>> AndroidRuntime START com.android.internal.os.RuntimeInit <<<<<< [task 2018-05-02T20:07:13.710Z] 20:07:13 INFO - 05-02 13:06:16.594 D/AndroidRuntime( 4684): CheckJNI is ON [task 2018-05-02T20:07:13.710Z] 20:07:13 INFO - 05-02 13:06:16.773 E/cutils-trace( 4684): Error opening trace file: No such file or directory (2) [task 2018-05-02T20:07:13.711Z] 20:07:13 INFO - 05-02 13:06:17.303 D/AndroidRuntime( 4684): Calling main entry com.android.commands.am.Am [task 2018-05-02T20:07:13.711Z] 20:07:13 INFO - 05-02 13:06:17.333 I/ActivityManager( 282): Force stopping package org.mozilla.fennec_aurora appid=10043 user=0 [task 2018-05-02T20:07:13.711Z] 20:07:13 INFO - 05-02 13:06:17.373 I/ActivityManager( 282): Start proc org.mozilla.fennec_aurora for added application org.mozilla.fennec_aurora: pid=4694 uid=10043 gids={50043, 3003, 1028, 1015, 1006} [task 2018-05-02T20:07:13.711Z] 20:07:13 INFO - 05-02 13:06:17.373 D/AndroidRuntime( 4684): Shutting down VM
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 3•4 years ago
|
||
I guess I should turn on session store logging on Try to get more details...
Assignee: nobody → jh+bugzilla
Comment hidden (mozreview-request) |
Assignee | ||
Comment 5•4 years ago
|
||
mozreview-review |
Comment on attachment 8975907 [details] Bug 1458697 - Temporarily enable Android session store debug logging in automation. https://reviewboard.mozilla.org/r/243866/#review250056 Simply change, affects test only.
Attachment #8975907 -
Flags: review?(jh+bugzilla) → review+
Pushed by mozilla@buttercookie.de: https://hg.mozilla.org/integration/autoland/rev/16c615f7a303 Temporarily enable Android session store debug logging in automation. r=JanH
Assignee | ||
Updated•4 years ago
|
Comment 7•4 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/16c615f7a303
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 11•4 years ago
|
||
> 06-03 13:05:01.333 4466 4466 D Robocop : handleMessage called for: Gecko:DelayedStartup; expecting: Gecko:DelayedStartup
> 06-03 13:05:01.393 4466 4466 I Robocop : {"message":"Gecko:DelayedStartup should equal Gecko:DelayedStartup","time":1528056301337,"source":"robocop","status":"PASS","test":"testSessionPrivateBrowsing","thread":null,"subtest":"Given message occurred for registered event: {type=null}","action":"test_status","pid":null}
> 06-03 13:05:01.403 4466 4466 D Robocop : received event Gecko:DelayedStartup
> 06-03 13:05:01.403 4466 4482 D Robocop : unblocked on expecter for Gecko:DelayedStartup
> 06-03 13:05:01.403 4466 4482 I Robocop : EventExpecter: no longer listening for Gecko:DelayedStartup
> 06-03 13:05:01.463 4466 4494 D GeckoSessionStore: timer-callback, pendingWrite = 0/8
> 06-03 13:05:01.463 4466 4494 D GeckoSessionStore: _saveState(aAsync = true)
> 06-03 13:05:01.473 4466 4494 D GeckoSessionStore: _saveState() current state collected
> 06-03 13:05:01.513 4466 4494 I Robocop : {"message":"PrivateBrowsing:Data should equal PrivateBrowsing:Data","time":1528056301492,"source":"robocop","status":"PASS","test":"testSessionPrivateBrowsing","thread":null,"subtest":"received PrivateBrowsing:Data event","action":"test_status","pid":null}
> 06-03 13:05:01.513 4466 4494 D GeckoSessionStore: _saveState() writing normal data, 1 tabs in window[0]
> 06-03 13:05:01.513 4466 4494 D GeckoSessionStore: _writeFile(aAsync = true), _pendingWrite = 8
> 06-03 13:05:01.523 4466 4494 D GeckoSessionStore: _write() writing asynchronously
> 06-03 13:05:01.553 4466 4494 D GeckoSessionStore: Session:FlushTabs
> 06-03 13:05:01.553 4466 4494 D GeckoSessionStore: flushPendingState(), _pendingWrite = 8
> 06-03 13:05:01.553 4466 4494 D GeckoSessionStore: _saveState(aAsync = false)
> 06-03 13:05:01.573 4466 4494 D GeckoSessionStore: _saveState() current state collected
> 06-03 13:05:01.623 4466 4494 I Robocop : {"message":"PrivateBrowsing:Data should equal PrivateBrowsing:Data","time":1528056301609,"source":"robocop","status":"PASS","test":"testSessionPrivateBrowsing","thread":null,"subtest":"received PrivateBrowsing:Data event","action":"test_status","pid":null}
> 06-03 13:05:01.633 4466 4494 I Robocop : {"time":1528056301632,"expected":"PASS","source":"robocop","status":"FAIL","test":"testSessionPrivateBrowsing","thread":null,"subtest":"got expected no change event","action":"test_status","pid":null}
> 06-03 13:05:01.653 4466 4494 W System.err: junit.framework.AssertionFailedError: TEST-UNEXPECTED-FAIL | testSessionPrivateBrowsing | got expected no change event - null
> 06-03 13:05:01.653 4466 4494 W System.err: at junit.framework.Assert.fail(Assert.java:50)
> 06-03 13:05:01.653 4466 4494 W System.err: at org.mozilla.gecko.FennecMochitestAssert._logMochitestResult(FennecMochitestAssert.java:124)
> 06-03 13:05:01.653 4466 4494 W System.err: at org.mozilla.gecko.FennecMochitestAssert.ok(FennecMochitestAssert.java:145)
> 06-03 13:05:01.663 4466 4494 W System.err: at org.mozilla.gecko.tests.testSessionPrivateBrowsing.handleMessage(testSessionPrivateBrowsing.java:80)
> 06-03 13:05:01.663 4466 4494 W System.err: at org.mozilla.gecko.EventDispatcher.dispatchToThreads(EventDispatcher.java:275)
> 06-03 13:05:01.663 4466 4494 W System.err: at org.mozilla.gecko.EventDispatcher.dispatchToThreads(EventDispatcher.java:255)
> 06-03 13:05:01.663 4466 4494 W System.err: at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)
> 06-03 13:05:01.663 4466 4494 W System.err: at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:498)
Okay, it seems that one possible failure source is that our attempt to flush the sessions store data to disk can happen at just the same time the session store was starting its own write after startup, like:
1. We wait for a PrivateBrowsing:Data message and send Session:FlushTabs.
2. We get back a PrivateBrowsing:Data message (triggered by the session store itself as it was trying to persist the tab data changes after startup) and advance to the next test stage.
3. We wait for a PrivateBrowsing:Data message and send Session:FlushTabs again.
4. We get a back PrivateBrowsing:Data message, but the one in response the Session:FlushTabs call in step 1 (!), which means its contents will not be what we expected, since we had already advanced to the next stage.
I wonder whether instead of waiting for (Delayed)Startup and then explicitly flushing the session store data to disk once it might be better to just wait until the first automatic session store write has completed before starting the rest of the test sequence?
Assignee | ||
Comment 14•4 years ago
|
||
I thinks this should make things better and at least it doesn't seem to have made them dramatically worse: https://treeherder.mozilla.org/#/jobs?repo=try&revision=d8f19a9b7be3dac424af611be2fdfcfeb713c0de
Comment hidden (mozreview-request) |
![]() |
||
Comment 17•4 years ago
|
||
mozreview-review |
Comment on attachment 8984356 [details] Bug 1458697 - Use different strategy for dealing with initial session store activity. https://reviewboard.mozilla.org/r/250032/#review256574 Looks great on try! Is there a chance of "missing" the Session:DataWritten -- if the test starts after the event is sent? Anything worth worrying about?? What's the plan for the debug logging added earlier?
Attachment #8984356 -
Flags: review?(gbrown) → review+
Assignee | ||
Comment 18•4 years ago
|
||
mozreview-review-reply |
Comment on attachment 8984356 [details] Bug 1458697 - Use different strategy for dealing with initial session store activity. https://reviewboard.mozilla.org/r/250032/#review256574 > Is there a chance of "missing" the Session:DataWritten -- if the test starts after the event is sent? Anything worth worrying about?? You're right, unfortunately that's not 100 % guaranteed, but in practice I think that Robocop startup being slower than Gecko startup (and after Gecko has initialised there's another 10 seconds before the first session store write) is pretty unlikely. > What's the plan for the debug logging added earlier? I'll leave the bug open for a little while and if everything looks fine I'll turn off the logging again and close this bug. But thanks for the reminder.
Comment 19•4 years ago
|
||
Pushed by mozilla@buttercookie.de: https://hg.mozilla.org/integration/autoland/rev/6aae8979eb2c Use different strategy for dealing with initial session store activity. r=gbrown
Comment 20•4 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/6aae8979eb2c
Comment hidden (Intermittent Failures Robot) |
Comment hidden (mozreview-request) |
Assignee | ||
Comment 23•4 years ago
|
||
mozreview-review |
Comment on attachment 8990524 [details] Bug 1458697 - Disable Android session store logging in automation again. https://reviewboard.mozilla.org/r/255590/#review262372
Attachment #8990524 -
Flags: review+
Comment 24•4 years ago
|
||
Pushed by mozilla@buttercookie.de: https://hg.mozilla.org/integration/autoland/rev/8a33f3ed0b33 Disable Android session store logging in automation again. r=JanH
Comment 25•4 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/8a33f3ed0b33
Assignee | ||
Comment 26•4 years ago
|
||
No new failures, so declaring this fixed.
Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox62:
--- → fixed
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → Firefox 62
Comment hidden (Intermittent Failures Robot) |
Updated•2 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
•