Skip to content

Commit c54bdfb

Browse files
committed
env_run: capture and log subprocess streams centrally
Previously `subprocess.run` inherited stdio, so each adapter call site was on its own for surfacing what the subprocess actually printed — nobody did, and failures left the user with just a non-zero return code and no traceback. Capture stdout and stderr in `run_in_conda_env` (`capture_output=True, text=True`) and log centrally: - non-zero return: `logger.warning` with script path, return code, stdout, and stderr. - success: `logger.debug` with script path and the captured streams, for post-mortem when something downstream of the subprocess goes wrong. The captured streams remain on the returned `CompletedProcess`, so adapters that want to inspect them still can. Adapter-side `if returncode: logger.warning(job-context...)` calls stay — they add job/species context the helper doesn't have — but they no longer need to also re-implement capture and stream rendering. `--no-capture-output` for conda/mamba is still correct: it tells the launcher to forward child stdio to its own stdio (which subprocess then captures via the pipe), avoiding conda's internal buffering. Micromamba already streams by default and rejects the flag.
1 parent 01301ef commit c54bdfb

2 files changed

Lines changed: 71 additions & 8 deletions

File tree

arc/job/env_run.py

Lines changed: 20 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -105,9 +105,14 @@ def run_in_conda_env(
105105
"""Run ``python script_path *script_args`` inside the env that owns
106106
``python_executable``, isolated from ARC's process env.
107107
108-
Returns the :class:`subprocess.CompletedProcess`. ``check=True``
109-
raises on non-zero exit. Args are passed as a list, so no shell
110-
quoting concerns.
108+
stdout and stderr are captured and logged centrally — debug on
109+
success, warning (with both streams and the return code) on
110+
non-zero exit — so call sites don't each re-implement capture and
111+
error reporting. The captured streams are also exposed on the
112+
returned :class:`subprocess.CompletedProcess` (``.stdout`` /
113+
``.stderr``) for callers that need to inspect them. ``check=True``
114+
raises ``CalledProcessError`` on non-zero exit. Args are passed as
115+
a list, so no shell quoting concerns.
111116
"""
112117
env_prefix = env_prefix_from_python(python_executable)
113118
launcher, extra_flags = _detect_launcher()
@@ -118,4 +123,15 @@ def run_in_conda_env(
118123
*script_args,
119124
]
120125
logger.debug("env-run: %s", " ".join(argv))
121-
return subprocess.run(argv, check=check)
126+
result = subprocess.run(argv, check=check, capture_output=True, text=True)
127+
if result.returncode:
128+
logger.warning(
129+
"env-run: %s exited with %d\nstdout:\n%s\nstderr:\n%s",
130+
script_path, result.returncode, result.stdout, result.stderr,
131+
)
132+
else:
133+
logger.debug(
134+
"env-run: %s exited 0\nstdout:\n%s\nstderr:\n%s",
135+
script_path, result.stdout, result.stderr,
136+
)
137+
return result

arc/job/env_run_test.py

Lines changed: 51 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
This module contains unit tests of the arc.job.env_run module.
66
"""
77

8+
import subprocess
89
import unittest
910
from unittest.mock import patch
1011

@@ -16,6 +17,12 @@
1617
)
1718

1819

20+
def _completed(returncode=0, stdout='', stderr=''):
21+
"""Build a CompletedProcess for mocking subprocess.run."""
22+
return subprocess.CompletedProcess(args=[], returncode=returncode,
23+
stdout=stdout, stderr=stderr)
24+
25+
1926
class TestEnvPrefixFromPython(unittest.TestCase):
2027
"""env_prefix_from_python should derive the env prefix from any
2128
interpreter path, not assume a literal envs/ segment."""
@@ -121,7 +128,8 @@ class TestRunInCondaEnv(unittest.TestCase):
121128
def test_argv_uses_prefix_and_extra_flags(self):
122129
with patch('arc.job.env_run._detect_launcher',
123130
return_value=('/opt/conda/bin/conda', ['--no-capture-output'])), \
124-
patch('arc.job.env_run.subprocess.run') as mock_run:
131+
patch('arc.job.env_run.subprocess.run',
132+
return_value=_completed()) as mock_run:
125133
run_in_conda_env(
126134
'/opt/conda/envs/tst_env/bin/python',
127135
'/path/to/script.py',
@@ -138,13 +146,18 @@ def test_argv_uses_prefix_and_extra_flags(self):
138146
'--flag', 'value',
139147
],
140148
)
149+
# Streams must be captured so the helper can log them centrally.
150+
kwargs = mock_run.call_args.kwargs
151+
self.assertTrue(kwargs.get('capture_output'))
152+
self.assertTrue(kwargs.get('text'))
141153
# No shell=True — args go through as a list.
142-
self.assertNotIn('shell', mock_run.call_args.kwargs)
154+
self.assertNotIn('shell', kwargs)
143155

144156
def test_micromamba_omits_no_capture_flag(self):
145157
with patch('arc.job.env_run._detect_launcher',
146158
return_value=('/usr/bin/micromamba', [])), \
147-
patch('arc.job.env_run.subprocess.run') as mock_run:
159+
patch('arc.job.env_run.subprocess.run',
160+
return_value=_completed()) as mock_run:
148161
run_in_conda_env(
149162
'/scratch/envs/ts_gcn/bin/python',
150163
'/path/to/gcn.py',
@@ -162,14 +175,48 @@ def test_micromamba_omits_no_capture_flag(self):
162175
def test_check_kwarg_passes_through(self):
163176
with patch('arc.job.env_run._detect_launcher',
164177
return_value=('/opt/conda/bin/conda', ['--no-capture-output'])), \
165-
patch('arc.job.env_run.subprocess.run') as mock_run:
178+
patch('arc.job.env_run.subprocess.run',
179+
return_value=_completed()) as mock_run:
166180
run_in_conda_env(
167181
'/opt/conda/envs/tst_env/bin/python',
168182
'/path/to/script.py',
169183
check=True,
170184
)
171185
self.assertTrue(mock_run.call_args.kwargs.get('check'))
172186

187+
def test_failure_logs_warning_with_captured_streams(self):
188+
completed = _completed(returncode=2, stdout='partial output\n',
189+
stderr='Traceback...\nValueError: boom\n')
190+
with patch('arc.job.env_run._detect_launcher',
191+
return_value=('/opt/conda/bin/conda', ['--no-capture-output'])), \
192+
patch('arc.job.env_run.subprocess.run', return_value=completed), \
193+
patch('arc.job.env_run.logger') as mock_logger:
194+
result = run_in_conda_env(
195+
'/opt/conda/envs/tst_env/bin/python',
196+
'/path/to/script.py',
197+
)
198+
self.assertEqual(result.returncode, 2)
199+
mock_logger.warning.assert_called_once()
200+
# Render the warning to verify it carries the actual stderr contents.
201+
fmt, *args = mock_logger.warning.call_args.args
202+
rendered = fmt % tuple(args)
203+
self.assertIn('ValueError: boom', rendered)
204+
self.assertIn('partial output', rendered)
205+
self.assertIn('/path/to/script.py', rendered)
206+
207+
def test_success_logs_debug_not_warning(self):
208+
with patch('arc.job.env_run._detect_launcher',
209+
return_value=('/opt/conda/bin/conda', ['--no-capture-output'])), \
210+
patch('arc.job.env_run.subprocess.run',
211+
return_value=_completed(stdout='ok\n')), \
212+
patch('arc.job.env_run.logger') as mock_logger:
213+
run_in_conda_env(
214+
'/opt/conda/envs/tst_env/bin/python',
215+
'/path/to/script.py',
216+
)
217+
mock_logger.warning.assert_not_called()
218+
mock_logger.debug.assert_called()
219+
173220

174221
if __name__ == '__main__':
175222
unittest.main()

0 commit comments

Comments
 (0)