Add logging for NsJail

NsJail's is configured to log to a temporary file rather than stderr.
The contents of the file are parsed using regex after the process exits.
When not debugging, some blacklisted messages and most info-level
messages are skipped.

* Add a snekbox logger
* Log the Python code being executed if debugging
* Use nested single quotes in a test to fix a linter error

3 files changed, 90 insertions, 28 deletions

diff --git a/snekbox/__init__.py b/snekbox/__init__.py
index af8429b..a48abd5 100644
--- a/snekbox/__init__.py
+++ b/snekbox/__init__.py
@@ -1,5 +1,6 @@
 import logging
 import os
+import sys
 
 from gunicorn import glogging
 
@@ -22,3 +23,12 @@ class GunicornLogger(glogging.Logger):
             self.loglevel = self.LOG_LEVELS.get(cfg.loglevel.lower(), logging.INFO)
 
         self.error_log.setLevel(self.loglevel)
+
+
+log = logging.getLogger("snekbox")
+log.setLevel(logging.DEBUG if DEBUG else logging.INFO)
+log.propagate = True
+formatter = logging.Formatter(GunicornLogger.error_fmt, GunicornLogger.datefmt)
+handler = logging.StreamHandler(sys.stdout)
+handler.setFormatter(formatter)
+log.addHandler(handler)
diff --git a/snekbox/nsjail.py b/snekbox/nsjail.py
index 2484ba2..0ebfe0c 100644
--- a/snekbox/nsjail.py
+++ b/snekbox/nsjail.py
@@ -1,6 +1,20 @@
+import logging
+import re
 import subprocess
 import sys
+import textwrap
 from pathlib import Path
+from tempfile import NamedTemporaryFile
+
+from snekbox import DEBUG
+
+log = logging.getLogger(__name__)
+
+# [level][timestamp][PID]? function_signature:line_no? message
+LOG_PATTERN = re.compile(
+    r"\[(?P<level>(I)|[WEF])\]\[.+?\](?(2)|(?P<func>\[\d+\] .+?:\d+ )) ?(?P<msg>.+)"
+)
+LOG_BLACKLIST = ("Process will be ",)
 
 # Explicitly define constants for NsJail's default values.
 CGROUP_PIDS_PARENT = Path("/sys/fs/cgroup/pids/NSJAIL")
@@ -56,39 +70,77 @@ class NsJail:
         pids.mkdir(parents=True, exist_ok=True)
         mem.mkdir(parents=True, exist_ok=True)
 
+    @staticmethod
+    def _parse_log(log_file):
+        """Parse and log NsJail's log messages."""
+        for line in log_file.read().decode("UTF-8").splitlines():
+            match = LOG_PATTERN.fullmatch(line)
+            if match is None:
+                log.warning(f"Failed to parse log line '{line}'")
+                continue
+
+            msg = match["msg"]
+            if not DEBUG and any(msg.startswith(s) for s in LOG_BLACKLIST):
+                # Skip blacklisted messages if not debugging.
+                continue
+
+            if DEBUG and match["func"]:
+                # Prepend PID, function signature, and line number if debugging.
+                msg = f"{match['func']}{msg}"
+
+            if match["level"] == "D":
+                log.debug(msg)
+            elif match["level"] == "I":
+                if DEBUG or msg.startswith("pid="):
+                    # Skip messages unrelated to process exit if not debugging.
+                    log.info(msg)
+            elif match["level"] == "W":
+                log.warning(msg)
+            else:
+                # Treat fatal as error.
+                log.error(msg)
+
     def python3(self, code: str) -> str:
         """Execute Python 3 code in an isolated environment and return stdout or an error."""
-        args = (
-            self.nsjail_binary, "-Mo",
-            "--rlimit_as", "700",
-            "--chroot", "/",
-            "-E", "LANG=en_US.UTF-8",
-            "-R/usr", "-R/lib", "-R/lib64",
-            "--user", "nobody",
-            "--group", "nogroup",
-            "--time_limit", "2",
-            "--disable_proc",
-            "--iface_no_lo",
-            "--cgroup_mem_max=52428800",
-            "--cgroup_mem_mount", str(CGROUP_MEMORY_PARENT.parent),
-            "--cgroup_mem_parent", CGROUP_MEMORY_PARENT.name,
-            "--cgroup_pids_max=1",
-            "--cgroup_pids_mount", str(CGROUP_PIDS_PARENT.parent),
-            "--cgroup_pids_parent", CGROUP_PIDS_PARENT.name,
-            "--quiet", "--",
-            self.python_binary, "-ISq", "-c", code
-        )
-
-        try:
-            proc = subprocess.run(args, capture_output=True, env=ENV, text=True)
-        except ValueError:
-            return "ValueError: embedded null byte"
+        with NamedTemporaryFile() as nsj_log:
+            args = (
+                self.nsjail_binary, "-Mo",
+                "--rlimit_as", "700",
+                "--chroot", "/",
+                "-E", "LANG=en_US.UTF-8",
+                "-R/usr", "-R/lib", "-R/lib64",
+                "--user", "nobody",
+                "--group", "nogroup",
+                "--time_limit", "2",
+                "--disable_proc",
+                "--iface_no_lo",
+                "--log", nsj_log.name,
+                "--cgroup_mem_max=52428800",
+                "--cgroup_mem_mount", str(CGROUP_MEMORY_PARENT.parent),
+                "--cgroup_mem_parent", CGROUP_MEMORY_PARENT.name,
+                "--cgroup_pids_max=1",
+                "--cgroup_pids_mount", str(CGROUP_PIDS_PARENT.parent),
+                "--cgroup_pids_parent", CGROUP_PIDS_PARENT.name,
+                "--",
+                self.python_binary, "-ISq", "-c", code
+            )
+
+            try:
+                msg = "Executing code..."
+                if DEBUG:
+                    msg = f"{msg[:-3]}:\n{textwrap.indent(code, '    ')}"
+                log.info(msg)
+
+                proc = subprocess.run(args, capture_output=True, env=ENV, text=True)
+            except ValueError:
+                return "ValueError: embedded null byte"
+
+            self._parse_log(nsj_log)
 
         if proc.returncode == 0:
             output = proc.stdout
         elif proc.returncode == 1:
-            filtered = (line for line in proc.stderr.split("\n") if not line.startswith("["))
-            output = "\n".join(filtered)
+            output = proc.stderr
         elif proc.returncode == 109:
             return "timed out or memory limit exceeded"
         elif proc.returncode == 255:
diff --git a/tests/api/test_eval.py b/tests/api/test_eval.py
index a5b83fd..bcd0ec4 100644
--- a/tests/api/test_eval.py
+++ b/tests/api/test_eval.py
@@ -26,7 +26,7 @@ class TestEvalResource(SnekAPITestCase):
         self.assertEqual(expected, result.json)
 
     def test_post_invalid_content_type_415(self):
-        body = "{\"input\": \"foo\"}"
+        body = "{'input': 'foo'}"
         headers = {"Content-Type": "application/xml"}
         result = self.simulate_post(self.PATH, body=body, headers=headers)