[tor-commits] [stegotorus/master] Add option to timestamp all logs. Fix some deadlocks in itestlib.py.

zwol at torproject.org zwol at torproject.org
Fri Jul 20 23:17:07 UTC 2012


commit 99efcadc17b1d082589e2e8509be6555576b9301
Author: Zack Weinberg <zackw at cmu.edu>
Date:   Wed Mar 28 19:12:45 2012 -0700

    Add option to timestamp all logs. Fix some deadlocks in itestlib.py.
---
 src/audit-globals.sh |    2 +
 src/main.cc          |   22 +++++++++---
 src/test/itestlib.py |   94 +++++++++++++++++++++++++++----------------------
 src/util.cc          |   66 ++++++++++++++++++-----------------
 src/util.h           |    7 +++-
 5 files changed, 111 insertions(+), 80 deletions(-)

diff --git a/src/audit-globals.sh b/src/audit-globals.sh
index ec08b21..99739b3 100644
--- a/src/audit-globals.sh
+++ b/src/audit-globals.sh
@@ -39,6 +39,8 @@ sed '
   /^rng rng$/d
   /^util log_dest$/d
   /^util log_min_sev$/d
+  /^util log_timestamps$/d
+  /^util log_ts_base$/d
   /^util the_evdns_base$/d
   /^crypt log_crypto()::initialized$/d
   /^crypt init_crypto()::initialized$/d
diff --git a/src/main.cc b/src/main.cc
index db338af..1c8e55f 100644
--- a/src/main.cc
+++ b/src/main.cc
@@ -176,6 +176,7 @@ usage(void)
           "--log-file=<file> ~ set logfile\n"
           "--log-min-severity=warn|info|debug ~ set minimum logging severity\n"
           "--no-log ~ disable logging\n"
+          "--timestamp-logs ~ add timestamps to all log messages\n"
           "--allow-kqueue ~ allow use of kqueue(2) (may be buggy)\n");
 
   exit(1);
@@ -188,6 +189,8 @@ usage(void)
    If it succeeds it returns the number of argv arguments its caller
    should skip to get past the optional arguments we already handled.
    If it fails, it exits the program.
+
+   Note: this function should NOT use log_* to print diagnostics.
 */
 static int
 handle_generic_args(const char *const *argv)
@@ -195,28 +198,30 @@ handle_generic_args(const char *const *argv)
   bool logmethod_set = false;
   bool logsev_set = false;
   bool allow_kq_set = false;
