[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]
[tor-commits] [stegotorus/master] Add option to timestamp all logs. Fix some deadlocks in itestlib.py.
commit 99efcadc17b1d082589e2e8509be6555576b9301
Author: Zack Weinberg <zackw@xxxxxxx>
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. */
_______________________________________________
tor-commits mailing list
tor-commits@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-commits