tests: flaky windows server startup failure on github action

From Teodoras PR #1250 (https://github.com/theupdateframework/tuf/runs/1658331874), a seemingly unrelated failure on ServerProcess tests

Notes:

seems windows-related
this is flaky: other builds on same branch do not show this
seems concentrated on TestServerProcess tests (other tests using a ServerProcess succeed at least on this run) maybe because those end up with many processes very quickly in row
may be python 3.6 only: https://bugs.python.org/issue37380
possible workaround may be to set something as stdin for the subprocess even if we don't use it https://stackoverflow.com/questions/40108816/python-running-as-windows-service-o

======================================================================
ERROR: test_cleanup (test_utils.TestServerProcess)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "d:\a\tuf\tuf\tests\utils.py", line 174, in __init__
    self._start_server(timeout, extra_cmd_args, popen_cwd)
  File "d:\a\tuf\tuf\tests\utils.py", line 190, in _start_server
    self._start_process(extra_cmd_args, popen_cwd)
  File "d:\a\tuf\tuf\tests\utils.py", line 207, in _start_process
    stdout=subprocess.PIPE, stderr=subprocess.STDOUT, cwd=popen_cwd)
  File "c:\hostedtoolcache\windows\python\3.6.8\x64\lib\subprocess.py", line 616, in __init__
    _cleanup()
  File "c:\hostedtoolcache\windows\python\3.6.8\x64\lib\subprocess.py", line 205, in _cleanup
    res = inst._internal_poll(_deadstate=sys.maxsize)
  File "c:\hostedtoolcache\windows\python\3.6.8\x64\lib\subprocess.py", line 1055, in _internal_poll
    if _WaitForSingleObject(self._handle, 0) == _WAIT_OBJECT_0:
OSError: [WinError 6] The handle is invalid

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:\a\tuf\tuf\tests\test_utils.py", line 134, in test_cleanup
    server='simple_server.py')
  File "d:\a\tuf\tuf\tests\utils.py", line 178, in __init__
    self.clean()
  File "d:\a\tuf\tuf\tests\utils.py", line 316, in clean
    self.flush_log()
  File "d:\a\tuf\tuf\tests\utils.py", line 294, in flush_log
    line = self._log_queue.get(block=False)
AttributeError: 'TestServerProcess' object has no attribute '_log_queue'

the latter exception seems like a separate bug that only comes up in this error case (_log_queue is not always defined when flush() gets called)

martin do you want to take a look?

Yes, I will.
I will try to do it these days.

I created a Windows VM, wrote a small python script that creates a python subprocess running the test_utils.py module
and run it with python 3.6.

I run it into a loop.
After 2419 iterations I get one unit test failing with the following error:

======================================================================
ERROR: test_simple_https_server_startup (__main__.TestServerProcess)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 257, in _wait_for_port
    line = self._log_queue.get(timeout=timeout)
  File "C:\Users\Martin Vrachev\AppData\Local\Programs\Python\Python36\lib\queue.py", line 172, in get
    raise Empty
queue.Empty

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\Martin Vrachev\src\tuf\tests\test_utils.py", line 76, in test_simple_https_server_startup
    server='simple_https_server.py')
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 179, in __init__
    raise e
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 174, in __init__
    self._start_server(timeout, extra_cmd_args, popen_cwd)
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 193, in _start_server
    self._wait_for_port(timeout)
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 273, in _wait_for_port
    raise TimeoutError('Failure during ' + self.server + ' startup!')
TimeoutError: Failure during simple_https_server.py startup!

but it seems to me that this error is not related.

Second time received that exception on iteration number 4545.

well that's annoying. The only idea I have is that the full suite run somehow uses all of [some operating system resource] that then triggers an issue in TestServerProcess. So you could try running the full suite a couple of hundred times (stopping on error)... but this might depend on the exact setup of the VM/machine.

Other than that, I think we just have to leave this open: if it does not not reproduce we close it later. If it does reproduce we have to come back to debugging it

I created a Windows VM, wrote a small python script that creates a python subprocess running the test_utils.py module
and run it with python 3.6.

I run it into a loop.
After 2419 iterations I get one unit test failing with the following error:

======================================================================
ERROR: test_simple_https_server_startup (__main__.TestServerProcess)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 257, in _wait_for_port
    line = self._log_queue.get(timeout=timeout)
  File "C:\Users\Martin Vrachev\AppData\Local\Programs\Python\Python36\lib\queue.py", line 172, in get
    raise Empty
queue.Empty

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\Martin Vrachev\src\tuf\tests\test_utils.py", line 76, in test_simple_https_server_startup
    server='simple_https_server.py')
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 179, in __init__
    raise e
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 174, in __init__
    self._start_server(timeout, extra_cmd_args, popen_cwd)
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 193, in _start_server
    self._wait_for_port(timeout)
  File "c:\users\martin vrachev\src\tuf\tests\utils.py", line 273, in _wait_for_port
    raise TimeoutError('Failure during ' + self.server + ' startup!')
TimeoutError: Failure during simple_https_server.py startup!

but it seems to me that this error is not related.

I tried a couple more times.
The problem I have is that in order to run the test_util.py extensively it requires a lot of time on my local machine and because I am
using another VM for other stuff my RAM just finished at a certain point and I receive the above message.

I just finished 23181 iterations and wasn't able to reproduce the documented error.

Probably it's something specific to the GitHub CI infrastructure?

After multiple tries and failures to reproduce this bug, we consider this issue obsolete.
If another occurrence of the bug reappears, we would open a new issue documenting it and referencing this one.

Navigation Menu

Repository navigation

tests: flaky windows server startup failure on github action #1255

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

tests: flaky windows server startup failure on github action #1255

Description

Activity

jku commented on Jan 8, 2021

MVrachev commented on Jan 12, 2021

MVrachev commented on Feb 19, 2021

MVrachev commented on Feb 20, 2021

jku commented on Feb 22, 2021

MVrachev commented on Mar 6, 2021

MVrachev commented on May 26, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions