commit a3f9647832dab69c5eda8047748d0de534fac073 Author: Damian Johnson atagar@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 = {}