From 9705e92052e74f1f8b1b73b5cb63c8e941ff0d5a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexis=20M=C3=A9taireau?= Date: Tue, 26 Nov 2024 17:19:34 +0100 Subject: [PATCH 1/5] Add a `--debug` flag to the CLI to help retrieve more logs When the flag is set, the `RUNSC_DEBUG=1` environment variable is added to the outer container, and stderr is captured in a separate thread, before printing its output. --- dangerzone/cli.py | 9 ++++- dangerzone/isolation_provider/base.py | 41 +++++++++++++++++----- dangerzone/isolation_provider/container.py | 13 +++++-- dangerzone/logic.py | 2 ++ 4 files changed, 54 insertions(+), 11 deletions(-) diff --git a/dangerzone/cli.py b/dangerzone/cli.py index 8f68e62..a8c0c47 100644 --- a/dangerzone/cli.py +++ b/dangerzone/cli.py @@ -42,6 +42,12 @@ def print_header(s: str) -> None: type=click.UNPROCESSED, callback=args.validate_input_filenames, ) +@click.option( + "--debug", + "debug", + flag_value=True, + help="Run Dangerzone in debug mode, to get logs from gVisor.", +) @click.version_option(version=get_version(), message="%(version)s") @errors.handle_document_errors def cli_main( @@ -50,6 +56,7 @@ def cli_main( filenames: List[str], archive: bool, dummy_conversion: bool, + debug: bool, ) -> None: setup_logging() @@ -58,7 +65,7 @@ def cli_main( elif is_qubes_native_conversion(): dangerzone = DangerzoneCore(Qubes()) else: - dangerzone = DangerzoneCore(Container()) + dangerzone = DangerzoneCore(Container(debug=debug)) display_banner() if len(filenames) == 1 and output_filename: diff --git a/dangerzone/isolation_provider/base.py b/dangerzone/isolation_provider/base.py index 7b353b7..de9fd36 100644 --- a/dangerzone/isolation_provider/base.py +++ b/dangerzone/isolation_provider/base.py @@ -5,7 +5,9 @@ import platform import signal import subprocess import sys +import threading from abc import ABC, abstractmethod +from io import BytesIO from typing import IO, Callable, Iterator, Optional import fitz @@ -86,11 +88,17 @@ class IsolationProvider(ABC): Abstracts an isolation provider """ - def __init__(self) -> None: - if getattr(sys, "dangerzone_dev", False) is True: + def __init__(self, debug: bool = False) -> None: + self.debug = debug + if self.should_capture_stderr(): self.proc_stderr = subprocess.PIPE else: self.proc_stderr = subprocess.DEVNULL + # Store the proc stderr in memory + self.stderr = BytesIO() + + def should_capture_stderr(self) -> bool: + return self.debug or getattr(sys, "dangerzone_dev", False) @abstractmethod def install(self) -> bool: @@ -328,6 +336,8 @@ class IsolationProvider(ABC): ) -> Iterator[subprocess.Popen]: """Start a conversion process, pass it to the caller, and then clean it up.""" p = self.start_doc_to_pixels_proc(document) + self.start_stderr_thread(p) + if platform.system() != "Windows": assert os.getpgid(p.pid) != os.getpgid( os.getpid() @@ -343,15 +353,30 @@ class IsolationProvider(ABC): document, p, timeout_grace=timeout_grace, timeout_force=timeout_force ) - # Read the stderr of the process only if: - # * Dev mode is enabled. - # * The process has exited (else we risk hanging). - if getattr(sys, "dangerzone_dev", False) and p.poll() is not None: - assert p.stderr - debug_log = read_debug_text(p.stderr, MAX_CONVERSION_LOG_CHARS) + if self.should_capture_stderr(): + self.stderr.seek(0) + debug_log = read_debug_text(self.stderr, MAX_CONVERSION_LOG_CHARS) log.info( "Conversion output (doc to pixels)\n" f"{DOC_TO_PIXELS_LOG_START}\n" f"{debug_log}" # no need for an extra newline here f"{DOC_TO_PIXELS_LOG_END}" ) + + def start_stderr_thread(self, process: subprocess.Popen) -> None: + """Start a thread to read stderr from the process""" + + def _stream_stderr(process_stderr: IO[bytes]) -> None: + try: + for line in process_stderr: + self.stderr.write(line) + except (ValueError, IOError) as e: + log.debug(f"Stderr stream closed: {e}") + + if process.stderr: + stderr_thread = threading.Thread( + target=_stream_stderr, + args=(process.stderr,), + daemon=True, + ) + stderr_thread.start() diff --git a/dangerzone/isolation_provider/container.py b/dangerzone/isolation_provider/container.py index 1a08385..4fbe20f 100644 --- a/dangerzone/isolation_provider/container.py +++ b/dangerzone/isolation_provider/container.py @@ -154,7 +154,7 @@ class Container(IsolationProvider): args, stdin=subprocess.PIPE, stdout=subprocess.PIPE, - stderr=self.proc_stderr, + stderr=subprocess.PIPE, startupinfo=startupinfo, # Start the conversion process in a new session, so that we can later on # kill the process group, without killing the controlling script. @@ -168,6 +168,10 @@ class Container(IsolationProvider): ) -> subprocess.Popen: container_runtime = container_utils.get_runtime() security_args = self.get_runtime_security_args() + debug_args = [] + if self.debug: + debug_args += ["-e", "RUNSC_DEBUG=1"] + enable_stdin = ["-i"] set_name = ["--name", name] prevent_leakage_args = ["--rm"] @@ -177,6 +181,7 @@ class Container(IsolationProvider): args = ( ["run"] + security_args + + debug_args + prevent_leakage_args + enable_stdin + set_name @@ -184,7 +189,11 @@ class Container(IsolationProvider): + command ) args = [container_runtime] + args - return self.exec(args) + args_str = " ".join(shlex.quote(s) for s in args) + log.info("> " + args_str) + + process = self.exec(args) + return process def kill_container(self, name: str) -> None: """Terminate a spawned container. diff --git a/dangerzone/logic.py b/dangerzone/logic.py index 786fc44..0ee17f6 100644 --- a/dangerzone/logic.py +++ b/dangerzone/logic.py @@ -1,6 +1,7 @@ import concurrent.futures import json import logging +from io import StringIO from typing import Callable, List, Optional import colorama @@ -71,6 +72,7 @@ class DangerzoneCore(object): ocr_lang, stdout_callback, ) + except Exception: log.exception( f"Unexpected error occurred while converting '{document}'" From 3a56f51e941738b27fcaf7474e2a22dc84b0fd06 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexis=20M=C3=A9taireau?= Date: Mon, 13 Jan 2025 15:54:30 +0100 Subject: [PATCH 2/5] FIXUP: join the thread before writing output --- dangerzone/isolation_provider/base.py | 27 +++++++++++++++------- dangerzone/isolation_provider/container.py | 7 +----- 2 files changed, 20 insertions(+), 14 deletions(-) diff --git a/dangerzone/isolation_provider/base.py b/dangerzone/isolation_provider/base.py index de9fd36..653be05 100644 --- a/dangerzone/isolation_provider/base.py +++ b/dangerzone/isolation_provider/base.py @@ -77,9 +77,9 @@ def read_int(f: IO[bytes]) -> int: return int.from_bytes(untrusted_int, "big", signed=False) -def read_debug_text(f: IO[bytes], size: int) -> str: - """Read arbitrarily long text (for debug purposes), and sanitize it.""" - untrusted_text = f.read(size).decode("ascii", errors="replace") +def read_debug_text(text: bytes) -> str: + """Read all the buffer and return a sanitized version""" + untrusted_text = text.decode("ascii", errors="replace") return replace_control_chars(untrusted_text, keep_newlines=True) @@ -336,7 +336,7 @@ class IsolationProvider(ABC): ) -> Iterator[subprocess.Popen]: """Start a conversion process, pass it to the caller, and then clean it up.""" p = self.start_doc_to_pixels_proc(document) - self.start_stderr_thread(p) + stderr_thread = self.start_stderr_thread(p) if platform.system() != "Windows": assert os.getpgid(p.pid) != os.getpgid( @@ -353,17 +353,26 @@ class IsolationProvider(ABC): document, p, timeout_grace=timeout_grace, timeout_force=timeout_force ) - if self.should_capture_stderr(): - self.stderr.seek(0) - debug_log = read_debug_text(self.stderr, MAX_CONVERSION_LOG_CHARS) + if stderr_thread: + # Wait for the thread to complete. If it's still alive, mention it in the debug log. + stderr_thread.join(timeout=1) + + debug_bytes = self.stderr.getvalue() + debug_log = read_debug_text(debug_bytes)[:MAX_CONVERSION_LOG_CHARS] + + incomplete = "(incomplete)\n" if stderr_thread.is_alive() else "" + log.info( "Conversion output (doc to pixels)\n" f"{DOC_TO_PIXELS_LOG_START}\n" f"{debug_log}" # no need for an extra newline here + f"{incomplete}" f"{DOC_TO_PIXELS_LOG_END}" ) - def start_stderr_thread(self, process: subprocess.Popen) -> None: + def start_stderr_thread( + self, process: subprocess.Popen + ) -> Optional[threading.Thread]: """Start a thread to read stderr from the process""" def _stream_stderr(process_stderr: IO[bytes]) -> None: @@ -380,3 +389,5 @@ class IsolationProvider(ABC): daemon=True, ) stderr_thread.start() + return stderr_thread + return None diff --git a/dangerzone/isolation_provider/container.py b/dangerzone/isolation_provider/container.py index 4fbe20f..7200a39 100644 --- a/dangerzone/isolation_provider/container.py +++ b/dangerzone/isolation_provider/container.py @@ -188,12 +188,7 @@ class Container(IsolationProvider): + image_name + command ) - args = [container_runtime] + args - args_str = " ".join(shlex.quote(s) for s in args) - log.info("> " + args_str) - - process = self.exec(args) - return process + return self.exec([container_runtime] + args) def kill_container(self, name: str) -> None: """Terminate a spawned container. From 3b961e6b9009779cd56609459eda84c1bb56469f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexis=20M=C3=A9taireau?= Date: Mon, 13 Jan 2025 16:08:16 +0100 Subject: [PATCH 3/5] FIXUP: Do not attach the stderr to the base object --- dangerzone/isolation_provider/base.py | 12 ++++++------ dangerzone/isolation_provider/container.py | 2 +- dangerzone/logic.py | 1 - 3 files changed, 7 insertions(+), 8 deletions(-) diff --git a/dangerzone/isolation_provider/base.py b/dangerzone/isolation_provider/base.py index 653be05..04cc7e1 100644 --- a/dangerzone/isolation_provider/base.py +++ b/dangerzone/isolation_provider/base.py @@ -94,8 +94,6 @@ class IsolationProvider(ABC): self.proc_stderr = subprocess.PIPE else: self.proc_stderr = subprocess.DEVNULL - # Store the proc stderr in memory - self.stderr = BytesIO() def should_capture_stderr(self) -> bool: return self.debug or getattr(sys, "dangerzone_dev", False) @@ -335,8 +333,10 @@ class IsolationProvider(ABC): timeout_force: int = TIMEOUT_FORCE, ) -> Iterator[subprocess.Popen]: """Start a conversion process, pass it to the caller, and then clean it up.""" + # Store the proc stderr in memory + stderr = BytesIO() p = self.start_doc_to_pixels_proc(document) - stderr_thread = self.start_stderr_thread(p) + stderr_thread = self.start_stderr_thread(p, stderr) if platform.system() != "Windows": assert os.getpgid(p.pid) != os.getpgid( @@ -357,7 +357,7 @@ class IsolationProvider(ABC): # Wait for the thread to complete. If it's still alive, mention it in the debug log. stderr_thread.join(timeout=1) - debug_bytes = self.stderr.getvalue() + debug_bytes = stderr.getvalue() debug_log = read_debug_text(debug_bytes)[:MAX_CONVERSION_LOG_CHARS] incomplete = "(incomplete)\n" if stderr_thread.is_alive() else "" @@ -371,14 +371,14 @@ class IsolationProvider(ABC): ) def start_stderr_thread( - self, process: subprocess.Popen + self, process: subprocess.Popen, stderr: IO[bytes] ) -> Optional[threading.Thread]: """Start a thread to read stderr from the process""" def _stream_stderr(process_stderr: IO[bytes]) -> None: try: for line in process_stderr: - self.stderr.write(line) + stderr.write(line) except (ValueError, IOError) as e: log.debug(f"Stderr stream closed: {e}") diff --git a/dangerzone/isolation_provider/container.py b/dangerzone/isolation_provider/container.py index 7200a39..0c3eb59 100644 --- a/dangerzone/isolation_provider/container.py +++ b/dangerzone/isolation_provider/container.py @@ -125,7 +125,7 @@ class Container(IsolationProvider): with subprocess.Popen( [container_runtime, "image", "ls"], stdout=subprocess.DEVNULL, - stderr=subprocess.PIPE, + stderr=self.proc_stderr, startupinfo=get_subprocess_startupinfo(), ) as p: _, stderr = p.communicate() diff --git a/dangerzone/logic.py b/dangerzone/logic.py index 0ee17f6..eb588b9 100644 --- a/dangerzone/logic.py +++ b/dangerzone/logic.py @@ -1,7 +1,6 @@ import concurrent.futures import json import logging -from io import StringIO from typing import Callable, List, Optional import colorama From f6a616f23b3323c640a461abee0a1b945e463d88 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexis=20M=C3=A9taireau?= Date: Mon, 13 Jan 2025 16:15:10 +0100 Subject: [PATCH 4/5] FIXUP: use proc_stderr when needed --- dangerzone/isolation_provider/container.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/dangerzone/isolation_provider/container.py b/dangerzone/isolation_provider/container.py index 0c3eb59..27383ac 100644 --- a/dangerzone/isolation_provider/container.py +++ b/dangerzone/isolation_provider/container.py @@ -125,7 +125,7 @@ class Container(IsolationProvider): with subprocess.Popen( [container_runtime, "image", "ls"], stdout=subprocess.DEVNULL, - stderr=self.proc_stderr, + stderr=subprocess.PIPE, startupinfo=get_subprocess_startupinfo(), ) as p: _, stderr = p.communicate() @@ -154,7 +154,7 @@ class Container(IsolationProvider): args, stdin=subprocess.PIPE, stdout=subprocess.PIPE, - stderr=subprocess.PIPE, + stderr=self.proc_stderr, startupinfo=startupinfo, # Start the conversion process in a new session, so that we can later on # kill the process group, without killing the controlling script. From 8532688bab6b292c4690a751de1547ffd9d7363c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexis=20M=C3=A9taireau?= Date: Tue, 14 Jan 2025 14:30:48 +0100 Subject: [PATCH 5/5] FIXUP: remove string tailcut, rename function --- dangerzone/isolation_provider/base.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/dangerzone/isolation_provider/base.py b/dangerzone/isolation_provider/base.py index 04cc7e1..4a074a5 100644 --- a/dangerzone/isolation_provider/base.py +++ b/dangerzone/isolation_provider/base.py @@ -20,7 +20,6 @@ from ..util import get_tessdata_dir, replace_control_chars log = logging.getLogger(__name__) -MAX_CONVERSION_LOG_CHARS = 150 * 50 # up to ~150 lines of 50 characters DOC_TO_PIXELS_LOG_START = "----- DOC TO PIXELS LOG START -----" DOC_TO_PIXELS_LOG_END = "----- DOC TO PIXELS LOG END -----" @@ -77,7 +76,7 @@ def read_int(f: IO[bytes]) -> int: return int.from_bytes(untrusted_int, "big", signed=False) -def read_debug_text(text: bytes) -> str: +def sanitize_debug_text(text: bytes) -> str: """Read all the buffer and return a sanitized version""" untrusted_text = text.decode("ascii", errors="replace") return replace_control_chars(untrusted_text, keep_newlines=True) @@ -358,7 +357,7 @@ class IsolationProvider(ABC): stderr_thread.join(timeout=1) debug_bytes = stderr.getvalue() - debug_log = read_debug_text(debug_bytes)[:MAX_CONVERSION_LOG_CHARS] + debug_log = sanitize_debug_text(debug_bytes) incomplete = "(incomplete)\n" if stderr_thread.is_alive() else ""