Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

init_failed leading to trying to write into closed queue, wptrunner hung #49715

Open
gsnedders opened this issue Dec 16, 2024 · 2 comments
Open

init_failed leading to trying to write into closed queue, wptrunner hung #49715

gsnedders opened this issue Dec 16, 2024 · 2 comments
Labels
infra wptrunner The automated test runner, commonly called through ./wpt run

Comments

@gsnedders
Copy link
Member

Maybe related to #41962.

 0:47.86 DEBUG Test runner started
 0:48.46 DEBUG Got command: 'log'
 0:48.46 DEBUG Executor setup
 0:48.47 DEBUG Got command: 'log'
 0:48.46 DEBUG Connecting to WebDriver on URL: http://127.0.0.1:63026/
 0:50.35 DEBUG Got command: 'log'
 0:50.35 DEBUG Loading http://web-platform.test:8000/testharness_runner.html
 1:17.34 DEBUG init_failed called from timer
 1:17.35 INFO STDERR: Exception in thread 
 1:17.35 INFO STDERR: Thread-2
 1:17.35 INFO STDERR: :
 1:17.35 INFO STDERR: Traceback (most recent call last):
 1:17.35 INFO STDERR:   File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 973, in _bootstrap_inner
 1:17.35 INFO STDERR:     
 1:17.35 INFO STDERR: self.run()
 1:17.35 INFO STDERR:   File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 1286, in run
 1:17.35 INFO STDERR:     
 1:17.35 INFO STDERR: self.function(*self.args, **self.kwargs)
 1:17.35 INFO STDERR:   File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 281, in init_timeout
 1:17.35 INFO STDERR:     
 1:17.36 INFO STDERR: self.send_message("init_failed")
 1:17.36 INFO STDERR:   File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 275, in send_message
 1:17.36 INFO STDERR:     
 1:17.36 INFO STDERR: self.command_queue.put((command, args))
 1:17.36 INFO STDERR:   File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/multiprocessing/queues.py", line 88, in put
 1:17.36 INFO STDERR:     
 1:17.36 INFO STDERR: raise ValueError(f"Queue {self!r} is closed")
 1:17.36 INFO STDERR: ValueError
 1:17.36 INFO STDERR: : 
 1:17.36 INFO STDERR: Queue <multiprocessing.queues.Queue object at 0x112114670> is closed

wptrunner then hung, never continuing.

SIGINT then led to:

 4:50.54 CRITICAL Main thread got signal; waiting for TestRunnerManager threads to exit.
 4:50.54 DEBUG Stop flag set in ManagerGroup
 4:50.54 DEBUG Got command: 'log'
 4:50.54 DEBUG Hanging up on WebDriver session
 4:50.54 DEBUG TestRunnerManager main loop terminating, starting cleanup
 4:50.55 CRITICAL Tests left in the queue: :'/FileAPI/BlobURL/cross-partition-navigation.tentative.https.html' and 33481 others
...
 4:51.20 DEBUG Test left in the queue: :'/xhr/xmlhttprequest-unsent.htm'
 4:51.20 DEBUG Stopping runner process
 5:00.54 DEBUG Stop flag set in ManagerGroup
 5:00.59 INFO Closing logging queue
 5:00.59 INFO queue closed
