commit 99efcadc17b1d082589e2e8509be6555576b9301 Author: Zack Weinberg zackw@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. */