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

Reporter

Description

•

7 years ago

treeherder

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

Comment hidden (Intermittent Failures Robot)

11 failures in 849 pushes (0.013 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 6
* mozilla-central: 3
* mozilla-beta: 1
* autoland: 1

Platform breakdown:
* windows7-32: 8
* windows10-64: 2
* windows7-32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1416039&startday=2017-11-06&endday=2017-11-12&tree=all

Tiberius Oros[:tiberius_oros]

Comment 3

•

7 years ago

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]

Comment hidden (Intermittent Failures Robot)

71 failures in 762 pushes (0.093 failures/push) were associated with this bug in the last 7 days. 

This is the #7 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* autoland: 32
* mozilla-inbound: 26
* mozilla-central: 13

Platform breakdown:
* windows7-32: 46
* windows10-64: 19
* windows7-32-nightly: 3
* windows10-64-stylo-disabled: 1
* windows10-64-nightly: 1
* osx-10-10: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1416039&startday=2017-11-13&endday=2017-11-19&tree=all

Comment hidden (Intermittent Failures Robot)

17 failures in 176 pushes (0.097 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 9
* mozilla-inbound: 8

Platform breakdown:
* windows7-32: 11
* windows10-64: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1416039&startday=2017-11-21&endday=2017-11-21&tree=all

Geoff Brown [:gbrown]

Comment 6

•

7 years ago

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)

Comment hidden (Intermittent Failures Robot)

15 failures in 146 pushes (0.103 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 6
* mozilla-inbound: 5
* mozilla-beta: 3
* mozilla-central: 1

Platform breakdown:
* windows7-32: 12
* windows7-32-devedition: 1
* windows10-64-nightly: 1
* windows10-64-devedition: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1416039&startday=2017-11-23&endday=2017-11-23&tree=all

Bob Silverberg [:bsilverberg]

Assignee

Updated

•

7 years ago

Assignee: nobody → bob.silverberg

Component: WebExtensions: Android → WebExtensions: General

Flags: needinfo?(bob.silverberg)

Comment hidden (mozreview-request)

The recent failures all seem to be on the assertion that lastAccessed of tab 1 is
later than the test start time. It's possible that things happen so quickly that
lastAccessed of tab 1 is the same as the start time, so this patch changes the
comparison to be a <=.

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

Shane Caraveo (:mixedpuppy)

Comment 9

•

7 years ago

mozreview-review

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 hidden (Intermittent Failures Robot)

102 failures in 744 pushes (0.137 failures/push) were associated with this bug in the last 7 days. 

This is the #6 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 52
* mozilla-inbound: 32
* mozilla-central: 12
* mozilla-beta: 6

Platform breakdown:
* windows7-32: 76
* windows10-64: 19
* windows7-32-devedition: 4
* windows7-32-nightly: 1
* windows10-64-nightly: 1
* windows10-64-devedition: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1416039&startday=2017-11-20&endday=2017-11-26&tree=all

Bob Silverberg [:bsilverberg]

Assignee

Comment 11

•

7 years ago

mozreview-review-reply

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.

Pulsebot

Comment 12

•

7 years ago

Pushed by bsilverberg@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/88e7018ac552
Fix intermittent browser_ext_tabs_lastAccessed.js, r=mixedpuppy

Eliza Balazs [:ebalazs_]

Comment 13

•

7 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/88e7018ac552

Status: NEW → RESOLVED

Closed: 7 years ago

status-firefox59: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla59

Ryan VanderMeulen [:RyanVM]

Updated

•

7 years ago

status-firefox58: --- → affected

Ryan VanderMeulen [:RyanVM]

Comment 14

•

7 years ago

bugherder uplift

https://hg.mozilla.org/releases/mozilla-beta/rev/99ad3a0eee48

status-firefox58: affected → fixed

Flags: in-testsuite+

Comment hidden (Intermittent Failures Robot)

15 failures in 137 pushes (0.109 failures/push) were associated with this bug yesterday.    

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

Repository breakdown:
* mozilla-inbound: 7
* autoland: 6
* try: 1
* mozilla-beta: 1

Platform breakdown:
* windows7-32: 11
* windows10-64: 3
* windows10-64-devedition: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1416039&startday=2017-11-27&endday=2017-11-27&tree=all

Bob Silverberg [:bsilverberg]

Assignee

Comment 16

•

7 years ago

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.

Comment hidden (Intermittent Failures Robot)

18 failures in 792 pushes (0.023 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 10
* autoland: 6
* try: 1
* mozilla-beta: 1

Platform breakdown:
* windows7-32: 12
* windows10-64: 5
* windows10-64-devedition: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1416039&startday=2017-11-27&endday=2017-12-03&tree=all

Joel Maher ( :jmaher ) (UTC -8)

Comment 18

•

7 years ago

looks good :bsilverberg.  Is there a link to the fix that you did?

Whiteboard: [stockwell disable-recommended] → [stockwell fixed:logic]

Bob Silverberg [:bsilverberg]

Assignee

Comment 19

•

7 years ago

(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

BMO Automation

Updated

•

6 years ago

Product: Toolkit → WebExtensions