Closed Bug 1458697 Opened 2 years ago Closed 2 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 :: Awesomescreen, defect, P5)

Product:
Firefox for Android
Component:
Awesomescreen
Platform:
All
Android
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 62
Tracking Flags:
Tracking Status
firefox62 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(3 files)

Bug 1458697 - Temporarily enable Android session store debug logging in automation.
59 bytes, text/x-review-board-request
JanH
: review+
Details
Bug 1458697 - Use different strategy for dealing with initial session store activity.
59 bytes, text/x-review-board-request
gbrown
: review+
Details
Bug 1458697 - Disable Android session store logging in automation again.
59 bytes, text/x-review-board-request
JanH
: review+
Details 
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
See Also: → 1459679
Duplicate of this bug: 1459679
I guess I should turn on session store logging on Try to get more details...
Assignee: nobody → jh+bugzilla
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
Keywords: leave-open
OS: Unspecified → Android
Hardware: Unspecified → All
> 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?
Duplicate of this bug: 1443069
Duplicate of this bug: 1467021
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
Duplicate of this bug: 1467637
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+
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.
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 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+
Pushed by mozilla@buttercookie.de:
https://hg.mozilla.org/integration/autoland/rev/8a33f3ed0b33
Disable Android session store logging in automation again. r=JanH
No new failures, so declaring this fixed.
Status: NEW → RESOLVED
Closed: 2 years ago
status-firefox62: --- → fixed
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → Firefox 62
You need to log in before you can comment on or make changes to this bug.