Closed Bug 1736729 Opened 4 years ago Closed 3 years ago

Intermittent toolkit/components/narrate/test/browser_voiceselect.js | Test timed out -

Categories

(Toolkit :: Reader Mode, defect, P5)

Product:
Toolkit
Component:
Reader Mode
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=355367631&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/HGGbw27RRceKh-3Sr5A-iA/runs/0/artifacts/public/logs/live_backing.log

[task 2021-10-19T20:59:56.655Z] 20:59:56     INFO - TEST-START | toolkit/components/narrate/test/browser_voiceselect.js
[task 2021-10-19T20:59:57.259Z] 20:59:57     INFO - GECKO(4214) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-10-19T21:00:41.686Z] 21:00:41     INFO - TEST-INFO | started process screentopng
[task 2021-10-19T21:00:41.855Z] 21:00:41     INFO - TEST-INFO | screentopng: exit 0
[task 2021-10-19T21:00:41.857Z] 21:00:41     INFO - Buffered messages logged at 20:59:56
[task 2021-10-19T21:00:41.857Z] 21:00:41     INFO - Entering test bound testVoiceselectDropdownAutoclose
[task 2021-10-19T21:00:41.857Z] 21:00:41     INFO - Buffered messages logged at 20:59:57
[task 2021-10-19T21:00:41.858Z] 21:00:41     INFO - TEST-PASS | toolkit/components/narrate/test/browser_voiceselect.js | popup is toggled - true == true - 
[task 2021-10-19T21:00:41.858Z] 21:00:41     INFO - TEST-PASS | toolkit/components/narrate/test/browser_voiceselect.js | voice options are initially hidden - true == true - 
[task 2021-10-19T21:00:41.858Z] 21:00:41     INFO - TEST-PASS | toolkit/components/narrate/test/browser_voiceselect.js | voice options are toggled - true == true - 
[task 2021-10-19T21:00:41.858Z] 21:00:41     INFO - TEST-PASS | toolkit/components/narrate/test/browser_voiceselect.js | narrate popup is dismissed - true == true - 
[task 2021-10-19T21:00:41.858Z] 21:00:41     INFO - TEST-PASS | toolkit/components/narrate/test/browser_voiceselect.js | narrate popup is showing again - true == true - 
[task 2021-10-19T21:00:41.858Z] 21:00:41     INFO - TEST-PASS | toolkit/components/narrate/test/browser_voiceselect.js | voice options are hidden after popup comes back - true == true - 
[task 2021-10-19T21:00:41.859Z] 21:00:41     INFO - Leaving test bound testVoiceselectDropdownAutoclose
[task 2021-10-19T21:00:41.859Z] 21:00:41     INFO - Entering test bound testVoiceselectLabelChange
[task 2021-10-19T21:00:41.859Z] 21:00:41     INFO - Buffered messages finished
[task 2021-10-19T21:00:41.860Z] 21:00:41     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/narrate/test/browser_voiceselect.js | Test timed out - 
[task 2021-10-19T21:00:41.860Z] 21:00:41     INFO - GECKO(4214) | MEMORY STAT | vsize 3251MB | residentFast 530MB | heapAllocated 159MB
[task 2021-10-19T21:00:41.860Z] 21:00:41     INFO - TEST-OK | toolkit/components/narrate/test/browser_voiceselect.js | took 45039ms
[task 2021-10-19T21:00:41.861Z] 21:00:41     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-10-19T21:00:41.861Z] 21:00:41     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/narrate/test/browser_voiceselect.js | Found a tab after previous test timed out: about:blank - 
[task 2021-10-19T21:00:41.862Z] 21:00:41     INFO - checking window state
[task 2021-10-19T21:00:41.862Z] 21:00:41     INFO - TEST-START | toolkit/components/narrate/test/browser_word_highlight.js
[task 2021-10-19T21:01:26.805Z] 21:01:26     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-10-19T21:01:26.806Z] 21:01:26     INFO - Buffered messages logged at 21:00:41
[task 2021-10-19T21:01:26.806Z] 21:01:26     INFO - Entering test bound testNarrate
[task 2021-10-19T21:01:26.806Z] 21:01:26     INFO - Buffered messages finished
[task 2021-10-19T21:01:26.806Z] 21:01:26     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/narrate/test/browser_word_highlight.js | Test timed out - 
[task 2021-10-19T21:01:26.809Z] 21:01:26     INFO - GECKO(4214) | MEMORY STAT | vsize 3251MB | residentFast 532MB | heapAllocated 161MB
[task 2021-10-19T21:01:26.810Z] 21:01:26     INFO - TEST-OK | toolkit/components/narrate/test/browser_word_highlight.js | took 45036ms
[task 2021-10-19T21:01:26.811Z] 21:01:26     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-10-19T21:01:26.811Z] 21:01:26     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/narrate/test/browser_word_highlight.js | Found a tab after previous test timed out: about:blank - 
[task 2021-10-19T21:01:26.855Z] 21:01:26     INFO - checking window state
[task 2021-10-19T21:01:36.886Z] 21:01:36     INFO - GECKO(4214) | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ShutdownLeaks: Wait for tabs to finish closing","state":"(none)","filename":"chrome://mochikit/content/browser-test.js","lineNumber":900,"stack":["chrome://mochikit/content/browser-test.js:nextTest/<:900","chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041"]}] Barrier: ShutdownLeaks: Wait for cleanup to be finished before checking for leaks
[task 2021-10-19T21:02:27.887Z] 21:02:27     INFO - GECKO(4214) | FATAL ERROR: AsyncShutdown timeout in ShutdownLeaks: Wait for cleanup to be finished before checking for leaks Conditions: [{"name":"ShutdownLeaks: Wait for tabs to finish closing","state":"(none)","filename":"chrome://mochikit/content/browser-test.js","lineNumber":900,"stack":["chrome://mochikit/content/browser-test.js:nextTest/<:900","chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1041"]}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
[task 2021-10-19T21:02:27.887Z] 21:02:27     INFO - GECKO(4214) | [Parent 4214, Main Thread] ###!!! ABORT: file chrome://mochikit/content/browser-test.js:900
[task 2021-10-19T21:02:27.887Z] 21:02:27     INFO - GECKO(4214) | [Parent 4214, Main Thread] ###!!! ABORT: file chrome://mochikit/content/browser-test.js:900
[task 2021-10-19T21:02:27.891Z] 21:02:27     INFO - GECKO(4214) | ExceptionHandler::GenerateDump cloned child ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2021-10-19T21:02:27.891Z] 21:02:27     INFO - GECKO(4214) | 4679
[task 2021-10-19T21:02:27.892Z] 21:02:27     INFO - GECKO(4214) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2021-10-19T21:02:27.999Z] 21:02:27     INFO - GECKO(4214) | Exiting due to channel error.
[task 2021-10-19T21:02:27.999Z] 21:02:27     INFO - GECKO(4214) | Exiting due to channel error.
[task 2021-10-19T21:02:27.999Z] 21:02:27     INFO - GECKO(4214) | Exiting due to channel error.
[task 2021-10-19T21:02:28.000Z] 21:02:27     INFO - GECKO(4214) | Exiting due to channel error.
[task 2021-10-19T21:08:38.015Z] 21:08:38     INFO - Buffered messages finished
[task 2021-10-19T21:08:38.016Z] 21:08:38    ERROR - TEST-UNEXPECTED-TIMEOUT | Last test finished | application timed out after 370 seconds with no output
[task 2021-10-19T21:08:38.016Z] 21:08:38    ERROR - Force-terminating active process(es).
[task 2021-10-19T21:08:38.016Z] 21:08:38     INFO - Determining child pids from psutil...
[task 2021-10-19T21:08:38.067Z] 21:08:38     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-10-19T21:08:38.067Z] 21:08:38     INFO - psutil found pid 4214 dead
[task 2021-10-19T21:08:38.092Z] 21:08:38     INFO - TEST-INFO | Main app process: exit 0

