1783048 - "LoggerShutdownError: shutdown action received after shutdown." when running a web platform reftest

Status: NEW

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

Description

[Markus Stange [:mstange]]

On macOS arm64, running this command shows an error:

./mach test testing/web-platform/tests/css/filter-effects/css-backdrop-filters-animation-contrast.html

% ./mach test testing/web-platform/tests/css/filter-effects/css-backdrop-filters-animation-contrast.html
 0:00.05 INFO Skipping manifest download because existing file is recent
 0:00.68 mozversion INFO application_buildid: 20220803143820
 0:00.68 mozversion INFO application_changeset: 8751d33bcf885e74603c6f80662ab24109f13a04
 0:00.68 mozversion INFO application_display_name: Nightly
 0:00.68 mozversion INFO application_id: {ec8030f7-c20a-464f-9b0e-13a3a9e97384}
 0:00.68 mozversion INFO application_name: Firefox
 0:00.68 mozversion INFO application_remotingname: firefox-default
 0:00.68 mozversion INFO application_vendor: Mozilla
 0:00.68 mozversion INFO application_version: 105.0a1
 0:00.68 mozversion INFO platform_buildid: 20220803143820
 0:00.68 mozversion INFO platform_changeset: 8751d33bcf885e74603c6f80662ab24109f13a04
 0:00.68 mozversion INFO platform_version: 105.0a1
 0:00.78 INFO Using 1 client processes
 0:03.49 INFO Installed font: Ahem.ttf
 0:03.64 wptserve INFO Starting http server on 127.0.0.1:8000
 0:03.77 wptserve INFO Starting http server on 127.0.0.1:8001
 0:03.90 wptserve INFO Starting http server on 127.0.0.1:8002
 0:04.02 wptserve INFO Starting http server on 127.0.0.1:8003
 0:04.15 wptserve INFO Starting https server on 127.0.0.1:8443
 0:04.27 wptserve INFO Starting https server on 127.0.0.1:8444
 0:04.39 wptserve INFO Starting https server on 127.0.0.1:8445
 0:04.51 wptserve INFO Starting https server on 127.0.0.1:8446
 0:04.64 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
 0:04.64 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
 0:04.64 wptserve INFO Listen on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
 0:04.76 wptserve INFO Create socket on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
 0:04.76 wptserve INFO Bind on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
 0:04.76 wptserve INFO Listen on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
 0:04.89 wptserve INFO Starting http2 server on 127.0.0.1:9000
 0:05.38 SUITE_START: web-platform-test - running 1 tests
 0:05.38 INFO Running reftest tests
 0:05.41 INFO Setting up ssl
 0:05.42 certutil Full command: /Users/mstange/code/obj-m-opt/dist/Nightly.app/Contents/MacOS/certutil -N -d /var/folders/n0/ks1j6rkx4zg1q4kfd06cmt9r0000gn/T/tmpqxcus5ct.mozrunner -f /var/folders/n0/ks1j6rkx4zg1q4kfd06cmt9r0000gn/T/tmpqxcus5ct.mozrunner/.crtdbpw
certutil b''
 0:05.44 certutil b''
 0:05.45 certutil b'\nCertificate Nickname                                         Trust Attributes\n                                                             SSL,S/MIME,JAR/XPI\n\nweb-platform-tests                                           CT,, \n'
 0:05.45 INFO Application command: /Users/mstange/code/obj-m-opt/dist/Nightly.app/Contents/MacOS/firefox --marionette about:blank -foreground -profile /var/folders/n0/ks1j6rkx4zg1q4kfd06cmt9r0000gn/T/tmp3l58eh3y
 0:05.45 INFO Starting runner
 0:05.71 pid:51243 Full command: /Users/mstange/code/obj-m-opt/dist/Nightly.app/Contents/MacOS/firefox --marionette about:blank
