Log subprocess input and output

pyk/src/pyk/kbuild/utils.py

@@ -7,7 +7,7 @@
 from typing import TYPE_CHECKING, final
 
 from ..cli.utils import check_dir_path, check_file_path
-from ..utils import run_process
+from ..utils import run_process_2
 
 if TYPE_CHECKING:
     from collections.abc import Iterable
@@ -71,7 +71,7 @@ def text(self) -> str:
 
 def k_version() -> KVersion:
     try:
-        proc_res = run_process(['kompile', '--version'], pipe_stderr=True)
+        proc_res = run_process_2(['kompile', '--version'])
     except FileNotFoundError as err:
         raise RuntimeError('K is not installed') from err
 

pyk/src/pyk/kllvm/compiler.py

@@ -7,7 +7,7 @@
 from typing import TYPE_CHECKING
 
 from ..cli.utils import check_dir_path, check_file_path
-from ..utils import run_process
+from ..utils import run_process_2
 
 if TYPE_CHECKING:
     from collections.abc import Iterable
@@ -37,7 +37,7 @@ def compile_kllvm(target_dir: str | Path, *, verbose: bool = False) -> Path:
         args += ['--verbose']
 
     _LOGGER.info(f'Compiling pythonast extension: {module_file.name}')
-    run_process(args, logger=_LOGGER)
+    run_process_2(args, logger=_LOGGER)
 
     assert module_file.is_file()
     return module_file
