Sporadic CI error on extraction tests

[terriko]

We've occasionally seen some errors involving the extraction tests that seem to be sporadic and not occurring on every run. I'm cutting and pasting the log here before I re-run Github Actions on the PR where it occurred. I'm not sure what the problem is at this time.

[gw3] [ 99%] PASSED test/test_scanner.py::TestScanner::test_version_mapping[gpgme-1.16.0-version_strings43] 
test/test_scanner.py::TestScanner::test_version_mapping[gpgme-1.13.1-version_strings44] 
Task was destroyed but it is pending!
task: <Task pending coro=<BaseSubprocessTransport._connect_pipes() running at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_subprocess.py:171> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f96dc2ee3d0>()]>>
Future exception was never retrieved
future: <Future finished exception=RuntimeError('Event loop is closed')>
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line [1452](https://github.com/intel/cve-bin-tool/runs/7531953989?check_suite_focus=true#step:10:1453), in connect_read_pipe
    await waiter
GeneratorExit

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_subprocess.py", line 171, in _connect_pipes
    proc.stdout)
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 1454, in connect_read_pipe
    transport.close()
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py", line 522, in close
    self._close(None)
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py", line 547, in _close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 691, in call_soon
    self._check_closed()
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 479, in _check_closed
Error:     raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
[gw3] [100%] PASSED test/test_scanner.py::TestScanner::test_version_mapping[gpgme-1.13.1-version_strings44] 

=================================== FAILURES ===================================
_______ TestExtractFilePkg.test_extract_file_pkg[inpath_return_values1] ________
[gw3] linux -- Python 3.7.13 /opt/hostedtoolcache/Python/3.7.13/x64/bin/python

self = <test.test_extractor.TestExtractFilePkg object at 0x7f96dc993450>
extension_list = {'.pkg'}, inpath_return_values = {'7z': True, 'tar': False}
mocker = <pytest_mock.plugin.MockerFixture object at 0x7f96dc1c8210>

    @pytest.mark.parametrize(
        "inpath_return_values",
        (
            {"tar": True, "7z": False},  # use `tar` to extract
            {"tar": False, "7z": True},  # use `7z` to extract
        ),
    )
    @pytest.mark.asyncio
    async def test_extract_file_pkg(
        self,
        extension_list: List[str],
        inpath_return_values: Dict[str, bool],
        mocker: MockerFixture,
    ):
        """Test the pkg file extraction"""
    
        if sys.version_info >= (3, 8):
            mock_func = mocker.AsyncMock(side_effect=inpath_return_values.get)
        else:
            mock_func = coroutine(
                mocker.MagicMock(side_effect=inpath_return_values.get)
            )
    
        mocker.patch("cve_bin_tool.extractor.aio_inpath", mock_func)
    
        async for extracted_path in self.extract_files(
>           [f"test{extension}" for extension in extension_list]
        ):

test/test_extractor.py:210: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test/test_extractor.py:60: in extract_files
    yield await ectx.aio_extract(str(self.tempdir / filename))
cve_bin_tool/extractor.py:314: in aio_extract
    if await extractor(filename, extracted_path) != 0:
cve_bin_tool/extractor.py:181: in extract_file_pkg
    return await _extract_through_7z()
cve_bin_tool/extractor.py:157: in _extract_through_7z
    ["7z", "x", filename, f"-o{self.tempdir}"]
cve_bin_tool/async_utils.py:79: in aio_run_command
    stderr=asyncio.subprocess.PIPE,
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/subprocess.py:217: in create_subprocess_exec
    stderr=stderr, **kwds)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:[1544](https://github.com/intel/cve-bin-tool/runs/7531953989?check_suite_focus=true#step:10:1545): in subprocess_exec
    bufsize, **kwargs)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:193: in _make_subprocess_transport
    self._child_watcher_callback, transp)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <asyncio.unix_events.SafeChildWatcher object at 0x7f96dc17ac10>