pid:51243 2022-08-03 14:55:10.220 plugin-container[51247:963484] nil host used in call to allowsSpecificHTTPSCertificateForHost
 0:05.71 pid:51243 2022-08-03 14:55:10.220 plugin-container[51247:963484] nil host used in call to allowsAnyHTTPSCertificateForHost:
 0:05.72 pid:51243 2022-08-03 14:55:10.222 plugin-container[51247:963484] nil host used in call to allowsSpecificHTTPSCertificateForHost
 0:05.72 pid:51243 2022-08-03 14:55:10.222 plugin-container[51247:963484] nil host used in call to allowsAnyHTTPSCertificateForHost:
 0:05.72 pid:51243 2022-08-03 14:55:10.222 plugin-container[51247:963485] nil host used in call to allowsSpecificHTTPSCertificateForHost
 0:05.72 pid:51243 2022-08-03 14:55:10.222 plugin-container[51247:963485] nil host used in call to allowsAnyHTTPSCertificateForHost:
 0:05.73 pid:51243 1659552910235	Marionette	INFO	Marionette enabled
 0:05.75 pid:51243 1659552910258	Marionette	INFO	Listening on port 50350
 0:06.22 pid:51243 UNSUPPORTED (log once): POSSIBLE ISSUE: unit 1 GLD_TEXTURE_INDEX_2D is unloadable and bound to sampler type (Float) - using zero texture because texture unloadable
 0:06.28 pid:51243 console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /var/folders/n0/ks1j6rkx4zg1q4kfd06cmt9r0000gn/T/tmp3l58eh3y/search.json.mozlz4", (void 0)))
 0:06.66 TEST_START: /css/filter-effects/css-backdrop-filters-animation-contrast.html
 0:06.67 INFO Setting pref dom.animations-api.compositing.enabled to true
 0:06.67 INFO Setting pref layout.css.cascade-layers.enabled to true
 0:06.67 INFO Setting pref layout.css.backdrop-filter.enabled to true
 0:06.76 pid:51243 1659552911270	Marionette	INFO	Testing http://web-platform.test:8000/css/filter-effects/css-backdrop-filters-animation-contrast.html == http://web-platform.test:8000/css/filter-effects/css-backdrop-filters-animation-contrast-ref.html
 0:06.79 pid:51243 JavaScript error: chrome://remote/content/shared/TabManager.jsm, line 311: TypeError: can't access property "linkedBrowser", tab is undefined
 0:06.90 pid:51243 1659552911407	Marionette	INFO	No differences allowed
 0:06.90 TEST_END: PASS
 0:06.90 INFO No more tests
 0:06.92 pid:51243 1659552911430	Marionette	INFO	Stopped listening on port 50350
 0:06.93 pid:51243 [Parent 51243, Main Thread] WARNING: ContentParent: id=1556f5c00 - BlockShutdown: NotifyImpendingShutdown.: file /Users/mstange/code/mozilla/dom/ipc/ContentParent.cpp:3612
 0:06.93 pid:51243 [Parent 51243, Main Thread] WARNING: ContentParent: id=1565c8800 - BlockShutdown: NotifyImpendingShutdown.: file /Users/mstange/code/mozilla/dom/ipc/ContentParent.cpp:3612
 0:07.18 INFO Browser exited with return code 0
 0:06.96 INFO Closing logging queue
 0:06.96 INFO queue closed
 0:07.19 INFO Got 0 unexpected results, with 0 unexpected passes
 0:07.19 SUITE_END
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:8000
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:8003
 0:07.38 wptserve INFO Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8888))
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:8001
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:8445
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:8444
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:8446
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:8443
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:9000
 0:07.38 wptserve INFO Stopped http server on 127.0.0.1:8002
 0:07.40 wptserve INFO Close on: (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('127.0.0.1', 8889))
 0:07.44 INFO Removed font: Ahem.ttf
 0:07.45 INFO Closing logging queue
 0:07.45 INFO queue closed
 0:07.45 
Overall Summary
===============

web-platform-test
~~~~~~~~~~~~~~~~~
Ran 1 checks (1 tests)
Expected results: 1
Unexpected results: 0
OK
Error running mach:

    ['test', 'testing/web-platform/tests/css/filter-effects/css-backdrop-filters-animation-contrast.html']

The error occurred in code that was called by the mach command. This is either
a bug in the called code itself or in the way that mach is calling it.
You can invoke |./mach busted| to check if this issue is already on file. If it
isn't, please use |./mach busted file test| to report it. If |./mach busted| is
misbehaving, you can also inspect the dependencies of bug 1543241.

If filing a bug, please include the full output of mach, including this error
message.

The details of the failure are as follows:

mozlog.structuredlog.LoggerShutdownError: shutdown action received after shutdown.

  File "/Users/mstange/code/mozilla/testing/mach_commands.py", line 467, in test
    log.shutdown()
  File "/Users/mstange/code/mozilla/testing/mozbase/mozlog/mozlog/logtypes.py", line 59, in inner
    return f(self, data)
  File "/Users/mstange/code/mozilla/testing/mozbase/mozlog/mozlog/structuredlog.py", line 585, in shutdown
    self._log_data("shutdown", data)
  File "/Users/mstange/code/mozilla/testing/mozbase/mozlog/mozlog/structuredlog.py", line 278, in _log_data
    self._handle_log(log_data)
  File "/Users/mstange/code/mozilla/testing/mozbase/mozlog/mozlog/structuredlog.py", line 282, in _handle_log
    raise LoggerShutdownError(

Sentry event ID: 3ab7bce06dc145ef82ed2552d983f20f

Comment 1

[Markus Stange [:mstange]]

This is on a clean tree with mozilla-central revision 8751d33bcf88.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

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

For more information, please visit auto_nag documentation.

Comment 3

[James Graham [:jgraham]]

So I don't think this is actually related to mac or arm64 or anything interesting like that. It's just that wptrunner calls shutdown on the logger at https://searchfox.org/mozilla-central/source/testing/web-platform/tests/tools/wptrunner/wptrunner/wptrunner.py#473 and then mach test does again at https://searchfox.org/mozilla-central/source/testing/mach_commands.py#467 So presumably this has been broken since bug 1209463.

I guess the obvious fix is to make wptrunner not shutdown the logger if it was passed in by a caller, so that it can be reused in other contexts. But that feels a little dangerous given that we have many entrypoints to update, not just in mozilla-central. I guess other suites are just depending on the gc to call the shutdown method.

Maybe there's a slightly hacky plan where we set a please don't shut down the logger flag when we're being called from mach test.

Comment 4

[Vincent Hilla [:vhilla]]

I encounter a similar error when doing ./mach test path-to-a-wpt-folder to run multiple web-platform-tests, but it doesn't happen with ./mach wpt ....