Traceback (most recent call last):
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptrunner.py", line 321, in run_test_iteration
    manager_group.run(tests_to_run)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 1100, in run
    self.wait()
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 1126, in wait
    self.stop_flag.wait_for_all_managers_done(timeout)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 59, in wait_for_all_managers_done
    self._all_managers_done.wait(timeout)
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 635, in wait
    self._wait(timeout)
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 670, in _wait
    if not self._cond.wait_for(lambda : self._state != 0, timeout):
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 347, in wait_for
    self.wait(waittime)
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 312, in wait
    waiter.acquire()
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/./wpt", line 10, in <module>
    wpt.main()
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wpt/wpt.py", line 233, in main
    rv = script(*args, **kwargs)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wpt/run.py", line 1012, in run
    rv = run_single(venv, **wptrunner_kwargs) > 0
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wpt/run.py", line 1021, in run_single
    return wptrunner.start(**kwargs)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptrunner.py", line 570, in start
    rv = not run_tests(**kwargs)[0] or logged_critical.has_log
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptrunner.py", line 503, in run_tests
    iter_success = run_test_iteration(test_status,
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/wptrunner.py", line 327, in run_test_iteration
    manager_group.wait(timeout=10)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 1126, in wait
    self.stop_flag.wait_for_all_managers_done(timeout)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 59, in wait_for_all_managers_done
    self._all_managers_done.wait(timeout)
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 635, in wait
    self._wait(timeout)
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 673, in _wait
    raise BrokenBarrierError
threading.BrokenBarrierError
Exception in thread TestRunnerManager-0:
Traceback (most recent call last):
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 957, in stop_runner
    self._ensure_runner_stopped()
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 985, in _ensure_runner_stopped
    self.logger.warning("Forcibly terminating runner process")
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/third_party_modified/mozlog/mozlog/logtypes.py", line 54, in inner
    return f(self, data)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/third_party_modified/mozlog/mozlog/structuredlog.py", line 683, in log
    self._log_data("log", data)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/third_party_modified/mozlog/mozlog/structuredlog.py", line 295, in _log_data
    self._handle_log(log_data)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/third_party_modified/mozlog/mozlog/structuredlog.py", line 299, in _handle_log
    raise LoggerShutdownError(
mozlog.structuredlog.LoggerShutdownError: log action received after shutdown.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 494, in _cleanup_run_loop
    self.stop_runner(force=force_stop)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 966, in stop_runner
    self.cleanup()
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 1015, in cleanup
    self.logger.debug("TestRunnerManager cleanup")
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/third_party_modified/mozlog/mozlog/logtypes.py", line 54, in inner
    return f(self, data)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/third_party_modified/mozlog/mozlog/structuredlog.py", line 683, in log
    self._log_data("log", data)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/third_party_modified/mozlog/mozlog/structuredlog.py", line 295, in _log_data
    self._handle_log(log_data)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/third_party_modified/mozlog/mozlog/structuredlog.py", line 299, in _handle_log
    raise LoggerShutdownError(
mozlog.structuredlog.LoggerShutdownError: log action received after shutdown.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 973, in _bootstrap_inner
    self.run()
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 910, in run
    self._target(*self._args, **self._kwargs)
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 472, in run_loop
    self._cleanup_run_loop()
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 504, in _cleanup_run_loop
    self.parent_stop_flag.wait_for_all_managers_done()
  File "/Volumes/gsnedders/projects/wpt/web-platform-tests/tools/wptrunner/wptrunner/testrunner.py", line 59, in wait_for_all_managers_done
    self._all_managers_done.wait(timeout)
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 626, in wait
    self._enter() # Block while the barrier drains.
  File "/Applications/Xcode.app/Contents/Developer/Library/Frameworks/Python3.framework/Versions/3.9/lib/python3.9/threading.py", line 650, in _enter
    raise BrokenBarrierError
threading.BrokenBarrierError
@gsnedders gsnedders added infra wptrunner The automated test runner, commonly called through ./wpt run labels Dec 16, 2024
@gsnedders
Copy link
Member Author

I think we have multiple different places waiting init_timeout seconds, but not all starting at exactly the same time, which inevitably goes badly.

@gsnedders
Copy link
Member Author

#48030 is kinda related, insofar as it intended for the runner to always exit before the browser, but this certainly seems like it probably didn't.

I don't know if this will suffice to reproduce, but fundamentally this is caused by the webdriver New Session command not returning until around our own init_timeout value is hit.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
infra wptrunner The automated test runner, commonly called through ./wpt run
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@gsnedders