Closed Bug 1471071 Opened 7 years ago Closed 7 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | dom/animation/test/style/test_transform-non-normalizable-rotate3d.html | application timed out after 370 seconds with no output

Categories

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

Product:
Core
Component:
DOM: Animation
Type:
defect

Tracking

()

Status:
RESOLVED INVALID

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: csabou [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=184799573&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/L54hSi5yQeKPvwueSw9b_g/runs/0/artifacts/public/logs/live_backing.log [task 2018-06-25T21:40:47.271Z] 21:40:47 ERROR - TEST-UNEXPECTED-TIMEOUT | dom/animation/test/style/test_transform-non-normalizable-rotate3d.html | application timed out after 370 seconds with no output [task 2018-06-25T21:40:47.274Z] 21:40:47 ERROR - Force-terminating active process(es). [task 2018-06-25T21:40:47.276Z] 21:40:47 INFO - Determining child pids from psutil... [task 2018-06-25T21:40:47.278Z] 21:40:47 INFO - [] [task 2018-06-25T21:40:47.280Z] 21:40:47 INFO - ==> process 1029 launched child process 1047 [task 2018-06-25T21:40:47.282Z] 21:40:47 INFO - ==> process 1029 launched child process 1074 [task 2018-06-25T21:40:47.284Z] 21:40:47 INFO - ==> process 1029 launched child process 1115 [task 2018-06-25T21:40:47.289Z] 21:40:47 INFO - Found child pids: set([1074, 1115, 1047]) [task 2018-06-25T21:40:47.290Z] 21:40:47 INFO - Failed to get child procs [task 2018-06-25T21:40:47.291Z] 21:40:47 INFO - Killing process: 1074 [task 2018-06-25T21:40:47.292Z] 21:40:47 INFO - TEST-INFO | started process screentopng [task 2018-06-25T21:40:47.952Z] 21:40:47 INFO - TEST-INFO | screentopng: exit 0 [task 2018-06-25T21:40:47.952Z] 21:40:47 INFO - Can't trigger Breakpad, just killing process [task 2018-06-25T21:40:47.952Z] 21:40:47 INFO - Error: Failed to kill process 1074: psutil.NoSuchProcess no process found with pid 1074 [task 2018-06-25T21:40:47.952Z] 21:40:47 INFO - Killing process: 1115 [task 2018-06-25T21:40:47.954Z] 21:40:47 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-06-25T21:40:47.955Z] 21:40:47 INFO - Can't trigger Breakpad, just killing process [task 2018-06-25T21:40:47.955Z] 21:40:47 INFO - Error: Failed to kill process 1115: psutil.NoSuchProcess no process found with pid 1115 [task 2018-06-25T21:40:47.956Z] 21:40:47 INFO - Killing process: 1047 [task 2018-06-25T21:40:47.956Z] 21:40:47 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-06-25T21:40:47.956Z] 21:40:47 INFO - Can't trigger Breakpad, just killing process [task 2018-06-25T21:41:17.990Z] 21:41:17 INFO - failed to kill pid 1047 after 30s [task 2018-06-25T21:41:17.991Z] 21:41:17 INFO - Killing process: 1029 [task 2018-06-25T21:41:17.991Z] 21:41:17 INFO - Not taking screenshot here: see the one that was previously logged [task 2018-06-25T21:41:17.991Z] 21:41:17 INFO - Can't trigger Breakpad, just killing process [task 2018-06-25T21:41:17.998Z] 21:41:17 INFO - psutil found pid 1029 dead [task 2018-06-25T21:41:17.999Z] 21:41:17 INFO - psutil found pid 1029 dead [task 2018-06-25T21:41:18.033Z] 21:41:18 WARNING - runtests.py | Failed to get app exit code - running/crashed? [task 2018-06-25T21:41:18.034Z] 21:41:18 INFO - TEST-INFO | Main app process: exit 0 [task 2018-06-25T21:41:18.035Z] 21:41:18 INFO - runtests.py | Application ran for: 0:07:33.836985 [task 2018-06-25T21:41:18.037Z] 21:41:18 INFO - zombiecheck | Reading PID log: /tmp/tmpDRsAnmpidlog [task 2018-06-25T21:41:18.038Z] 21:41:18 INFO - ==> process 1029 launched child process 1047 [task 2018-06-25T21:41:18.039Z] 21:41:18 INFO - ==> process 1029 launched child process 1074 [task 2018-06-25T21:41:18.040Z] 21:41:18 INFO - ==> process 1029 launched child process 1115 [task 2018-06-25T21:41:18.041Z] 21:41:18 INFO - zombiecheck | Checking for orphan process with PID: 1074 [task 2018-06-25T21:41:18.043Z] 21:41:18 INFO - zombiecheck | Checking for orphan process with PID: 1115 [task 2018-06-25T21:41:18.044Z] 21:41:18 INFO - zombiecheck | Checking for orphan process with PID: 1047 [task 2018-06-25T21:41:18.045Z] 21:41:18 INFO - Stopping web server [task 2018-06-25T21:41:18.066Z] 21:41:18 INFO - Stopping web socket server [task 2018-06-25T21:41:18.084Z] 21:41:18 INFO - Stopping ssltunnel [task 2018-06-25T21:41:18.101Z] 21:41:18 WARNING - leakcheck | refcount logging is off, so leaks can't be detected! [task 2018-06-25T21:41:18.102Z] 21:41:18 INFO - runtests.py | Running tests: end. [task 2018-06-25T21:41:18.119Z] 21:41:18 INFO - Buffered messages finished [task 2018-06-25T21:41:18.120Z] 21:41:18 INFO - Running manifest: dom/asmjscache/test/mochitest.ini [task 2018-06-25T21:41:18.158Z] 21:41:18 INFO - Setting pipeline to PAUSED ... [task 2018-06-25T21:41:18.159Z] 21:41:18 INFO - Pipeline is PREROLLING ... [task 2018-06-25T21:41:18.159Z] 21:41:18 INFO - Pipeline is PREROLLED ... [task 2018-06-25T21:41:18.159Z] 21:41:18 INFO - Setting pipeline to PLAYING ... [task 2018-06-25T21:41:18.160Z] 21:41:18 INFO - New clock: GstSystemClock [task 2018-06-25T21:41:18.197Z] 21:41:18 INFO - Got EOS from element "pipeline0". [task 2018-06-25T21:41:18.197Z] 21:41:18 INFO - Execution ended after 0:00:00.033493425 [task 2018-06-25T21:41:18.199Z] 21:41:18 INFO - Setting pipeline to PAUSED ... [task 2018-06-25T21:41:18.199Z] 21:41:18 INFO - Setting pipeline to READY ... [task 2018-06-25T21:41:18.200Z] 21:41:18 INFO - (gst-launch-1.0:1159): GStreamer-CRITICAL **: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed [task 2018-06-25T21:41:18.200Z] 21:41:18 INFO - Setting pipeline to NULL ... [task 2018-06-25T21:41:18.201Z] 21:41:18 INFO - Freeing pipeline ... [task 2018-06-25T21:41:18.237Z] 21:41:18 INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer [task 2018-06-25T21:41:18.244Z] 21:41:18 INFO - INFO | runtests.py | ASan running in default memory configuration [task 2018-06-25T21:41:18.520Z] 21:41:18 INFO - pk12util: PKCS12 IMPORT SUCCESSFUL [task 2018-06-25T21:41:18.657Z] 21:41:18 INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer [task 2018-06-25T21:41:18.661Z] 21:41:18 INFO - LSan enabled. [task 2018-06-25T21:41:18.662Z] 21:41:18 INFO - LSan using suppression file /builds/worker/workspace/build/tests/mochitest/lsan_suppressions.txt [task 2018-06-25T21:41:18.664Z] 21:41:18 INFO - INFO | runtests.py | ASan running in default memory configuration [task 2018-06-25T21:41:18.665Z] 21:41:18 INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer [task 2018-06-25T21:41:18.673Z] 21:41:18 INFO - INFO | runtests.py | ASan running in default memory configuration [task 2018-06-25T21:41:18.682Z] 21:41:18 INFO - MochitestServer : launching [u'/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-f', '/builds/worker/workspace/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmprO30BS.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js'] [task 2018-06-25T21:41:18.682Z] 21:41:18 INFO - runtests.py | Server pid: 1188 [task 2018-06-25T21:41:18.706Z] 21:41:18 INFO - runtests.py | Websocket server pid: 1191 [task 2018-06-25T21:41:18.708Z] 21:41:18 INFO - INFO | runtests.py | ASan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer [task 2018-06-25T21:41:18.730Z] 21:41:18 INFO - INFO | runtests.py | ASan running in default memory configuration [task 2018-06-25T21:41:18.758Z] 21:41:18 INFO - runtests.py | SSL tunnel pid: 1196 [task 2018-06-25T21:41:19.159Z] 21:41:19 INFO - runtests.py | Running with e10s: True [task 2018-06-25T21:41:19.159Z] 21:41:19 INFO - runtests.py | Running tests: start. [task 2018-06-25T21:41:19.159Z] 21:41:19 INFO - [task 2018-06-25T21:41:19.184Z] 21:41:19 WARNING - Found 'firefox' running before starting test browser! [task 2018-06-25T21:41:19.184Z] 21:41:19 WARNING - {'username': 'worker', 'cmdline': [], 'ppid': 1, 'pid': 1047, 'name': 'firefox'} [task 2018-06-25T21:41:19.184Z] 21:41:19 WARNING - [task 2018-06-25T21:41:19.188Z] 21:41:19 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmprO30BS.mozrunner [task 2018-06-25T21:41:19.209Z] 21:41:19 INFO - runtests.py | Application pid: 1212 [task 2018-06-25T21:41:19.209Z] 21:41:19 INFO - TEST-INFO | started process GECKO(1212) [task 2018-06-25T21:41:21.384Z] 21:41:21 INFO - GECKO(1212) | 1529962881381 Marionette DEBUG Received observer notification profile-after-change [task 2018-06-25T21:41:21.543Z] 21:41:21 INFO - GECKO(1212) | 1529962881536 Marionette DEBUG Received observer notification command-line-startup [task 2018-06-25T21:41:21.543Z] 21:41:21 INFO - GECKO(1212) | 1529962881536 Marionette DEBUG Received observer notification nsPref:changed [task 2018-06-25T21:41:21.543Z] 21:41:21 INFO - GECKO(1212) | 1529962881537 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false) [task 2018-06-25T21:41:24.667Z] 21:41:24 INFO - GECKO(1212) | 1529962884661 Marionette DEBUG Received observer notification sessionstore-windows-restored [task 2018-06-25T21:41:24.667Z] 21:41:24 INFO - GECKO(1212) | 1529962884662 Marionette DEBUG Waiting for delayed startup... [task 2018-06-25T21:41:26.064Z] 21:41:26 INFO - GECKO(1212) | 1529962886052 Marionette DEBUG Waiting for startup tests... [task 2018-06-25T21:41:26.424Z] 21:41:26 INFO - GECKO(1212) | 1529962886418 Marionette INFO Listening on port 2828 [task 2018-06-25T21:41:26.425Z] 21:41:26 INFO - GECKO(1212) | 1529962886419 Marionette DEBUG Remote service is active [task 2018-06-25T21:41:26.466Z] 21:41:26 INFO - GECKO(1212) | 1529962886459 Marionette DEBUG Accepted connection 0 from 127.0.0.1:42724 [task 2018-06-25T21:41:26.483Z] 21:41:26 INFO - GECKO(1212) | 1529962886469 Marionette DEBUG Accepted connection 1 from 127.0.0.1:42726 [task 2018-06-25T21:41:26.483Z] 21:41:26 INFO - GECKO(1212) | 1529962886472 Marionette DEBUG Closed connection 0 [task 2018-06-25T21:41:26.499Z] 21:41:26 INFO - GECKO(1212) | 1529962886490 Marionette TRACE 1 -> [0,1,"WebDriver:NewSession",{}] [task 2018-06-25T21:41:26.945Z] 21:41:26 INFO - GECKO(1212) | 1529962886938 Marionette DEBUG [2147483649] Frame script loaded [task 2018-06-25T21:41:26.969Z] 21:41:26 INFO - GECKO(1212) | 1529962886964 Marionette DEBUG [2147483649] Frame script registered [task 2018-06-25T21:41:26.989Z] 21:41:26 INFO - GECKO(1212) | 1529962886986 Marionette TRACE 1 <- [1,1,null,{"sessionId":"8cac9860-672f-44c8-8eab-e373bde660b5","capabilities":{"browserName":"firefox","browserVersion":"63.0a ... ssID":1212,"moz:profile":"/tmp/tmprO30BS.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-06-25T21:41:27.071Z] 21:41:27 INFO - GECKO(1212) | 1529962887067 Marionette TRACE 1 -> [0,2,"Addon:Install",{"path":"/tmp/tmpdSGHWS.zip","temporary":false}] [task 2018-06-25T21:41:27.302Z] 21:41:27 INFO - GECKO(1212) | 1529962887297 Marionette TRACE 1 <- [1,2,null,{"value":"special-powers@mozilla.org"}] [task 2018-06-25T21:41:27.363Z] 21:41:27 INFO - GECKO(1212) | 1529962887358 Marionette TRACE 1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpIopukz.zip","temporary":false}] [task 2018-06-25T21:41:27.502Z] 21:41:27 INFO - GECKO(1212) | 1529962887490 Marionette TRACE 1 <- [1,3,null,{"value":"mochikit@mozilla.org"}] [task 2018-06-25T21:41:27.519Z] 21:41:27 INFO - GECKO(1212) | 1529962887509 Marionette TRACE 1 -> [0,4,"Marionette:GetContext",{}] [task 2018-06-25T21:41:27.519Z] 21:41:27 INFO - GECKO(1212) | 1529962887510 Marionette TRACE 1 <- [1,4,null,{"value":"content"}] [task 2018-06-25T21:41:27.525Z] 21:41:27 INFO - GECKO(1212) | 1529962887518 Marionette TRACE 1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}] [task 2018-06-25T21:41:27.526Z] 21:41:27 INFO - GECKO(1212) | 1529962887521 Marionette TRACE 1 <- [1,5,null,{"value":null}] [task 2018-06-25T21:41:27.535Z] 21:41:27 INFO - GECKO(1212) | 1529962887528 Marionette TRACE 1 -> [0,6,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[{"testUrl":"http://mochi.test:8888/tests?autor ... new CustomEvent(\"mochitest-load\", {\"detail\": [flavor, url]});\nwin.dispatchEvent(ev);","sandbox":"default","line":1754}] [task 2018-06-25T21:41:27.558Z] 21:41:27 INFO - GECKO(1212) | 1529962887552 Marionette TRACE 1 <- [1,6,null,{"value":null}] [task 2018-06-25T21:41:27.562Z] 21:41:27 INFO - GECKO(1212) | 1529962887556 Marionette TRACE 1 -> [0,7,"Marionette:SetContext",{"value":"content"}] [task 2018-06-25T21:41:27.564Z] 21:41:27 INFO - GECKO(1212) | 1529962887558 Marionette TRACE 1 <- [1,7,null,{"value":null}] [task 2018-06-25T21:41:27.622Z] 21:41:27 INFO - GECKO(1212) | 1529962887613 Marionette TRACE 1 -> [0,8,"WebDriver:DeleteSession",{}] [task 2018-06-25T21:41:27.627Z] 21:41:27 INFO - GECKO(1212) | 1529962887621 Marionette TRACE 1 <- [1,8,null,{"value":null}] [task 2018-06-25T21:41:27.645Z] 21:41:27 INFO - runtests.py | Waiting for browser...
This seems weird. From the log, https://treeherder.mozilla.org/logviewer.html#?job_id=184799573&repo=mozilla-inbound&lineNumber=1564 [task 2018-06-25T21:34:31.972Z] 21:34:31 INFO - GECKO(1029) | MEMORY STAT | vsize 20973499MB | residentFast 776MB [task 2018-06-25T21:34:31.988Z] 21:34:31 INFO - TEST-OK | dom/animation/test/style/test_transform-non-normalizable-rotate3d.html | took 298ms [task 2018-06-25T21:34:32.068Z] 21:34:32 INFO - TEST-START | Shutdown The test cases finished there.
This fail was fixed by this backout: https://hg.mozilla.org/integration/mozilla-inbound/rev/c38b3264ab366874c4280038b5eb24ab4e3a9848
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.