commit 4788095929ab2a3bfde04ade0b2cdf52fe82dc82 Author: Damian Johnson atagar@torproject.org Date: Tue Jan 3 18:52:14 2012 -0800

Tidying up lower runlevel logging

Cleaning up the log output for DEBUG and INFO runlevels we encounter when running the unit tests to be more helpful and user friendly. --- run_tests.py | 4 +-- stem/connection.py | 2 +- stem/socket.py | 34 +++++++++++++++++++++---------- stem/util/log.py | 1 + stem/util/system.py | 2 +- test/unit/connection/authentication.py | 9 ++++++++ 6 files changed, 36 insertions(+), 16 deletions(-)

diff --git a/run_tests.py b/run_tests.py index 280b05e..c0ab23d 100755 --- a/run_tests.py +++ b/run_tests.py @@ -8,7 +8,6 @@ import os import sys import time import getopt -import logging import unittest import StringIO

@@ -208,10 +207,9 @@ if __name__ == '__main__': test.output.colorize, )

- stem_logger = logging.getLogger("stem") + stem_logger = log.get_logger() logging_buffer = test.output.LogBuffer(log.logging_level(logging_runlevel)) stem_logger.addHandler(logging_buffer) - stem_logger.setLevel(logging.DEBUG)

if run_unit_tests: print_divider("UNIT TESTS", True) diff --git a/stem/connection.py b/stem/connection.py index 37578cf..5c1fc55 100644 --- a/stem/connection.py +++ b/stem/connection.py @@ -795,7 +795,7 @@ class ProtocolInfoResponse(stem.socket.ControlMessage): else: unknown_auth_methods.append(method) message_id = "stem.connection.unknown_auth_%s" % method - log.log_once(message_id, log.INFO, "PROTOCOLINFO response had an unrecognized authentication method: %s" % method) + log.log_once(message_id, log.INFO, "PROTOCOLINFO response included a type of authentication that we don't recognize: %s" % method)

# our auth_methods should have a single AuthMethod.UNKNOWN entry if # any unknown authentication methods exist diff --git a/stem/socket.py b/stem/socket.py index b2bde2b..d383d35 100644 --- a/stem/socket.py +++ b/stem/socket.py @@ -690,6 +690,7 @@ def recv_message(control_file): """

parsed_content, raw_content = [], "" + logging_prefix = "Error while receiving a control message (%s): "

while True: try: line = control_file.readline() @@ -697,13 +698,15 @@ def recv_message(control_file): # if the control_file has been closed then we will receive: # AttributeError: 'NoneType' object has no attribute 'recv'

- log.info("SocketClosed: socket file has been closed") + prefix = logging_prefix % "SocketClosed" + log.info(prefix + "socket file has been closed") raise SocketClosed("socket file has been closed") except socket.error, exc: # when disconnected we get... # socket.error: [Errno 107] Transport endpoint is not connected

- log.info("SocketClosed: received an exception (%s)" % exc) + prefix = logging_prefix % "SocketClosed" + log.info(prefix + "received exception "%s"" % exc) raise SocketClosed(exc)

raw_content += line @@ -715,16 +718,20 @@ def recv_message(control_file): # if the socket is disconnected then the readline() method will provide # empty content

- log.info("SocketClosed: empty socket content") + prefix = logging_prefix % "SocketClosed" + log.info(prefix + "empty socket content") raise SocketClosed("Received empty socket content.") elif len(line) < 4: - log.info("ProtocolError: line too short (%s)" % log.escape(line)) + prefix = logging_prefix % "ProtocolError" + log.info(prefix + "line too short, "%s"" % log.escape(line)) raise ProtocolError("Badly formatted reply line: too short") elif not re.match(r'^[a-zA-Z0-9]{3}[-+ ]', line): - log.info("ProtocolError: malformed status code/divider (%s)" % log.escape(line)) + prefix = logging_prefix % "ProtocolError" + log.info(prefix + "malformed status code/divider, "%s"" % log.escape(line)) raise ProtocolError("Badly formatted reply line: beginning is malformed") elif not line.endswith("\r\n"): - log.info("ProtocolError: no CRLF linebreak (%s)" % log.escape(line)) + prefix = logging_prefix % "ProtocolError" + log.info(prefix + "no CRLF linebreak, "%s"" % log.escape(line)) raise ProtocolError("All lines should end with CRLF")

