# Copyright (C) 2015 Custodia Project Contributors - see LICENSE file from __future__ import absolute_import import logging import sys import warnings import six LOGGING_FORMAT = "%(asctime)s - %(origin)-32s - %(message)s" LOGGING_DATEFORMAT = "%Y-%m-%d %H:%M:%S" class OriginContextFilter(logging.Filter): """Context filter to include 'origin' attribute in record """ def filter(self, record): if not hasattr(record, 'origin'): record.origin = record.name.split('.')[-1] return True class CustodiaFormatter(logging.Formatter): def format(self, record): # customize record.exc_text, Formatter.format() does not modify # exc_text when it has been set before. short_exc = False if record.exc_info and not record.exc_text: if getattr(record, "exc_fullstack", True): record.exc_text = self.formatException(record.exc_info) else: short_exc = True record.exc_text = u"{0.__name__}: {1}".format( record.exc_info[0], record.exc_info[1] ) result = super(CustodiaFormatter, self).format(record) if short_exc: # format() adds \n between message and exc_text text, exc = result.rsplit(u'\n', 1) return u"{0} ({1})".format(text, exc) else: return result class CustodiaLoggingAdapter(logging.LoggerAdapter): def __init__(self, plugin, debug): logger = logging.getLogger( '{0.__class__.__module__}.{0.__class__.__name__}'.format(plugin) ) logger.setLevel(logging.DEBUG if debug else logging.INFO) extra = {'origin': plugin.origin} super(CustodiaLoggingAdapter, self).__init__(logger, extra=extra) def exception(self, msg, *args, **kwargs): """Like standard exception() logger but only print stack in debug mode """ extra = kwargs.setdefault('extra', {}) extra['exc_fullstack'] = self.isEnabledFor(logging.DEBUG) kwargs['exc_info'] = True self.log(logging.ERROR, msg, *args, **kwargs) def getLogger(name): """Create logger with custom exception() method """ def exception(self, msg, *args, **kwargs): extra = kwargs.setdefault('extra', {}) extra['exc_fullstack'] = self.isEnabledFor(logging.DEBUG) kwargs['exc_info'] = True self.log(logging.ERROR, msg, *args, **kwargs) logger = logging.getLogger(name) logger.exception = six.create_bound_method(exception, logger) return logger def setup_logging(debug=False, auditfile=None, handler=None): root_logger = logging.getLogger() # default is stream handler to stderr if handler is None: handler = logging.StreamHandler(sys.stderr) # remove handler instance from root handler to prevent multiple # output handlers. handler_cls = type(handler) root_logger.handlers[:] = list( h for h in root_logger.handlers if not isinstance(h, handler_cls) ) # configure handler handler.setFormatter(CustodiaFormatter( fmt=LOGGING_FORMAT, datefmt=LOGGING_DATEFORMAT )) handler.addFilter(OriginContextFilter()) root_logger.addHandler(handler) # set logging level custodia_logger = getLogger('custodia') if debug: custodia_logger.setLevel(logging.DEBUG) custodia_logger.debug('Custodia debug logger enabled') # If the global debug is enabled, turn debug on in all 'custodia.*' # loggers logdict = logging.Logger.manager.loggerDict for name, obj in logdict.items(): if not isinstance(obj, logging.Logger): continue if name.startswith('custodia.'): obj.setLevel(logging.DEBUG) else: custodia_logger.setLevel(logging.INFO) # setup file handler for audit log audit_logger = logging.getLogger('custodia.audit') if auditfile is not None and len(audit_logger.handlers) == 0: audit_fmt = logging.Formatter(LOGGING_FORMAT, LOGGING_DATEFORMAT) audit_hdrl = logging.FileHandler(auditfile) audit_hdrl.setFormatter(audit_fmt) audit_logger.addHandler(audit_hdrl) custodia_logger.debug('Custodia audit log: %s', auditfile) AUDIT_NONE = 0 AUDIT_GET_ALLOWED = 1 AUDIT_GET_DENIED = 2 AUDIT_SET_ALLOWED = 3 AUDIT_SET_DENIED = 4 AUDIT_DEL_ALLOWED = 5 AUDIT_DEL_DENIED = 6 AUDIT_LAST = 7 AUDIT_SVC_NONE = 8 AUDIT_SVC_AUTH_PASS = 9 AUDIT_SVC_AUTH_FAIL = 10 AUDIT_SVC_AUTHZ_PASS = 11 AUDIT_SVC_AUTHZ_FAIL = 12 AUDIT_SVC_LAST = 13 AUDIT_MESSAGES = [ "AUDIT FAILURE", "ALLOWED: '%(client)s' requested key '%(key)s'", # AUDIT_GET_ALLOWED "DENIED: '%(client)s' requested key '%(key)s'", # AUDIT_GET_DENIED "ALLOWED: '%(client)s' stored key '%(key)s'", # AUDIT_SET_ALLOWED "DENIED: '%(client)s' stored key '%(key)s'", # AUDIT_SET_DENIED "ALLOWED: '%(client)s' deleted key '%(key)s'", # AUDIT_DEL_ALLOWED "DENIED: '%(client)s' deleted key '%(key)s'", # AUDIT_DEL_DENIED "AUDIT FAILURE 7", "AUDIT FAILURE 8", "PASS: '%(cli)s' authenticated as '%(name)s'", # SVC_AUTH_PASS "FAIL: '%(cli)s' authenticated as '%(name)s'", # SVC_AUTH_FAIL "PASS: '%(cli)s' authorized for '%(name)s'", # SVC_AUTHZ_PASS "FAIL: '%(cli)s' authorized for '%(name)s'", # SVC_AUTHZ_FAIL "AUDIT FAILURE 13", ] class AuditLog: def __init__(self, logger): self.logger = logger def key_access(self, origin, action, client, keyname): if action <= AUDIT_NONE or action >= AUDIT_LAST: action = AUDIT_NONE msg = AUDIT_MESSAGES[action] args = {'client': client, 'key': keyname} self.logger.info(msg, args, extra={'origin': origin}) def svc_access(self, origin, action, client, name): if action <= AUDIT_SVC_NONE or action >= AUDIT_SVC_LAST: action = AUDIT_NONE msg = AUDIT_MESSAGES[action] args = {'cli': client, 'name': name} self.logger.info(msg, args, extra={'origin': origin}) auditlog = AuditLog(logging.getLogger('custodia.audit')) class ProvisionalWarning(FutureWarning): pass def warn_provisional(modulename, stacklevel=3): msg = ("Module '{}' is a provisional API. It may changed or get " "removed in future releases.") return warnings.warn(msg.format(modulename), ProvisionalWarning, stacklevel=stacklevel)