commit b7e9f5c9314159679c73c707e3a6a15f5ff03fdc Author: Damian Johnson atagar@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)