line = line[:-2] # strips off the CRLF @@ -740,7 +747,7 @@ def recv_message(control_file): # 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.debug("Received:" + div + log_message) + log.trace("Received from Tor:" + div + log_message)

return ControlMessage(parsed_content, raw_content) elif divider == "+": @@ -749,12 +756,16 @@ def recv_message(control_file):

while True: try: line = control_file.readline() - except socket.error, exc: raise SocketClosed(exc) + except socket.error, exc: + prefix = logging_prefix % "SocketClosed" + log.info(prefix + "received an exception while mid-way through a data reply (exception: "%s", read content: "%s")" % (exc, log.escape(raw_content))) + raise SocketClosed(exc)

raw_content += line

if not line.endswith("\r\n"): - log.info("ProtocolError: no CRLF linebreak for data entry (%s)" % log.escape(line)) + prefix = logging_prefix % "ProtocolError" + log.info(prefix + "CRLF linebreaks missing from a data reply, "%s"" % log.escape(raw_content)) raise ProtocolError("All lines should end with CRLF") elif line == ".\r\n": break # data block termination @@ -775,8 +786,9 @@ def recv_message(control_file): else: # this should never be reached due to the prefix regex, but might as well # be safe... - log.warn("ProtocolError: unrecognized divider type (%s)" % line) - raise ProtocolError("Unrecognized type '%s': %s" % (divider, line)) + prefix = logging_prefix % "ProtocolError" + log.warn(prefix + ""%s" isn't a recognized divider type" % line) + raise ProtocolError("Unrecognized divider type '%s': %s" % (divider, line))

def send_formatting(message): """ diff --git a/stem/util/log.py b/stem/util/log.py index de84ead..fc4244f 100644 --- a/stem/util/log.py +++ b/stem/util/log.py @@ -36,6 +36,7 @@ LOG_VALUES = { }

LOGGER = logging.getLogger("stem") +LOGGER.setLevel(LOG_VALUES[TRACE])

# There's some messages that we don't want to log more than once. This set has # the messages IDs that we've logged which fall into this category. diff --git a/stem/util/system.py b/stem/util/system.py index aa1180e..40d0669 100644 --- a/stem/util/system.py +++ b/stem/util/system.py @@ -245,7 +245,7 @@ def get_pid_by_name(process_name): pid = results[0].strip() if pid.isdigit(): return int(pid)

- log.debug("failed to resolve a pid for %s" % process_name) + log.debug("failed to resolve a pid for '%s'" % process_name) return None

def get_pid_by_port(port): diff --git a/test/unit/connection/authentication.py b/test/unit/connection/authentication.py index 729e6c7..ba56ccd 100644 --- a/test/unit/connection/authentication.py +++ b/test/unit/connection/authentication.py @@ -7,6 +7,7 @@ import functools import unittest

import stem.connection +import stem.util.log as log

# Functors to replace get_protocolinfo and authenticate_*. All of them take any # number of arguments. @@ -106,6 +107,11 @@ class TestAuthenticate(unittest.TestCase): subclass being raised. """

+ # mute the logger for this test since otherwise the output is overwhelming + + stem_logger = log.get_logger() + stem_logger.setLevel(log.logging_level(None)) + # exceptions that the authentication functions are documented to raise auth_none_exc_types = (None, stem.connection.OpenAuthRejected) @@ -151,4 +157,7 @@ class TestAuthenticate(unittest.TestCase): stem.connection.authenticate(None, "blah", protocolinfo_input) else: self.assertRaises(stem.connection.AuthenticationFailure, stem.connection.authenticate, None, "blah", protocolinfo_input) + + # revert logging back to normal + stem_logger.setLevel(log.logging_level(log.TRACE))