+  bool timestamps_set = false;
   int i = 1;
 
   while (argv[i] &&
          !strncmp(argv[i],"--",2)) {
     if (!strncmp(argv[i], "--log-file=", 11)) {
       if (logmethod_set) {
-        log_warn("you've already set a log file!");
+        fprintf(stderr, "you've already set a log file!\n");
         exit(1);
       }
       if (log_set_method(LOG_METHOD_FILE,
                          (char *)argv[i]+11) < 0) {
-        log_warn("failed creating logfile");
+        fprintf(stderr, "failed to open logfile '%s': %s\n", argv[i]+11,
+                strerror(errno));
         exit(1);
       }
       logmethod_set=1;
     } else if (!strncmp(argv[i], "--log-min-severity=", 19)) {
       if (logsev_set) {
-        log_warn("you've already set a min. log severity!");
+        fprintf(stderr, "you've already set a min. log severity!\n");
         exit(1);
       }
       if (log_set_min_severity((char *)argv[i]+19) < 0) {
-        log_warn("error at setting logging severity");
+        fprintf(stderr, "error at setting logging severity");
         exit(1);
       }
       logsev_set = true;
@@ -230,6 +235,13 @@ handle_generic_args(const char *const *argv)
           exit(1);
         }
         logsev_set = true;
+    } else if (!strcmp(argv[i], "--timestamp-logs")) {
+      if (timestamps_set) {
+        fprintf(stderr, "you've already asked for timestamps!\n");
+        exit(1);
+      }
+      log_enable_timestamps();
+      timestamps_set = true;
     } else if (!strcmp(argv[i], "--allow-kqueue")) {
       if (allow_kq_set) {
         fprintf(stderr, "you've already allowed kqueue!\n");
@@ -238,7 +250,7 @@ handle_generic_args(const char *const *argv)
       allow_kq = true;
       allow_kq_set = true;
     } else {
-      log_warn("unrecognizable argument '%s'", argv[i]);
+      fprintf(stderr, "unrecognizable argument '%s'", argv[i]);
       exit(1);
     }
     i++;
diff --git a/src/test/itestlib.py b/src/test/itestlib.py
index 60d082e..1c483f3 100644
--- a/src/test/itestlib.py
+++ b/src/test/itestlib.py
@@ -10,6 +10,8 @@ import subprocess
 import threading
 import time
 
+TIMEOUT_LEN = 5 # seconds
+
 # Helper: stick "| " at the beginning of each line of |s|.
 
 def indent(s):
@@ -39,9 +41,13 @@ def diff(label, expected, received):
 # elsewhere.  Mode 2 is "abort immediately, without flooding
 # /dev/tty with useless diagnostics" (the documentation SAYS
 # they go to stderr, but they don't).
+
+# there is an as-yet-not-pinned-down bug, probably in libevent, that
+# causes deadlocks on OSX when kqueue is allowed.
 stegotorus_env = {}
 stegotorus_env.update(os.environ)
 stegotorus_env['MALLOC_CHECK_'] = '2'
+stegotorus_env['EVENT_NOKQUEUE'] = '1'
 
 # check for a grinder
 if 'GRINDER' in stegotorus_env:
@@ -52,7 +58,8 @@ else:
 class Stegotorus(subprocess.Popen):
     def __init__(self, *args, **kwargs):
         argv = stegotorus_grindv[:]
-        argv.extend(("./stegotorus", "--log-min-severity=debug"))
+        argv.extend(("./stegotorus", "--log-min-severity=debug",
+                     "--timestamp-logs"))
 
         if len(args) == 1 and (isinstance(args[0], list) or
                                isinstance(args[0], tuple)):
@@ -69,23 +76,30 @@ class Stegotorus(subprocess.Popen):
                                   **kwargs)
         # wait for startup completion, which is signaled by
         # the subprocess closing its stdout
-        self.stdout.read()
+        self.output = self.stdout.read()
+        # read stderr in a separate thread, since we will
+        # have several processes outstanding at the same time
+        self.communicator = threading.Thread(target=self.run_communicate)
+        self.communicator.start()
+        self.timeout = threading.Timer(TIMEOUT_LEN, self.stop)
+        self.timeout.start()
 
     severe_error_re = re.compile(
         r"\[(?:warn|err(?:or)?)\]|ERROR SUMMARY: [1-9]|LEAK SUMMARY:")
 
-    def check_completion(self, label, force_stderr=False):
+    def stop(self):
         if self.poll() is None:
-            # subprocess.communicate has no timeout; arrange to blow
-            # the process away if it doesn't respond to the initial
-            # shutdown request in a timely fashion.
-            timeout = threading.Thread(target=self.stop, args=(1.0,))
-            timeout.daemon = True
-            timeout.start()
-
-        # this will close the subprocess's stdin as its first act, which
-        # will trigger a clean shutdown
-        (out, err) = self.communicate()
+            self.terminate()
+
+    def run_communicate(self):
+        self.errput = self.stderr.read()
+
+    def check_completion(self, label, force_stderr=False):
+        self.stdin.close()
+        self.communicator.join()
+        self.timeout.cancel()
+        self.timeout.join()
+        self.poll()
 
         report = ""
 
@@ -96,25 +110,18 @@ class Stegotorus(subprocess.Popen):
             report += label + " killed: signal %d\n" % -self.returncode
 
         # there should be nothing on stdout
