[tor-commits] [stem/master] Implementing TRACE level logging
atagar at torproject.org
atagar at torproject.org
Thu Jan 5 18:40:50 UTC 2012
commit b7e9f5c9314159679c73c707e3a6a15f5ff03fdc
Author: Damian Johnson <atagar at torproject.org>
Date: Thu Jan 5 10:34:09 2012 -0800
Implementing TRACE level logging
Adding request/reply logging for tor and system calls. I'm also messing with
the runlevels and messages of other logging to make the integ test output more
readable.
---
run_tests.py | 1 -
stem/socket.py | 8 ++++----
stem/util/conf.py | 15 ++++++++-------
stem/util/system.py | 10 +++++++---
test/runner.py | 3 ---
5 files changed, 19 insertions(+), 18 deletions(-)
diff --git a/run_tests.py b/run_tests.py
index 2b1cd1e..8b59710 100755
--- a/run_tests.py
+++ b/run_tests.py
@@ -267,7 +267,6 @@ if __name__ == '__main__':
for test_class in INTEG_TESTS:
print_divider(test_class.__module__)
- stem_logger.info("STARTING INTEGRATION TEST => %s" % test_class.__module__)
suite = unittest.TestLoader().loadTestsFromTestCase(test_class)
test_results = StringIO.StringIO()
unittest.TextTestRunner(test_results, verbosity=2).run(suite)
diff --git a/stem/socket.py b/stem/socket.py
index d383d35..f3aeaf8 100644
--- a/stem/socket.py
+++ b/stem/socket.py
@@ -656,11 +656,13 @@ def send_message(control_file, message, raw = False):
# uses a newline divider if this is a multi-line message (more readable)
log_message = message.replace("\r\n", "\n").rstrip()
div = "\n" if "\n" in log_message else " "
- log.debug("Sending:" + div + log_message)
try:
control_file.write(message)
control_file.flush()
+
+ log_message = message.replace("\r\n", "\n").rstrip()
+ log.trace("Sent to tor:\n" + log_message)
except socket.error, exc:
log.info("Failed to send message: %s" % exc)
raise SocketError(exc)
@@ -744,10 +746,8 @@ def recv_message(control_file):
# end of the message, return the message
parsed_content.append((status_code, divider, content))
- # uses a newline divider if this is a multi-line message (more readable)
log_message = raw_content.replace("\r\n", "\n").rstrip()
- div = "\n" if "\n" in log_message else " "
- log.trace("Received from Tor:" + div + log_message)
+ log.trace("Received from tor:\n" + log_message)
return ControlMessage(parsed_content, raw_content)
elif divider == "+":
diff --git a/stem/util/conf.py b/stem/util/conf.py
index 7111149..4c468d7 100644
--- a/stem/util/conf.py
+++ b/stem/util/conf.py
@@ -303,17 +303,17 @@ class Config():
if val.lower() == "true": val = True
elif val.lower() == "false": val = False
else:
- log.info("Config entry '%s' is expected to be a boolean, defaulting to '%s'" % (key, str(default)))
+ log.debug("Config entry '%s' is expected to be a boolean, defaulting to '%s'" % (key, str(default)))
val = default
elif isinstance(default, int):
try: val = int(val)
except ValueError:
- log.info("Config entry '%s' is expected to be an integer, defaulting to '%i'" % (key, default))
+ log.debug("Config entry '%s' is expected to be an integer, defaulting to '%i'" % (key, default))
val = default
elif isinstance(default, float):
try: val = float(val)
except ValueError:
- log.info("Config entry '%s' is expected to be a float, defaulting to '%f'" % (key, default))
+ log.debug("Config entry '%s' is expected to be a float, defaulting to '%f'" % (key, default))
val = default
elif isinstance(default, list):
pass # nothing special to do (already a list)
@@ -326,7 +326,7 @@ class Config():
entryKey, entryVal = entry.split("=>", 1)
valMap[entryKey.strip()] = entryVal.strip()
else:
- log.info("Ignoring invalid %s config entry (expected a mapping, but \"%s\" was missing \"=>\")" % (key, entry))
+ log.debug("Ignoring invalid %s config entry (expected a mapping, but \"%s\" was missing \"=>\")" % (key, entry))
val = valMap
return val
@@ -353,7 +353,8 @@ class Config():
if not multiple: val = val[-1]
self._requested_keys.add(key)
else:
- log.debug("config entry '%s' not found, defaulting to '%s'" % (key, default))
+ message_id = "stem.util.conf.missing_config_key_%s" % key
+ log.log_once(message_id, log.TRACE, "config entry '%s' not found, defaulting to '%s'" % (key, default))
val = default
self._contents_lock.release()
@@ -387,7 +388,7 @@ class Config():
defaultStr = ", ".join([str(i) for i in default])
msg += ", defaulting to '%s'" % defaultStr
- log.info(msg)
+ log.debug(msg)
return default
return conf_comp
@@ -434,7 +435,7 @@ class Config():
break
if error_msg:
- log.info(error_msg)
+ log.debug(error_msg)
return default
else: return [int(val) for val in conf_comp]
diff --git a/stem/util/system.py b/stem/util/system.py
index 40d0669..5b6d9fe 100644
--- a/stem/util/system.py
+++ b/stem/util/system.py
@@ -582,13 +582,17 @@ def call(command, suppress_exc = True):
try:
start_time = time.time()
+ log.trace("Sent to system:\n" + command)
stdout, stderr = subprocess.Popen(command.split(), stdout = subprocess.PIPE, stderr = subprocess.PIPE).communicate()
stdout, stderr = stdout.strip(), stderr.strip()
runtime = time.time() - start_time
- msg = "system call: %s (runtime: %0.2f)" % (command, runtime)
- if stderr: msg += "\nstderr: %s" % stderr
- log.debug(msg)
+ if not stderr:
+ log.trace("Received from system:\n" + stdout)
+ else:
+ log.trace("Received from system:\nstdout: %s\nstderr: %s" % (stdout, stderr))
+
+ log.debug("system call: %s (runtime: %0.2f)" % (command, runtime))
if stdout: return stdout.split("\n")
else: return []
diff --git a/test/runner.py b/test/runner.py
index 581f95a..d6da306 100644
--- a/test/runner.py
+++ b/test/runner.py
@@ -455,9 +455,6 @@ class Runner:
datefmt = '%D %H:%M:%S',
)
- stem_logger = logging.getLogger("stem")
- stem_logger.info("Logging opened for integration test run")
-
_print_status("done\n", STATUS_ATTR, quiet)
else:
_print_status(" configuring logger... skipped\n", STATUS_ATTR, quiet)
More information about the tor-commits
mailing list