pid = 3309
callback = <bound method _UnixSelectorEventLoop._child_watcher_callback of <_UnixSelectorEventLoop running=False closed=False debug=False>>
args = (<_UnixSubprocessTransport pid=3309 running stdout=<_UnixReadPipeTransport fd=13 polling>>,)

    def add_child_handler(self, pid, callback, *args):
        if self._loop is None:
            raise RuntimeError(
>               "Cannot add child handler, "
                "the child watcher does not have a loop attached")
E           RuntimeError: Cannot add child handler, the child watcher does not have a loop attached

/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:941: RuntimeError
___________________ TestExtractFileDeb.test_extract_file_deb ___________________
[gw3] linux -- Python 3.7.13 /opt/hostedtoolcache/Python/3.7.13/x64/bin/python

self = <test.test_extractor.TestExtractFileDeb object at 0x7f96dca38410>
extension_list = {'.deb', '.ipk'}

    @pytest.mark.asyncio
    async def test_extract_file_deb(self, extension_list: List[str]):
        """Test the deb file extraction"""
        async for extracted_path in self.extract_files(
>           [f"test{extension}" for extension in extension_list]
        ):

test/test_extractor.py:254: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test/test_extractor.py:60: in extract_files
    yield await ectx.aio_extract(str(self.tempdir / filename))
cve_bin_tool/extractor.py:314: in aio_extract
    if await extractor(filename, extracted_path) != 0:
cve_bin_tool/extractor.py:190: in extract_file_deb
    stdout, stderr, _ = await aio_run_command(["ar", "x", filename])
cve_bin_tool/async_utils.py:79: in aio_run_command
    stderr=asyncio.subprocess.PIPE,
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/subprocess.py:217: in create_subprocess_exec
    stderr=stderr, **kwds)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:1544: in subprocess_exec
    bufsize, **kwargs)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:193: in _make_subprocess_transport
    self._child_watcher_callback, transp)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <asyncio.unix_events.SafeChildWatcher object at 0x7f96dc17ac10>
pid = 3336
callback = <bound method _UnixSelectorEventLoop._child_watcher_callback of <_UnixSelectorEventLoop running=False closed=False debug=False>>
args = (<_UnixSubprocessTransport pid=3336 running stdout=<_UnixReadPipeTransport fd=14 polling>>,)

    def add_child_handler(self, pid, callback, *args):
        if self._loop is None:
            raise RuntimeError(
>               "Cannot add child handler, "
                "the child watcher does not have a loop attached")
E           RuntimeError: Cannot add child handler, the child watcher does not have a loop attached

/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:941: RuntimeError
_______ TestExtractFileZip.test_extract_file_zip[inpath_return_values2] ________
[gw3] linux -- Python 3.7.13 /opt/hostedtoolcache/Python/3.7.13/x64/bin/python

self = <test.test_extractor.TestExtractFileZip object at 0x7f96dc9a2150>
extension_list = ['.exe', '.whl', '.jar', '.msi', '.war', '.egg', ...]
inpath_return_values = {'7z': False, 'file': False, 'unzip': False, 'zipinfo': True}
mocker = <pytest_mock.plugin.MockerFixture object at 0x7f96dc37a750>

    @pytest.mark.parametrize(
        "inpath_return_values",
        (
            {"unzip": True, "7z": False, "zipinfo": False, "file": False},
            {"unzip": False, "7z": True, "zipinfo": False, "file": False},
            {"unzip": False, "7z": False, "zipinfo": True, "file": False},
            {"unzip": False, "7z": False, "zipinfo": False, "file": True},
        ),
    )
    @pytest.mark.asyncio
    async def test_extract_file_zip(
        self,
        extension_list: List[str],
        inpath_return_values: Dict[str, bool],
        mocker: MockerFixture,
    ):
        """Test the zip file extraction"""
    
        if sys.version_info >= (3, 8):
            mock_func = mocker.AsyncMock(side_effect=inpath_return_values.get)
        else:
            mock_func = coroutine(
                mocker.MagicMock(side_effect=inpath_return_values.get)
            )
    
        mocker.patch("cve_bin_tool.extractor.aio_inpath", mock_func)
    
        async for dir_path in self.extract_files(
>           [f"test{extension}" for extension in extension_list]
        ):