@@ -87,7 +87,7 @@ def compile_runtime(
         args += ccopts
 
     _LOGGER.info(f'Compiling python extension: {module_file.name}')
-    run_process(args, logger=_LOGGER)
+    run_process_2(args, logger=_LOGGER)
 
     assert module_file.is_file()
     return module_file
@@ -123,7 +123,7 @@ def generate_hints(
 
     args = [str(interpreter), str(input_kore_file), '-1', str(hints_file), '--proof-output']
     _LOGGER.info(f'Generating hints: {hints_file.name}')
-    run_process(args, logger=_LOGGER)
+    run_process_2(args, logger=_LOGGER)
 
     assert hints_file.is_file()
 

pyk/src/pyk/kllvm/load_static.py

@@ -3,7 +3,7 @@
 from pathlib import Path
 from typing import TYPE_CHECKING
 
-from ..utils import run_process
+from ..utils import run_process_2
 from .importer import import_kllvm
 
 if TYPE_CHECKING:
@@ -12,7 +12,7 @@
 
 def get_kllvm() -> Path:
     args = ['llvm-kompile', '--bindings-path']
-    proc = run_process(args, pipe_stdout=True)
+    proc = run_process_2(args)
     bindings_dir = Path(proc.stdout.rstrip()).resolve()
     kllvm_dir = bindings_dir / 'kllvm'
     return kllvm_dir

pyk/src/pyk/kore/rpc.py

@@ -19,7 +19,7 @@
 
 from psutil import Process
 
-from ..utils import FrozenDict, check_dir_path, check_file_path, filter_none, run_process
+from ..utils import FrozenDict, check_dir_path, check_file_path, filter_none, run_process_2
 from . import manip
 from .prelude import SORT_GENERATED_TOP_CELL
 from .syntax import And, Equals, EVar, kore_term
@@ -1281,7 +1281,7 @@ def _extra_args(self) -> list[str]:
     def _populate_bug_report(self, bug_report: BugReport) -> None:
         prog_name = self._command[0]
         bug_report.add_file(self._definition_file, Path('definition.kore'))
-        version_info = run_process((prog_name, '--version'), pipe_stderr=True, logger=_LOGGER).stdout.strip()
+        version_info = run_process_2((prog_name, '--version'), logger=_LOGGER).stdout.strip()
         bug_report.add_file_contents(version_info, Path('server_version.txt'))
         server_instance = {
             'exe': prog_name,
@@ -1387,7 +1387,7 @@ def _extra_args(self) -> list[str]:
     def _populate_bug_report(self, bug_report: BugReport) -> None:
         super()._populate_bug_report(bug_report)
         bug_report.add_file(self._llvm_definition, Path('llvm_definition/definition.kore'))
-        llvm_version = run_process('llvm-backend-version', pipe_stderr=True, logger=_LOGGER).stdout.strip()
+        llvm_version = run_process_2('llvm-backend-version', logger=_LOGGER).stdout.strip()
         bug_report.add_file_contents(llvm_version, Path('llvm_version.txt'))
 
 

pyk/src/pyk/kore/tools.py

@@ -5,7 +5,7 @@
 from typing import TYPE_CHECKING
 
 from ..cli.utils import check_dir_path, check_file_path
-from ..utils import run_process
+from ..utils import run_process_2
 
 if TYPE_CHECKING:
     from .syntax import Pattern
@@ -79,5 +79,5 @@ def _kore_print(
     if color is not None:
         args += ['--color', 'on' if color else 'off']
 
-    run_res = run_process(args, input=input)
+    run_res = run_process_2(args, input=input)
     return run_res.stdout.strip()

pyk/src/pyk/ktool/kompile.py

@@ -15,7 +15,7 @@
 from subprocess import CalledProcessError
 from typing import TYPE_CHECKING, final
 
-from ..utils import abs_or_rel_to, check_dir_path, check_file_path, run_process, single
+from ..utils import abs_or_rel_to, check_dir_path, check_file_path, run_process_2, single
 from . import TypeInferenceMode
 
 if TYPE_CHECKING:
@@ -332,7 +332,7 @@ def __call__(
             args += ['-Wno', ','.join(ignore_warnings)]
 
         try:
-            proc_res = run_process(args, logger=_LOGGER, cwd=cwd, check=check)
+            proc_res = run_process_2(args, write_stderr=True, logger=_LOGGER, cwd=cwd, check=check)
         except CalledProcessError as err:
             raise RuntimeError(
                 f'Command kompile exited with code {err.returncode} for: {self.base_args.main_file}',

pyk/src/pyk/ktool/kprint.py

@@ -19,7 +19,7 @@
 from ..kore.parser import KoreParser
 from ..kore.syntax import App, SortApp
 from ..kore.tools import PrintOutput, kore_print
-from ..utils import run_process
+from ..utils import run_process_2
 from .kompile import DefinitionInfo
 
 if TYPE_CHECKING:
@@ -108,7 +108,7 @@ def _kast(
     )
 
     try:
-        return run_process(args, logger=_LOGGER, check=check)
+        return run_process_2(args, write_stderr=True, logger=_LOGGER, check=check)
     except CalledProcessError as err:
         raise RuntimeError(
             f'Command kast exited with code {err.returncode} for: {file}', err.stdout, err.stderr

pyk/src/pyk/ktool/kprove.py

@@ -19,7 +19,7 @@
 from ..kast.outer import KDefinition, KFlatModule, KFlatModuleList, KImport, KRequire
 from ..kore.rpc import KoreExecLogFormat
 from ..prelude.ml import is_top
-from ..utils import gen_file_timestamp, run_process
+from ..utils import gen_file_timestamp, run_process_2
 from . import TypeInferenceMode
 from .claim_index import ClaimIndex
 from .kprint import KPrint
@@ -98,7 +98,7 @@ def _kprove(
 
     try:
         run_args = tuple(chain(command, [str(spec_file)], typed_args, args))
-        return run_process(run_args, logger=_LOGGER, env=env, check=check)
+        return run_process_2(run_args, write_stderr=True, logger=_LOGGER, env=env, check=check)
     except CalledProcessError as err:
         raise RuntimeError(
             f'Command kprove exited with code {err.returncode} for: {spec_file}', err.stdout, err.stderr, err

pyk/src/pyk/ktool/krun.py

@@ -9,7 +9,7 @@
 from ..cli.utils import check_dir_path, check_file_path
 from ..kore.parser import KoreParser
 from ..kore.tools import PrintOutput, kore_print
-from ..utils import run_process
+from ..utils import run_process, run_process_2
 from .kprint import KPrint
 
 if TYPE_CHECKING:
@@ -344,4 +344,4 @@ def llvm_interpret_raw(definition_dir: str | Path, kore: str, depth: int | None
     depth = depth if depth is not None else -1
     args = [str(interpreter_file), '/dev/stdin', str(depth), '/dev/stdout']
 
-    return run_process(args, input=kore, pipe_stderr=True)
+    return run_process_2(args, input=kore)

pyk/src/pyk/utils.py

@@ -8,19 +8,21 @@
 import subprocess
 import sys
 import tarfile
+import threading
 import time
 from collections.abc import Hashable, Mapping
 from dataclasses import dataclass
 from datetime import datetime
 from pathlib import Path
+from subprocess import CompletedProcess, Popen
 from tempfile import NamedTemporaryFile
 from typing import TYPE_CHECKING, Generic, TypeVar, cast, final, overload
 
 if TYPE_CHECKING:
     from collections.abc import Callable, Iterable, Iterator
     from logging import Logger
-    from subprocess import CalledProcessError, CompletedProcess
-    from typing import Any, Final
+    from subprocess import CalledProcessError
+    from typing import IO, Any, Final
 
     P1 = TypeVar('P1')
     P2 = TypeVar('P2')
@@ -453,6 +455,154 @@ def run_process(
     return res
 
 
+def run_process_2(
+    args: str | Iterable[str],
+    *,
+    input: str | None = None,
+    write_stdout: bool = False,
+    write_stderr: bool = False,
+    cwd: str | Path | None = None,
+    env: Mapping[str, str] | None = None,
+    logger: Logger | None = None,
+    check: bool = True,
+) -> CompletedProcess:
+    if type(args) is str:
+        args = (args,)
+    else:
+        args = tuple(args)
+
+    if cwd is not None:
+        cwd = Path(cwd)
+        check_dir_path(cwd)
+
+    if not logger:
+        logger = _LOGGER
+
+    res = _subprocess_run(
+        args,
+        input=input,
+        write_stdout=write_stdout,
+        write_stderr=write_stderr,
+        cwd=cwd,
+        env=env,
+        logger=logger,
+    )
+
+    if check:
+        res.check_returncode()
+
+    return res
+
+
+def _subprocess_run(
+    args: tuple[Any, ...],
+    *,
+    input: str | None,
+    write_stdout: bool,
+    write_stderr: bool,
+    env: Mapping[str, str] | None,
+    cwd: Path | None,
+    logger: Logger,
+) -> CompletedProcess:
+    with Popen(
+        args,
+        stdin=subprocess.PIPE if input is not None else subprocess.DEVNULL,
+        stdout=subprocess.PIPE,
+        stderr=subprocess.PIPE,
+        env=env,
+        cwd=cwd,
+        text=True,
+    ) as popen:
+        log_prefix = f'[PID={popen.pid}]'
+
+        command = shlex.join(args)
+        for line in command.split('\n'):
+            logger.info(f'{log_prefix}[exec] {line}')
+
+        start_time = time.time()
+
+        try:
+            returncode, stdout, stderr = _subprocess_communicate(
+                popen,
+                input=input,
+                logger=logger,
+                write_stdout=write_stdout,
+                write_stderr=write_stderr,
+            )
+        except BaseException:
+            popen.kill()
+            delta_time = time.time() - start_time
+            logger.info(f'{log_prefix}[fail] time={delta_time:.3f}s')
+            raise
+
+    delta_time = time.time() - start_time
+    logger.info(f'{log_prefix}[done] status={returncode} time={delta_time:.3f}s')
+
+    return CompletedProcess(popen.args, returncode, stdout, stderr)
+
+
+def _subprocess_communicate(
+    popen: Popen,
+    *,
+    input: str | None,
+    write_stdout: bool,
+    write_stderr: bool,
+    logger: Logger,
+) -> tuple[int, str, str]:
+    assert popen.stdout is not None
+    assert popen.stderr is not None
+
+    log_prefix = f'[PID={popen.pid}]'
+
+    def readerthread(
+        input_fh: IO[str],
+        buffer: list[str],
+        stream_prefix: str,
+        output_fh: IO[str] | None,
+    ) -> None:
+        for line in input_fh:
+            buffer.append(line)
+            logger.info(f'{log_prefix}{stream_prefix} {line.rstrip()}')
+            if output_fh:
+                output_fh.write(line)
+                output_fh.flush()
+        input_fh.close()
+
+    stdout_buff: list[str] = []
+    stdout_prefix = '[stdo]'
+    stdout_fh = sys.stdout if write_stdout else None
+    stdout_thread = threading.Thread(target=readerthread, args=(popen.stdout, stdout_buff, stdout_prefix, stdout_fh))
+    stdout_thread.daemon = True
+    stdout_thread.start()
+
+    stderr_buff: list[str] = []
+    stderr_prefix = '[stde]'
+    stderr_fh = sys.stderr if write_stderr else None
+    stderr_thread = threading.Thread(target=readerthread, args=(popen.stderr, stderr_buff, stderr_prefix, stderr_fh))
+    stderr_thread.daemon = True
+    stderr_thread.start()
+
+    if input is not None:
+        assert popen.stdin is not None
+        for line in input.split('\n'):
+            logger.info(f'{log_prefix}[stdi] {line}')
+        # Note: popen.stdin.write does not work for llvm_interpret_raw
+        popen._stdin_write(input)  # type: ignore [attr-defined]
+
+    stdout_thread.join()
+    stderr_thread.join()
+
+    # Should be closed by readerthread at this point
+    # popen.stdout.close()
+    # popen.stderr.close()
+
+    returncode = popen.wait()
+    stdout = ''.join(stdout_buff)
+    stderr = ''.join(stderr_buff)
+
+    return returncode, stdout, stderr
+
+
 def exit_with_process_error(err: CalledProcessError) -> None:
     sys.stderr.write(f'[ERROR] Running process failed with returncode {err.returncode}:\n    {shlex.join(err.cmd)}\n')
     sys.stderr.flush()