Repository: byllyfish/shellous (language: python)

Issue:
[0.9.0] Failed test: test_audit_block_pipe_specific_cmd
```
_____________________ test_audit_block_pipe_specific_cmd ______________________

    async def test_audit_block_pipe_specific_cmd():
        "Test PEP 578 audit hooks to block a specific command (in a pipe)."
    
        global _HOOK
        grep_path = shutil.which("grep")
    
        def _hook(event, args):
            if event == AUDIT_EVENT_SUBPROCESS_SPAWN and args[0] == grep_path:
                raise RuntimeError("grep blocked")
    
        callbacks = []
    
        def _callback(phase, info):
            runner = info["runner"]
            failure = info.get("failure")
            callbacks.append(f"{phase}:{runner.name}:{runner.returncode}:{failure}")
    
        try:
            _HOOK = _hook
    
            sh = shellous.context().set(audit_callback=_callback)
            hello = sh(sys.executable, "-c", "print('hello')").set(alt_name="hello")
            cmd = hello | sh("grep")
            with pytest.raises(RuntimeError, match="grep blocked"):
                await cmd
    
        finally:
            _HOOK = None
    
        exit_code = 1 if sys.platform == "win32" else -15
>       assert callbacks == [
            "start:hello:None:None",
            "start:grep:None:None",
            "stop:grep:None:RuntimeError",
            "signal:hello:None:None",
            f"stop:hello:{exit_code}:CancelledError",
        ]
E       AssertionError: assert ['start:hello:None:None',\n 'start:grep:None:None',\n 'stop:grep:None:RuntimeError',\n 'signal:hello:None:None',\n 'stop:hello:120:CancelledError'] == ['start:hello:None:None',\n 'start:grep:None:None',\n 'stop:grep:None:RuntimeError',\n 'signal:hello:None:None',\n 'stop:hello:1:CancelledError']
E         At index 4 diff: 'stop:hello:120:CancelledError' != 'stop:hello:1:CancelledError'
E         Full diff:
E           [
E            'start:hello:None:None',
E            'start:grep:None:None',
E            'stop:grep:None:RuntimeError',
E            'signal:hello:None:None',
E         -  'stop:hello:1:CancelledError',
E         +  'stop:hello:120:CancelledError',
E         ?               ++
E           ]

tests\test_audit.py:184: AssertionError
------------------------------ Captured log call ------------------------------
INFO     shellous:log.py:102 PipeRunner.__aenter__ stepin <PipeRunner 'hello|grep'>
INFO     shellous:log.py:102 PipeRunner._start stepin <PipeRunner 'hello|grep'>
INFO     shellous:log.py:113 PipeRunner._start stepout <PipeRunner 'hello|grep'> ex=None
INFO     shellous:log.py:113 PipeRunner.__aenter__ stepout <PipeRunner 'hello|grep'> ex=None
INFO     shellous:log.py:102 PipeRunner.__aexit__ stepin <PipeRunner 'hello|grep'> exc_value=None
INFO     shellous:log.py:102 PipeRunner._finish stepin <PipeRunner 'hello|grep'>
INFO     shellous:log.py:102 PipeRunner._wait stepin <PipeRunner 'hello|grep'>
INFO     shellous:log.py:102 Runner.__aenter__ stepin <Runner 'hello' pid=None> (Windows-10 CPython 3.10.0 asyncio.windows_events.ProactorEventLoop MainThread)
INFO     shellous:log.py:102 Runner._start stepin <Runner 'hello' pid=None>
INFO     shellous:log.py:102 Runner._subprocess_spawn stepin <Runner 'hello' pid=None>
INFO     shellous:log.py:102 Runner.__aenter__ stepin <Runner 'grep' pid=None> (Windows-10 CPython 3.10.0 asyncio.windows_events.ProactorEventLoop MainThread)
INFO     shellous:log.py:102 Runner._start stepin <Runner 'grep' pid=None>
INFO     shellous:log.py:102 Runner._subprocess_spawn stepin <Runner 'grep' pid=None>
INFO     shellous:log.py:102 Runner._subprocess_exec stepin <Runner 'hello' pid=None>
INFO     shellous:log.py:102 Runner._subprocess_exec stepin <Runner 'grep' pid=None>
INFO     shellous:log.py:113 Runner._subprocess_exec stepout <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 Runner._subprocess_spawn stepout <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
WARNING  shellous:runner.py:93 _RunOptions.exit 'grep' exc_value=RuntimeError('grep blocked')
INFO     shellous:runner.py:518 Runner._start <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 Runner._start stepout <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 Runner.__aenter__ stepout <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
INFO     asyncio:base_events.py:1656 execute program 'C:\\Users\\runneradmin\\AppData\\Local\\pypoetry\\Cache\\virtualenvs\\shellous-j1zXeGWZ-py3.10\\Scripts\\python.exe': <_WindowsSubprocessTransport pid=2764 running stdin=<_ProactorWritePipeTransport fd=656 read=<_OverlappedFuture pending overlapped=<pending, 0x20391a479a0> cb=[_ProactorWritePipeTransport._pipe_closed()] created at C:\hostedtoolcache\windows\Python\3.10.0\x64\lib\asyncio\windows_events.py:465>>>
INFO     shellous:log.py:113 Runner._subprocess_exec stepout <Runner 'hello' pid=2764 exit_code=None> ex=None
INFO     shellous:log.py:113 Runner._subprocess_spawn stepout <Runner 'hello' pid=2764 exit_code=None> ex=CancelledError()
WARNING  shellous:runner.py:93 _RunOptions.exit 'hello' exc_value=CancelledError()
INFO     shellous:runner.py:518 Runner._start <Runner 'hello' pid=2764 exit_code=None> ex=CancelledError()
INFO     shellous:log.py:102 Runner._kill stepin <Runner 'hello' cancelled pid=2764 exit_code=None>
INFO     shellous:runner.py:446 Runner.signal <Runner 'hello' cancelled pid=2764 exit_code=None> signal=<Signals.SIGTERM: 15>
WARNING  asyncio:base_events.py:1876 Executing <Task pending name='hello|grep#' coro=<Runner.run_command() running at D:\a\shellous\shellous\shellous\runner.py:735> wait_for=<Future pending cb=[Task.task_wakeup()] created at C:\hostedtoolcache\windows\Python\3.10.0\x64\lib\asyncio\base_events.py:424> cb=[_wait.<locals>._on_completion() at C:\hostedtoolcache\windows\Python\3.10.0\x64\lib\asyncio\tasks.py:479] created at C:\hostedtoolcache\windows\Python\3.10.0\x64\lib\asyncio\tasks.py:337> took 0.906 seconds
INFO     shellous:log.py:102 Runner._waiter stepin <Runner 'hello' cancelled pid=2764 exit_code=None>
INFO     asyncio:base_subprocess.py:211 <_WindowsSubprocessTransport pid=2764 running stdin=<_ProactorWritePipeTransport closing fd=656>> exited with return code 120
INFO     shellous:log.py:113 Runner._waiter stepout <Runner 'hello' cancelled pid=2764 exit_code=120> ex=None
INFO     shellous:log.py:113 Runner._kill stepout <Runner 'hello' cancelled pid=2764 exit_code=120> ex=CancelledError()
INFO     shellous:log.py:113 Runner._start stepout <Runner 'hello' cancelled pid=2764 exit_code=120> ex=CancelledError()
INFO     shellous:log.py:113 Runner.__aenter__ stepout <Runner 'hello' cancelled pid=2764 exit_code=120> ex=ResultError(Result(output_bytes=b'', exit_code=120, cancelled=True, encoding='utf-8', extra=None))
INFO     shellous:log.py:113 PipeRunner._wait stepout <PipeRunner 'hello|grep'> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 PipeRunner._finish stepout <PipeRunner 'hello|grep'> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 PipeRunner.__aexit__ stepout <PipeRunner 'hello|grep'> ex=RuntimeError('grep blocked') exc_value=None
```
[0.9.0] Failed test: test_audit_block_pipe_specific_cmd
```
_____________________ test_audit_block_pipe_specific_cmd ______________________

    async def test_audit_block_pipe_specific_cmd():
        "Test PEP 578 audit hooks to block a specific command (in a pipe)."
    
        global _HOOK
        grep_path = shutil.which("grep")
    
        def _hook(event, args):
            if event == AUDIT_EVENT_SUBPROCESS_SPAWN and args[0] == grep_path:
                raise RuntimeError("grep blocked")
    
        callbacks = []
    
        def _callback(phase, info):
            runner = info["runner"]
            failure = info.get("failure")
            callbacks.append(f"{phase}:{runner.name}:{runner.returncode}:{failure}")
    
        try:
            _HOOK = _hook
    
            sh = shellous.context().set(audit_callback=_callback)
            hello = sh(sys.executable, "-c", "print('hello')").set(alt_name="hello")
            cmd = hello | sh("grep")
            with pytest.raises(RuntimeError, match="grep blocked"):
                await cmd
    
        finally:
            _HOOK = None
    
        exit_code = 1 if sys.platform == "win32" else -15
>       assert callbacks == [
            "start:hello:None:None",
            "start:grep:None:None",
            "stop:grep:None:RuntimeError",
            "signal:hello:None:None",
            f"stop:hello:{exit_code}:CancelledError",
        ]
E       AssertionError: assert ['start:hello:None:None',\n 'start:grep:None:None',\n 'stop:grep:None:RuntimeError',\n 'signal:hello:None:None',\n 'stop:hello:120:CancelledError'] == ['start:hello:None:None',\n 'start:grep:None:None',\n 'stop:grep:None:RuntimeError',\n 'signal:hello:None:None',\n 'stop:hello:1:CancelledError']
E         At index 4 diff: 'stop:hello:120:CancelledError' != 'stop:hello:1:CancelledError'
E         Full diff:
E           [
E            'start:hello:None:None',
E            'start:grep:None:None',
E            'stop:grep:None:RuntimeError',
E            'signal:hello:None:None',
E         -  'stop:hello:1:CancelledError',
E         +  'stop:hello:120:CancelledError',
E         ?               ++
E           ]

tests\test_audit.py:184: AssertionError
------------------------------ Captured log call ------------------------------
INFO     shellous:log.py:102 PipeRunner.__aenter__ stepin <PipeRunner 'hello|grep'>
INFO     shellous:log.py:102 PipeRunner._start stepin <PipeRunner 'hello|grep'>
INFO     shellous:log.py:113 PipeRunner._start stepout <PipeRunner 'hello|grep'> ex=None
INFO     shellous:log.py:113 PipeRunner.__aenter__ stepout <PipeRunner 'hello|grep'> ex=None
INFO     shellous:log.py:102 PipeRunner.__aexit__ stepin <PipeRunner 'hello|grep'> exc_value=None
INFO     shellous:log.py:102 PipeRunner._finish stepin <PipeRunner 'hello|grep'>
INFO     shellous:log.py:102 PipeRunner._wait stepin <PipeRunner 'hello|grep'>
INFO     shellous:log.py:102 Runner.__aenter__ stepin <Runner 'hello' pid=None> (Windows-10 CPython 3.10.0 asyncio.windows_events.ProactorEventLoop MainThread)
INFO     shellous:log.py:102 Runner._start stepin <Runner 'hello' pid=None>
INFO     shellous:log.py:102 Runner._subprocess_spawn stepin <Runner 'hello' pid=None>
INFO     shellous:log.py:102 Runner.__aenter__ stepin <Runner 'grep' pid=None> (Windows-10 CPython 3.10.0 asyncio.windows_events.ProactorEventLoop MainThread)
INFO     shellous:log.py:102 Runner._start stepin <Runner 'grep' pid=None>
INFO     shellous:log.py:102 Runner._subprocess_spawn stepin <Runner 'grep' pid=None>
INFO     shellous:log.py:102 Runner._subprocess_exec stepin <Runner 'hello' pid=None>
INFO     shellous:log.py:102 Runner._subprocess_exec stepin <Runner 'grep' pid=None>
INFO     shellous:log.py:113 Runner._subprocess_exec stepout <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 Runner._subprocess_spawn stepout <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
WARNING  shellous:runner.py:93 _RunOptions.exit 'grep' exc_value=RuntimeError('grep blocked')
INFO     shellous:runner.py:518 Runner._start <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 Runner._start stepout <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 Runner.__aenter__ stepout <Runner 'grep' pid=None> ex=RuntimeError('grep blocked')
INFO     asyncio:base_events.py:1656 execute program 'C:\\Users\\runneradmin\\AppData\\Local\\pypoetry\\Cache\\virtualenvs\\shellous-j1zXeGWZ-py3.10\\Scripts\\python.exe': <_WindowsSubprocessTransport pid=2764 running stdin=<_ProactorWritePipeTransport fd=656 read=<_OverlappedFuture pending overlapped=<pending, 0x20391a479a0> cb=[_ProactorWritePipeTransport._pipe_closed()] created at C:\hostedtoolcache\windows\Python\3.10.0\x64\lib\asyncio\windows_events.py:465>>>
INFO     shellous:log.py:113 Runner._subprocess_exec stepout <Runner 'hello' pid=2764 exit_code=None> ex=None
INFO     shellous:log.py:113 Runner._subprocess_spawn stepout <Runner 'hello' pid=2764 exit_code=None> ex=CancelledError()
WARNING  shellous:runner.py:93 _RunOptions.exit 'hello' exc_value=CancelledError()
INFO     shellous:runner.py:518 Runner._start <Runner 'hello' pid=2764 exit_code=None> ex=CancelledError()
INFO     shellous:log.py:102 Runner._kill stepin <Runner 'hello' cancelled pid=2764 exit_code=None>
INFO     shellous:runner.py:446 Runner.signal <Runner 'hello' cancelled pid=2764 exit_code=None> signal=<Signals.SIGTERM: 15>
WARNING  asyncio:base_events.py:1876 Executing <Task pending name='hello|grep#' coro=<Runner.run_command() running at D:\a\shellous\shellous\shellous\runner.py:735> wait_for=<Future pending cb=[Task.task_wakeup()] created at C:\hostedtoolcache\windows\Python\3.10.0\x64\lib\asyncio\base_events.py:424> cb=[_wait.<locals>._on_completion() at C:\hostedtoolcache\windows\Python\3.10.0\x64\lib\asyncio\tasks.py:479] created at C:\hostedtoolcache\windows\Python\3.10.0\x64\lib\asyncio\tasks.py:337> took 0.906 seconds
INFO     shellous:log.py:102 Runner._waiter stepin <Runner 'hello' cancelled pid=2764 exit_code=None>
INFO     asyncio:base_subprocess.py:211 <_WindowsSubprocessTransport pid=2764 running stdin=<_ProactorWritePipeTransport closing fd=656>> exited with return code 120
INFO     shellous:log.py:113 Runner._waiter stepout <Runner 'hello' cancelled pid=2764 exit_code=120> ex=None
INFO     shellous:log.py:113 Runner._kill stepout <Runner 'hello' cancelled pid=2764 exit_code=120> ex=CancelledError()
INFO     shellous:log.py:113 Runner._start stepout <Runner 'hello' cancelled pid=2764 exit_code=120> ex=CancelledError()
INFO     shellous:log.py:113 Runner.__aenter__ stepout <Runner 'hello' cancelled pid=2764 exit_code=120> ex=ResultError(Result(output_bytes=b'', exit_code=120, cancelled=True, encoding='utf-8', extra=None))
INFO     shellous:log.py:113 PipeRunner._wait stepout <PipeRunner 'hello|grep'> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 PipeRunner._finish stepout <PipeRunner 'hello|grep'> ex=RuntimeError('grep blocked')
INFO     shellous:log.py:113 PipeRunner.__aexit__ stepout <PipeRunner 'hello|grep'> ex=RuntimeError('grep blocked') exc_value=None
```


