1761475 - Intermittent browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected read on C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\key4.db before becoming idle -

Status: RESOLVED DUPLICATE of bug 1784868

(Firefox :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=372329304&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/B-qV1GXZQCKOODIdzQRNjQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2022-03-25T12:08:39.187Z] 12:08:39     INFO - TEST-START | browser/base/content/test/performance/browser_startup_mainthreadio.js
[task 2022-03-25T12:08:39.275Z] 12:08:39     INFO - TEST-INFO | started process screenshot
[task 2022-03-25T12:08:39.406Z] 12:08:39     INFO - TEST-INFO | screenshot: exit 0
[task 2022-03-25T12:08:39.416Z] 12:08:39     INFO - <snipped 88 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2022-03-25T12:08:39.416Z] 12:08:39     INFO - Buffered messages logged at 12:08:39
[task 2022-03-25T12:08:39.417Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | read on C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\cookies.sqlite as many times as expected before opening first browser window - 
[task 2022-03-25T12:08:39.418Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | write on C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\cookies.sqlite as many times as expected before opening first browser window - 
[task 2022-03-25T12:08:39.419Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\cookies.sqlite-wal as many times as expected before opening first browser window - 
[task 2022-03-25T12:08:39.420Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\extensions as many times as expected before opening first browser window - 
[task 2022-03-25T12:08:39.420Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\AppData\Roaming\Mozilla\Firefox allowed 1 more times before opening first browser window - 
[task 2022-03-25T12:08:39.421Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 1 more times before opening first browser window - 
[task 2022-03-25T12:08:39.422Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 2 more times before opening first browser window - 
[task 2022-03-25T12:08:39.422Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 1 more times before opening first browser window - 
[task 2022-03-25T12:08:39.423Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 2 more times before opening first browser window - 
[task 2022-03-25T12:08:39.424Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 1 more times before opening first browser window - 
[task 2022-03-25T12:08:39.424Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 2 more times before opening first browser window - 
[task 2022-03-25T12:08:39.425Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 1 more times before opening first browser window - 
[task 2022-03-25T12:08:39.426Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 2 more times before opening first browser window - 
[task 2022-03-25T12:08:39.426Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 1 more times before opening first browser window - 
[task 2022-03-25T12:08:39.427Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 2 more times before opening first browser window - 
[task 2022-03-25T12:08:39.428Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 1 more times before opening first browser window - 
[task 2022-03-25T12:08:39.428Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | close on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 2 more times before opening first browser window - 
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO - known main thread IO paths during before first paint:
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   C:\ProgramData\Mozilla\updates\DAE3987EE46B43A2 - condition: true, stat: 1, listedPath: OldUpdRootD:
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\DAE3987EE46B43A2\updates\0\update.status - condition: true, stat: 1, listedPath: UpdRootD:updates/0/update.status
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   Z:\task_164820884654898\build\application\firefox\distribution\distribution.ini - condition: true, stat: 1, listedPath: XREAppDist:distribution.ini
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   *Fonts\StaticCache.dat - condition: true, ignoreIfUnused: true, read: 1, listedPath: *Fonts/StaticCache.dat
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   C:\Windows\system32\spool\drivers\color\* - condition: true, read: 1, listedPath: SysD:spool/drivers/color/*
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   Z:\task_164820884654898\AppData\Roaming\Mozilla\Firefox - ignoreIfUnused: true, condition: true, stat: 1, listedPath: UAppData:
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\d3d11layers.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:d3d11layers.guard
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\glcontext.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:glcontext.guard
[task 2022-03-25T12:08:39.430Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\wmfvpxvideo.guard - ignoreIfUnused: true, stat: 1, listedPath: ProfD:wmfvpxvideo.guard
[task 2022-03-25T12:08:39.431Z] 12:08:39     INFO - (PoisonIOInterposer) stat - C:\ProgramData\Mozilla\updates\DAE3987EE46B43A2
[task 2022-03-25T12:08:39.431Z] 12:08:39     INFO - (PoisonIOInterposer) stat - C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\updates\DAE3987EE46B43A2\updates\0\update.status
[task 2022-03-25T12:08:39.431Z] 12:08:39     INFO - (PoisonIOInterposer) stat - Z:\task_164820884654898\build\application\firefox\distribution\distribution.ini
[task 2022-03-25T12:08:39.432Z] 12:08:39     INFO - (PoisonIOInterposer) read - C:\Windows\system32\spool\drivers\color\sRGB Color Space Profile.icm
<...>
task 2022-03-25T12:08:39.478Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 1 more times before handling user events - 
[task 2022-03-25T12:08:39.478Z] 12:08:39     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_mainthreadio.js | stat on Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] allowed 1 more times before handling user events - 
[task 2022-03-25T12:08:39.481Z] 12:08:39     INFO - known main thread IO paths during before becoming idle:
[task 2022-03-25T12:08:39.481Z] 12:08:39     INFO -   Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] - ignoreIfUnused: true, close: 1, listedPath: XREAppFeat:[e-mail]
[task 2022-03-25T12:08:39.481Z] 12:08:39     INFO -   Z:\task_164820884654898\build\application\firefox\browser\features\[e-mail] - ignoreIfUnused: true, stat: 1, close: 1, listedPath: XREAppFeat:[e-mail]
[task 2022-03-25T12:08:39.481Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\places.sqlite-journal - ignoreIfUnused: true, fsync: 1, stat: 4, read: 1, write: 2, listedPath: ProfD:places.sqlite-journal
[task 2022-03-25T12:08:39.481Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\places.sqlite-wal - ignoreIfUnused: true, stat: 4, fsync: 3, read: 51, write: 178, listedPath: ProfD:places.sqlite-wal
[task 2022-03-25T12:08:39.481Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\places.sqlite-shm - condition: true, ignoreIfUnused: true, stat: 1, listedPath: ProfD:places.sqlite-shm
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\places.sqlite - ignoreIfUnused: true, fsync: 2, read: 4, stat: 3, write: 1324, listedPath: ProfD:places.sqlite
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\favicons.sqlite-journal - ignoreIfUnused: true, fsync: 2, stat: 7, read: 2, write: 7, listedPath: ProfD:favicons.sqlite-journal
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\favicons.sqlite-wal - ignoreIfUnused: true, fsync: 2, stat: 7, read: 7, write: 15, listedPath: ProfD:favicons.sqlite-wal
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\favicons.sqlite-shm - condition: true, ignoreIfUnused: true, stat: 2, listedPath: ProfD:favicons.sqlite-shm
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\favicons.sqlite - ignoreIfUnused: true, fsync: 3, read: 8, stat: 4, write: 1300, listedPath: ProfD:favicons.sqlite
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\key4.db-journal - condition: true, stat: 2, listedPath: ProfD:key4.db-journal
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\key4.db-wal - condition: true, stat: 2, listedPath: ProfD:key4.db-wal
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO -   C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner - condition: true, ignoreIfUnused: true, stat: 3, listedPath: ProfD:
[task 2022-03-25T12:08:39.482Z] 12:08:39     INFO - (PoisonIOInterposer) stat - C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\key4.db-journal
[task 2022-03-25T12:08:39.483Z] 12:08:39     INFO - Buffered messages finished
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_mainthreadio.js | unexpected read on C:\Users\task_164820884654898\AppData\Local\Temp\tmp97rcgbrd.mozrunner\key4.db before becoming idle - 
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO - Stack trace:
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO -   nsIPK11TokenDB.getInternalKeyToken
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO -   init (resource://gre/modules/crypto-SDR.js:51:6)
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO -   LoginManagerCrypto_SDR (resource://gre/modules/crypto-SDR.js:16:31)
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO -   GetServiceByContractID @mozilla.org/login-manager/crypto/SDR;1
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO -   get _crypto (resource://gre/modules/storage-json.js:55:13)
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO -   initialize (resource://gre/modules/storage-json.js:81:12)
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO -   XPCWrappedJS method call
[task 2022-03-25T12:08:39.484Z] 12:08:39     INFO -   nsILoginManagerStorage.initialize
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   _initStorage (resource://gre/modules/LoginManager.jsm:93:14)
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   init (resource://gre/modules/LoginManager.jsm:80:6)
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   LoginManager (resource://gre/modules/LoginManager.jsm:42:21)
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   Services_Resolve logins
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   task (resource:///modules/BrowserGlue.jsm:2411:14)
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   _scheduleStartupIdleTasks/< (resource:///modules/BrowserGlue.jsm:2762:8)
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   ChromeUtils::IdleDispatch handler
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   Task ChromeUtils::IdleDispatch
[task 2022-03-25T12:08:39.485Z] 12:08:39     INFO -   XREMain::XRE_main

Comment 1

[Natalia Csoregi [:nataliaCs]]

Could be from https://hg.mozilla.org/integration/autoland/rev/24c821997842bd5aaffc77a05a20deee26167462 but triggered later?
Sergey, any chance you could take a look?
Thank you.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64-2004-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-03-21&endday=2022-03-27&tree=all

Comment 3

[Jared Hirsch [:jhirsch] (he/him) (Needinfo please)]

Hey Serg, have you had a chance to take a look at this bug?

Comment 4

[Sergey Galich [:serg]]

I've reviewed patch https://phabricator.services.mozilla.com/D141625 again and can't see any reason for changes in test behavior. Most of that patch is simple renames, no logic change there.

Comment 5

[Sergey Galich [:serg]]

According to this comment https://searchfox.org/mozilla-central/rev/d34f9713ae128a3138c2b70d8041a535f1049d19/browser/components/BrowserGlue.jsm#2413-2416

...If the data is required before this runs, for example because a restored page contains a password field, it will be loaded on the main thread, and this initialization request will be ignored.

I would expect that this is possible to touch keys4.db from main thread during startup, but this bug suggests that it shouldn't be happening.

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-central: 1
• try: 1

Platform and build breakdown:

• windows10-64-2004-qr: 2
  • opt: 2
• windows10-64-2004-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-04-18&endday=2022-04-24&tree=all

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-05-02&endday=2022-05-08&tree=all

Comment 8

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 9

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=381866825&repo=autoland

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• try: 1
• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-qr: 2
  • opt: 2
• windows10-64-2004-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-06-20&endday=2022-06-26&tree=all

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-06-27&endday=2022-07-03&tree=all

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4
• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-qr: 4
  • opt: 4
• windows10-64-2004-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-07-04&endday=2022-07-10&tree=all

Comment 13

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform and build breakdown:

• windows10-64-2004-ccov-qr: 1
  • opt: 1
• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-07-11&endday=2022-07-17&tree=all

Comment 14

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-07-18&endday=2022-07-24&tree=all

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 3

Platform and build breakdown:

• windows10-64-2004-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-07-25&endday=2022-07-31&tree=all

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64-2004-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-08-01&endday=2022-08-07&tree=all

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• windows10-64-2004-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1761475&startday=2022-08-08&endday=2022-08-14&tree=all