commit cc83936455cbe4e39016b3aef9d345652a82130d Author: Isis Lovecruft <isis@torproject.org> Date: Mon Apr 7 12:17:49 2014 +0000 Move log configuration functions to bridgedb.util module. * MOVE `Main.configureLogging()` → `util.configureLogging()`. * CHANGE `configureLogging()` function to use `logging.config.dictConfig()` with automatic safelogging filters from `bridgedb.safelog` module. * ADD `util._getRotatingFileHandlers()` function for chmod/chown'ing the rotated log files to be readable only by the running process owner. * ADD `util.JustifiedLogFormatter` class for justified printing of log messages when the config options LOG_TRACE and LOG_THREADS are enabled (this extra information is then printed in justified columns on the left, leaving the actual log messages left-justified to the same width on the right, which in my opinion is much easier to read quickly). --- lib/bridgedb/Main.py | 39 +--------- lib/bridgedb/util.py | 192 ++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 193 insertions(+), 38 deletions(-) diff --git a/lib/bridgedb/Main.py b/lib/bridgedb/Main.py index e29e991..90a03ef 100644 --- a/lib/bridgedb/Main.py +++ b/lib/bridgedb/Main.py @@ -13,7 +13,6 @@ import signal import sys import time import logging -import logging.handlers import gettext from twisted.internet import reactor @@ -29,42 +28,6 @@ import bridgedb.Dist as Dist import bridgedb.Time as Time import bridgedb.Storage -def configureLogging(cfg): - """Set up Python's logging subsystem based on the configuratino. - """ - - # Turn on safe logging by default - safelogging = getattr(cfg, 'SAFELOGGING', True) - - level = getattr(cfg, 'LOGLEVEL', 'WARNING') - level = getattr(logging, level) - logfile = getattr(cfg, 'LOGFILE', "") - logfile_count = getattr(cfg, 'LOGFILE_COUNT', 5) - logfile_rotate_size = getattr(cfg, 'LOGFILE_ROTATE_SIZE', 10000000) - safelog.setSafeLogging(safelogging) - - logging.getLogger().setLevel(level) - if logfile: - handler = logging.handlers.RotatingFileHandler(logfile, 'a', - logfile_rotate_size, - logfile_count) - formatter = logging.Formatter('%(asctime)s [%(levelname)s] %(message)s', - "%b %d %H:%M:%S") - handler.setFormatter(formatter) - logging.getLogger().addHandler(handler) - - logging.info("Logger Started.") - logging.info("Level: %s", level) - if logfile: - logging.info("Log File: %s", os.path.abspath(logfile)) - logging.info("Log File Count: %d", logfile_count) - logging.info("Rotate Logs After Size: %d", logfile_rotate_size) - else: - logging.info("Logging to stderr") - if safelogging: - logging.info("Safe Logging: Enabled") - else: - logging.warn("Safe Logging: Disabled") def load(state, splitter, clear=False): """Read and parse all descriptors, and load into a bridge splitter. @@ -461,7 +424,7 @@ def startup(options): # called. Otherwise a default handler that logs to the console will be # created by the imported module, and all further calls to # :func:`logging.basicConfig` will be ignored. - configureLogging(config) + util.configureLogging(config) if options['dump-bridges'] or (options.subCommand is not None): runSubcommand(options, config) diff --git a/lib/bridgedb/util.py b/lib/bridgedb/util.py index ebca7e1..691b9bc 100644 --- a/lib/bridgedb/util.py +++ b/lib/bridgedb/util.py @@ -11,5 +11,197 @@ """Common utilities for BridgeDB.""" +import logging +import logging.config +import logging.handlers +import os +def _getLogHandlers(logToFile=True, logToStderr=True): + """Get the appropriate list of log handlers. + + :param bool logToFile: If ``True``, add a logfile handler. + :param bool logToStderr: If ``True``, add a stream handler to stderr. + :rtype: list + :returns: A list containing the appropriate log handler names from the + :class:`logging.config.dictConfigClass`. + """ + logHandlers = [] + if logToFile: + logHandlers.append('rotating') + if logToStderr: + logHandlers.append('console') + return logHandlers + +def _getRotatingFileHandler(filename, mode='a', filesize=1000000, filecount=0, + encoding='utf-8', uid=None, gid=None): + """Get a :class:`logging.RotatingFileHandler` with a logfile which is + readable+writable only by the given **uid** and **gid**. + + :param str filename: The full path to the log file. + :param str mode: The mode to open **filename** with. (default: ``'a'``) + :param int filesize: Rotate logfiles after they have grown to this size in + bytes. + :param int filecount: The number of logfiles to keep in rotation. + :param str encoding: The encoding for the logfile. + :param int uid: The owner UID to set on the logfile. + :param int gid: The GID to set on the logfile. + :rtype: :class:`logging.handlers.RotatingFileHandler` + :returns: A logfile handler which will rotate files and chown/chmod newly + created files. + """ + # Default to the current process owner's uid and gid: + uid = os.getuid() if not uid else uid + gid = os.getgid() if not gid else gid + + if not os.path.exists(filename): + open(filename, 'a').close() + os.chown(filename, uid, gid) + os.chmod(filename, os.ST_WRITE | os.ST_APPEND) + + fileHandler = logging.handlers.RotatingFileHandler(filename, mode, + maxBytes=filesize, + backupCount=filecount, + encoding=encoding) + return fileHandler + +def configureLogging(cfg): + """Set up Python's logging subsystem based on the configuration. + + :type cfg: :class:`~bridgedb.persistent.Conf` + :param cfg: The current configuration, including any in-memory settings. + """ + from bridgedb import safelog + + # Turn on safe logging by default: + safelogging = getattr(cfg, 'SAFELOGGING', True) + safelog.setSafeLogging(safelogging) + + level = getattr(cfg, 'LOGLEVEL', 'WARNING') + logLevel = getattr(logging, level, 0) + logStderr = getattr(cfg, 'LOG_TO_STDERR', False) + logfileName = getattr(cfg, 'LOGFILE', "") + logfileCount = getattr(cfg, 'LOGFILE_COUNT', 3) - 1 + logfileRotateSize = getattr(cfg, 'LOGFILE_ROTATE_SIZE', 10000000) + logThreads = getattr(cfg, 'LOG_THREADS', False) + logTrace = getattr(cfg, 'LOG_TRACE', False) + logTimeFormat = getattr(cfg, 'LOG_TIME_FORMAT', "%H:%M:%S") + + logFilters = [] + if safelogging: + logFilters = ['safelogEmail', 'safelogIPv4', 'safelogIPv6'] + + logConfig = { + 'version': 1, + 'filters': { + 'safelogEmail': {'()': safelog.SafelogEmailFilter}, + 'safelogIPv4': {'()': safelog.SafelogIPv4Filter}, + 'safelogIPv6': {'()': safelog.SafelogIPv6Filter}, + }, + 'formatters': { + 'default': {'()': JustifiedLogFormatter, + # These values below are kwargs passed to + # :class:`JustifiedFormatter`: + 'logThreads': logThreads, + 'logTrace': logTrace, + 'datefmt': logTimeFormat}, + }, + 'handlers': { + 'console': {'class': 'logging.StreamHandler', + 'level': logLevel, + 'formatter': 'default', + 'filters': logFilters}, + 'rotating': {'()': _getRotatingFileHandler, + 'level': logLevel, + 'formatter': 'default', + 'filters': logFilters, + # The values below are passed to the handler creator, + # :func:`getChownedFileHandler`, as kwargs: + 'filename': logfileName, + 'filesize': logfileRotateSize, + 'filecount': logfileCount}, + }, + 'root': { + 'handlers': _getLogHandlers(logfileName, logStderr), + 'level': logLevel, + }, + } + + logging.config.dictConfig(logConfig) + + logging.info("Logger Started.") + logging.info("Level: %s", logLevel) + logging.info("Safe Logging: %sabled" % ("En" if safelogging else "Dis")) + + +class JustifiedLogFormatter(logging.Formatter): + """A logging formatter which pretty prints thread and calling function + information, in addition to the normal timestamp, log level, and log + message. + + :ivar int width: The width of the column for the calling function + information, if the latter is to be included. + """ + width = 30 + + def __init__(self, logThreads=False, logTrace=False, + datefmt="%H:%M:%s"): + """If **logTrace** is ``True``, the line number, module name, and + function name where the logger was called will be included in the + message, and the width of this information will always equal ``width``. + + :param bool logThreads: If ``True``, include the current thread name + and ID in formatted log messages. + :param bool logTrace: If ``True``, include information on the calling + function in formatted log messages. + """ + super(JustifiedLogFormatter, self).__init__(datefmt=datefmt) + self.logThreads = logThreads + self.logTrace = logTrace + + _fmt = ["%(asctime)s %(levelname)-7.7s"] + if self.logThreads: + _fmt.append("[%(threadName)s id:%(thread)d]") + _fmt.append("%(callingFunc)s") + _fmt.append("%(message)s") + + self._fmt = " ".join(_fmt) + + def _formatCallingFuncName(self, record): + """Format the combined module name and function name of the place where + the log message/record was recorded, so that the formatted string is + left-justified and not longer than the :cvar:`width`. + + :type record: :class:`logging.LogRecord` + :param record: A record of an event created by calling a logger. + :returns: The :class:`logging.LogRecord` with its ``message`` + attribute rewritten to contain the module and function name, + truncated to ``width``, or padded on the right with spaces as is + necessary. + """ + callingFunc = "" + if self.logTrace: + # The '.' character between the module name and function name + # would otherwise be interpreted as a format string specifier, so + # we must specify ``chr(46)``: + lineno = "L%s:" % record.lineno + caller = "%s%-s%s" % (lineno.rjust(6), record.module, chr(46)) + maxFuncNameWidth = self.width - 2 - len(caller) + funcName = record.funcName + if len(funcName) > maxFuncNameWidth: + funcName = record.funcName[:maxFuncNameWidth] + caller += "%s()" % (funcName) + callingFunc = caller.ljust(self.width) + + record.callingFunc = callingFunc + return record + + def format(self, record): + """Reformat this log **record** to neatly print thread and function + traces, if configured to do so. + + :type record: :class:`logging.LogRecord` + :param record: A record of an event created by calling a logger. + """ + record = self._formatCallingFuncName(record) + return super(JustifiedLogFormatter, self).format(record)