[tor-commits] [stem/master] Routing all logging through stem.util.log
atagar at torproject.org
atagar at torproject.org
Sat Dec 31 21:58:55 UTC 2011
commit a3f9647832dab69c5eda8047748d0de534fac073
Author: Damian Johnson <atagar at torproject.org>
Date: Sat Dec 31 12:54:49 2011 -0800
Routing all logging through stem.util.log
Back and forth I go - first I wrote my own logging then used the builtin python
logging module. Now I'm going to a hybrid of the two. The builtin logging
module is rich but somewhat hard to customize without a wrapper.
Changes we want on the logging module are aliased commands, additional
runlevels ('NOTICE' and 'TRACE'), and logging sends complaints to stdout if
there isn't a listener (very, very dumb of its author and I've been working
around this via a __init__ module hack).
Functionally this does not change anything. I'll be changing the modules to
take advantage of these new runlevels later.
---
stem/connection.py | 18 +++++-------
stem/socket.py | 27 +++++++++----------
stem/util/__init__.py | 2 +-
stem/util/conf.py | 23 ++++++----------
stem/util/log.py | 70 +++++++++++++++++++++++++++++++++++++++++++++++++
stem/util/proc.py | 10 ++-----
stem/util/system.py | 22 +++++++--------
stem/version.py | 3 --
8 files changed, 114 insertions(+), 61 deletions(-)
diff --git a/stem/connection.py b/stem/connection.py
index eb5da62..7cb76be 100644
--- a/stem/connection.py
+++ b/stem/connection.py
@@ -82,15 +82,13 @@ AuthenticationFailure - Base exception raised for authentication failures.
import os
import getpass
-import logging
import binascii
import stem.socket
import stem.version
import stem.util.enum
import stem.util.system
-
-LOGGER = logging.getLogger("stem")
+import stem.util.log as log
# enums representing classes that the connect_* methods can return
Controller = stem.util.enum.Enum("NONE")
@@ -375,7 +373,7 @@ def authenticate(control_socket, password = None, protocolinfo_response = None):
exc_msg = "unrecognized authentication method%s (%s)" % (plural_label, methods_label)
auth_exceptions.append(UnrecognizedAuthMethods(exc_msg, unknown_methods))
else:
- LOGGER.debug("Authenticating to a socket with unrecognized auth method%s, ignoring them: %s" % (plural_label, methods_label))
+ log.debug("Authenticating to a socket with unrecognized auth method%s, ignoring them: %s" % (plural_label, methods_label))
if AuthMethod.COOKIE in auth_methods and protocolinfo_response.cookie_path == None:
auth_methods.remove(AuthMethod.COOKIE)
@@ -405,12 +403,12 @@ def authenticate(control_socket, password = None, protocolinfo_response = None):
except PasswordAuthRejected, exc:
# Since the PROTOCOLINFO says password auth is available we can assume
# that if PasswordAuthRejected is raised it's being raised in error.
- LOGGER.debug("The authenticate_password method raised a PasswordAuthRejected when password auth should be available. Stem may need to be corrected to recognize this response: %s" % exc)
+ log.debug("The authenticate_password method raised a PasswordAuthRejected when password auth should be available. Stem may need to be corrected to recognize this response: %s" % exc)
auth_exceptions.append(IncorrectPassword(str(exc)))
except (IncorrectCookieSize, UnreadableCookieFile, IncorrectCookieValue), exc:
auth_exceptions.append(exc)
except CookieAuthRejected, exc:
- LOGGER.debug("The authenticate_cookie method raised a CookieAuthRejected when cookie auth should be available. Stem may need to be corrected to recognize this response: %s" % exc)
+ log.debug("The authenticate_cookie method raised a CookieAuthRejected when cookie auth should be available. Stem may need to be corrected to recognize this response: %s" % exc)
auth_exceptions.append(IncorrectCookieValue(str(exc)))
except stem.socket.ControllerError, exc:
auth_exceptions.append(AuthenticationFailure(str(exc)))
@@ -678,7 +676,7 @@ def _expand_cookie_path(protocolinfo_response, pid_resolver, pid_resolution_arg)
}
pid_resolver_label = resolver_labels.get(pid_resolver, "")
- LOGGER.debug("unable to expand relative tor cookie path%s: %s" % (pid_resolver_label, exc))
+ log.debug("unable to expand relative tor cookie path%s: %s" % (pid_resolver_label, exc))
protocolinfo_response.cookie_path = cookie_path
@@ -774,7 +772,7 @@ class ProtocolInfoResponse(stem.socket.ControlMessage):
# an effort to parse like a v1 response.
if self.protocol_version != 1:
- LOGGER.warn("We made a PROTOCOLINFO v1 query but got a version %i response instead. We'll still try to use it, but this may cause problems." % self.protocol_version)
+ log.warn("We made a PROTOCOLINFO v1 query but got a version %i response instead. We'll still try to use it, but this may cause problems." % self.protocol_version)
elif line_type == "AUTH":
# Line format:
# AuthLine = "250-AUTH" SP "METHODS=" AuthMethod *("," AuthMethod)
@@ -796,7 +794,7 @@ class ProtocolInfoResponse(stem.socket.ControlMessage):
auth_methods.append(AuthMethod.COOKIE)
else:
unknown_auth_methods.append(method)
- LOGGER.info("PROTOCOLINFO response had an unrecognized authentication method: %s" % method)
+ log.info("PROTOCOLINFO response had an unrecognized authentication method: %s" % method)
# our auth_methods should have a single AuthMethod.UNKNOWN entry if
# any unknown authentication methods exist
@@ -825,7 +823,7 @@ class ProtocolInfoResponse(stem.socket.ControlMessage):
except ValueError, exc:
raise stem.socket.ProtocolError(exc)
else:
- LOGGER.debug("unrecognized PROTOCOLINFO line type '%s', ignoring entry: %s" % (line_type, line))
+ log.debug("unrecognized PROTOCOLINFO line type '%s', ignoring entry: %s" % (line_type, line))
self.auth_methods = tuple(auth_methods)
self.unknown_auth_methods = tuple(unknown_auth_methods)
diff --git a/stem/socket.py b/stem/socket.py
index aa094ed..961fece 100644
--- a/stem/socket.py
+++ b/stem/socket.py
@@ -44,10 +44,9 @@ ControllerError - Base exception raised when using the controller.
from __future__ import absolute_import
import re
import socket
-import logging
import threading
-LOGGER = logging.getLogger("stem.socket")
+import stem.util.log as log
KEY_ARG = re.compile("^(\S+)=")
@@ -657,19 +656,19 @@ 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 " "
- LOGGER.debug("Sending:" + div + log_message)
+ log.debug("Sending:" + div + log_message)
try:
control_file.write(message)
control_file.flush()
except socket.error, exc:
- LOGGER.info("Failed to send message: %s" % exc)
+ log.info("Failed to send message: %s" % exc)
raise SocketError(exc)
except AttributeError:
# if the control_file has been closed then flush will receive:
# AttributeError: 'NoneType' object has no attribute 'sendall'
- LOGGER.info("Failed to send message: file has been closed")
+ log.info("Failed to send message: file has been closed")
raise SocketClosed("file has been closed")
def recv_message(control_file):
@@ -698,13 +697,13 @@ def recv_message(control_file):
# if the control_file has been closed then we will receive:
# AttributeError: 'NoneType' object has no attribute 'recv'
- LOGGER.warn("SocketClosed: socket file has been closed")
+ log.warn("SocketClosed: 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
- LOGGER.warn("SocketClosed: received an exception (%s)" % exc)
+ log.warn("SocketClosed: received an exception (%s)" % exc)
raise SocketClosed(exc)
raw_content += line
@@ -716,16 +715,16 @@ def recv_message(control_file):
# if the socket is disconnected then the readline() method will provide
# empty content
- LOGGER.warn("SocketClosed: empty socket content")
+ log.warn("SocketClosed: empty socket content")
raise SocketClosed("Received empty socket content.")
elif len(line) < 4:
- LOGGER.warn("ProtocolError: line too short (%s)" % line)
+ log.warn("ProtocolError: line too short (%s)" % line)
raise ProtocolError("Badly formatted reply line: too short")
elif not re.match(r'^[a-zA-Z0-9]{3}[-+ ]', line):
- LOGGER.warn("ProtocolError: malformed status code/divider (%s)" % line)
+ log.warn("ProtocolError: malformed status code/divider (%s)" % line)
raise ProtocolError("Badly formatted reply line: beginning is malformed")
elif not line.endswith("\r\n"):
- LOGGER.warn("ProtocolError: no CRLF linebreak (%s)" % line)
+ log.warn("ProtocolError: no CRLF linebreak (%s)" % line)
raise ProtocolError("All lines should end with CRLF")
line = line[:-2] # strips off the CRLF
@@ -741,7 +740,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 " "
- LOGGER.debug("Received:" + div + log_message)
+ log.debug("Received:" + div + log_message)
return ControlMessage(parsed_content, raw_content)
elif divider == "+":
@@ -755,7 +754,7 @@ def recv_message(control_file):
raw_content += line
if not line.endswith("\r\n"):
- LOGGER.warn("ProtocolError: no CRLF linebreak for data entry (%s)" % line)
+ log.warn("ProtocolError: no CRLF linebreak for data entry (%s)" % line)
raise ProtocolError("All lines should end with CRLF")
elif line == ".\r\n":
break # data block termination
@@ -776,7 +775,7 @@ def recv_message(control_file):
else:
# this should never be reached due to the prefix regex, but might as well
# be safe...
- LOGGER.warn("ProtocolError: unrecognized divider type (%s)" % line)
+ log.warn("ProtocolError: unrecognized divider type (%s)" % line)
raise ProtocolError("Unrecognized type '%s': %s" % (divider, line))
def send_formatting(message):
diff --git a/stem/util/__init__.py b/stem/util/__init__.py
index 42569c9..14692fe 100644
--- a/stem/util/__init__.py
+++ b/stem/util/__init__.py
@@ -16,5 +16,5 @@ stem_logger = logging.getLogger("stem")
if not stem_logger.handlers:
stem_logger.addHandler(NullHandler())
-__all__ = ["conf", "enum", "proc", "system", "term"]
+__all__ = ["conf", "enum", "log", "proc", "system", "term"]
diff --git a/stem/util/conf.py b/stem/util/conf.py
index 2bfa6e1..7111149 100644
--- a/stem/util/conf.py
+++ b/stem/util/conf.py
@@ -26,10 +26,10 @@ Config - Custom configuration.
+- get_int_csv - gets a value as a comma separated list of integers
"""
-import logging
import threading
-LOGGER = logging.getLogger("stem")
+import stem.util.log as log
+
CONFS = {} # mapping of identifier to singleton instances of configs
# TODO: methods that will be needed if we want to allow for runtime
@@ -303,20 +303,17 @@ class Config():
if val.lower() == "true": val = True
elif val.lower() == "false": val = False
else:
- msg = "Config entry '%s' is expected to be a boolean, defaulting to '%s'" % (key, str(default))
- LOGGER.info(msg)
+ log.info("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:
- msg = "Config entry '%s' is expected to be an integer, defaulting to '%i'" % (key, default)
- LOGGER.info(msg)
+ log.info("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:
- msg = "Config entry '%s' is expected to be a float, defaulting to '%f'" % (key, default)
- LOGGER.info(msg)
+ log.info("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)
@@ -329,8 +326,7 @@ class Config():
entryKey, entryVal = entry.split("=>", 1)
valMap[entryKey.strip()] = entryVal.strip()
else:
- msg = "Ignoring invalid %s config entry (expected a mapping, but \"%s\" was missing \"=>\")" % (key, entry)
- LOGGER.info(msg)
+ log.info("Ignoring invalid %s config entry (expected a mapping, but \"%s\" was missing \"=>\")" % (key, entry))
val = valMap
return val
@@ -357,8 +353,7 @@ class Config():
if not multiple: val = val[-1]
self._requested_keys.add(key)
else:
- msg = "config entry '%s' not found, defaulting to '%s'" % (key, default)
- LOGGER.debug(msg)
+ log.debug("config entry '%s' not found, defaulting to '%s'" % (key, default))
val = default
self._contents_lock.release()
@@ -392,7 +387,7 @@ class Config():
defaultStr = ", ".join([str(i) for i in default])
msg += ", defaulting to '%s'" % defaultStr
- LOGGER.info(msg)
+ log.info(msg)
return default
return conf_comp
@@ -439,7 +434,7 @@ class Config():
break
if error_msg:
- LOGGER.info(error_msg)
+ log.info(error_msg)
return default
else: return [int(val) for val in conf_comp]
diff --git a/stem/util/log.py b/stem/util/log.py
new file mode 100644
index 0000000..6476a67
--- /dev/null
+++ b/stem/util/log.py
@@ -0,0 +1,70 @@
+"""
+Functions to aid library logging. Default logging is usually NOTICE and above,
+runlevels being used as follows...
+
+ ERROR - critical issue occured, the user needs to be notified
+ WARN - non-critical issue occured that the user should be aware of
+ NOTICE - information that is helpful to the user
+ INFO - high level library activity
+ DEBUG - low level library activity
+ TRACE - request/reply logging
+"""
+
+import logging
+
+import stem.util.enum
+
+# Logging runlevels. These are *very* commonly used so including shorter
+# aliases (so they can be referenced as log.DEBUG, log.WARN, etc).
+
+Runlevel = stem.util.enum.Enum(
+ ("TRACE", "TRACE"), ("DEBUG", "DEBUG"), ("INFO", "INFO"),
+ ("NOTICE", "NOTICE"), ("WARN", "WARN"), ("ERROR", "ERROR"))
+
+TRACE, DEBUG, INFO, NOTICE, WARN, ERR = list(Runlevel)
+
+# mapping of runlevels to the logger module's values, TRACE and DEBUG aren't
+# built into the module
+
+LOG_VALUES = {
+ Runlevel.TRACE: logging.DEBUG - 5,
+ Runlevel.DEBUG: logging.DEBUG,
+ Runlevel.INFO: logging.INFO,
+ Runlevel.NOTICE: logging.INFO + 5,
+ Runlevel.WARN: logging.WARN,
+ Runlevel.ERROR: logging.ERROR,
+}
+
+LOGGER = logging.getLogger("stem")
+
+def get_logger():
+ """
+ Provides the stem logger.
+
+ Returns:
+ logging.Logger for stem
+ """
+
+ return LOGGER
+
+def log(runlevel, message):
+ """
+ Logs a message at the given runlevel.
+
+ Arguments:
+ runlevel (Runlevel) - runlevel to log the message at, logging is skipped if
+ None
+ message (str) - message to be logged
+ """
+
+ if runlevel:
+ LOGGER.log(LOG_VALUES[runlevel], message)
+
+# shorter aliases for logging at a runlevel
+def trace(message): log(Runlevel.TRACE, message)
+def debug(message): log(Runlevel.DEBUG, message)
+def info(message): log(Runlevel.INFO, message)
+def notice(message): log(Runlevel.NOTICE, message)
+def warn(message): log(Runlevel.WARN, message)
+def error(message): log(Runlevel.ERROR, message)
+
diff --git a/stem/util/proc.py b/stem/util/proc.py
index 32ab920..bf91ace 100644
--- a/stem/util/proc.py
+++ b/stem/util/proc.py
@@ -27,11 +27,9 @@ import sys
import time
import socket
import base64
-import logging
import stem.util.enum
-
-LOGGER = logging.getLogger("stem")
+import stem.util.log as log
# cached system values
IS_PROC_AVAILABLE, SYS_START_TIME, SYS_PHYSICAL_MEMORY = None, None, None
@@ -441,8 +439,7 @@ def _log_runtime(parameter, proc_location, start_time):
"""
runtime = time.time() - start_time
- msg = "proc call (%s): %s (runtime: %0.4f)" % (parameter, proc_location, runtime)
- LOGGER.debug(msg)
+ log.debug("proc call (%s): %s (runtime: %0.4f)" % (parameter, proc_location, runtime))
def _log_failure(parameter, exc):
"""
@@ -453,6 +450,5 @@ def _log_failure(parameter, exc):
exc (Exception) - exception that we're raising
"""
- msg = "proc call failed (%s): %s" % (parameter, exc)
- LOGGER.debug(msg)
+ log.debug("proc call failed (%s): %s" % (parameter, exc))
diff --git a/stem/util/system.py b/stem/util/system.py
index bb50093..86a2e27 100644
--- a/stem/util/system.py
+++ b/stem/util/system.py
@@ -18,12 +18,10 @@ call - runs the given system command and provides back the results
import os
import time
-import logging
import subprocess
import stem.util.proc
-
-LOGGER = logging.getLogger("stem")
+import stem.util.log as log
# Functor for mocking the call function, which should either return a string
# (or None) to emulate responses, or a boolean to indicate if we should filter
@@ -247,7 +245,7 @@ def get_pid_by_name(process_name):
pid = results[0].strip()
if pid.isdigit(): return int(pid)
- LOGGER.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):
@@ -426,11 +424,11 @@ def get_cwd(pid):
results = call(GET_CWD_PWDX % pid)
if not results:
- LOGGER.debug("%s pwdx didn't return any results" % logging_prefix)
+ log.debug("%s pwdx didn't return any results" % logging_prefix)
elif results[0].endswith("No such process"):
- LOGGER.debug("%s pwdx processes reported for this pid" % logging_prefix)
+ log.debug("%s pwdx processes reported for this pid" % logging_prefix)
elif len(results) != 1 or results[0].count(" ") != 1 or not results[0].startswith("%s: " % pid):
- LOGGER.debug("%s we got unexpected output from pwdx: %s" % (logging_prefix, results))
+ log.debug("%s we got unexpected output from pwdx: %s" % (logging_prefix, results))
else:
return results[0].split(" ", 1)[1].strip()
@@ -455,7 +453,7 @@ def get_cwd(pid):
if results and len(results) == 2 and results[1].startswith("n/"):
return results[1][1:].strip()
else:
- LOGGER.debug("%s we got unexpected output from lsof: %s" % (logging_prefix, results))
+ log.debug("%s we got unexpected output from lsof: %s" % (logging_prefix, results))
return None # all queries failed
@@ -489,9 +487,9 @@ def get_bsd_jail_id(pid):
os_name = os.uname()[0]
if os_name == "FreeBSD":
- LOGGER.warn("Failed to figure out the FreeBSD jail id for pid %s. Guessing that it's not in a jail." % pid)
+ log.warn("Failed to figure out the FreeBSD jail id for pid %s. Guessing that it's not in a jail." % pid)
else:
- LOGGER.debug("get_bsd_jail_id(%s): this function isn't supported on %s" % (pid, os_name))
+ log.debug("get_bsd_jail_id(%s): this function isn't supported on %s" % (pid, os_name))
return 0
@@ -592,12 +590,12 @@ def call(command, suppress_exc = True):
msg = "system call: %s (runtime: %0.2f)" % (command, runtime)
if stderr: msg += "\nstderr: %s" % stderr
- LOGGER.debug(msg)
+ log.debug(msg)
if stdout: return stdout.split("\n")
else: return []
except OSError, exc:
- LOGGER.debug("system call (failed): %s (error: %s)" % (command, exc))
+ log.debug("system call (failed): %s (error: %s)" % (command, exc))
if suppress_exc: return None
else: raise exc
diff --git a/stem/version.py b/stem/version.py
index b984125..0b57301 100644
--- a/stem/version.py
+++ b/stem/version.py
@@ -19,13 +19,10 @@ Requirement - Enumerations for the version requirements of features.
"""
import re
-import logging
import stem.util.enum
import stem.util.system
-LOGGER = logging.getLogger("stem")
-
# cache for the get_tor_version function
VERSION_CACHE = {}
More information about the tor-commits
mailing list