test/test_extractor.py:367: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test/test_extractor.py:60: in extract_files
    yield await ectx.aio_extract(str(self.tempdir / filename))
cve_bin_tool/extractor.py:314: in aio_extract
    if await extractor(filename, extracted_path) != 0:
cve_bin_tool/extractor.py:217: in extract_file_apk
    ["zipinfo", filename], process_can_fail
cve_bin_tool/async_utils.py:79: in aio_run_command
    stderr=asyncio.subprocess.PIPE,
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/subprocess.py:217: in create_subprocess_exec
    stderr=stderr, **kwds)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:1544: in subprocess_exec
    bufsize, **kwargs)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:193: in _make_subprocess_transport
    self._child_watcher_callback, transp)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <asyncio.unix_events.SafeChildWatcher object at 0x7f96dc17ac10>
pid = 3368
callback = <bound method _UnixSelectorEventLoop._child_watcher_callback of <_UnixSelectorEventLoop running=False closed=False debug=False>>
args = (<_UnixSubprocessTransport pid=3368 running stdout=<_UnixReadPipeTransport fd=13 polling> stderr=<_UnixReadPipeTransport fd=15 polling>>,)

    def add_child_handler(self, pid, callback, *args):
        if self._loop is None:
            raise RuntimeError(
>               "Cannot add child handler, "
                "the child watcher does not have a loop attached")
E           RuntimeError: Cannot add child handler, the child watcher does not have a loop attached

/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:941: RuntimeError
------------------------------ Captured log call -------------------------------
WARNING  cve_bin_tool.TempDirExtractorContext:extractor.py:321 Failure extracting /tmp/cve-bin-tool-frzk7nn_/test.exe
WARNING  cve_bin_tool.TempDirExtractorContext:extractor.py:321 Failure extracting /tmp/cve-bin-tool-frzk7nn_/test.whl
WARNING  cve_bin_tool.TempDirExtractorContext:extractor.py:321 Failure extracting /tmp/cve-bin-tool-frzk7nn_/test.jar
WARNING  cve_bin_tool.TempDirExtractorContext:extractor.py:321 Failure extracting /tmp/cve-bin-tool-frzk7nn_/test.msi
WARNING  cve_bin_tool.TempDirExtractorContext:extractor.py:321 Failure extracting /tmp/cve-bin-tool-frzk7nn_/test.war
WARNING  cve_bin_tool.TempDirExtractorContext:extractor.py:321 Failure extracting /tmp/cve-bin-tool-frzk7nn_/test.egg
WARNING  cve_bin_tool.TempDirExtractorContext:extractor.py:321 Failure extracting /tmp/cve-bin-tool-frzk7nn_/test.ear
___________________ TestHelperScript.test_scan_files_version ___________________
[gw3] linux -- Python 3.7.13 /opt/hostedtoolcache/Python/3.7.13/x64/bin/python

self = <test.test_helper_script.TestHelperScript object at 0x7f96dc985a50>
caplog = <_pytest.logging.LogCaptureFixture object at 0x7f96dc4acb10>

    def test_scan_files_version(self, caplog):
        args = {
            "filenames": [
                "test/condensed-downloads/dovecot-2.3.14-1.fc34.i686.rpm",
                "test/condensed-downloads/dovecot-core_2.3.13+dfsg1-1ubuntu1_amd64.deb",
            ],
            "product_name": "dovecot",
            "version_number": "2.3.14",
            "string_length": 30,
        }
    
        with caplog.at_level(logging.WARNING):
>           scan_files(args)

test/test_helper_script.py:83: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
cve_bin_tool/helper_script.py:436: in scan_files
    hs.extract_and_parse_file(args["filenames"][i])
