tests: flaky windows server startup failure on github action

[jku]

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)

[jku]

martin do you want to take a look?

[MVrachev]

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

[MVrachev]

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.

[MVrachev]

Second time received that exception on iteration number 4545.

[jku]

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

[MVrachev]

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?

[MVrachev]

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.