Open Bug 1820732 Opened 2 years ago Updated 2 years ago

Intermittent TCw TEST-UNEXPECTED-TIMEOUT | /css/css-multicol/parallel-flow-after-spanner-002.html | single tracking bug

Categories

(Testing :: web-platform-tests, defect)

Product:
Testing
Component:
web-platform-tests
Type:
defect

Tracking

(firefox-esr102 unaffected, firefox110 unaffected, firefox111 unaffected, firefox112 affected)

Tracking Flags:
Tracking Status
firefox-esr102 --- unaffected
firefox110 --- unaffected
firefox111 --- unaffected
firefox112 --- affected

People

(Reporter: SerbanS, Unassigned)

Details

[task 2023-03-07T07:20:50.055Z] 07:20:50     INFO - TEST-START | /css/css-multicol/parallel-flow-after-spanner-002.html
[task 2023-03-07T07:20:50.070Z] 07:20:50     INFO - Setting pref dom.animations-api.compositing.enabled to true
[task 2023-03-07T07:20:50.086Z] 07:20:50     INFO - Setting pref layout.css.cascade-layers.enabled to true
[task 2023-03-07T07:20:50.103Z] 07:20:50     INFO - Setting pref layout.css.more_color_4.enabled to true
[task 2023-03-07T07:20:50.117Z] 07:20:50     INFO - PID 8596 | [CodeCoverage] Requested flush for 7912.
[task 2023-03-07T07:20:51.295Z] 07:20:51     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:20:51.547Z] 07:20:51     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:20:51.558Z] 07:20:51     INFO - PID 8596 | [CodeCoverage] Requested flush for 3328.
[task 2023-03-07T07:20:51.559Z] 07:20:51     INFO - PID 8596 | [CodeCoverage] Requested flush for 3596.
[task 2023-03-07T07:20:51.559Z] 07:20:51     INFO - PID 8596 | [CodeCoverage] Requested flush for 7688.
[task 2023-03-07T07:20:51.560Z] 07:20:51     INFO - PID 8596 | [CodeCoverage] Requested flush for 9200.
[task 2023-03-07T07:20:51.560Z] 07:20:51     INFO - PID 8596 | [CodeCoverage] Requested flush for 1096.
[task 2023-03-07T07:20:53.368Z] 07:20:53     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:20:53.384Z] 07:20:53     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:20:55.298Z] 07:20:55     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:20:55.304Z] 07:20:55     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:20:57.755Z] 07:20:57     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:20:57.768Z] 07:20:57     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:21:00.195Z] 07:21:00     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:21:00.206Z] 07:21:00     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:21:02.189Z] 07:21:02     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:21:02.198Z] 07:21:02     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:21:03.668Z] 07:21:03     INFO - PID 8596 | 1678173663669	Marionette	INFO	Testing http://web-platform.test:8000/css/css-multicol/parallel-flow-after-spanner-002.html == http://web-platform.test:8000/css/reference/ref-filled-green-100px-square.xht
[task 2023-03-07T07:21:03.899Z] 07:21:03     INFO - PID 8596 | 1678173663911	Marionette	INFO	No differences allowed
[task 2023-03-07T07:21:03.945Z] 07:21:03     INFO - PID 8596 | [CodeCoverage] Requested flush for 7912.
[task 2023-03-07T07:21:06.284Z] 07:21:06     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:21:06.456Z] 07:21:06     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:21:06.471Z] 07:21:06     INFO - PID 8596 | [CodeCoverage] Requested flush for 3328.
[task 2023-03-07T07:21:06.471Z] 07:21:06     INFO - PID 8596 | [CodeCoverage] Requested flush for 1096.
[task 2023-03-07T07:21:06.472Z] 07:21:06     INFO - PID 8596 | [CodeCoverage] Requested flush for 3596.
[task 2023-03-07T07:21:06.473Z] 07:21:06     INFO - PID 8596 | [CodeCoverage] Requested flush for 9200.
[task 2023-03-07T07:21:07.460Z] 07:21:07     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:21:07.476Z] 07:21:07     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:21:14.426Z] 07:21:14     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:21:14.437Z] 07:21:14     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:21:21.974Z] 07:21:21     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:21:21.984Z] 07:21:21     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:21:25.066Z] 07:21:25     INFO - Got timeout in harness
[task 2023-03-07T07:21:25.522Z] 07:21:25     INFO - TEST-UNEXPECTED-TIMEOUT | /css/css-multicol/parallel-flow-after-spanner-002.html | TestRunner hit external timeout (this may indicate a hang)
[task 2023-03-07T07:21:25.534Z] 07:21:25     INFO - TEST-INFO took 35467ms
[task 2023-03-07T07:21:25.534Z] 07:21:25     INFO - No more tests
[task 2023-03-07T07:21:31.486Z] 07:21:31     INFO - PID 8596 | [CodeCoverage] flush completed.
[task 2023-03-07T07:21:31.502Z] 07:21:31     INFO - PID 8596 | [CodeCoverage] JS flush completed.
[task 2023-03-07T07:21:31.612Z] 07:21:31     INFO - PID 8596 | JavaScript error: chrome://remote/content/shared/TabManager.sys.mjs, line 106: TypeError: can't access property "gBrowser", win is null
[task 2023-03-07T07:21:31.629Z] 07:21:31     INFO - PID 8596 | 1678173691642	Marionette	INFO	Stopped listening on port 59768
[task 2023-03-07T07:21:32.051Z] 07:21:32     INFO - PID 8596 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-03-07T07:21:32.061Z] 07:21:32     INFO - PID 8596 |           Blocker:  Waiting for ping task
[task 2023-03-07T07:21:32.062Z] 07:21:32     INFO - PID 8596 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-03-07T07:21:32.062Z] 07:21:32     INFO - PID 8596 |           State: (none)
<...>
[task 2023-03-07T07:21:32.116Z] 07:21:32     INFO - PID 8596 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-03-07T07:21:32.116Z] 07:21:32     INFO - PID 8596 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-03-07T07:21:32.117Z] 07:21:32     INFO - PID 8596 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-03-07T07:21:32.117Z] 07:21:32     INFO - PID 8596 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-03-07T07:21:32.118Z] 07:21:32     INFO - PID 8596 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-03-07T07:21:32.118Z] 07:21:32     INFO - PID 8596 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-03-07T07:21:32.119Z] 07:21:32     INFO - PID 8596 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:823:36
[task 2023-03-07T07:21:32.120Z] 07:21:32     INFO - PID 8596 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-03-07T07:21:32.132Z] 07:21:32     INFO - PID 8596 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-07T07:21:32.142Z] 07:21:32     INFO - PID 8596 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-07T07:21:32.143Z] 07:21:32     INFO - PID 8596 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-07T07:21:32.144Z] 07:21:32     INFO - PID 8596 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-07T07:21:32.145Z] 07:21:32     INFO - PID 8596 | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-03-07T07:21:33.055Z] 07:21:33     INFO - PID 8596 | [Parent 7912, IPC I/O Parent] WARNING: Process 3596 may be hanging at shutdown; will wait for up to 80000ms: file Z:/task_167816705645275/build/src/ipc/chromium/src/chrome/common/process_watcher_win.cc:129
[task 2023-03-07T07:21:39.275Z] 07:21:39     INFO - Browser exited with return code 0
[task 2023-03-07T07:21:39.280Z] 07:21:39  WARNING - Command left in command_queue during cleanup: 'test_ended', (<wptrunner.wpttest.ReftestTest /css/css-multicol/parallel-flow-after-spanner-002.html>, (<wptrunner.wpttest.ReftestResult PASS>, []))
[task 2023-03-07T07:21:39.281Z] 07:21:39     INFO - Closing logging queue
[task 2023-03-07T07:21:39.281Z] 07:21:39     INFO - queue closed
[task 2023-03-07T07:21:39.307Z] 07:21:39     INFO - SUITE-END | took 54s
[task 2023-03-07T07:21:39.312Z] 07:21:39     INFO - Got 1 unexpected results, with 0 unexpected passes
[task 2023-03-07T07:21:39.510Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:8000
[task 2023-03-07T07:21:39.573Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:8003
[task 2023-03-07T07:21:39.576Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:8001
[task 2023-03-07T07:21:39.577Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:8002
[task 2023-03-07T07:21:39.605Z] 07:21:39     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
[task 2023-03-07T07:21:39.605Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:8446
[task 2023-03-07T07:21:39.605Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:8445
[task 2023-03-07T07:21:39.605Z] 07:21:39     INFO - wptserve Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
[task 2023-03-07T07:21:39.605Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:8443
[task 2023-03-07T07:21:39.605Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:8444
[task 2023-03-07T07:21:39.651Z] 07:21:39     INFO - wptserve Stopped http server on 127.0.0.1:9000
[task 2023-03-07T07:21:39.699Z] 07:21:39     INFO - Removed font: Ahem.ttf
[task 2023-03-07T07:21:39.746Z] 07:21:39     INFO - Closing logging queue
[task 2023-03-07T07:21:39.761Z] 07:21:39     INFO - queue closed
[task 2023-03-07T07:21:40.200Z] 07:21:40     INFO - Return code: 1

The severity field is not set for this bug.
:jgraham, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(james)

Seems like this has happened once ever?

Severity: -- → S4
Flags: needinfo?(james)
You need to log in before you can comment on or make changes to this bug.