cve_bin_tool/helper_script.py:70: in extract_and_parse_file
    for filepath in self.walker([ectx.extract(filename)]):
cve_bin_tool/extractor.py:342: in extract
    return run_coroutine(self.aio_extract(filename))
cve_bin_tool/async_utils.py:71: in run_coroutine
    result = loop.run_until_complete(aws)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:587: in run_until_complete
    return future.result()
cve_bin_tool/extractor.py:314: in aio_extract
    if await extractor(filename, extracted_path) != 0:
cve_bin_tool/extractor.py:96: in extract_file_rpm
    stdout, stderr, _ = await aio_run_command(["rpm2cpio", filename])
cve_bin_tool/async_utils.py:79: in aio_run_command
    stderr=asyncio.subprocess.PIPE,
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/subprocess.py:217: in create_subprocess_exec
    stderr=stderr, **kwds)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:1544: in subprocess_exec
    bufsize, **kwargs)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:193: in _make_subprocess_transport
    self._child_watcher_callback, transp)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <asyncio.unix_events.SafeChildWatcher object at 0x7f96dc17ac10>
pid = 3524
callback = <bound method _UnixSelectorEventLoop._child_watcher_callback of <_UnixSelectorEventLoop running=False closed=False debug=False>>
args = (<_UnixSubprocessTransport pid=3524 running>,)

    def add_child_handler(self, pid, callback, *args):
        if self._loop is None:
            raise RuntimeError(
>               "Cannot add child handler, "
                "the child watcher does not have a loop attached")
E           RuntimeError: Cannot add child handler, the child watcher does not have a loop attached

/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:941: RuntimeError
------------------------------ Captured log call -------------------------------
INFO     cve_bin_tool:helper_script.py:412 Scanning files
WARNING  cve_bin_tool:helper_script.py:432 VERSION_NUMBER in arguments, common strings may not be found if files have different versions
WARNING  cve_bin_tool:helper_script.py:274 
===============================================================
Multiple ("vendor", "product") pairs found for "dovecot"
Please manually select the appropriate pair.
===============================================================
=============================== warnings summary ===============================
test/test_checkers.py: 52 warnings
  /home/runner/work/cve-bin-tool/cve-bin-tool/test/test_checkers.py:121: DeprecationWarning: SelectableGroups dict interface is deprecated. Use select.
    checkers = importlib_metadata.entry_points()["cve_bin_tool.checker"]

test/test_cvescanner.py: 10 warnings
test/test_exploits.py: 4 warnings
test/test_csv2cve.py: 16 warnings
test/test_merge.py: 3 warnings
test/test_output_engine.py: 2 warnings
  /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/site-packages/packaging/version.py:114: DeprecationWarning: Creating a LegacyVersion has been deprecated and will be removed in the next major release
    DeprecationWarning,

test/test_checkers.py::TestCheckerVersionParser::test_glibc_latest_version
  /home/runner/work/cve-bin-tool/cve-bin-tool/test/test_checkers.py:170: DeprecationWarning: SelectableGroups dict interface is deprecated. Use select.
    checkers = importlib_metadata.entry_points()["cve_bin_tool.checker"]

test/test_csv2cve.py::TestCSV2CVE::test_csv2cve_valid_file
  /home/runner/work/cve-bin-tool/cve-bin-tool/cve_bin_tool/version_scanner.py:88: DeprecationWarning: SelectableGroups dict interface is deprecated. Use select.
    checkers = importlib_metadata.entry_points()[cls.CHECKER_ENTRYPOINT]

