From f5eee734ce9cfc255aa2636caf372086e8e442e4 Mon Sep 17 00:00:00 2001
From: Googler <noreply@google.com>
Date: Tue, 22 Sep 2020 18:01:18 -0700
Subject: [PATCH] linux-sandbox: improve commenting and debug logging.

In particular, include timestamps and make it clear when clone and fork start
and return.

PiperOrigin-RevId: 333198030
---
 src/main/tools/linux-sandbox-pid1.cc |  5 +++++
 src/main/tools/linux-sandbox.cc      | 14 ++++++++++++++
 src/main/tools/logging.h             | 22 ++++++++++++++++------
 3 files changed, 35 insertions(+), 6 deletions(-)

diff --git a/src/main/tools/linux-sandbox-pid1.cc b/src/main/tools/linux-sandbox-pid1.cc
index 82f228b4071151..ae7bc4a30748de 100644
--- a/src/main/tools/linux-sandbox-pid1.cc
+++ b/src/main/tools/linux-sandbox-pid1.cc
@@ -397,6 +397,7 @@ static void SetupSignalHandlers() {
 }
 
 static void SpawnChild() {
+  PRINT_DEBUG("calling fork...");
   global_child_pid = fork();
 
   if (global_child_pid < 0) {
@@ -425,6 +426,8 @@ static void SpawnChild() {
     if (execvp(opt.args[0], opt.args.data()) < 0) {
       DIE("execvp(%s, %p)", opt.args[0], opt.args.data());
     }
+  } else {
+    PRINT_DEBUG("child started with PID %d", global_child_pid);
   }
 }
 
@@ -465,6 +468,8 @@ static int WaitForChild() {
 }
 
 int Pid1Main(void *sync_pipe_param) {
+  PRINT_DEBUG("Pid1Main started");
+
   if (getpid() != 1) {
     DIE("Using PID namespaces, but we are not PID 1");
   }
diff --git a/src/main/tools/linux-sandbox.cc b/src/main/tools/linux-sandbox.cc
index d4f04ad8709959..a025e0fe9974f3 100644
--- a/src/main/tools/linux-sandbox.cc
+++ b/src/main/tools/linux-sandbox.cc
@@ -57,6 +57,7 @@
 #include <sys/types.h>
 #include <sys/wait.h>
 #include <unistd.h>
+
 #include <string>
 #include <vector>
 
@@ -130,6 +131,8 @@ static void SpawnPid1() {
   const int kStackSize = 1024 * 1024;
   std::vector<char> child_stack(kStackSize);
 
+  PRINT_DEBUG("calling pipe(2)...");
+
   int sync_pipe[2];
   if (pipe(sync_pipe) < 0) {
     DIE("pipe");
@@ -147,6 +150,8 @@ static void SpawnPid1() {
   // We use clone instead of unshare, because unshare sometimes fails with
   // EINVAL due to a race condition in the Linux kernel (see
   // https://lkml.org/lkml/2015/7/28/833).
+  PRINT_DEBUG("calling clone(2)...");
+
   global_child_pid =
       clone(Pid1Main, child_stack.data() + kStackSize, clone_flags, sync_pipe);
   if (global_child_pid < 0) {
@@ -169,6 +174,8 @@ static void SpawnPid1() {
   if (close(sync_pipe[0]) < 0) {
     DIE("close");
   }
+
+  PRINT_DEBUG("done manipulating pipes");
 }
 
 static int WaitForPid1() {
@@ -277,14 +284,21 @@ int main(int argc, char *argv[]) {
 
   CloseFds();
 
+  // Spawn the child that will fork the sandboxed progam with fresh namespaces
+  // etc.
   SpawnPid1();
 
+  // Set up signal handlers to manipulate the child as desired.
   SetupSignalHandlers();
 
+  // If we've been asked to automatically time out after a certain amount of
+  // time, arrange for SIGALRM to handle the timeout and then set up an interval
+  // timer that will raise SIGALRM.
   if (opt.timeout_secs > 0) {
     InstallSignalHandler(SIGALRM, OnTimeoutOrTerm);
     SetTimeout(opt.timeout_secs);
   }
 
+  // Wait for the child to finish.
   return WaitForPid1();
 }
diff --git a/src/main/tools/logging.h b/src/main/tools/logging.h
index be646a71095454..c3abe35e231758 100644
--- a/src/main/tools/logging.h
+++ b/src/main/tools/logging.h
@@ -15,6 +15,12 @@
 #ifndef SRC_MAIN_TOOLS_LOGGING_H_
 #define SRC_MAIN_TOOLS_LOGGING_H_
 
+#include <inttypes.h>
+#include <stdint.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <time.h>
+
 // see
 // http://stackoverflow.com/questions/5641427/how-to-make-preprocessor-generate-a-string-for-line-keyword
 #define S(x) #x
@@ -29,12 +35,16 @@
     exit(EXIT_FAILURE);                                         \
   }
 
-#define PRINT_DEBUG(...)                                        \
-  do {                                                          \
-    if (global_debug) {                                         \
-      fprintf(stderr, __FILE__ ":" S__LINE__ ": " __VA_ARGS__); \
-      fprintf(stderr, "\n");                                    \
-    }                                                           \
+#define PRINT_DEBUG(fmt, ...)                                       \
+  do {                                                              \
+    if (global_debug) {                                             \
+      struct timespec ts;                                           \
+      clock_gettime(CLOCK_REALTIME, &ts);                           \
+                                                                    \
+      fprintf(stderr, "%" PRId64 ".%09ld: %s:%d: " fmt "\n",        \
+              ((int64_t)ts.tv_sec), ts.tv_nsec, __FILE__, __LINE__, \
+              ##__VA_ARGS__);                                       \
+    }                                                               \
   } while (0)
 
 // Set to `true` to let PRINT_DEBUG() print messages.