Merge pull request #13 from replit/th-multiple-log-files

Better logging

Author: airportyh

scripts/mypython

@@ -3,6 +3,7 @@
 # A python wrapper that uses LD_AUDIT with rtld loader for testing.
 
 export PYTHONPATH=${REPL_HOME}/.pythonlibs/lib/python3.10/site-packages
+export REPLIT_RTLD_LOG_LEVEL=2
 export LD_LIBRARY_PATH=
 export LD_AUDIT=$REPL_HOME/rtld_loader.so
 exec "python3" "$@"

src/logging.c

@@ -3,6 +3,9 @@
 #include "string_funs.h"
 #include "syscalls.h"
 
+#define LOG_FILE_PREFIX "rtld_loader.log."
+#define LOG_FILE_PREFIX_LENGTH 16
+
 static int audit_log_fd = -1;
 static int log_level;
 
@@ -17,11 +20,49 @@ void fprint_int(int fd, int num) {
   sys_write(fd, int_str, len);
 }
 
+// For troubleshooting purposes: output contents of /proc/self/cmdline to the
+// log file
+void _output_cmdline() {
+  char buf[1024];
+  if (log_level < INFO) {
+    return;
+  }
+  log_info("cmdline: ");
+  int cmdline_fd = sys_open("/proc/self/cmdline", O_RDONLY, 0);
+  while (1) {
+    int bytes = sys_read(cmdline_fd, buf, sizeof(buf));
+    if (bytes <= 0) {
+      break;
+    }
+    sys_write(audit_log_fd, buf, bytes);
+  }
+  log_info("\n");
+  sys_close(cmdline_fd);
+}
+
 void log_init(int ll) {
   log_level = ll;
   if (log_level > 0) {
-    audit_log_fd =
-        sys_open("rtld_loader.log", O_WRONLY | O_CREAT | O_TRUNC, 0644);
+    // Generated a log file name with a numeric suffix, i.e. rtld_loader.log.1
+    // if the file already exists, increment the suffix
+    char log_filename[LOG_FILE_PREFIX_LENGTH + MAX_DECIMAL_INT_LEN + 1];
+    my_strncpy(log_filename, LOG_FILE_PREFIX, LOG_FILE_PREFIX_LENGTH);
+    int suffix = 1;
+    while (1) {
+      int suffix_len = itoa(suffix, log_filename + LOG_FILE_PREFIX_LENGTH, 10);
+      log_filename[LOG_FILE_PREFIX_LENGTH + suffix_len] = '\0';
+      if (sys_access(log_filename, R_OK) == 0) {
+        // file already exists, try the next suffix
+        suffix++;
+      } else {
+        // we can use this one
+        audit_log_fd =
+            sys_open(log_filename, O_WRONLY | O_CREAT | O_TRUNC, 0644);
+        break;
+      }
+    }
+
+    _output_cmdline();
   }
 }
 

test/integration_tests.py

@@ -16,6 +16,7 @@ def realize(pkgpath):
 realize(ace)
 
 def test_ace_dynamic():
+  subprocess.run(["bash", "-c", "rm rtld_loader.log.*"])
   code = "import ctypes; print(ctypes.cdll.LoadLibrary('libACE_ETCL.so'))"
 
   env = rtld_env.copy()
@@ -26,8 +27,31 @@ def test_ace_dynamic():
     ["%s/bin/python" % python_23_11, '-c', code],
     env = env
   )
-  
+
+  print(str(output, 'UTF-8'))
   assert str(output, 'UTF-8').startswith("<CDLL 'libACE_ETCL.so'")
   print('OK test_ace_dynamic')
 
-test_ace_dynamic()
+def test_multiple_logs_for_subprocess():
+  subprocess.run(["bash", "-c", "rm rtld_loader.log.*"])
+  code = "import subprocess; subprocess.run(['echo', 'hello, world!'])"
+  output = subprocess.check_output(
+    ["%s/bin/python" % python_23_11, '-c', code],
+    env = {
+      "LD_AUDIT": "%s/rtld_loader.so" % pwd,
+      "REPLIT_RTLD_LOG_LEVEL": "3"
+    }
+  )
+  assert os.path.exists("rtld_loader.log.1")
+  assert os.path.exists("rtld_loader.log.2")
+  with open("rtld_loader.log.1", "r") as f:
+    content = f.read()
+    assert "/bin/python" in content
+  with open("rtld_loader.log.2", "r") as f:
+    content = f.read()
+    assert "echo" in content
+    assert "hello, world!" in content
+  print('OK test_multiple_logs_for_subprocess')
+
+test_ace_dynamic()
+test_multiple_logs_for_subprocess()