test/test_helper_script.py: 16 warnings
test/test_language_scanner.py: 7 warnings
test/test_scanner.py: 3 warnings
  /home/runner/work/cve-bin-tool/cve-bin-tool/cve_bin_tool/version_scanner.py:81: DeprecationWarning: SelectableGroups dict interface is deprecated. Use select.
    importlib_metadata.entry_points()[cls.CHECKER_ENTRYPOINT],

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=========================== short test summary info ============================
FAILED test/test_extractor.py::TestExtractFilePkg::test_extract_file_pkg[inpath_return_values1]
FAILED test/test_extractor.py::TestExtractFileDeb::test_extract_file_deb - Ru...
FAILED test/test_extractor.py::TestExtractFileZip::test_extract_file_zip[inpath_return_values2]
FAILED test/test_helper_script.py::TestHelperScript::test_scan_files_version
===== 4 failed, 375 passed, 316 skipped, 115 warnings in 65.04s (0:01:05) ======

[terriko]

So far this always seems to happen on the Linux python 3.7 run, but it may just be due to the order the jobs are picked up. I've never seen it happen on windows (though we get other failures on windows regularly).

[anthonyharrison]

So far this always seems to happen on the Linux python 3.7 run, but it may just be due to the order the jobs are picked up. I've never seen it happen on windows (though we get other failures on windows regularly).

@terriko Just seen this on Pull requiest #1850 . As you say it is only for Python 3.7 and looking at the log files, it seems that the jobs are not being scheduled in order.

[terriko]

I'm still seeing this regularly, sometimes with more tests failing:

=========================== short test summary info ============================
FAILED test/test_extractor.py::TestExtractFileRpm::test_extract_file_rpm_no_rpm2cipo
FAILED test/test_extractor.py::TestExtractFilePkg::test_extract_file_pkg[inpath_return_values0]
FAILED test/test_extractor.py::TestExtractFileDeb::test_bad_files - RuntimeEr...
FAILED test/test_extractor.py::TestExtractFileCab::test_extract_file_cab - Ru...
FAILED test/test_extractor.py::TestExtractFileZip::test_extract_file_zip[inpath_return_values1]
FAILED test/test_helper_script.py::TestHelperScript::test_scan_files_multiline
FAILED test/test_strings.py::TestStrings::test_curl_7_34_0 - RuntimeError: Ca...
FAILED test/test_strings.py::TestStrings::test_kerberos_1_15_1 - RuntimeError...
===== 8 failed, 372 passed, 316 skipped, 115 warnings in 92.39s (0:01:32) ======

It looks in this case like a bunch of the failures are in asyncio:

Task was destroyed but it is pending!
task: <Task pending coro=<BaseSubprocessTransport._connect_pipes() running at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_subprocess.py:171> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fcaa1c1c210>()]>>
Future exception was never retrieved
future: <Future finished exception=RuntimeError('Event loop is closed')>
Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 1452, in connect_read_pipe
    await waiter
GeneratorExit

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_subprocess.py", line 171, in _connect_pipes
    proc.stdout)
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 1454, in connect_read_pipe
    transport.close()
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py", line 522, in close
    self._close(None)
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py", line 547, in _close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 691, in call_soon
    self._check_closed()
  File "/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py", line 479, in _check_closed
Error:     raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
Task was destroyed but it is pending!
task: <Task pending coro=<BaseSubprocessTransport._connect_pipes() running at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_subprocess.py:171> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fcaa1ffe590>()]>>
Task was destroyed but it is pending!
task: <Task pending coro=<BaseSubprocessTransport._connect_pipes() running at /opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_subprocess.py:171> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7fcaa1d50c10>()]>>
[gw3] [100%] PASSED test/test_scanner.py::TestScanner::test_version_mapping[gpgme-1.13.1-version_strings44] 

=================================== FAILURES ===================================
_____________ TestExtractFileRpm.test_extract_file_rpm_no_rpm2cipo _____________
[gw2] linux -- Python 3.7.13 /opt/hostedtoolcache/Python/3.7.13/x64/bin/python

