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

@@ -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:

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()

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.

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}'"