diff --git a/docs/settings/settings_local.dev.py b/docs/settings/settings_local.dev.py index 22e8480aa2..be50e73a23 100644 --- a/docs/settings/settings_local.dev.py +++ b/docs/settings/settings_local.dev.py @@ -1,5 +1,19 @@ from settings import * +DEBUG = True +TEMPLATE_DEBUG = DEBUG +DEBUG_PROPAGATE_EXCEPTIONS = DEBUG + +# These apps are great during development. +INSTALLED_APPS += ( + 'debug_toolbar', + 'django_extensions', + 'fixture_magic', +) + +CACHE_BACKEND = 'django_pylibmc.memcached://localhost:11211?timeout=5000' +# Uncomment to disable caching: +# CACHE_BACKEND = 'dummy://' DATABASES = { 'default': { @@ -13,16 +27,18 @@ DATABASES = { }, } + +LOG_LEVEL = logging.DEBUG +HAS_SYSLOG = False + # For debug toolbar. -MIDDLEWARE_CLASSES += ('debug_toolbar.middleware.DebugToolbarMiddleware',) -INTERNAL_IPS = ('127.0.0.1',) -INSTALLED_APPS += ('debug_toolbar',) - -CACHE_BACKEND = 'caching.backends.memcached://localhost:11211?timeout=500' - -DEBUG = True - -DEBUG_PROPAGATE_EXCEPTIONS = DEBUG +if DEBUG: + INTERNAL_IPS = ('127.0.0.1',) + MIDDLEWARE_CLASSES += ('debug_toolbar.middleware.DebugToolbarMiddleware',) + DEBUG_TOOLBAR_CONFIG = { + 'HIDE_DJANGO_SQL': False, + 'INTERCEPT_REDIRECTS': False, + } # If you're not running on SSL you'll want this to be False SESSION_COOKIE_SECURE = False diff --git a/docs/topics/logging.rst b/docs/topics/logging.rst index 9fa3f8c568..3130fb48b5 100644 --- a/docs/topics/logging.rst +++ b/docs/topics/logging.rst @@ -27,26 +27,36 @@ tree. It sets up sensible defaults, but you can twiddle with these settings: import logging LOG_LEVEL = logging.WARN -``LOG_FILTERS`` - If this optional setting is set to a tuple, only log items matching strings - in said tuple will be displayed. +``HAS_SYSLOG`` + Set this to ``False`` if you don't want logging sent to syslog when + ``DEBUG`` is ``False``. - For example:: +``LOGGING`` + See PEP 391 and log_settings.py for formatting help. Each section of LOGGING + will get merged into the corresponding section of log_settings.py. + Handlers and log levels are set up automatically based on LOG_LEVEL and DEBUG + unless you set them here. Messages will not propagate through a logger unless + propagate: True is set. - LOG_FILTERS = ('z.sphinx.', ) + :: - This will show you messages **only** that start with ``z.sphinx``. + LOGGING = { + 'loggers': { + 'caching': {'handlers': ['null']}, + }, + } -``LOG_FORMAT`` - This string controls what gets printed out for each log message. See the - default in ``log_settings.py``. The complete list of formatting options is - available at http://docs.python.org/library/logging.html#formatter. + If you want to add more to this in ``settings_local.py``, do something like + this:: -``SYSLOG_FORMAT`` - This setting is the same as ``LOG_FORMAT`` except it controls the format for - what is sent to syslog. By default, it's the same as ``LOG_FORMAT`` except - it strips the date/time prefix since syslogd is going to timestamp - everything anyway. + LOGGING['loggers'].update({ + 'z.paypal': { + 'level': logging.DEBUG, + }, + 'z.sphinx': { + 'handlers': ['null'], + }, + }) Using Loggers @@ -69,4 +79,12 @@ Logs can be nested as much as you want. Maintaining log namespaces is useful because we can turn up the logging output for a particular section of zamboni without becoming overwhelmed with logging from all other parts. + +commonware.log vs. logging +~~~~~~~~~~~~~~~~~~~~~~~~~~ + +``commonware.log.getLogger`` should be used inside the request cycle. It +returns a ``LoggingAdapter`` that inserts the current user's IP address into +the log message. + Complete logging docs: http://docs.python.org/library/logging.html diff --git a/lib/dictconfig.py b/lib/dictconfig.py new file mode 100644 index 0000000000..97f038c819 --- /dev/null +++ b/lib/dictconfig.py @@ -0,0 +1,527 @@ +import logging.handlers +import re +import sys +import types + +IDENTIFIER = re.compile('^[a-z_][a-z0-9_]*$', re.I) + +def valid_ident(s): + m = IDENTIFIER.match(s) + if not m: + raise ValueError('Not a valid Python identifier: %r' % s) + return True + +# +# This function is defined in logging only in recent versions of Python +# +try: + from logging import _checkLevel +except ImportError: + def _checkLevel(level): + if isinstance(level, int): + rv = level + elif str(level) == level: + if level not in logging._levelNames: + raise ValueError('Unknown level: %r' % level) + rv = logging._levelNames[level] + else: + raise TypeError('Level not an integer or a ' + 'valid string: %r' % level) + return rv + +# The ConvertingXXX classes are wrappers around standard Python containers, +# and they serve to convert any suitable values in the container. The +# conversion converts base dicts, lists and tuples to their wrapped +# equivalents, whereas strings which match a conversion format are converted +# appropriately. +# +# Each wrapper should have a configurator attribute holding the actual +# configurator to use for conversion. + +class ConvertingDict(dict): + """A converting dictionary wrapper.""" + + def __getitem__(self, key): + value = dict.__getitem__(self, key) + result = self.configurator.convert(value) + #If the converted value is different, save for next time + if value is not result: + self[key] = result + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + + def get(self, key, default=None): + value = dict.get(self, key, default) + result = self.configurator.convert(value) + #If the converted value is different, save for next time + if value is not result: + self[key] = result + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + + def pop(self, key, default=None): + value = dict.pop(self, key, default) + result = self.configurator.convert(value) + if value is not result: + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + +class ConvertingList(list): + """A converting list wrapper.""" + def __getitem__(self, key): + value = list.__getitem__(self, key) + result = self.configurator.convert(value) + #If the converted value is different, save for next time + if value is not result: + self[key] = result + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + + def pop(self, idx=-1): + value = list.pop(self, idx) + result = self.configurator.convert(value) + if value is not result: + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + return result + +class ConvertingTuple(tuple): + """A converting tuple wrapper.""" + def __getitem__(self, key): + value = tuple.__getitem__(self, key) + result = self.configurator.convert(value) + if value is not result: + if type(result) in (ConvertingDict, ConvertingList, + ConvertingTuple): + result.parent = self + result.key = key + return result + +class BaseConfigurator(object): + """ + The configurator base class which defines some useful defaults. + """ + + CONVERT_PATTERN = re.compile(r'^(?P[a-z]+)://(?P.*)$') + + WORD_PATTERN = re.compile(r'^\s*(\w+)\s*') + DOT_PATTERN = re.compile(r'^\.\s*(\w+)\s*') + INDEX_PATTERN = re.compile(r'^\[\s*(\w+)\s*\]\s*') + DIGIT_PATTERN = re.compile(r'^\d+$') + + value_converters = { + 'ext' : 'ext_convert', + 'cfg' : 'cfg_convert', + } + + # We might want to use a different one, e.g. importlib + importer = __import__ + + def __init__(self, config): + self.config = ConvertingDict(config) + self.config.configurator = self + + def resolve(self, s): + """ + Resolve strings to objects using standard import and attribute + syntax. + """ + name = s.split('.') + used = name.pop(0) + found = self.importer(used) + for frag in name: + used += '.' + frag + try: + found = getattr(found, frag) + except AttributeError: + self.importer(used) + found = getattr(found, frag) + return found + + def ext_convert(self, value): + """Default converter for the ext:// protocol.""" + return self.resolve(value) + + def cfg_convert(self, value): + """Default converter for the cfg:// protocol.""" + rest = value + m = self.WORD_PATTERN.match(rest) + if m is None: + raise ValueError("Unable to convert %r" % value) + else: + rest = rest[m.end():] + d = self.config[m.groups()[0]] + #print d, rest + while rest: + m = self.DOT_PATTERN.match(rest) + if m: + d = d[m.groups()[0]] + else: + m = self.INDEX_PATTERN.match(rest) + if m: + idx = m.groups()[0] + if not self.DIGIT_PATTERN.match(idx): + d = d[idx] + else: + try: + n = int(idx) # try as number first (most likely) + d = d[n] + except TypeError: + d = d[idx] + if m: + rest = rest[m.end():] + else: + raise ValueError('Unable to convert ' + '%r at %r' % (value, rest)) + #rest should be empty + return d + + def convert(self, value): + """ + Convert values to an appropriate type. dicts, lists and tuples are + replaced by their converting alternatives. Strings are checked to + see if they have a conversion format and are converted if they do. + """ + if not isinstance(value, ConvertingDict) and isinstance(value, dict): + value = ConvertingDict(value) + value.configurator = self + elif not isinstance(value, ConvertingList) and isinstance(value, list): + value = ConvertingList(value) + value.configurator = self + elif not isinstance(value, ConvertingTuple) and\ + isinstance(value, tuple): + value = ConvertingTuple(value) + value.configurator = self + elif isinstance(value, basestring): # str for py3k + m = self.CONVERT_PATTERN.match(value) + if m: + d = m.groupdict() + prefix = d['prefix'] + converter = self.value_converters.get(prefix, None) + if converter: + suffix = d['suffix'] + converter = getattr(self, converter) + value = converter(suffix) + return value + + def configure_custom(self, config): + """Configure an object with a user-supplied factory.""" + c = config.pop('()') + if not hasattr(c, '__call__') and hasattr(types, 'ClassType') and type(c) != types.ClassType: + c = self.resolve(c) + props = config.pop('.', None) + # Check for valid identifiers + kwargs = dict([(k, config[k]) for k in config if valid_ident(k)]) + result = c(**kwargs) + if props: + for name, value in props.items(): + setattr(result, name, value) + return result + + def as_tuple(self, value): + """Utility function which converts lists to tuples.""" + if isinstance(value, list): + value = tuple(value) + return value + +class DictConfigurator(BaseConfigurator): + """ + Configure logging using a dictionary-like object to describe the + configuration. + """ + + def configure(self): + """Do the configuration.""" + + config = self.config + if 'version' not in config: + raise ValueError("dictionary doesn't specify a version") + if config['version'] != 1: + raise ValueError("Unsupported version: %s" % config['version']) + incremental = config.pop('incremental', False) + EMPTY_DICT = {} + logging._acquireLock() + try: + if incremental: + handlers = config.get('handlers', EMPTY_DICT) + # incremental handler config only if handler name + # ties in to logging._handlers (Python 2.7) + if sys.version_info[:2] == (2, 7): + for name in handlers: + if name not in logging._handlers: + raise ValueError('No handler found with ' + 'name %r' % name) + else: + try: + handler = logging._handlers[name] + handler_config = handlers[name] + level = handler_config.get('level', None) + if level: + handler.setLevel(_checkLevel(level)) + except StandardError, e: + raise ValueError('Unable to configure handler ' + '%r: %s' % (name, e)) + loggers = config.get('loggers', EMPTY_DICT) + for name in loggers: + try: + self.configure_logger(name, loggers[name], True) + except StandardError, e: + raise ValueError('Unable to configure logger ' + '%r: %s' % (name, e)) + root = config.get('root', None) + if root: + try: + self.configure_root(root, True) + except StandardError, e: + raise ValueError('Unable to configure root ' + 'logger: %s' % e) + else: + disable_existing = config.pop('disable_existing_loggers', True) + + logging._handlers.clear() + del logging._handlerList[:] + + # Do formatters first - they don't refer to anything else + formatters = config.get('formatters', EMPTY_DICT) + for name in formatters: + try: + formatters[name] = self.configure_formatter( + formatters[name]) + except StandardError, e: + raise ValueError('Unable to configure ' + 'formatter %r: %s' % (name, e)) + # Next, do filters - they don't refer to anything else, either + filters = config.get('filters', EMPTY_DICT) + for name in filters: + try: + filters[name] = self.configure_filter(filters[name]) + except StandardError, e: + raise ValueError('Unable to configure ' + 'filter %r: %s' % (name, e)) + + # Next, do handlers - they refer to formatters and filters + # As handlers can refer to other handlers, sort the keys + # to allow a deterministic order of configuration + handlers = config.get('handlers', EMPTY_DICT) + for name in sorted(handlers): + try: + handler = self.configure_handler(handlers[name]) + handler.name = name + handlers[name] = handler + except StandardError, e: + raise ValueError('Unable to configure handler ' + '%r: %s' % (name, e)) + # Next, do loggers - they refer to handlers and filters + + #we don't want to lose the existing loggers, + #since other threads may have pointers to them. + #existing is set to contain all existing loggers, + #and as we go through the new configuration we + #remove any which are configured. At the end, + #what's left in existing is the set of loggers + #which were in the previous configuration but + #which are not in the new configuration. + root = logging.root + existing = root.manager.loggerDict.keys() + #The list needs to be sorted so that we can + #avoid disabling child loggers of explicitly + #named loggers. With a sorted list it is easier + #to find the child loggers. + existing.sort() + #We'll keep the list of existing loggers + #which are children of named loggers here... + child_loggers = [] + #now set up the new ones... + loggers = config.get('loggers', EMPTY_DICT) + for name in loggers: + if name in existing: + i = existing.index(name) + prefixed = name + "." + pflen = len(prefixed) + num_existing = len(existing) + i = i + 1 # look at the entry after name + while (i < num_existing) and\ + (existing[i][:pflen] == prefixed): + child_loggers.append(existing[i]) + i = i + 1 + existing.remove(name) + try: + self.configure_logger(name, loggers[name]) + except StandardError, e: + raise ValueError('Unable to configure logger ' + '%r: %s' % (name, e)) + + #Disable any old loggers. There's no point deleting + #them as other threads may continue to hold references + #and by disabling them, you stop them doing any logging. + #However, don't disable children of named loggers, as that's + #probably not what was intended by the user. + for log in existing: + logger = root.manager.loggerDict[log] + if log in child_loggers: + logger.level = logging.NOTSET + logger.handlers = [] + logger.propagate = True + elif disable_existing: + logger.disabled = True + + # And finally, do the root logger + root = config.get('root', None) + if root: + try: + self.configure_root(root) + except StandardError, e: + raise ValueError('Unable to configure root ' + 'logger: %s' % e) + finally: + logging._releaseLock() + + def configure_formatter(self, config): + """Configure a formatter from a dictionary.""" + if '()' in config: + factory = config['()'] # for use in exception handler + try: + result = self.configure_custom(config) + except TypeError, te: + if "'format'" not in str(te): + raise + #Name of parameter changed from fmt to format. + #Retry with old name. + #This is so that code can be used with older Python versions + #(e.g. by Django) + config['fmt'] = config.pop('format') + config['()'] = factory + result = self.configure_custom(config) + else: + fmt = config.get('format', None) + dfmt = config.get('datefmt', None) + result = logging.Formatter(fmt, dfmt) + return result + + def configure_filter(self, config): + """Configure a filter from a dictionary.""" + if '()' in config: + result = self.configure_custom(config) + else: + name = config.get('name', '') + result = logging.Filter(name) + return result + + def add_filters(self, filterer, filters): + """Add filters to a filterer from a list of names.""" + for f in filters: + try: + filterer.addFilter(self.config['filters'][f]) + except StandardError, e: + raise ValueError('Unable to add filter %r: %s' % (f, e)) + + def configure_handler(self, config): + """Configure a handler from a dictionary.""" + formatter = config.pop('formatter', None) + if formatter: + try: + formatter = self.config['formatters'][formatter] + except StandardError, e: + raise ValueError('Unable to set formatter ' + '%r: %s' % (formatter, e)) + level = config.pop('level', None) + filters = config.pop('filters', None) + if '()' in config: + c = config.pop('()') + if not hasattr(c, '__call__') and hasattr(types, 'ClassType') and type(c) != types.ClassType: + c = self.resolve(c) + factory = c + else: + klass = self.resolve(config.pop('class')) + #Special case for handler which refers to another handler + if issubclass(klass, logging.handlers.MemoryHandler) and\ + 'target' in config: + try: + config['target'] = self.config['handlers'][config['target']] + except StandardError, e: + raise ValueError('Unable to set target handler ' + '%r: %s' % (config['target'], e)) + elif issubclass(klass, logging.handlers.SMTPHandler) and\ + 'mailhost' in config: + config['mailhost'] = self.as_tuple(config['mailhost']) + elif issubclass(klass, logging.handlers.SysLogHandler) and\ + 'address' in config: + config['address'] = self.as_tuple(config['address']) + factory = klass + kwargs = dict([(k, config[k]) for k in config if valid_ident(k)]) + try: + result = factory(**kwargs) + except TypeError, te: + if "'stream'" not in str(te): + raise + #The argument name changed from strm to stream + #Retry with old name. + #This is so that code can be used with older Python versions + #(e.g. by Django) + kwargs['strm'] = kwargs.pop('stream') + result = factory(**kwargs) + if formatter: + result.setFormatter(formatter) + if level is not None: + result.setLevel(_checkLevel(level)) + if filters: + self.add_filters(result, filters) + return result + + def add_handlers(self, logger, handlers): + """Add handlers to a logger from a list of names.""" + for h in handlers: + try: + logger.addHandler(self.config['handlers'][h]) + except StandardError, e: + raise ValueError('Unable to add handler %r: %s' % (h, e)) + + def common_logger_config(self, logger, config, incremental=False): + """ + Perform configuration which is common to root and non-root loggers. + """ + level = config.get('level', None) + if level is not None: + logger.setLevel(_checkLevel(level)) + if not incremental: + #Remove any existing handlers + for h in logger.handlers[:]: + logger.removeHandler(h) + handlers = config.get('handlers', None) + if handlers: + self.add_handlers(logger, handlers) + filters = config.get('filters', None) + if filters: + self.add_filters(logger, filters) + + def configure_logger(self, name, config, incremental=False): + """Configure a non-root logger from a dictionary.""" + logger = logging.getLogger(name) + self.common_logger_config(logger, config, incremental) + propagate = config.get('propagate', None) + if propagate is not None: + logger.propagate = propagate + + def configure_root(self, config, incremental=False): + """Configure a root logger from a dictionary.""" + root = logging.getLogger() + self.common_logger_config(root, config, incremental) + +dictConfigClass = DictConfigurator + +def dictConfig(config): + """Configure logging using a dictionary.""" + dictConfigClass(config).configure() diff --git a/log_settings.py b/log_settings.py index 9220a2f087..eb47b53950 100644 --- a/log_settings.py +++ b/log_settings.py @@ -3,40 +3,67 @@ import logging.handlers from django.conf import settings -# Loggers created under the "z" namespace, e.g. "z.caching", will inherit the -# configuration from the base z logger. -log = logging.getLogger('z') +import commonware.log +import dictconfig + + +class NullHandler(logging.Handler): + + def emit(self, record): + pass -level = settings.LOG_LEVEL base_fmt = ('%(name)s:%(levelname)s %(message)s ' ':%(pathname)s:%(lineno)s') -if settings.DEBUG: - fmt = getattr(settings, 'LOG_FORMAT', '%(asctime)s ' + base_fmt) - handler, root_handler = logging.StreamHandler(), logging.StreamHandler() - formatter = logging.Formatter(fmt, datefmt='%H:%M:%S') - root_handler.setFormatter(formatter) -else: - SysLogger = logging.handlers.SysLogHandler - handler = SysLogger(facility=SysLogger.LOG_LOCAL7) - # Use a root formatter that's known to be safe. - root_handler = SysLogger(facility=SysLogger.LOG_LOCAL7) - root_handler.setFormatter( - logging.Formatter('%s: %s' % (settings.SYSLOG_TAG, base_fmt))) +cfg = { + 'version': 1, + 'filters': {}, + 'formatters': { + 'debug': { + '()': commonware.log.Formatter, + 'datefmt': '%H:%M:%s', + 'format': '%(asctime)s ' + base_fmt, + }, + 'prod': { + '()': commonware.log.Formatter, + 'datefmt': '%H:%M:%s', + 'format': '%s: [%%(REMOTE_ADDR)s] %s' % (settings.SYSLOG_TAG, + base_fmt), + }, + }, + 'handlers': { + 'console': { + '()': logging.StreamHandler, + 'formatter': 'debug', + }, + 'syslog': { + '()': logging.handlers.SysLogHandler, + 'facility': logging.handlers.SysLogHandler.LOG_LOCAL7, + 'formatter': 'prod', + }, + 'null': { + '()': NullHandler, + }, + }, + 'loggers': { + 'z': {}, + }, + 'root': {}, +} - fmt = '%s: [%%(REMOTE_ADDR)s] %s' % (settings.SYSLOG_TAG, base_fmt) - fmt = getattr(settings, 'SYSLOG_FORMAT', fmt) - formatter = logging.Formatter(fmt) +for key, value in settings.LOGGING.items(): + cfg[key].update(value) -# Set a root handler to catch everything else. -logging.getLogger().addHandler(root_handler) +# Set the level and handlers for all loggers. +for logger in cfg['loggers'].values() + [cfg['root']]: + syslog = settings.HAS_SYSLOG and not settings.DEBUG + if 'handlers' not in logger: + logger['handlers'] = ['syslog' if syslog else 'console'] + if 'level' not in logger: + logger['level'] = settings.LOG_LEVEL + if logger is not cfg['root'] and 'propagate' not in logger: + logger['propagate'] = False -log.setLevel(level) -handler.setLevel(level) -handler.setFormatter(formatter) -for f in getattr(settings, 'LOG_FILTERS', []): - handler.addFilter(logging.Filter(f)) - -log.addHandler(handler) +dictconfig.dictConfig(cfg) diff --git a/settings.py b/settings.py index 530f1f98ca..df3ca759eb 100644 --- a/settings.py +++ b/settings.py @@ -18,8 +18,6 @@ ROOT_PACKAGE = os.path.basename(ROOT) DEBUG = True TEMPLATE_DEBUG = DEBUG DEBUG_PROPAGATE_EXCEPTIONS = True -LOG_LEVEL = logging.DEBUG -SYSLOG_TAG = "http_app_addons" ADMINS = ( # ('Your Name', 'your_email@domain.com'), @@ -105,8 +103,8 @@ MEDIA_URL = '/media//' ADMIN_MEDIA_PREFIX = '/admin-media/' # paths that don't require an app prefix -SUPPORTED_NONAPPS = ('admin', 'developers', 'editors', 'img', 'jsi18n', - 'localizers', 'media', 'statistics', 'services', 'firefoxcup') +SUPPORTED_NONAPPS = ('admin', 'developers', 'editors', 'firefoxcup', 'img', + 'jsi18n', 'localizers', 'media', 'statistics', 'services') DEFAULT_APP = 'firefox' # paths that don't require a locale prefix @@ -455,3 +453,18 @@ CUSTOM_DUMPS = { 'files.file'), } } + +# Logging +LOG_LEVEL = logging.DEBUG +HAS_SYSLOG = True # syslog is used if HAS_SYSLOG and NOT DEBUG. +SYSLOG_TAG = "http_app_addons" +# See PEP 391 and log_settings.py for formatting help. Each section of LOGGING +# will get merged into the corresponding section of log_settings.py. +# Handlers and log levels are set up automatically based on LOG_LEVEL and DEBUG +# unless you set them here. Messages will not propagate through a logger +# unless propagate: True is set. +LOGGING = { + 'loggers': { + 'caching': {'handlers': ['null']}, + }, +}