-        if out != "":
-            report += label + " stdout:\n%s\n" % indent(out)
+        if self.output != "":
+            report += label + " stdout:\n%s\n" % indent(self.output)
 
         # there will be debugging messages on stderr, but there should be
         # no [warn], [err], or [error] messages.
         if (force_stderr or
-            self.severe_error_re.search(err) or
+            self.severe_error_re.search(self.errput) or
             self.returncode != 0):
-            report += label + " stderr:\n%s\n" % indent(err)
+            report += label + " stderr:\n%s\n" % indent(self.errput)
 
         return report
 
-    def stop(self, delay=None):
-        if self.poll() is None:
-            if delay is not None:
-                time.sleep(delay)
-                if self.poll() is not None: return
-            self.terminate()
-
 # As above, but for the 'tltester' test helper rather than for
 # stegotorus itself.
 class Tltester(subprocess.Popen):
@@ -129,37 +136,40 @@ class Tltester(subprocess.Popen):
                                   env=stegotorus_env,
                                   close_fds=True,
                                   **kwargs)
-
-    def stop(self, delay=None):
+        # invoke communicate() in a separate thread, since we will
+        # have several processes outstanding at the same time
+        self.communicator = threading.Thread(target=self.run_communicate)
+        self.communicator.start()
+        self.timeout = threading.Timer(TIMEOUT_LEN, self.stop)
+        self.timeout.start()
+
+    def stop(self):
         if self.poll() is None:
-            if delay is not None:
-                time.sleep(delay)
-                if self.poll() is not None: return
             self.terminate()
 
-    def check_completion(self, label):
-        if self.poll() is None:
-            # subprocess.communicate has no timeout; arrange to blow
-            # the process away if it doesn't finish what it's doing in
-            # a timely fashion.
-            timeout = threading.Thread(target=self.stop, args=(2.0,))
-            timeout.daemon = True
-            timeout.start()
-
+    def run_communicate(self):
         (out, err) = self.communicate()
+        self.output = out
+        self.errput = err
+
+    def check_completion(self, label):
+        self.communicator.join()
+        self.timeout.cancel()
+        self.timeout.join()
+        self.poll()
 
         # exit status should be zero, and there should be nothing on
         # stderr
-        if self.returncode != 0 or err != "":
+        if self.returncode != 0 or self.errput != "":
             report = ""
             # exit status should be zero
             if self.returncode > 0:
                 report += label + " exit code: %d\n" % self.returncode
             elif self.returncode < 0:
                 report += label + " killed: signal %d\n" % -self.returncode
-            if err != "":
-                report += label + " stderr:\n%s\n" % indent(err)
+            if self.errput != "":
+                report += label + " stderr:\n%s\n" % indent(self.errput)
             raise AssertionError(report)
 
         # caller will crunch the output
-        return out
+        return self.output
diff --git a/src/util.cc b/src/util.cc
index 7273671..b813ae9 100644
--- a/src/util.cc
+++ b/src/util.cc
@@ -402,6 +402,9 @@ ascii_strlower(char *s)
 static FILE *log_dest;
 /* minimum logging severity */
 static int log_min_sev = LOG_SEV_INFO;
+/* whether timestamps are wanted */
+static bool log_timestamps = false;
+static struct timeval log_ts_base = { 0, 0 };
 
 /** Helper: map a log severity to descriptive string. */
 static const char *
@@ -473,7 +476,7 @@ log_open(const char *filename)
    Ignores errors.
 */
 void
-log_close(void)
+log_close()
 {
   if (log_dest && log_dest != stderr)
     fclose(log_dest);
@@ -523,11 +526,19 @@ log_set_min_severity(const char* sev_string)
   return 0;
 }
 
+/** Enable timestamps on all log messages. */
+void
+log_enable_timestamps()
+{
+  log_timestamps = true;
+  gettimeofday(&log_ts_base, 0);
+}
+
 /** True if the minimum log severity is "debug".  Used in a few places
     to avoid some expensive formatting work if we are going to ignore the
     result. */
 int
-log_do_debug(void)
+log_do_debug()
 {
   return log_min_sev == LOG_SEV_DEBUG;
 }
