Closed Bug 1706439 Opened 3 years ago Closed 3 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | devtools/client/storage/test/browser_storage_fission_indexeddb.js | application timed out after 370 seconds with no output

Categories

(DevTools :: Storage Inspector, defect, P5)

defect

Tracking

(firefox-esr78 unaffected, firefox-esr91 disabled, firefox88 unaffected, firefox89 unaffected, firefox90 disabled, firefox91 disabled, firefox92 disabled, firefox93 fixed)

RESOLVED FIXED
93 Branch
Tracking Status
firefox-esr78 --- unaffected
firefox-esr91 --- disabled
firefox88 --- unaffected
firefox89 --- unaffected
firefox90 --- disabled
firefox91 --- disabled
firefox92 --- disabled
firefox93 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell needswork:owner])

Attachments

(1 file)

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=337173856&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZaLVOhINQTO5oSTmkiqslg/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/ZaLVOhINQTO5oSTmkiqslg/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2021-04-20T16:09:44.542Z] 16:09:44    ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/storage/test/browser_storage_fission_indexeddb.js | application timed out after 370 seconds with no output
[task 2021-04-20T16:09:44.542Z] 16:09:44    ERROR - Force-terminating active process(es).
[task 2021-04-20T16:09:44.542Z] 16:09:44     INFO - Determining child pids from psutil...
[task 2021-04-20T16:09:44.542Z] 16:09:44     INFO - [1478, 1470, 1471, 1479]
[task 2021-04-20T16:09:44.542Z] 16:09:44     INFO - ==> process 1469 launched child process 1470
[task 2021-04-20T16:09:44.543Z] 16:09:44     INFO - ==> process 1469 launched child process 1471
[task 2021-04-20T16:09:44.543Z] 16:09:44     INFO - ==> process 1469 launched child process 1478
[task 2021-04-20T16:09:44.543Z] 16:09:44     INFO - ==> process 1469 launched child process 1479
[task 2021-04-20T16:09:44.543Z] 16:09:44     INFO - Found child pids: set([1479, 1470, 1478, 1471])
[task 2021-04-20T16:09:44.543Z] 16:09:44     INFO - Killing process: 1479
[task 2021-04-20T16:09:44.543Z] 16:09:44     INFO - TEST-INFO | started process screencapture
[task 2021-04-20T16:09:44.648Z] 16:09:44     INFO - TEST-INFO | screencapture: exit 0
[task 2021-04-20T16:09:44.648Z] 16:09:44     INFO - Killing process: 1470
[task 2021-04-20T16:09:44.648Z] 16:09:44     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-20T16:09:44.649Z] 16:09:44     INFO - Killing process: 1478
[task 2021-04-20T16:09:44.649Z] 16:09:44     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-20T16:09:44.649Z] 16:09:44     INFO - Killing process: 1471
[task 2021-04-20T16:09:44.649Z] 16:09:44     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-20T16:09:46.541Z] 16:09:46     INFO - psutil found pid 1478 dead
[task 2021-04-20T16:09:46.541Z] 16:09:46     INFO - psutil found pid 1479 dead
[task 2021-04-20T16:09:46.541Z] 16:09:46     INFO - psutil found pid 1471 dead
[task 2021-04-20T16:09:46.542Z] 16:09:46     INFO - psutil found pid 1470 dead
[task 2021-04-20T16:09:46.542Z] 16:09:46     INFO - Killing process: 1469
[task 2021-04-20T16:09:46.542Z] 16:09:46     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-20T16:09:46.656Z] 16:09:46     INFO - psutil found pid 1469 dead
[task 2021-04-20T16:09:46.687Z] 16:09:46  WARNING - runtests.py | Failed to get app exit code - running/crashed?
[task 2021-04-20T16:09:46.687Z] 16:09:46     INFO - TEST-INFO | Main app process: exit 0
[task 2021-04-20T16:09:46.687Z] 16:09:46     INFO - runtests.py | Application ran for: 0:07:57.377873
[task 2021-04-20T16:09:46.687Z] 16:09:46     INFO - zombiecheck | Reading PID log: /var/folders/hy/4prvwgbx2cs7jfv1cdf10p_m000017/T/tmp_djPsXpidlog
[task 2021-04-20T16:09:46.688Z] 16:09:46     INFO - ==> process 1469 launched child process 1470
[task 2021-04-20T16:09:46.688Z] 16:09:46     INFO - ==> process 1469 launched child process 1471
[task 2021-04-20T16:09:46.688Z] 16:09:46     INFO - ==> process 1469 launched child process 1478
[task 2021-04-20T16:09:46.688Z] 16:09:46     INFO - ==> process 1469 launched child process 1479
[task 2021-04-20T16:09:46.689Z] 16:09:46     INFO - ==> process 1469 launched child process 1541
[task 2021-04-20T16:09:46.689Z] 16:09:46     INFO - ==> process 1469 launched child process 1545
[task 2021-04-20T16:09:46.689Z] 16:09:46     INFO - zombiecheck | Checking for orphan process with PID: 1541
[task 2021-04-20T16:09:46.689Z] 16:09:46     INFO - zombiecheck | Checking for orphan process with PID: 1478
[task 2021-04-20T16:09:46.689Z] 16:09:46     INFO - zombiecheck | Checking for orphan process with PID: 1479
[task 2021-04-20T16:09:46.689Z] 16:09:46     INFO - zombiecheck | Checking for orphan process with PID: 1545
[task 2021-04-20T16:09:46.690Z] 16:09:46     INFO - zombiecheck | Checking for orphan process with PID: 1470
[task 2021-04-20T16:09:46.690Z] 16:09:46     INFO - zombiecheck | Checking for orphan process with PID: 1471
[task 2021-04-20T16:09:46.690Z] 16:09:46     INFO - mozcrash Downloading symbols from: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/NssaDOM9RKGenRBFWDs7VA/artifacts/public/build/target.crashreporter-symbols.zip
[task 2021-04-20T16:09:49.111Z] 16:09:49     INFO - mozcrash Copy/paste: /Users/cltbld/tasks/task_1618934222/fetches/minidump_stackwalk/minidump_stackwalk /var/folders/hy/4prvwgbx2cs7jfv1cdf10p_m000017/T/tmp9HQlB8.mozrunner/minidumps/FD03A9AF-84C7-4228-A537-202D69F32D84.dmp /var/folders/hy/4prvwgbx2cs7jfv1cdf10p_m000017/T/tmprW6sgp
[task 2021-04-20T16:09:52.466Z] 16:09:52     INFO - mozcrash Saved minidump as /Users/cltbld/tasks/task_1618934222/build/blobber_upload_dir/FD03A9AF-84C7-4228-A537-202D69F32D84.dmp
[task 2021-04-20T16:09:52.467Z] 16:09:52     INFO - mozcrash Saved app info as /Users/cltbld/tasks/task_1618934222/build/blobber_upload_dir/FD03A9AF-84C7-4228-A537-202D69F32D84.extra
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ mach_msg_trap + 0xa]
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO - Crash dump filename: /var/folders/hy/4prvwgbx2cs7jfv1cdf10p_m000017/T/tmp9HQlB8.mozrunner/minidumps/FD03A9AF-84C7-4228-A537-202D69F32D84.dmp
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO - Operating system: Mac OS X
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO -                   10.14.5 18F132
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO - CPU: amd64
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO -      family 6 model 69 stepping 1
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO -      4 CPUs
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO - 
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO - GPU: UNKNOWN
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO - 
[task 2021-04-20T16:09:52.532Z] 16:09:52     INFO - Crash reason:  EXC_SOFTWARE / SIGABRT
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO - Crash address: 0x7fff6817922a
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO - Process uptime: 475 seconds
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO - 
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO - Thread 0 (crashed)
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -  0  libsystem_kernel.dylib!mach_msg_trap + 0xa
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -     rax = 0x000000000100001f   rdx = 0x0000000000000000
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -     rcx = 0x00007ffeecbdd138   rbx = 0x0000000000000102
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -     rsi = 0x0000000000000102   rdi = 0x00007ffeecbdd1f0
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -     rbp = 0x00007ffeecbdd190   rsp = 0x00007ffeecbdd138
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -      r8 = 0x0000000000003817    r9 = 0x0000000000001388
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -     r10 = 0x000000000000041c   r11 = 0x0000000000000202
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -     r12 = 0x0000000000000102   r13 = 0x000000000000041c
[task 2021-04-20T16:09:52.533Z] 16:09:52     INFO -     r14 = 0x00007ffeecbdd1f0   r15 = 0x0000000000000000
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     rip = 0x00007fff6817922a
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     Found by: given as instruction pointer in context
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -  1  XUL!google_breakpad::ReceivePort::WaitForMessage(google_breakpad::MachReceiveMessage*, unsigned int) [MachIPC.mm:64467b7c9c64938cca9fd14b756520226ae67119 : 249 + 0x18]
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     rbp = 0x00007ffeecbdd1b0   rsp = 0x00007ffeecbdd1a0
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     rip = 0x0000000107ee39ea
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -  2  XUL!google_breakpad::CrashGenerationClient::RequestDumpForException(int, int, int, unsigned int, unsigned int) [crash_generation_client.cc:64467b7c9c64938cca9fd14b756520226ae67119 : 70 + 0xd]
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     rbp = 0x00007ffeecbdda60   rsp = 0x00007ffeecbdd1c0
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     rip = 0x0000000107ed9772
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -  3  XUL!google_breakpad::ExceptionHandler::WriteMinidumpWithException(int, int, int, __darwin_ucontext*, unsigned int, unsigned int, bool, bool) [exception_handler.cc:64467b7c9c64938cca9fd14b756520226ae67119 : 403 + 0x1c]
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     rbp = 0x00007ffeecbddb50   rsp = 0x00007ffeecbdda70
[task 2021-04-20T16:09:52.534Z] 16:09:52     INFO -     rip = 0x0000000107edc5da
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -  4  XUL!google_breakpad::ExceptionHandler::SignalHandler(int, __siginfo*, void*) [exception_handler.cc:64467b7c9c64938cca9fd14b756520226ae67119 : 658 + 0x27]
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     rbp = 0x00007ffeecbddb90   rsp = 0x00007ffeecbddb60
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     rip = 0x0000000107edcd47
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -  5  libsystem_platform.dylib!_sigtramp + 0x1d
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     rbp = 0x00007ffeecbddba0   rsp = 0x00007ffeecbddba0
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     rip = 0x00007fff6822fb5d
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -  6  0x7ffeecbde170
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     rbp = 0x00007ffeecbddba0   rsp = 0x00007ffeecbddba8
[task 2021-04-20T16:09:52.535Z] 16:09:52     INFO -     rip = 0x00007ffeecbde170
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     Found by: call frame info
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO - 
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO - Thread 1
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -  0  libsystem_kernel.dylib!mach_msg_trap + 0xa
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     rax = 0x000000000100001f   rdx = 0x0000000000000000
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     rcx = 0x000070000be70be8   rbx = 0x0000000000000006
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     rsi = 0x0000000000000006   rdi = 0x000070000be70c90
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     rbp = 0x000070000be70c40   rsp = 0x000070000be70be8
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -      r8 = 0x0000000000005403    r9 = 0x0000000000000000
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     r10 = 0x000000000000024c   r11 = 0x0000000000000206
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     r12 = 0x0000000000000006   r13 = 0x000000000000024c
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     r14 = 0x000070000be70c90   r15 = 0x0000000000000000
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     rip = 0x00007fff6817922a
[task 2021-04-20T16:09:52.536Z] 16:09:52     INFO -     Found by: given as instruction pointer in context
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -  1  XUL!google_breakpad::ExceptionHandler::WaitForMessage(void*) [exception_handler.cc:64467b7c9c64938cca9fd14b756520226ae67119 : 524 + 0x1d]
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     rbp = 0x000070000be70f10   rsp = 0x000070000be70c50
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     rip = 0x0000000107edc865
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -  2  libsystem_pthread.dylib!_pthread_body + 0x7e
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     rbp = 0x000070000be70f30   rsp = 0x000070000be70f20
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     rip = 0x00007fff682382eb
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -  3  libsystem_pthread.dylib!_pthread_start + 0x42
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     rbp = 0x000070000be70f50   rsp = 0x000070000be70f40
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     rip = 0x00007fff6823b249
[task 2021-04-20T16:09:52.537Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.538Z] 16:09:52     INFO -  4  libsystem_pthread.dylib!thread_start + 0xd
[task 2021-04-20T16:09:52.538Z] 16:09:52     INFO -     rbp = 0x000070000be70f78   rsp = 0x000070000be70f60
[task 2021-04-20T16:09:52.538Z] 16:09:52     INFO -     rip = 0x00007fff6823740d
[task 2021-04-20T16:09:52.538Z] 16:09:52     INFO -     Found by: previous frame's frame pointer
[task 2021-04-20T16:09:52.538Z] 16:09:52     INFO -  5  XUL + 0x3ffb7e0
[task 2021-04-20T16:09:52.538Z] 16:09:52     INFO -     rsp = 0x000070000be71090   rip = 0x0000000107edc7e0
[task 2021-04-20T16:09:52.538Z] 16:09:52     INFO -     Found by: stack scanning
[task 2021-04-20T16:09:52.538Z] 16:09:52     INFO - ```

Set release status flags based on info from the regressing bug 1666532

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent TV TEST-UNEXPECTED-TIMEOUT | devtools/client/storage/test/browser_storage_fission_indexeddb.js | application timed out after 370 seconds with no output → Intermittent TEST-UNEXPECTED-TIMEOUT | devtools/client/storage/test/browser_storage_fission_indexeddb.js | application timed out after 370 seconds with no output

There have been 43 total failures in the last 7 days (recent failure log).
Affected platforms are:

  • linux1804-64-asan-qr
  • linux1804-64-qr

Belén, could you please take a look?

Flags: needinfo?(balbeza)
Whiteboard: [stockwell needswork:owner]

The indexedDB fission test was sometimes timing out in the registered clean up function, when it was trying to remove the DB with a dom api call. This patch bails out this clearing if it takes too long. Try push https://treeherder.mozilla.org/jobs?repo=try&revision=403faa4e321d613fe5b056006c31eacda62f878a

Assignee: nobody → balbeza
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 93 Branch
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: