Closed
Bug 1713616
Opened 4 years ago
Closed 4 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | dom/base/test/meta_viewport/test_meta_viewport_device_width_with_initial_scale_2.html | application timed out after 370 seconds with no output
Categories
(Core :: DOM: Core & HTML, defect, P5)
Core
DOM: Core & HTML
Tracking
()
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=341266906&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FHMwXUA-RRy7iAswIUIm4A/runs/0/artifacts/public/logs/live_backing.log
[task 2021-05-31T11:59:39.241Z] 11:59:39 INFO - TEST-OK | dom/base/test/meta_viewport/test_meta_viewport_device_width_with_initial_scale_0_5.html | took 775ms
[task 2021-05-31T11:59:39.686Z] 11:59:39 INFO - TEST-START | dom/base/test/meta_viewport/test_meta_viewport_device_width_with_initial_scale_2.html
[task 2021-05-31T12:05:15.714Z] 12:05:15 INFO - GECKO(2117) | 1622462715712 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates
[task 2021-05-31T12:11:25.728Z] 12:11:25 INFO - Buffered messages finished
[task 2021-05-31T12:11:25.729Z] 12:11:25 ERROR - TEST-UNEXPECTED-TIMEOUT | dom/base/test/meta_viewport/test_meta_viewport_device_width_with_initial_scale_2.html | application timed out after 370 seconds with no output
[task 2021-05-31T12:11:25.729Z] 12:11:25 ERROR - Force-terminating active process(es).
[task 2021-05-31T12:11:25.729Z] 12:11:25 INFO - Determining child pids from psutil...
[task 2021-05-31T12:11:25.731Z] 12:11:25 INFO - [2179, 2203, 2255, 2296]
[task 2021-05-31T12:11:25.733Z] 12:11:25 INFO - ==> process 2117 launched child process 2132
[task 2021-05-31T12:11:25.733Z] 12:11:25 INFO - ==> process 2117 launched child process 2179
[task 2021-05-31T12:11:25.733Z] 12:11:25 INFO - ==> process 2117 launched child process 2203
[task 2021-05-31T12:11:25.734Z] 12:11:25 INFO - ==> process 2117 launched child process 2255
[task 2021-05-31T12:11:25.734Z] 12:11:25 INFO - ==> process 2117 launched child process 2296
[task 2021-05-31T12:11:25.734Z] 12:11:25 INFO - Found child pids: {2179, 2255, 2132, 2296, 2203}
[task 2021-05-31T12:11:25.734Z] 12:11:25 INFO - Failed to get child procs
[task 2021-05-31T12:11:25.734Z] 12:11:25 INFO - Killing process: 2179
[task 2021-05-31T12:11:25.734Z] 12:11:25 INFO - TEST-INFO | started process screentopng
[task 2021-05-31T12:11:25.939Z] 12:11:25 INFO - TEST-INFO | screentopng: exit 0
[task 2021-05-31T12:11:25.939Z] 12:11:25 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-31T12:11:30.571Z] 12:11:30 INFO - psutil found pid 2179 dead
[task 2021-05-31T12:11:30.572Z] 12:11:30 INFO - Killing process: 2255
[task 2021-05-31T12:11:30.573Z] 12:11:30 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-31T12:11:30.573Z] 12:11:30 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-31T12:11:30.573Z] 12:11:30 INFO - Error: Failed to kill process 2255: psutil.NoSuchProcess no process found with pid 2255
[task 2021-05-31T12:11:30.573Z] 12:11:30 INFO - Killing process: 2132
[task 2021-05-31T12:11:30.574Z] 12:11:30 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-31T12:11:30.574Z] 12:11:30 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-31T12:11:30.575Z] 12:11:30 INFO - Error: Failed to kill process 2132: psutil.NoSuchProcess no process found with pid 2132
[task 2021-05-31T12:11:30.575Z] 12:11:30 INFO - Killing process: 2296
[task 2021-05-31T12:11:30.576Z] 12:11:30 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-31T12:11:30.577Z] 12:11:30 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-31T12:11:30.578Z] 12:11:30 INFO - Error: Failed to kill process 2296: psutil.NoSuchProcess no process found with pid 2296
[task 2021-05-31T12:11:30.578Z] 12:11:30 INFO - Killing process: 2203
[task 2021-05-31T12:11:30.578Z] 12:11:30 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-31T12:11:30.578Z] 12:11:30 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-31T12:11:30.578Z] 12:11:30 INFO - Error: Failed to kill process 2203: psutil.NoSuchProcess no process found with pid 2203
[task 2021-05-31T12:11:30.578Z] 12:11:30 INFO - Killing process: 2117
[task 2021-05-31T12:11:30.579Z] 12:11:30 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-31T12:11:30.579Z] 12:11:30 INFO - Can't trigger Breakpad, just killing process
[task 2021-05-31T12:12:00.596Z] 12:12:00 INFO - psutil found pid 2117 dead
[task 2021-05-31T12:12:00.597Z] 12:12:00 INFO - failed to kill pid 2348 after 30s
[task 2021-05-31T12:12:00.597Z] 12:12:00 INFO - psutil found pid 2117 dead
[task 2021-05-31T12:12:00.598Z] 12:12:00 INFO - TEST-INFO | Main app process: exit 0
[task 2021-05-31T12:12:00.598Z] 12:12:00 INFO - runtests.py | Application ran for: 0:13:19.472865
[task 2021-05-31T12:12:00.598Z] 12:12:00 INFO - zombiecheck | Reading PID log: /tmp/tmpolfbcc3_pidlog
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - ==> process 2117 launched child process 2132
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - ==> process 2117 launched child process 2179
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - ==> process 2117 launched child process 2203
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - ==> process 2117 launched child process 2255
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - ==> process 2117 launched child process 2296
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - zombiecheck | Checking for orphan process with PID: 2179
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - zombiecheck | Checking for orphan process with PID: 2255
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - zombiecheck | Checking for orphan process with PID: 2132
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - zombiecheck | Checking for orphan process with PID: 2296
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - zombiecheck | Checking for orphan process with PID: 2203
[task 2021-05-31T12:12:00.601Z] 12:12:00 INFO - Stopping web server
[task 2021-05-31T12:12:00.615Z] 12:12:00 INFO - Server shut down.
[task 2021-05-31T12:12:00.635Z] 12:12:00 INFO - Web server killed.
[task 2021-05-31T12:12:00.635Z] 12:12:00 INFO - Stopping web socket server
[task 2021-05-31T12:12:00.655Z] 12:12:00 INFO - Stopping ssltunnel
[task 2021-05-31T12:12:00.679Z] 12:12:00 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-05-31T12:12:00.679Z] 12:12:00 INFO - runtests.py | Running tests: end.
[task 2021-05-31T12:12:00.703Z] 12:12:00 INFO - Buffered messages finished
[task 2021-05-31T12:12:00.704Z] 12:12:00 INFO - Running manifest: dom/html/test/mochitest.ini
[task 2021-05-31T12:12:00.704Z] 12:12:00 INFO - The following extra prefs will be set:
[task 2021-05-31T12:12:00.704Z] 12:12:00 INFO - plugin.load_flash_only=false
[task 2021-05-31T12:12:00.704Z] 12:12:00 INFO - dom.menuitem.enabled=true
[task 2021-05-31T12:12:00.722Z] 12:12:00 INFO - Setting pipeline to PAUSED ...
[task 2021-05-31T12:12:00.722Z] 12:12:00 INFO - Pipeline is PREROLLING ...
[task 2021-05-31T12:12:00.723Z] 12:12:00 INFO - Pipeline is PREROLLED ...
[task 2021-05-31T12:12:00.724Z] 12:12:00 INFO - Setting pipeline to PLAYING ...
[task 2021-05-31T12:12:00.724Z] 12:12:00 INFO - New clock: GstSystemClock
[task 2021-05-31T12:12:00.757Z] 12:12:00 INFO - Got EOS from element "pipeline0".
[task 2021-05-31T12:12:00.757Z] 12:12:00 INFO - Execution ended after 0:00:00.033454650
[task 2021-05-31T12:12:00.757Z] 12:12:00 INFO - Setting pipeline to PAUSED ...
[task 2021-05-31T12:12:00.758Z] 12:12:00 INFO - Setting pipeline to READY ...
[task 2021-05-31T12:12:00.758Z] 12:12:00 INFO - (gst-launch-1.0:2351): GStreamer-CRITICAL **: 12:12:00.757: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2021-05-31T12:12:00.758Z] 12:12:00 INFO - Setting pipeline to NULL ...
[task 2021-05-31T12:12:00.759Z] 12:12:00 INFO - Freeing pipeline ...
[task 2021-05-31T12:12:00.794Z] 12:12:00 INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-05-31T12:12:01.328Z] 12:12:01 INFO - PID 2364 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2021-05-31T12:12:01.464Z] 12:12:01 INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-05-31T12:12:01.465Z] 12:12:01 INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-05-31T12:12:01.470Z] 12:12:01 INFO - MochitestServer : launching ['/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/tmpg7mrbxc8.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 2021-05-31T12:12:01.470Z] 12:12:01 INFO - runtests.py | Server pid: 2370
[task 2021-05-31T12:12:01.485Z] 12:12:01 INFO - runtests.py | Websocket server pid: 2373
[task 2021-05-31T12:12:01.486Z] 12:12:01 INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-05-31T12:12:01.492Z] 12:12:01 INFO - runtests.py | SSL tunnel pid: 2377
[task 2021-05-31T12:12:02.047Z] 12:12:02 INFO - runtests.py | Running with scheme: http
[task 2021-05-31T12:12:02.047Z] 12:12:02 INFO - runtests.py | Running with e10s: True
[task 2021-05-31T12:12:02.048Z] 12:12:02 INFO - runtests.py | Running with fission: False
[task 2021-05-31T12:12:02.048Z] 12:12:02 INFO - runtests.py | Running with cross-origin iframes: False
[task 2021-05-31T12:12:02.049Z] 12:12:02 INFO - runtests.py | Running with serviceworker_e10s: True
[task 2021-05-31T12:12:02.049Z] 12:12:02 INFO - runtests.py | Running with socketprocess_e10s: False
[task 2021-05-31T12:12:02.049Z] 12:12:02 INFO - runtests.py | Running tests: start.
[task 2021-05-31T12:12:02.050Z] 12:12:02 INFO -
[task 2021-05-31T12:12:02.057Z] 12:12:02 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpg7mrbxc8.mozrunner
[task 2021-05-31T12:12:02.063Z] 12:12:02 INFO - runtests.py | Application pid: 2396
[task 2021-05-31T12:12:02.063Z] 12:12:02 INFO - TEST-INFO | started process GECKO(2396)
[task 2021-05-31T12:12:06.182Z] 12:12:06 INFO - GECKO(2396) | 1622463126181 Marionette INFO Marionette enabled
[task 2021-05-31T12:12:06.979Z] 12:12:06 INFO - GECKO(2396) | 1622463126978 Marionette TRACE Received observer notification toplevel-window-ready
[task 2021-05-31T12:12:14.527Z] 12:12:14 INFO - GECKO(2396) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpg7mrbxc8.mozrunner/search.json.mozlz4", (void 0)))
[task 2021-05-31T12:12:20.942Z] 12:12:20 INFO - GECKO(2396) | 1622463140939 Marionette TRACE Received observer notification marionette-startup-requested
[task 2021-05-31T12:12:20.943Z] 12:12:20 INFO - GECKO(2396) | 1622463140941 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2021-05-31T12:12:21.091Z] 12:12:21 INFO - GECKO(2396) | 1622463141090 Marionette TRACE All scripts recorded.
[task 2021-05-31T12:12:21.105Z] 12:12:21 INFO - GECKO(2396) | 1622463141104 Marionette INFO Listening on port 2828
[task 2021-05-31T12:12:21.107Z] 12:12:21 INFO - GECKO(2396) | 1622463141106 Marionette DEBUG Marionette is listening
[task 2021-05-31T12:12:21.278Z] 12:12:21 INFO - GECKO(2396) | 1622463141277 Marionette DEBUG Accepted connection 0 from 127.0.0.1:48412
[task 2021-05-31T12:12:21.297Z] 12:12:21 INFO - GECKO(2396) | 1622463141295 Marionette DEBUG Closed connection 0
[task 2021-05-31T12:12:21.298Z] 12:12:21 INFO - GECKO(2396) | 1622463141298 Marionette DEBUG Accepted connection 1 from 127.0.0.1:48414
[task 2021-05-31T12:12:21.381Z] 12:12:21 INFO - GECKO(2396) | 1622463141380 Marionette DEBUG 1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-05-31T12:12:21.497Z] 12:12:21 INFO - GECKO(2396) | 1622463141496 Marionette DEBUG 1 <- [1,1,null,{"sessionId":"187477f7-690a-4b88-a504-a2843fdd4ba4","capabilities":{"browserName":"firefox","browserVersion":"90.0a ... .mozrunner","moz:shutdownTimeout":360000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-05-31T12:12:21.577Z] 12:12:21 INFO - GECKO(2396) | 1622463141576 Marionette DEBUG 1 -> [0,2,"Addon:Install",{"path":"/tmp/tmpffkwjqs0.zip","temporary":false}]
[task 2021-05-31T12:12:22.056Z] 12:12:22 INFO - GECKO(2396) | 1622463142052 Marionette TRACE [39] MarionetteEvents actor created for window id 22
[task 2021-05-31T12:12:22.511Z] 12:12:22 INFO - GECKO(2396) | 1622463142510 Marionette DEBUG 1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2021-05-31T12:12:22.543Z] 12:12:22 INFO - GECKO(2396) | 1622463142541 Marionette DEBUG 1 -> [0,3,"Addon:Install",{"path":"/tmp/tmpby9o2j6t.zip","temporary":false}]
[task 2021-05-31T12:12:22.745Z] 12:12:22 INFO - GECKO(2396) | 1622463142743 Marionette DEBUG 1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2021-05-31T12:12:22.765Z] 12:12:22 INFO - GECKO(2396) | 1622463142763 Marionette DEBUG 1 -> [0,4,"Marionette:GetContext",{}]
[task 2021-05-31T12:12:22.767Z] 12:12:22 INFO - GECKO(2396) | 1622463142765 Marionette DEBUG 1 <- [1,4,null,{"value":"content"}]
[task 2021-05-31T12:12:22.773Z] 12:12:22 INFO - GECKO(2396) | 1622463142772 Marionette DEBUG 1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-05-31T12:12:22.775Z] 12:12:22 INFO - GECKO(2396) | 1622463142775 Marionette DEBUG 1 <- [1,5,null,{"value":null}]
[task 2021-05-31T12:12:22.782Z] 12:12:22 INFO - GECKO(2396) | 1622463142781 Marionette DEBUG 1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... ry=%2Ftmp&cleanupCrashes=true"}],"newSandbox":true,"sandbox":"default","line":1935,"filename":"tests/mochitest/runtests.py"}]
[task 2021-05-31T12:12:22.823Z] 12:12:22 INFO - GECKO(2396) | 1622463142822 Marionette TRACE [7] MarionetteCommands actor created for window id 2
[task 2021-05-31T12:12:22.873Z] 12:12:22 INFO - GECKO(2396) | 1622463142872 Marionette DEBUG 1 <- [1,6,null,{"value":null}]
[task 2021-05-31T12:12:22.889Z] 12:12:22 INFO - GECKO(2396) | 1622463142888 Marionette DEBUG 1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2021-05-31T12:12:22.891Z] 12:12:22 INFO - GECKO(2396) | 1622463142890 Marionette DEBUG 1 <- [1,7,null,{"value":null}]
[task 2021-05-31T12:12:22.903Z] 12:12:22 INFO - GECKO(2396) | 1622463142900 Marionette DEBUG 1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2021-05-31T12:12:22.912Z] 12:12:22 INFO - GECKO(2396) | 1622463142911 Marionette DEBUG 1 <- [1,8,null,{"value":null}]
[task 2021-05-31T12:12:22.914Z] 12:12:22 INFO - GECKO(2396) | 1622463142909 Marionette TRACE [19] MarionetteEvents actor created for window id 2147483649
[task 2021-05-31T12:12:22.922Z] 12:12:22 INFO - GECKO(2396) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'
[task 2021-05-31T12:12:22.923Z] 12:12:22 INFO - runtests.py | Waiting for browser...
[task 2021-05-31T12:12:23.126Z] 12:12:23 INFO - GECKO(2396) | 1622463143124 Marionette DEBUG Closed connection 1
[task 2021-05-31T12:12:23.890Z] 12:12:23 INFO - GECKO(2396) | 1622463143889 Marionette TRACE [39] MarionetteEvents actor created for window id 6442450945
[task 2021-05-31T12:12:23.998Z] 12:12:23 INFO - GECKO(2396) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'
[task 2021-05-31T12:12:25.317Z] 12:12:25 INFO - SimpleTest START
[task 2021-05-31T12:12:25.352Z] 12:12:25 INFO - TEST-START | dom/html/test/test_a_text.html
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•