Discussion / hints:

Fix patch:
diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml
index 8203805f..4ba526f8 100644
--- a/.github/workflows/ci.yml
+++ b/.github/workflows/ci.yml
@@ -21,7 +21,7 @@ jobs:
     strategy:
       fail-fast: false
       matrix:
-        os: [ ubuntu-latest, macos-latest, windows-latest ]
+        os: [ ubuntu-latest, macos-11, windows-latest ]
         python-version: [ '3.9', '3.10' ]
 
     env:
@@ -88,12 +88,3 @@ jobs:
       env:
         SHELLOUS_CHILDWATCHER_TYPE: "multi"
       continue-on-error: true  # not confident yet
-    - name: Run Tests with FastChildWatcher (Linux)
-      # FastChildWatcher is not supported on FreeBSD or MacOS (pty doesn't work).
-      # FastChildWatcher also appears to be unreliable.
-      if: matrix.os == 'ubuntu-latest'
-      run: |
-        $POETRY_RUN python -m pytest -vv -s --log-cli-level=DEBUG
-      env:
-        SHELLOUS_CHILDWATCHER_TYPE: "fast"
-      continue-on-error: true  # FastChildWatcher is unreliable


Test patch:
diff --git a/tests/test_audit.py b/tests/test_audit.py
index 8f239262..4a9e4b90 100644
--- a/tests/test_audit.py
+++ b/tests/test_audit.py
@@ -166,7 +166,10 @@ def _hook(event, args):
     def _callback(phase, info):
         runner = info["runner"]
         failure = info.get("failure")
-        callbacks.append(f"{phase}:{runner.name}:{runner.returncode}:{failure}")
+        exit_code = runner.returncode
+        if exit_code is not None:
+            exit_code = "Zero" if exit_code == 0 else "NonZero"
+        callbacks.append(f"{phase}:{runner.name}:{exit_code}:{failure}")
 
     try:
         _HOOK = _hook
@@ -180,11 +183,10 @@ def _callback(phase, info):
     finally:
         _HOOK = None
 
-    exit_code = 1 if sys.platform == "win32" else -15
     assert callbacks == [
         "start:hello:None:None",
         "start:grep:None:None",
         "stop:grep:None:RuntimeError",
         "signal:hello:None:None",
-        f"stop:hello:{exit_code}:CancelledError",
+        "stop:hello:NonZero:CancelledError",
     ]