[tor-commits] [stem/master] Tidying up lower runlevel logging
atagar at torproject.org
atagar at torproject.org
Thu Jan 5 18:40:50 UTC 2012
commit 4788095929ab2a3bfde04ade0b2cdf52fe82dc82
Author: Damian Johnson <atagar at 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))
More information about the tor-commits
mailing list