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)

Tracking

(firefox62 fixed)

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. 4 years ago Jan Henning [:JanH] 59 bytes, text/x-review-board-request	JanH : review+	Details
Bug 1458697 - Use different strategy for dealing with initial session store activity. 4 years ago Jan Henning [:JanH] 59 bytes, text/x-review-board-request	gbrown : review+	Details
Bug 1458697 - Disable Android session store logging in automation again. 4 years ago Jan Henning [:JanH] 59 bytes, text/x-review-board-request	JanH : review+	Details

Treeherder Bug Filer

Reporter

Description

•

4 years ago

treeherder

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)

3 failures in 551 pushes (0.005 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 2
* mozilla-inbound: 1

Platform breakdown:
* android-4-3-armv7-api16: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458697&startday=2018-04-30&endday=2018-05-06&tree=trunk

Geoff Brown [:gbrown]

Updated

•

4 years ago

Updated

•

4 years ago

Duplicate of this bug: 1459679

Jan Henning [:JanH]

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)

Review commit: https://reviewboard.mozilla.org/r/243866/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/243866/

Jan Henning [:JanH]

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+

Pulsebot

Comment 6

•

4 years ago

Pushed by mozilla@buttercookie.de:
https://hg.mozilla.org/integration/autoland/rev/16c615f7a303
Temporarily enable Android session store debug logging in automation. r=JanH

Jan Henning [:JanH]

Assignee

Updated

•

4 years ago

Keywords: leave-open

OS: Unspecified → Android

Hardware: Unspecified → All

Dorel Luca [:dluca]

Comment 7

•

4 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/16c615f7a303

Comment hidden (Intermittent Failures Robot)

3 failures in 639 pushes (0.005 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 2
* autoland: 1

Platform breakdown:
* android-4-3-armv7-api16: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458697&startday=2018-05-14&endday=2018-05-20&tree=trunk

Comment hidden (Intermittent Failures Robot)

1 failures in 632 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* android-4-3-armv7-api16: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458697&startday=2018-05-21&endday=2018-05-27&tree=trunk

Comment hidden (Intermittent Failures Robot)

5 failures in 655 pushes (0.008 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 4
* autoland: 1

Platform breakdown:
* android-4-3-armv7-api16: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458697&startday=2018-05-28&endday=2018-06-03&tree=trunk

Jan Henning [:JanH]

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?

Jan Henning [:JanH]

Assignee

Updated

•

4 years ago

Duplicate of this bug: 1443069

Jan Henning [:JanH]

Assignee

Updated

•

4 years ago

Duplicate of this bug: 1467021

Jan Henning [:JanH]

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)

Waiting for delayed startup and then attempting to force any possibly still
pending session store write to disk by flushing the session store data didn't
turn out to be a good idea, because if the session store had already started its
own automatic write at that moment in time, we'd get back an additional
"PrivateBrowsing:Data" event that we didn't expect, thereby confusing the test.

Instead, we now wait for the first session store write after startup to occur
naturally before proceeding with the test.

Review commit: https://reviewboard.mozilla.org/r/250032/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/250032/

Jan Henning [:JanH]

Assignee

Updated

•

4 years ago

Duplicate of this bug: 1467637

Geoff Brown [:gbrown]

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+

Jan Henning [:JanH]

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.

Pulsebot

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

Bogdan Tara[:bogdan_tara | bogdant]

Comment 20

•

4 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/6aae8979eb2c

Comment hidden (Intermittent Failures Robot)

7 failures in 669 pushes (0.01 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 5
* mozilla-central: 1
* autoland: 1

Platform breakdown:
* android-4-3-armv7-api16: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458697&startday=2018-06-04&endday=2018-06-10&tree=trunk

Comment hidden (mozreview-request)

Review commit: https://reviewboard.mozilla.org/r/255590/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/255590/

Jan Henning [:JanH]

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+

Pulsebot

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

Arthur Iakab [arthur_iakab]

Comment 25

•

4 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/8a33f3ed0b33

Jan Henning [:JanH]

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)

1 failures in 1862 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* android-em-4-3-armv7-api16-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458697&startday=2018-12-03&endday=2018-12-09&tree=all

BMO Automation

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.