@@ -550,7 +561,7 @@ logv(int severity, const char *format, va_list ap)
   putc('\n', log_dest);
 }
 
-static void
+static bool
 logpfx(int severity, const char *fn)
 {
   if (!sev_is_valid(severity))
@@ -558,48 +569,39 @@ logpfx(int severity, const char *fn)
 
   /* See if the user is interested in this log message. */
   if (!log_dest || severity < log_min_sev)
-    return;
+    return false;
+
+  if (log_timestamps) {
+    struct timeval now, delta;
+    gettimeofday(&now, 0);
+    timeval_subtract(&now, &log_ts_base, &delta);
+    fprintf(log_dest, "%.4f ",
+            delta.tv_sec + double(delta.tv_usec) / 1e6);
+  }
 
   fprintf(log_dest, "[%s] ", sev_to_string(severity));
   if (log_min_sev == LOG_SEV_DEBUG && fn)
     fprintf(log_dest, "%s: ", fn);
+  return true;
 }
 
 static void
 logpfx(int severity, const char *fn, circuit_t *ckt)
 {
-  if (!sev_is_valid(severity))
-    abort();
-
-  /* See if the user is interested in this log message. */
-  if (!log_dest || severity < log_min_sev)
-    return;
-
-  fprintf(log_dest, "[%s] ", sev_to_string(severity));
-  if (log_min_sev == LOG_SEV_DEBUG && fn)
-    fprintf(log_dest, "%s: ", fn);
-  if (ckt)
-    fprintf(log_dest, "<%u> ", ckt->serial);
+  if (logpfx(severity, fn))
+    if (ckt)
+      fprintf(log_dest, "<%u> ", ckt->serial);
 }
 
 static void
 logpfx(int severity, const char *fn, conn_t *conn)
 {
-  if (!sev_is_valid(severity))
-    abort();
-
-  /* See if the user is interested in this log message. */
-  if (!log_dest || severity < log_min_sev)
-    return;
-
-  fprintf(log_dest, "[%s] ", sev_to_string(severity));
-  if (log_min_sev == LOG_SEV_DEBUG && fn)
-    fprintf(log_dest, "%s: ", fn);
-  if (conn) {
-    circuit_t *ckt = conn->circuit();
-    unsigned int ckt_serial = ckt ? ckt->serial : 0;
-    fprintf(log_dest, "<%u.%u> ", ckt_serial, conn->serial);
-  }
+  if (logpfx(severity, fn))
+    if (conn) {
+      circuit_t *ckt = conn->circuit();
+      unsigned int ckt_serial = ckt ? ckt->serial : 0;
+      fprintf(log_dest, "<%u.%u> ", ckt_serial, conn->serial);
+    }
 }
 
 /**** Public logging API. ****/
@@ -722,7 +724,7 @@ int timeval_subtract(struct timeval *x, struct timeval *y,
     y->tv_sec -= nsec;
   }
 
-  /* Compute the time remaining to wait.                                        
+  /* Compute the time remaining to wait.
      tv_usec is certainly positive. */
   result->tv_sec = x->tv_sec - y->tv_sec;
   result->tv_usec = x->tv_usec - y->tv_usec;
diff --git a/src/util.h b/src/util.h
index 32750c1..05bc6d0 100644
--- a/src/util.h
+++ b/src/util.h
@@ -171,7 +171,12 @@ int log_set_method(int method, const char *filename);
     'sev_string' may be "warn", "info", or "debug" (case-insensitively). */
 int log_set_min_severity(const char* sev_string);
 
-/** True if debug messages are being logged. */
+/** Request timestamps on all log messages. */
+void log_enable_timestamps();
+
+/** True if debug messages are being logged. Guard expensive debugging
+    checks with this, to avoid doing useless work when the messages are
+    just going to be thrown away anyway. */
 int log_do_debug(void);
 
 /** Close the logfile if it's open.  Ignores errors. */





More information about the tor-commits mailing list