Closed Bug 1441745 Opened 7 years ago Closed 7 years ago

Intermittent docshell/test/test_bug384014.html | Test timed out.

Categories

(Core :: DOM: Navigation, defect, P5)

Product:
Core
Component:
DOM: Navigation
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=164655339&repo=mozilla-beta https://queue.taskcluster.net/v1/task/Vhp4hq_DSoe29VlE15OB8A/runs/0/artifacts/public/logs/live_backing.log [task 2018-02-27T17:55:22.608Z] 17:55:22 INFO - TEST-START | docshell/test/test_bug384014.html [task 2018-02-27T17:55:22.693Z] 17:55:22 INFO - GECKO(3144) | Sandbox: Unexpected EOF, op 0 flags 00 path /proc/3197/statm [task 2018-02-27T17:55:22.695Z] 17:55:22 INFO - GECKO(3144) | JavaScript error: chrome://specialpowers/content/specialpowersAPI.js, line 232: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIMemoryReporterManager.residentFast] [task 2018-02-27T18:00:47.027Z] 18:00:47 INFO - TEST-INFO | started process screentopng [task 2018-02-27T18:00:47.305Z] 18:00:47 INFO - TEST-INFO | screentopng: exit 0 [task 2018-02-27T18:00:47.306Z] 18:00:47 INFO - Buffered messages logged at 17:55:22 [task 2018-02-27T18:00:47.307Z] 18:00:47 INFO - TEST-PASS | docshell/test/test_bug384014.html | We fail [task 2018-02-27T18:00:47.307Z] 18:00:47 INFO - Buffered messages finished [task 2018-02-27T18:00:47.308Z] 18:00:47 INFO - TEST-UNEXPECTED-FAIL | docshell/test/test_bug384014.html | Test timed out. [task 2018-02-27T18:00:47.308Z] 18:00:47 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-27T18:00:47.308Z] 18:00:47 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 [task 2018-02-27T18:00:48.029Z] 18:00:48 ERROR - [SimpleTest.finish()] this test already called finish! [task 2018-02-27T18:00:48.030Z] 18:00:48 INFO - TEST-UNEXPECTED-ERROR | docshell/test/test_bug384014.html | called finish() multiple times [task 2018-02-27T18:00:48.031Z] 18:00:48 INFO - TEST-INFO took 325422ms [task 2018-02-27T18:01:17.031Z] 18:01:17 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:01:17.032Z] 18:01:17 INFO - TEST-UNEXPECTED-FAIL | docshell/test/test_bug384014.html | Test timed out. [task 2018-02-27T18:01:17.033Z] 18:01:17 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-27T18:01:17.033Z] 18:01:17 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 [task 2018-02-27T18:01:18.038Z] 18:01:18 ERROR - [SimpleTest.finish()] this test already called finish! [task 2018-02-27T18:01:18.039Z] 18:01:18 INFO - TEST-UNEXPECTED-ERROR | docshell/test/test_bug384014.html | called finish() multiple times [task 2018-02-27T18:01:18.039Z] 18:01:18 INFO - TEST-INFO [task 2018-02-27T18:01:47.034Z] 18:01:47 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:01:47.035Z] 18:01:47 INFO - TEST-UNEXPECTED-FAIL | docshell/test/test_bug384014.html | Test timed out. [task 2018-02-27T18:01:47.035Z] 18:01:47 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-27T18:01:47.036Z] 18:01:47 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 [task 2018-02-27T18:01:48.040Z] 18:01:48 ERROR - [SimpleTest.finish()] this test already called finish! [task 2018-02-27T18:01:48.041Z] 18:01:48 INFO - TEST-UNEXPECTED-ERROR | docshell/test/test_bug384014.html | called finish() multiple times [task 2018-02-27T18:01:48.042Z] 18:01:48 INFO - TEST-INFO [task 2018-02-27T18:02:17.034Z] 18:02:17 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:02:17.035Z] 18:02:17 INFO - TEST-UNEXPECTED-FAIL | docshell/test/test_bug384014.html | Test timed out. [task 2018-02-27T18:02:17.035Z] 18:02:17 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-27T18:02:17.036Z] 18:02:17 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7 [task 2018-02-27T18:02:17.037Z] 18:02:17 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:02:17.037Z] 18:02:17 INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. [task 2018-02-27T18:02:17.038Z] 18:02:17 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-27T18:02:17.038Z] 18:02:17 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:150:9 [task 2018-02-27T18:02:17.039Z] 18:02:17 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:02:17.039Z] 18:02:17 INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 38 remaining tests. [task 2018-02-27T18:02:17.039Z] 18:02:17 INFO - reportError@SimpleTest/TestRunner.js:121:7 [task 2018-02-27T18:02:17.039Z] 18:02:17 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:152:9 [task 2018-02-27T18:02:18.043Z] 18:02:18 ERROR - [SimpleTest.finish()] this test already called finish! [task 2018-02-27T18:02:18.044Z] 18:02:18 INFO - TEST-UNEXPECTED-ERROR | (SimpleTest/TestRunner.js) | called finish() multiple times [task 2018-02-27T18:02:18.045Z] 18:02:18 INFO - TEST-INFO [task 2018-02-27T18:08:28.052Z] 18:08:28 INFO - Buffered messages finished [task 2018-02-27T18:08:28.054Z] 18:08:28 ERROR - TEST-UNEXPECTED-TIMEOUT | docshell/test/test_bug384014.html | application timed out after 370 seconds with no output [task 2018-02-27T18:08:28.056Z] 18:08:28 ERROR - Force-terminating active process(es). [task 2018-02-27T18:08:28.058Z] 18:08:28 INFO - Determining child pids from psutil... [task 2018-02-27T18:08:28.064Z] 18:08:28 INFO - [3197, 3247] [task 2018-02-27T18:08:28.066Z] 18:08:28 INFO - ==> process 3144 launched child process 3167 [task 2018-02-27T18:08:28.068Z] 18:08:28 INFO - ==> process 3144 launched child process 3197 [task 2018-02-27T18:08:28.069Z] 18:08:28 INFO - ==> process 3144 launched child process 3247 [task 2018-02-27T18:08:28.070Z] 18:08:28 INFO - Found child pids: set([3167, 3197, 3247]) [task 2018-02-27T18:08:28.071Z] 18:08:28 INFO - Failed to get child procs [task 2018-02-27T18:08:28.072Z] 18:08:28 INFO - Killing process: 3167 [task 2018-02-27T18:08:28.074Z] 18:08:28 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:08:28.075Z] 18:08:28 INFO - Can't trigger Breakpad, process no longer exists [task 2018-02-27T18:08:28.076Z] 18:08:28 INFO - Killing process: 3197 [task 2018-02-27T18:08:28.077Z] 18:08:28 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:08:28.079Z] 18:08:28 INFO - Killing process: 3247 [task 2018-02-27T18:08:28.080Z] 18:08:28 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:08:28.081Z] 18:08:28 INFO - Killing process: 3144 [task 2018-02-27T18:08:28.082Z] 18:08:28 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-02-27T18:08:28.213Z] 18:08:28 INFO - psutil found pid 3144 dead [task 2018-02-27T18:08:28.424Z] 18:08:28 WARNING - runtests.py | Failed to get app exit code - running/crashed? [task 2018-02-27T18:08:28.425Z] 18:08:28 INFO - TEST-INFO | Main app process: exit 0 [task 2018-02-27T18:08:28.426Z] 18:08:28 INFO - runtests.py | Application ran for: 0:13:14.491488 [task 2018-02-27T18:08:28.426Z] 18:08:28 INFO - zombiecheck | Reading PID log: /tmp/tmpWPtInUpidlog [task 2018-02-27T18:08:28.427Z] 18:08:28 INFO - ==> process 3144 launched child process 3167 [task 2018-02-27T18:08:28.428Z] 18:08:28 INFO - ==> process 3144 launched child process 3197 [task 2018-02-27T18:08:28.428Z] 18:08:28 INFO - ==> process 3144 launched child process 3247 [task 2018-02-27T18:08:28.429Z] 18:08:28 INFO - zombiecheck | Checking for orphan process with PID: 3247 [task 2018-02-27T18:08:28.429Z] 18:08:28 INFO - zombiecheck | Checking for orphan process with PID: 3197 [task 2018-02-27T18:08:28.429Z] 18:08:28 INFO - zombiecheck | Checking for orphan process with PID: 3167 [task 2018-02-27T18:08:28.431Z] 18:08:28 INFO - mozcrash Downloading symbols from: https://queue.taskcluster.net/v1/task/MjUvKxfwQI2D7izHbyN9Cg/artifacts/public/build/target.crashreporter-symbols.zip [task 2018-02-27T18:08:33.595Z] 18:08:33 INFO - mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmp_9S0yn.mozrunner/minidumps/43621938-ee39-7ac9-1ffb-8f6006c6941d.dmp /tmp/tmpUklti_ [task 2018-02-27T18:08:39.811Z] 18:08:39 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/43621938-ee39-7ac9-1ffb-8f6006c6941d.dmp [task 2018-02-27T18:08:39.812Z] 18:08:39 INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/43621938-ee39-7ac9-1ffb-8f6006c6941d.extra [task 2018-02-27T18:08:39.878Z] 18:08:39 INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ libc-2.23.so + 0xfb74d] [task 2018-02-27T18:08:39.878Z] 18:08:39 INFO - Crash dump filename: /tmp/tmp_9S0yn.mozrunner/minidumps/43621938-ee39-7ac9-1ffb-8f6006c6941d.dmp [task 2018-02-27T18:08:39.879Z] 18:08:39 INFO - Operating system: Linux [task 2018-02-27T18:08:39.880Z] 18:08:39 INFO - 0.0.0 Linux 4.4.0-98-generic #121~14.04.1-Ubuntu SMP Wed Oct 11 11:54:55 UTC 2017 x86_64 [task 2018-02-27T18:08:39.880Z] 18:08:39 INFO - CPU: amd64 [task 2018-02-27T18:08:39.881Z] 18:08:39 INFO - family 6 model 62 stepping 4 [task 2018-02-27T18:08:39.881Z] 18:08:39 INFO - 2 CPUs [task 2018-02-27T18:08:39.882Z] 18:08:39 INFO - [task 2018-02-27T18:08:39.883Z] 18:08:39 INFO - GPU: UNKNOWN [task 2018-02-27T18:08:39.883Z] 18:08:39 INFO - [task 2018-02-27T18:08:39.884Z] 18:08:39 INFO - Crash reason: SIGABRT [task 2018-02-27T18:08:39.885Z] 18:08:39 INFO - Crash address: 0x3e8000003ea [task 2018-02-27T18:08:39.885Z] 18:08:39 INFO - Process uptime: not available [task 2018-02-27T18:08:39.886Z] 18:08:39 INFO - [task 2018-02-27T18:08:39.886Z] 18:08:39 INFO - Thread 0 (crashed) [task 2018-02-27T18:08:39.887Z] 18:08:39 INFO - 0 libc-2.23.so + 0xfb74d [task 2018-02-27T18:08:39.888Z] 18:08:39 INFO - rax = 0xfffffffffffffffc rdx = 0x00000000ffffffff [task 2018-02-27T18:08:39.888Z] 18:08:39 INFO - rcx = 0x00007ff0a19e974d rbx = 0x00007ff073a93100 [task 2018-02-27T18:08:39.889Z] 18:08:39 INFO - rsi = 0x0000000000000005 rdi = 0x00007ff073a93100 [task 2018-02-27T18:08:39.889Z] 18:08:39 INFO - rbp = 0x0000000000000005 rsp = 0x00007ffff9ac93b0 [task 2018-02-27T18:08:39.890Z] 18:08:39 INFO - r8 = 0x0000000000000005 r9 = 0x0000000000000001 [task 2018-02-27T18:08:39.890Z] 18:08:39 INFO - r10 = 0x00007ff074e06cc0 r11 = 0x0000000000000293 [task 2018-02-27T18:08:39.891Z] 18:08:39 INFO - r12 = 0x00000000ffffffff r13 = 0x00000000ffffffff [task 2018-02-27T18:08:39.891Z] 18:08:39 INFO - r14 = 0x00007ff0941f02f0 r15 = 0x0000000000000005 [task 2018-02-27T18:08:39.891Z] 18:08:39 INFO - rip = 0x00007ff0a19e974d [task 2018-02-27T18:08:39.892Z] 18:08:39 INFO - Found by: given as instruction pointer in context [task 2018-02-27T18:08:39.892Z] 18:08:39 INFO - 1 libxul.so!PollWrapper [nsAppShell.cpp:2cd2df314044 : 53 + 0xe] [task 2018-02-27T18:08:39.892Z] 18:08:39 INFO - rsp = 0x00007ffff9ac93c0 rip = 0x00007ff0941f0314 [task 2018-02-27T18:08:39.892Z] 18:08:39 INFO - Found by: stack scanning [task 2018-02-27T18:08:39.893Z] 18:08:39 INFO - 2 libglib-2.0.so.0.4800.2 + 0x4a38c [task 2018-02-27T18:08:39.893Z] 18:08:39 INFO - rbx = 0x00007ff0a16ea190 rbp = 0x0000000000000005 [task 2018-02-27T18:08:39.894Z] 18:08:39 INFO - rsp = 0x00007ffff9ac93e0 r12 = 0x00007ff073a93100 [task 2018-02-27T18:08:39.895Z] 18:08:39 INFO - rip = 0x00007ff09c77538c [task 2018-02-27T18:08:39.895Z] 18:08:39 INFO - Found by: call frame info [task 2018-02-27T18:08:39.896Z] 18:08:39 INFO - 3 libglib-2.0.so.0.4800.2 + 0x4a49c [task 2018-02-27T18:08:39.896Z] 18:08:39 INFO - rsp = 0x00007ffff9ac9440 rip = 0x00007ff09c77549c [task 2018-02-27T18:08:39.897Z] 18:08:39 INFO - Found by: stack scanning [task 2018-02-27T18:08:39.897Z] 18:08:39 INFO - 4 libxul.so!nsAppShell::ProcessNextNativeEvent [nsAppShell.cpp:2cd2df314044 : 295 + 0xb] [task 2018-02-27T18:08:39.898Z] 18:08:39 INFO - rsp = 0x00007ffff9ac9460 rip = 0x00007ff0941f02df [task 2018-02-27T18:08:39.898Z] 18:08:39 INFO - Found by: stack scanning [task 2018-02-27T18:08:39.899Z] 18:08:39 INFO - 5 libxul.so!nsBaseAppShell::OnProcessNextEvent(nsIThreadInternal*, bool) + 0x136 [task 2018-02-27T18:08:39.899Z] 18:08:39 INFO - rsp = 0x00007ffff9ac9470 rip = 0x00007ff0941edb56 [task 2018-02-27T18:08:39.900Z] 18:08:39 INFO - Found by: call frame info [task 2018-02-27T18:08:39.900Z] 18:08:39 INFO - 6 libxul.so!nsThread::ProcessNextEvent(bool, bool*) + 0x137 [task 2018-02-27T18:08:39.901Z] 18:08:39 INFO - rbx = 0x00007ff0a16487a0 rbp = 0x00007ff088f8f648 [task 2018-02-27T18:08:39.901Z] 18:08:39 INFO - rsp = 0x00007ffff9ac94d0 r12 = 0x0000000000000001 [task 2018-02-27T18:08:39.902Z] 18:08:39 INFO - r13 = 0x00007ff08fcecc00 r14 = 0x00007ffff9ac94f0 [task 2018-02-27T18:08:39.903Z] 18:08:39 INFO - r15 = 0x00007ffff9ac95df rip = 0x00007ff093fd34c7 [task 2018-02-27T18:08:39.903Z] 18:08:39 INFO - Found by: call frame info [task 2018-02-27T18:08:39.904Z] 18:08:39 INFO - 7 libxul.so!NS_ProcessNextEvent [nsThreadUtils.cpp:2cd2df314044 : 517 + 0xf] [task 2018-02-27T18:08:39.904Z] 18:08:39 INFO - rbx = 0x00007ff08fc0aec0 rbp = 0x00007ff0a16855d0 [task 2018-02-27T18:08:39.905Z] 18:08:39 INFO - rsp = 0x00007ffff9ac95c0 r12 = 0x00007ff0a16487a0 [task 2018-02-27T18:08:39.905Z] 18:08:39 INFO - r13 = 0x00007ff08fc0aee0 r14 = 0x00007ff093fd9340 [task 2018-02-27T18:08:39.906Z] 18:08:39 INFO - r15 = 0x00007ff0964aa8c8 rip = 0x00007ff093fd7428 [task 2018-02-27T18:08:39.907Z] 18:08:39 INFO - Found by: call frame info [task 2018-02-27T18:08:39.907Z] 18:08:39 INFO - 8 libxul.so!mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) + 0xf8 [task 2018-02-27T18:08:39.908Z] 18:08:39 INFO - rbx = 0x00007ff08fc0aec0 rbp = 0x00007ff0a16855d0 [task 2018-02-27T18:08:39.908Z] 18:08:39 INFO - rsp = 0x00007ffff9ac95f0 r12 = 0x00007ff0a16487a0 [task 2018-02-27T18:08:39.909Z] 18:08:39 INFO - r13 = 0x00007ff08fc0aee0 r14 = 0x00007ff093fd9340 [task 2018-02-27T18:08:39.909Z] 18:08:39 INFO - r15 = 0x00007ff0964aa8c8 rip = 0x00007ff09402f8c8 [task 2018-02-27T18:08:39.910Z] 18:08:39 INFO - Found by: call frame info [task 2018-02-27T18:08:39.910Z] 18:08:39 INFO - 9 libxul.so!MessageLoop::Run() + 0x42 [task 2018-02-27T18:08:39.910Z] 18:08:39 INFO - rbx = 0x00007ff088f8f640 rbp = 0x00007ff0a16487a0 [task 2018-02-27T18:08:39.911Z] 18:08:39 INFO - rsp = 0x00007ffff9ac9640 r12 = 0x00007ff096748140 [task 2018-02-27T18:08:39.911Z] 18:08:39 INFO - r13 = 0x0000000000000077 r14 = 0x00007ffff9ac9700 [task 2018-02-27T18:08:39.911Z] 18:08:39 INFO - r15 = 0x00007ff09673e848 rip = 0x00007ff0947bfcb2 [task 2018-02-27T18:08:39.911Z] 18:08:39 INFO - Found by: call frame info [task 2018-02-27T18:08:39.912Z] 18:08:39 INFO - 10 libxul.so!nsBaseAppShell::Run [nsBaseAppShell.cpp:2cd2df314044 : 157 + 0xd] [task 2018-02-27T18:08:39.912Z] 18:08:39 INFO - rbx = 0x00007ff088f8f640 rbp = 0x00007ff0a16487a0 [task 2018-02-27T18:08:39.913Z] 18:08:39 INFO - rsp = 0x00007ffff9ac9670 r12 = 0x00007ff096748140 [task 2018-02-27T18:08:39.913Z] 18:08:39 INFO - r13 = 0x0000000000000077 r14 = 0x00007ffff9ac9700 [task 2018-02-27T18:08:39.913Z] 18:08:39 INFO - r15 = 0x00007ff09673e848 rip = 0x00007ff0949ec158 [task 2018-02-27T18:08:39.914Z] 18:08:39 INFO - Found by: call frame info
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.