1665798 - High frequency <test> | application crashed [@ MessageLoop::DoWork()]

Status: RESOLVED FIXED

(Core :: Storage: IndexedDB, defect)

Description

[Treeherder Bug Filer]

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=315984465&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aj6ofYGWQGOOH-5J8qgxWA/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aj6ofYGWQGOOH-5J8qgxWA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

>[task 2020-09-17T20:06:13.343Z] 20:06:13     INFO - AssertionError
[task 2020-09-17T20:07:55.057Z] 20:07:55  WARNING - Failed to start protocol connection
[task 2020-09-17T20:07:55.058Z] 20:07:55  WARNING - Traceback (most recent call last):
[task 2020-09-17T20:07:55.058Z] 20:07:55  WARNING -   File "Z:\task_1600371167\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\protocol.py", line 47, in setup
[task 2020-09-17T20:07:55.058Z] 20:07:55  WARNING -     self.connect()
[task 2020-09-17T20:07:55.058Z] 20:07:55  WARNING -   File "Z:\task_1600371167\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 657, in connect
[task 2020-09-17T20:07:55.058Z] 20:07:55  WARNING -     self.marionette.raise_for_port()
[task 2020-09-17T20:07:55.059Z] 20:07:55  WARNING -   File "Z:\task_1600371167\build\venv\lib\site-packages\marionette_driver\marionette.py", line 573, in raise_for_port
[task 2020-09-17T20:07:55.059Z] 20:07:55  WARNING -     self.host, self.port))
[task 2020-09-17T20:07:55.059Z] 20:07:55  WARNING - timeout: Timed out waiting for connection on 127.0.0.1:56011!
[task 2020-09-17T20:07:55.059Z] 20:07:55  WARNING - 
[task 2020-09-17T20:07:55.060Z] 20:07:55     INFO - mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VUfpvSOtQYKCInalmSxR1g/artifacts/public/build/target.crashreporter-symbols.zip
[task 2020-09-17T20:07:57.665Z] 20:07:57     INFO - mozcrash Copy/paste: Z:\task_1600371167\fetches\minidump_stackwalk\minidump_stackwalk.exe c:\users\task_1600371167\appdata\local\temp\tmppvicst\minidumps\021e59e1-23a9-4df9-87ce-7dc7935f55a4.dmp c:\users\task_1600371167\appdata\local\temp\tmp_vzojv
[task 2020-09-17T20:08:03.220Z] 20:08:03     INFO - mozcrash Saved minidump as Z:\task_1600371167\build\blobber_upload_dir\021e59e1-23a9-4df9-87ce-7dc7935f55a4.dmp
[task 2020-09-17T20:08:03.220Z] 20:08:03     INFO - mozcrash Saved app info as Z:\task_1600371167\build\blobber_upload_dir\021e59e1-23a9-4df9-87ce-7dc7935f55a4.extra
[task 2020-09-17T20:08:03.372Z] 20:08:03     INFO - PROCESS-CRASH | pid: 5060 | application crashed [@ MessageLoop::DoWork()]
[task 2020-09-17T20:08:03.372Z] 20:08:03     INFO - Crash dump filename: c:\users\task_1600371167\appdata\local\temp\tmppvicst\minidumps\021e59e1-23a9-4df9-87ce-7dc7935f55a4.dmp
[task 2020-09-17T20:08:03.372Z] 20:08:03     INFO - Operating system: Windows NT
[task 2020-09-17T20:08:03.372Z] 20:08:03     INFO -                   10.0.17134 
[task 2020-09-17T20:08:03.372Z] 20:08:03     INFO - CPU: amd64
[task 2020-09-17T20:08:03.372Z] 20:08:03     INFO -      family 6 model 79 stepping 1
[task 2020-09-17T20:08:03.373Z] 20:08:03     INFO -      4 CPUs
[task 2020-09-17T20:08:03.373Z] 20:08:03     INFO - 
[task 2020-09-17T20:08:03.373Z] 20:08:03     INFO - GPU: UNKNOWN
[task 2020-09-17T20:08:03.373Z] 20:08:03     INFO - 
[task 2020-09-17T20:08:03.373Z] 20:08:03     INFO - Crash reason:  EXCEPTION_ACCESS_VIOLATION_READ
[task 2020-09-17T20:08:03.373Z] 20:08:03     INFO - Crash address: 0xffffffff
[task 2020-09-17T20:08:03.374Z] 20:08:03     INFO - Process uptime: 11 seconds
[task 2020-09-17T20:08:03.374Z] 20:08:03     INFO - 
[task 2020-09-17T20:08:03.374Z] 20:08:03     INFO - Thread 3 (crashed)
[task 2020-09-17T20:08:03.374Z] 20:08:03     INFO -  0  xul.dll!MessageLoop::DoWork() [message_loop.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 548 + 0x33]
[task 2020-09-17T20:08:03.374Z] 20:08:03     INFO -     rax = 0xe5e5e5e5e5e5e5e5   rdx = 0x000002a0d7dfa600
[task 2020-09-17T20:08:03.375Z] 20:08:03     INFO -     rcx = 0xa1fad4c7df030000   rbx = 0x000000fa1a5ff9b0
[task 2020-09-17T20:08:03.375Z] 20:08:03     INFO -     rsi = 0x000000fa1a5ff958   rdi = 0x000002a0d7dfa600
[task 2020-09-17T20:08:03.375Z] 20:08:03     INFO -     rbp = 0x0000000000000000   rsp = 0x000000fa1a5ff6e0
[task 2020-09-17T20:08:03.375Z] 20:08:03     INFO -      r8 = 0x0000000000000000    r9 = 0x000002a0cc213190
[task 2020-09-17T20:08:03.375Z] 20:08:03     INFO -     r10 = 0x00000fff2b2c1c38   r11 = 0x0100010000000000
[task 2020-09-17T20:08:03.375Z] 20:08:03     INFO -     r12 = 0x000000fa1a5ff7e0   r13 = 0x00007ff95f63e374
[task 2020-09-17T20:08:03.376Z] 20:08:03     INFO -     r14 = 0x000000fa1a5ff710   r15 = 0x000000fa1a5ff708
[task 2020-09-17T20:08:03.376Z] 20:08:03     INFO -     rip = 0x00007ff95960e34a
[task 2020-09-17T20:08:03.376Z] 20:08:03     INFO -     Found by: given as instruction pointer in context
[task 2020-09-17T20:08:03.376Z] 20:08:03     INFO -  1  xul.dll!base::MessagePumpForIO::DoRunLoop() [message_pump_win.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 419 + 0x14]
[task 2020-09-17T20:08:03.376Z] 20:08:03     INFO -     rbx = 0x000000fa1a5ff9b0   rbp = 0x0000000000000000
[task 2020-09-17T20:08:03.377Z] 20:08:03     INFO -     rsp = 0x000000fa1a5ff780   r12 = 0x000000fa1a5ff7e0
[task 2020-09-17T20:08:03.377Z] 20:08:03     INFO -     r13 = 0x00007ff95f63e374   r14 = 0x000000fa1a5ff710
[task 2020-09-17T20:08:03.377Z] 20:08:03     INFO -     r15 = 0x000000fa1a5ff708   rip = 0x00007ff95a5518e1
[task 2020-09-17T20:08:03.377Z] 20:08:03     INFO -     Found by: call frame info
[task 2020-09-17T20:08:03.377Z] 20:08:03     INFO -  2  xul.dll!base::MessagePumpWin::Run(base::MessagePump::Delegate*) [message_pump_win.h:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 79 + 0x55]
[task 2020-09-17T20:08:03.377Z] 20:08:03     INFO -     rbx = 0x000000fa1a5ff9b0   rbp = 0x0000000000000000
[task 2020-09-17T20:08:03.377Z] 20:08:03     INFO -     rsp = 0x000000fa1a5ff850   r12 = 0x000000fa1a5ff7e0
[task 2020-09-17T20:08:03.378Z] 20:08:03     INFO -     r13 = 0x00007ff95f63e374   r14 = 0x000000fa1a5ff710
[task 2020-09-17T20:08:03.378Z] 20:08:03     INFO -     r15 = 0x000000fa1a5ff708   rip = 0x00007ff95960e195
[task 2020-09-17T20:08:03.378Z] 20:08:03     INFO -     Found by: call frame info
[task 2020-09-17T20:08:03.378Z] 20:08:03     INFO -  3  xul.dll!MessageLoop::RunHandler() [message_loop.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 327 + 0x16]
[task 2020-09-17T20:08:03.378Z] 20:08:03     INFO -     rbx = 0x000000fa1a5ff9b0   rbp = 0x0000000000000000
[task 2020-09-17T20:08:03.379Z] 20:08:03     INFO -     rsp = 0x000000fa1a5ff8b0   r12 = 0x000000fa1a5ff7e0
[task 2020-09-17T20:08:03.379Z] 20:08:03     INFO -     r13 = 0x00007ff95f63e374   r14 = 0x000000fa1a5ff710
[task 2020-09-17T20:08:03.379Z] 20:08:03     INFO -     r15 = 0x000000fa1a5ff708   rip = 0x00007ff95a55b1af
[task 2020-09-17T20:08:03.379Z] 20:08:03     INFO -     Found by: call frame info
[task 2020-09-17T20:08:03.379Z] 20:08:03     INFO -  4  xul.dll!base::Thread::ThreadMain() [thread.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 192 + 0x46]
[task 2020-09-17T20:08:03.379Z] 20:08:03     INFO -     rbx = 0x000000fa1a5ff9b0   rbp = 0x0000000000000000
[task 2020-09-17T20:08:03.380Z] 20:08:03     INFO -     rsp = 0x000000fa1a5ff900   r12 = 0x000000fa1a5ff7e0
[task 2020-09-17T20:08:03.380Z] 20:08:03     INFO -     r13 = 0x00007ff95f63e374   r14 = 0x000000fa1a5ff710
[task 2020-09-17T20:08:03.380Z] 20:08:03     INFO -     r15 = 0x000000fa1a5ff708   rip = 0x00007ff95960c2a4
[task 2020-09-17T20:08:03.380Z] 20:08:03     INFO -     Found by: call frame info
[task 2020-09-17T20:08:03.380Z] 20:08:03     INFO -  5  xul.dll!`anonymous namespace'::ThreadFunc(void*) [platform_thread_win.cc:2da9fde7a1095a35fbdcc37d2b8d103cf9935507 : 19 + 0xd]
[task 2020-09-17T20:08:03.380Z] 20:08:03     INFO -     rbx = 0x000000fa1a5ff9b0   rbp = 0x0000000000000000
[task 2020-09-17T20:08:03.381Z] 20:08:03     INFO -     rsp = 0x000000fa1a5ffae0   r12 = 0x000000fa1a5ff7e0
[task 2020-09-17T20:08:03.381Z] 20:08:03     INFO -     r13 = 0x00007ff95f63e374   r14 = 0x000000fa1a5ff710
[task 2020-09-17T20:08:03.381Z] 20:08:03     INFO -     r15 = 0x000000fa1a5ff708   rip = 0x00007ff95a5525f1
[task 2020-09-17T20:08:03.381Z] 20:08:03     INFO -     Found by: call frame info
[task 2020-09-17T20:08:03.381Z] 20:08:03     INFO -  6  kernel32.dll!RtlpLowFragHeapAllocFromContext + 0x204
[task 2020-09-17T20:08:03.382Z] 20:08:03     INFO -     rbx = 0x000000fa1a5ff9b0   rbp = 0x0000000000000000
[task 2020-09-17T20:08:03.382Z] 20:08:03     INFO -     rsp = 0x000000fa1a5ffb10   r12 = 0x000000fa1a5ff7e0
[task 2020-09-17T20:08:03.382Z] 20:08:03     INFO -     r13 = 0x00007ff95f63e374   r14 = 0x000000fa1a5ff710
[task 2020-09-17T20:08:03.382Z] 20:08:03     INFO -     r15 = 0x000000fa1a5ff708   rip = 0x00007ff9a1233034
[task 2020-09-17T20:08:03.382Z] 20:08:03     INFO -     Found by: call frame info
[task 2020-09-17T20:08:03.383Z] 20:08:03     INFO - ```