[task 2021-10-19T21:08:46.777Z] 21:08:46     INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ nsDebugImpl::Abort(char const*, int) + 0x20]
[task 2021-10-19T21:08:46.777Z] 21:08:46     INFO - Crash dump filename: /tmp/tmp21o0_8i0.mozrunner/minidumps/1293c0a0-4109-59bf-9b6e-11515c4a0c57.dmp
[task 2021-10-19T21:08:46.777Z] 21:08:46     INFO - Operating system: Linux
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO -                   0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO - CPU: amd64
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO -      family 6 model 85 stepping 4
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO -      4 CPUs
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO - 
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO - GPU: UNKNOWN
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO - 
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO - Crash reason:  SIGSEGV / SEGV_MAPERR
[task 2021-10-19T21:08:46.778Z] 21:08:46     INFO - Crash address: 0x0
[task 2021-10-19T21:08:46.779Z] 21:08:46     INFO - Process uptime: not available
[task 2021-10-19T21:08:46.779Z] 21:08:46     INFO - 
[task 2021-10-19T21:08:46.779Z] 21:08:46     INFO - Thread 0 tid 4214 (crashed) 0  firefox-bin!mozalloc_abort [mozalloc_abort.cpp:071e79ac291629df585272854d70a2b1d47a77ab : 33 + 0x11]
[task 2021-10-19T21:08:46.779Z] 21:08:46     INFO -     rax = 0x000055e96afe5eb0   rdx = 0x00007f91a33f28b0
[task 2021-10-19T21:08:46.779Z] 21:08:46     INFO -     rcx = 0x000055e96b143720   rbx = 0x00007f91a33f1840
[task 2021-10-19T21:08:46.779Z] 21:08:46     INFO -     rsi = 0x00007f91a33f1703   rdi = 0x0000000000000000
[task 2021-10-19T21:08:46.779Z] 21:08:46     INFO -     rbp = 0x00007ffd2370f040   rsp = 0x00007ffd2370f030
[task 2021-10-19T21:08:46.779Z] 21:08:46     INFO -      r8 = 0x0000000000000000    r9 = 0x00007f91a33f28b0
[task 2021-10-19T21:08:46.780Z] 21:08:46     INFO -     r10 = 0x000000000000000a   r11 = 0x0000000000000000
[task 2021-10-19T21:08:46.780Z] 21:08:46     INFO -     r12 = 0x0000000000000003   r13 = 0x0000000000000000
[task 2021-10-19T21:08:46.780Z] 21:08:46     INFO -     r14 = 0x00007ffd2370f090   r15 = 0x00007ffd2370f3a0
[task 2021-10-19T21:08:46.780Z] 21:08:46     INFO -     rip = 0x000055e96b0435e6
[task 2021-10-19T21:08:46.780Z] 21:08:46     INFO -     Found by: given as instruction pointer in context
[task 2021-10-19T21:08:46.780Z] 21:08:46     INFO -  1  libxul.so!NS_DebugBreak [nsDebugImpl.cpp:071e79ac291629df585272854d70a2b1d47a77ab : 409 + 0x25]
[task 2021-10-19T21:08:46.780Z] 21:08:46     INFO -     rbx = 0x00007ffd2370f060   rbp = 0x00007ffd2370f6d0
[task 2021-10-19T21:08:46.781Z] 21:08:46     INFO -     rsp = 0x00007ffd2370f050   r12 = 0x0000000000000003
[task 2021-10-19T21:08:46.781Z] 21:08:46     INFO -     r13 = 0x0000000000000000   r14 = 0x00007ffd2370f090
[task 2021-10-19T21:08:46.781Z] 21:08:46     INFO -     r15 = 0x00007ffd2370f3a0   rip = 0x00007f918891a567
[task 2021-10-19T21:08:46.781Z] 21:08:46     INFO -     Found by: call frame info
[task 2021-10-19T21:08:46.781Z] 21:08:46     INFO -  2  libxul.so!nsDebugImpl::Abort(char const*, int) + 0x20
[task 2021-10-19T21:08:46.781Z] 21:08:46     INFO -     rbx = 0x00007f91846ac180   rbp = 0x00007ffd2370f6e0
[task 2021-10-19T21:08:46.781Z] 21:08:46     INFO -     rsp = 0x00007ffd2370f6e0   r12 = 0x00007f91788c6a40
[task 2021-10-19T21:08:46.781Z] 21:08:46     INFO -     r13 = 0x0000000000000009   r14 = 0x00007f91846ac180
[task 2021-10-19T21:08:46.782Z] 21:08:46     INFO -     r15 = 0x0000000000000000   rip = 0x00007f918891a660
[task 2021-10-19T21:08:46.782Z] 21:08:46     INFO -     Found by: call frame info
[task 2021-10-19T21:08:46.782Z] 21:08:46     INFO -  3  libxul.so!NS_InvokeByIndex + 0x8e
[task 2021-10-19T21:08:46.782Z] 21:08:46     INFO -     rbx = 0x00007f91846ac180   rbp = 0x00007ffd2370f710
[task 2021-10-19T21:08:46.782Z] 21:08:46     INFO -     rsp = 0x00007ffd2370f6f0   r12 = 0x00007f91788c6a40
[task 2021-10-19T21:08:46.783Z] 21:08:46     INFO -     r13 = 0x0000000000000009   r14 = 0x00007f91846ac180
[task 2021-10-19T21:08:46.783Z] 21:08:46     INFO -     r15 = 0x0000000000000000   rip = 0x00007f9188af4aa2
[task 2021-10-19T21:08:46.783Z] 21:08:46     INFO -     Found by: call frame info
[task 2021-10-19T21:08:46.783Z] 21:08:46     INFO -  4  libxul.so!XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [XPCWrappedNative.cpp:071e79ac291629df585272854d70a2b1d47a77ab : 1130 + 0x2327]
[task 2021-10-19T21:08:46.783Z] 21:08:46     INFO -     rbx = 0x00007f91846ac180   rbp = 0x00007ffd2370f940
[task 2021-10-19T21:08:46.784Z] 21:08:46     INFO -     rsp = 0x00007ffd2370f720   r12 = 0x0000000000036f2c
[task 2021-10-19T21:08:46.784Z] 21:08:46     INFO -     r13 = 0x0000000000000002   r14 = 0x00007f91846ac180
[task 2021-10-19T21:08:46.784Z] 21:08:46     INFO -     r15 = 0x0000000000000000   rip = 0x00007f9189e64102
[task 2021-10-19T21:08:46.784Z] 21:08:46     INFO -     Found by: call frame info
[task 2021-10-19T21:08:46.784Z] 21:08:46     INFO -  5  libxul.so!XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [XPCWrappedNativeJSOps.cpp:071e79ac291629df585272854d70a2b1d47a77ab : 921 + 0x8]
[task 2021-10-19T21:08:46.785Z] 21:08:46     INFO -     rbx = 0x00007f915c3cddf8   rbp = 0x00007ffd2370fa70
[task 2021-10-19T21:08:46.785Z] 21:08:46     INFO -     rsp = 0x00007ffd2370f950   r12 = 0x00007f9194d18c08
[task 2021-10-19T21:08:46.785Z] 21:08:46     INFO -     r13 = 0x0000123aabd6a060   r14 = 0x00007ffd2370f9a8
[task 2021-10-19T21:08:46.785Z] 21:08:46     INFO -     r15 = 0x00007f9178915100   rip = 0x00007f9189e670fb
[task 2021-10-19T21:08:46.785Z] 21:08:46     INFO -     Found by: call frame info

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

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.