self = <test.test_extractor.TestExtractFileRpm object at 0x7fcaa23167d0>
extension_list = {'.rpm'}

    @pytest.mark.asyncio
    async def test_extract_file_rpm_no_rpm2cipo(self, extension_list: List[str]):
        """Test rpm extraction using rpmfile"""
        with unittest.mock.patch(
            "cve_bin_tool.async_utils.aio_inpath",
            return_value=False,
        ), unittest.mock.patch(
            "cve_bin_tool.async_utils.aio_run_command",
        ) as mock_aio_run_command:
>           await self.test_extract_file_rpm(extension_list)

test/test_extractor.py:148: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test/test_extractor.py:135: in test_extract_file_rpm
    [f"test{extension}" for extension in extension_list]
test/test_extractor.py:60: in extract_files
    yield await ectx.aio_extract(str(self.tempdir / filename))
cve_bin_tool/extractor.py:314: in aio_extract
    if await extractor(filename, extracted_path) != 0:
cve_bin_tool/extractor.py:96: in extract_file_rpm
    stdout, stderr, _ = await aio_run_command(["rpm2cpio", filename])
cve_bin_tool/async_utils.py:79: in aio_run_command
    stderr=asyncio.subprocess.PIPE,
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/subprocess.py:217: in create_subprocess_exec
    stderr=stderr, **kwds)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/base_events.py:[1544](https://github.com/intel/cve-bin-tool/runs/7641503155?check_suite_focus=true#step:10:1545): in subprocess_exec
    bufsize, **kwargs)
/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:193: in _make_subprocess_transport
    self._child_watcher_callback, transp)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <asyncio.unix_events.SafeChildWatcher object at 0x7fcaa1d3c890>
pid = 2955
callback = <bound method _UnixSelectorEventLoop._child_watcher_callback of <_UnixSelectorEventLoop running=False closed=False debug=False>>
args = (<_UnixSubprocessTransport pid=2955 running stdout=<_UnixReadPipeTransport fd=13 polling>>,)

    def add_child_handler(self, pid, callback, *args):
        if self._loop is None:
            raise RuntimeError(
>               "Cannot add child handler, "
                "the child watcher does not have a loop attached")
E           RuntimeError: Cannot add child handler, the child watcher does not have a loop attached

/opt/hostedtoolcache/Python/3.7.13/x64/lib/python3.7/asyncio/unix_events.py:941: RuntimeError

It's possible putting in some better handling for RuntimeErrors will help us pinpoint the problem further.

[terriko]

Further thoughts from the meeting:

• 3.7 's EOL date is in 10 months so dropping it is likely not a reasonable option yet
• could be related to Mock on 3.7 specifically
• We may want to just disable the problematic tests on 3.7 specifically to improve stability. They're being run on 3.8, 3.9, and 3.10 and that's probably enough.

[terriko]

Today looks like the same 8:

=========================== short test summary info ============================
FAILED test/test_extractor.py::TestExtractFileRpm::test_extract_file_rpm_no_rpm2cipo
FAILED test/test_extractor.py::TestExtractFilePkg::test_extract_file_pkg[inpath_return_values0]
FAILED test/test_extractor.py::TestExtractFileDeb::test_bad_files - RuntimeEr...
FAILED test/test_extractor.py::TestExtractFileCab::test_extract_file_cab - Ru...
FAILED test/test_extractor.py::TestExtractFileZip::test_extract_file_zip[inpath_return_values1]
FAILED test/test_helper_script.py::TestHelperScript::test_scan_files_multiline
FAILED test/test_strings.py::TestStrings::test_curl_7_34_0 - RuntimeError: Ca...
FAILED test/test_strings.py::TestStrings::test_kerberos_1_15_1 - RuntimeError...
===== 8 failed, 374 passed, 321 skipped, 115 warnings in 88.64s (0:01:28) ======

I'm planning to experiment with temporarily disabling those 8 tests on Python 3.7 and seeing if that gives us improved CI test stability because re-running tests regularly is slowing down my ability to merge PRs considerably.

[terriko]

I think all of these ones have been closed so this issue can be closed. If you see any new ones, please open a new issue!