Comment 1

[Intermittent Failures Robot]

27 failures in 719 pushes (0.038 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 27

Platform breakdown:

• windows10-64-shippable-qr: 15
• windows10-64-shippable: 6
• windows7-32-shippable: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1665798&startday=2020-09-17&endday=2020-09-17&tree=all

Comment 2

[Intermittent Failures Robot]

52 failures in 3760 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #18 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: 52

Platform breakdown:

• windows10-64-shippable-qr: 31
• windows10-64-shippable: 15
• windows7-32-shippable: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1665798&startday=2020-09-14&endday=2020-09-20&tree=all

Comment 3

[Andrew McCreight [:mccr8]]

Given the frequency of this crash, maybe somebody could bisect it back on treeherder to figure out when it was introduced. It looks like Raptor is the most common place for this crash.

Comment 4

[Andrew McCreight [:mccr8]]

[Tracking Requested - why for this release]: high-frequency scary looking crash regression.

Comment 5

[Andrew McCreight [:mccr8]]

I've started doing some retriggers to hopefully narrow down the range a bit. The frequency is pretty high, but it is scattered across a number of test suites, so I'm not sure how high the rate will be on any given test.

Comment 6

[Andrew McCreight [:mccr8]]

It looked like there was a huge spike on the 17th, but it hasn't recurred since then. The first instance of this crash was the push for bug 1663924, and most of that patch was backed out later that day, so maybe that's what caused it. I'll clear the flags given that it appears to have gone away for now.

Comment 7

[Andrew McCreight [:mccr8]]

I did a lot of retriggers of 2 of the tests that were failing, and I was unable to reproduce a failure on a push earlier than the one for bug 1663924, and I did reproduce it once there so I'm going to call this a regression from that:

https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=raptor%2Cwindows10%2Ctp6%2Ce10s%2Ccold%2Ctwitter&tochange=2da9fde7a1095a35fbdcc37d2b8d103cf9935507&fromchange=f3b0c35583ebeb8e67dcb3c9b963773237d9c5a6
https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=raptor%2Cwindows10%2Ctp6%2Ce10s%2Ccold%2Cyahoo-news&tochange=2da9fde7a1095a35fbdcc37d2b8d103cf9935507&fromchange=f3b0c35583ebeb8e67dcb3c9b963773237d9c5a6

Comment 9

[Andrew McCreight [:mccr8]]

I'm going to call this fixed by the backout of (some of?) bug 1663924.