Closed Bug 1416039 Opened 2 years ago Closed 2 years ago

Intermittent browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js | lastAccessed of tab 1 is later than the test start time. -

Categories

(WebExtensions :: General, defect)

defect
Not set

Tracking

(firefox58 fixed, firefox59 fixed)

RESOLVED FIXED
mozilla59
Tracking Status
firefox58 --- fixed
firefox59 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:logic])

Attachments

(1 file)

Filed by: archaeopteryx [at] coole-files.de

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

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

15:34:08     INFO -  14 INFO TEST-START | browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js
15:34:09     INFO -  TEST-INFO | started process screenshot
15:34:09     INFO -  TEST-INFO | screenshot: exit 0
15:34:09     INFO -  Buffered messages logged at 15:34:08
15:34:09     INFO -  15 INFO Entering test bound testLastAccessed
15:34:09     INFO -  Buffered messages logged at 15:34:09
15:34:09     INFO -  16 INFO Extension loaded
15:34:09     INFO -  17 INFO TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js | Expected tabs were found -
15:34:09     INFO -  Buffered messages finished
15:34:09    ERROR -  18 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js | lastAccessed of tab 1 is later than the test start time. -
15:34:09     INFO -  Stack trace:
15:34:09     INFO -      background/<@moz-extension://7e584f17-aadd-436b-a56e-10ec9e7e4283/%7B3771b005-b9bf-4f49-952c-05c765e85513%7D.js:10:9
15:34:09     INFO -  19 INFO TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js | lastAccessed of tab 2 is later than lastAccessed of tab 1. -
15:34:09     INFO -  20 INFO TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js | lastAccessed of tab 2 is earlier than now. -
15:34:09     INFO -  21 INFO TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js | tabs.lastAccessed -
15:34:09     INFO -  22 INFO TEST-PASS | browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js | test result correct -
15:34:09     INFO -  23 INFO Leaving test bound testLastAccessed
15:34:09     INFO -  GECKO(6112) | MEMORY STAT | vsize 1769MB | vsizeMaxContiguous 131891418MB | residentFast 270MB | heapAllocated 128MB
15:34:09     INFO -  24 INFO TEST-OK | browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js | took 227ms
Duplicate of this bug: 1416130
64 total failures in the last week

Ocurrences on platforms: 
- 42 on windows 7
- 18 on windows10-64
- 3 on windows7-32-nightly
- 1 on OS X 10.10

The most affect build type is pgo and there are also 7 failures on opt.

Here is a recent relevant log file: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=145864589&lineNumber=2968
and a snippet from it:

22:42:44     INFO -  442 INFO TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_lastAccessed.js
2960
22:42:44     INFO -  TEST-INFO | started process screenshot
2961
22:42:44     INFO -  TEST-INFO | screenshot: exit 0
2962
22:42:44     INFO -  Buffered messages logged at 22:42:44
2963
22:42:44     INFO -  443 INFO Entering test bound testLastAccessed
2964
22:42:44     INFO -  444 INFO Extension loaded
2965
22:42:44     INFO -  445 INFO Console message: Warning: attempting to write 15090 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
2966
22:42:44     INFO -  446 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_lastAccessed.js | Expected tabs were found -
2967
22:42:44     INFO -  Buffered messages finished
2968
22:42:44    ERROR -  447 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_lastAccessed.js | lastAccessed of tab 1 is later than the test start time. -
2969
22:42:44     INFO -  Stack trace:
2970
22:42:44     INFO -      background/<@moz-extension://50e39b8e-6fc3-4794-870e-3a2635646b28/%7B8f147913-5e34-42ac-9493-04c3614193a5%7D.js:10:9
2971
22:42:44     INFO -  448 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_lastAccessed.js | lastAccessed of tab 2 is later than lastAccessed of tab 1. -
2972
22:42:44     INFO -  449 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_lastAccessed.js | lastAccessed of tab 2 is earlier than now. -
2973
22:42:44     INFO -  450 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_lastAccessed.js | tabs.lastAccessed -
2974
22:42:44     INFO -  451 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_tabs_lastAccessed.js | test result correct -
2975
22:42:44     INFO -  452 INFO Leaving test bound testLastAccessed

:andym, could you please take a look?
Flags: needinfo?(amckay)
Whiteboard: [stockwell needswork]
Bug 1381684 modified this test to fix an intermittent. On landing, test-verify failed with this failure on Windows 10: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=c908b2bffe6e8991ede42e196358e7db3041a9be&selectedJob=143348976 (although it passed elsewhere). Intermittent failures in this bug followed soon after. So I think this is a continuation/morph of bug 1381684...probably bsilverberg will be interested.
Blocks: 1381684
Flags: needinfo?(amckay) → needinfo?(bob.silverberg)
Assignee: nobody → bob.silverberg
Component: WebExtensions: Android → WebExtensions: General
Flags: needinfo?(bob.silverberg)
Comment on attachment 8931667 [details]
Bug 1416039 - Fix intermittent browser_ext_tabs_lastAccessed.js,

https://reviewboard.mozilla.org/r/202828/#review208212

In general I'm not sure of the value of this test, it doesn't seem to add much over what should already be tested on tabbrowser.

::: browser/components/extensions/test/browser/browser_ext_tabs_lastAccessed.js:26
(Diff revision 1)
>  
>          let now = Date.now();
>  
> -        browser.test.assertTrue(past < tab1.lastAccessed,
> +        browser.test.assertTrue(past <= tab1.lastAccessed,
>                                  "lastAccessed of tab 1 is later than the test start time.");
>          browser.test.assertTrue(tab1.lastAccessed < tab2.lastAccessed,

Will this also be an issue if the test runs fast enough?
Attachment #8931667 - Flags: review?(mixedpuppy) → review+
Comment on attachment 8931667 [details]
Bug 1416039 - Fix intermittent browser_ext_tabs_lastAccessed.js,

https://reviewboard.mozilla.org/r/202828/#review208212

I guess we're testing that we are picking up the correct value from tabbrowser.

> Will this also be an issue if the test runs fast enough?

I've never seen the test fail on this assertion, and if we make this a `<=` then I'd be worried that we might miss a regression if one occurred. I think I'll leave it as is for now, and change it later if the intermittent starts failing with this assertion.
Pushed by bsilverberg@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/88e7018ac552
Fix intermittent browser_ext_tabs_lastAccessed.js, r=mixedpuppy
https://hg.mozilla.org/mozilla-central/rev/88e7018ac552
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla59
I pushed a fix for this yesterday, which I hope will fix the intermittent. Just pointing this out because of the comment above:

"** This test has failed more than 200 times in the last 30 days. It should be disabled until it can be fixed. ** "

Let's hold off on disabling this for a few days to see if the fix works.
looks good :bsilverberg.  Is there a link to the fix that you did?
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:logic]
(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #18)
> looks good :bsilverberg.  Is there a link to the fix that you did?

Yeah, it's in comment 13, above: https://hg.mozilla.org/mozilla-central/rev/88e7018ac552
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.