Changeset View
Changeset View
Standalone View
Standalone View
scap/log.py
| # -*- coding: utf-8 -*- | # -*- coding: utf-8 -*- | ||||
| """ | """ | ||||
| scap.log | scap.log | ||||
| ~~~~~~~~ | ~~~~~~~~ | ||||
| Helpers for routing and formatting log data. | Helpers for routing and formatting log data. | ||||
| """ | """ | ||||
| import fnmatch | import fnmatch | ||||
| from functools import partial | |||||
| import json | import json | ||||
| import logging | import logging | ||||
| import math | import math | ||||
| import operator | |||||
| import logging.handlers | import logging.handlers | ||||
| import re | import re | ||||
| import shlex | |||||
| import socket | import socket | ||||
| import sys | import sys | ||||
| import time | import time | ||||
| import traceback | import traceback | ||||
| from . import utils | from . import utils | ||||
| # Format string for log messages. Interpolates LogRecord attributes. | # Format string for log messages. Interpolates LogRecord attributes. | ||||
| ▲ Show 20 Lines • Show All 67 Lines • ▼ Show 20 Lines | |||||
| class JSONFormatter(logging.Formatter): | class JSONFormatter(logging.Formatter): | ||||
| """Serialize logging output as JSON. | """Serialize logging output as JSON. | ||||
| Can be used to maintain logged event structure between the deployment host | Can be used to maintain logged event structure between the deployment host | ||||
| and remote targets. | and remote targets. | ||||
| """ | """ | ||||
| MAPPING = [('name', ''), | MAPPING = [('name', ''), | ||||
dduvall: Arbitrary fields should still be included. See the `_isvalid(field)` method. | |||||
Not Done Inline ActionsI was a bit worried about running into circular references there, but it looks like the JSON encoder actually takes care of that. dduvall: I was a bit worried about running into circular references there, but it looks like the JSON… | |||||
| ('levelno', logging.INFO), | ('levelno', logging.INFO), | ||||
| ('filename', None), | ('filename', None), | ||||
| ('lineno', None), | ('lineno', None), | ||||
| ('msg', ''), | ('msg', ''), | ||||
| ('args', []), | ('args', []), | ||||
| ('exc_info', None), | ('exc_info', None), | ||||
| ('funcName', None)] | ('funcName', None)] | ||||
| # extrapolate efficient sets of mapped and built-in LogRecord attributes | # extrapolate efficient sets of mapped and built-in LogRecord attributes | ||||
| TIMES = {'created', 'msecs', 'relativeCreated'} | TIMES = {'created', 'msecs', 'relativeCreated'} | ||||
| FIELDS = {k for k, _ in MAPPING} | TIMES | FIELDS = {k for k, _ in MAPPING} | TIMES | ||||
| NATIVE = set(logging.LogRecord(*[v for _, v in MAPPING]).__dict__.keys()) | NATIVE = set(logging.LogRecord(*[v for _, v in MAPPING]).__dict__.keys()) | ||||
Done Inline Actionswhy is args marked unserializable? It needs to be serialized for parameterized log messages to work. Now all the log entries print out just the format string without the data, for example: 19:48:39 [debian-jessie] %s on %s returned [%d]: %s mmodell: why is args marked unserializable? It needs to be serialized for parameterized log messages to… | |||||
| @staticmethod | @staticmethod | ||||
| def make_record(data): | def make_record(data): | ||||
| fields = json.loads(data) | fields = json.loads(data) | ||||
| args = [fields.get(k, v) for k, v in JSONFormatter.MAPPING] | args = [fields.get(k, v) for k, v in JSONFormatter.MAPPING] | ||||
| record = logging.LogRecord(*args) | record = logging.LogRecord(*args) | ||||
Done Inline ActionsThis fails when there is an exception passed from the remote deploy-local via json, because the exception can't be serialized in a satisfactory format. We probably need to create our own stack trace (as a string or whatever...) and avoid passing it in the exc_info argument slot. mmodell: This fails when there is an exception passed from the remote deploy-local via json, because the… | |||||
Not Done Inline ActionsPre-formatting exc_info makes sense to me. Per our IRC discussion, we need to figure out how to properly deserialize/propagate this info on the consuming end. dduvall: Pre-formatting `exc_info` makes sense to me. Per our IRC discussion, we need to figure out how… | |||||
dduvallAuthorUnsubmitted Not Done Inline ActionsJust added a failing test for this. dduvall: Just added a failing test for this. | |||||
Not Done Inline Actionslogrecord can actually contain arbitrary fields, and this doesn't account for any we decide to add. Maybe not a huge deal but @thcipriani and I were talking about surfacing important errors by including an "important" tag field in the log messages on the target machine, which would cause them to pass the filter on the main scap deploy(cli.application) console. mmodell: logrecord can actually contain arbitrary fields, and this doesn't account for any we decide to… | |||||
| for k in fields: | for k in fields: | ||||
| if k in JSONFormatter.TIMES or k not in JSONFormatter.NATIVE: | if k in JSONFormatter.TIMES or k not in JSONFormatter.NATIVE: | ||||
| record.__dict__[k] = fields[k] | record.__dict__[k] = fields[k] | ||||
| return record | return record | ||||
| def format(self, record): | def format(self, record): | ||||
| rec = record.__dict__ | rec = record.__dict__ | ||||
| fields = {k: rec[k] for k in rec if self._isvalid(k)} | fields = {k: rec[k] for k in rec if self._isvalid(k)} | ||||
| return json.dumps(fields) | return json.dumps(fields) | ||||
Done Inline ActionsIf we add this, it will ensure that unserializable objects won't throw exceptions here: def serialize_obj(obj): if hasattr(obj, "getvalue"): return obj.getvalue() elif hasattr(obj, "__dict__"): return obj.__dict__ return None rec = record.__dict__.copy() return json.dumps(rec, default=serialize_obj, skipkeys=True) mmodell: If we add this, it will ensure that unserializable objects won't throw exceptions here… | |||||
Done Inline ActionsThis fails when there is an exception in the record. Exceptions aren't serializable. You can pass default=callable(rec) to the dumps method, to override the default handling of non-serializable objects, however, when I do that, there is another problem on the other end when we reconstruct the logmessage from the serialized json (see above, line #119) mmodell: This fails when there is an exception in the record. Exceptions aren't serializable. You can… | |||||
dduvallAuthorUnsubmitted Done Inline ActionsAdded a failing test for this as well. dduvall: Added a failing test for this as well. | |||||
| def _isvalid(self, field): | def _isvalid(self, field): | ||||
| return field in self.FIELDS or field not in self.NATIVE | return field in self.FIELDS or field not in self.NATIVE | ||||
| class LogstashFormatter(logging.Formatter): | class LogstashFormatter(logging.Formatter): | ||||
| """Format log messages for logstash.""" | """Format log messages for logstash.""" | ||||
| ▲ Show 20 Lines • Show All 141 Lines • ▼ Show 20 Lines | def _progress(self): | ||||
| self._fd.write(fmt % self._output()) | self._fd.write(fmt % self._output()) | ||||
| def _output(self): | def _output(self): | ||||
| return '%s: %3.0f%% (ok: %d; fail: %d; left: %d)' % ( | return '%s: %3.0f%% (ok: %d; fail: %d; left: %d)' % ( | ||||
| self._name, self.percent_complete, | self._name, self.percent_complete, | ||||
| self.ok, self.failed, self.remaining) | self.ok, self.failed, self.remaining) | ||||
| class DeployLogFormatter(JSONFormatter): | |||||
| """Ensures that all `deploy.log` records contain a host attribute.""" | |||||
| def format(self, record): | |||||
| if not hasattr(record, 'host'): | |||||
| record.host = socket.gethostname() | |||||
| return super(DeployLogFormatter, self).format(record) | |||||
| class DeployLogHandler(logging.FileHandler): | |||||
| """Handler for `scap/deploy.log`.""" | |||||
| def __init__(self, log_file): | |||||
| super(DeployLogHandler, self).__init__(log_file) | |||||
| self.setFormatter(DeployLogFormatter()) | |||||
| self.setLevel(logging.DEBUG) | |||||
| class Filter(object): | class Filter(object): | ||||
| """Generic log filter that matches record properties against criteria. | """Generic log filter that matches record attributes against criteria. | ||||
| You can provide either a glob pattern, regular expression, or lambda as | You can provide either a glob pattern, regular expression, or lambda as | ||||
| each property criteria, and invert the logic by passing filter=False. | each attribute criterion, and invert the logic by passing filter=False. | ||||
| Examples: | Examples: | ||||
| Filter(name='*.target.*') | Filter({'name': '*.target.*', 'host': 'scap-target-01'}) | ||||
| Filter(message=re.compile('some annoying (message|msg)')) | Filter({'msg': re.compile('some annoying (message|msg)')}) | ||||
| Filter(levelno=lambda lvl: lvl < logging.WARNING) | Filter({'levelno': lambda lvl: lvl < logging.WARNING}) | ||||
| Filter({'name': '*.target.*'}, filter=False) | |||||
| Equivalent DSL examples: | |||||
| Filter.loads('name == *.target.* host == scap-target-01') | |||||
| Filter.loads('msg ~ "some annoying (message|msg)"') | |||||
| Filter.loads('levelno < WARNING') | |||||
| Filter.loads('name == *.target.*', filter=False) | |||||
| """ | |||||
| OPERATORS = {'=', '==', '~', '>', '>=', '<', '<='} | |||||
| COMPARISONS = {'>': 'gt', '>=': 'ge', '<': 'lt', '<=': 'le'} | |||||
| LOG_LEVELS = ['CRITICAL', 'ERROR', 'WARNING', 'INFO', 'DEBUG'] | |||||
| @staticmethod | |||||
| def loads(expression, filter=True): | |||||
| """Constructs a `Filter` from the given free-form expression. | |||||
| See :class:`Filter` for examples. | |||||
| """ | |||||
| criteria = [] | |||||
| for lhs, op, rhs in Filter.parse(expression): | |||||
| if lhs == 'levelno' and rhs in Filter.LOG_LEVELS: | |||||
| criterion = getattr(logging, rhs) | |||||
| elif rhs.isdigit(): | |||||
| criterion = int(rhs) | |||||
| else: | |||||
| criterion = rhs | |||||
| if op in Filter.COMPARISONS: | |||||
| # map to a "rich comparison" operator | |||||
| # e.g. foo < 10 becomes `operator.lt(foo, 10)` | |||||
| func = getattr(operator, Filter.COMPARISONS[op]) | |||||
| criterion = partial(lambda f, c, v: f(v, c), func, criterion) | |||||
Done Inline ActionsThis seems to blow up since the partial returned by using the expression: levelno > WARNING would be: lambda v: getattr(30, 'gt')(v) thcipriani: This seems to blow up since the partial returned by using the expression: `levelno > WARNING`… | |||||
| elif op == '~': | |||||
| criterion = re.compile(criterion) | |||||
| criteria.append((lhs, criterion)) | |||||
| return Filter(criteria, filter=filter) | |||||
| @staticmethod | |||||
| def parse(expression): | |||||
| """Parses the given filter expression and generates its parts. | |||||
| :param expression: Filter expression. | |||||
| :type expression: str | |||||
| Filter(filter=False, name='*.target.*') | :yields: (lhs, op, rhs) | ||||
| """ | """ | ||||
| def __init__(self, filter=True, **criteria): | parts = shlex.split(expression) | ||||
| # check that we're dealing with tuples of 3s (lhs, operator, rhs) | |||||
| if len(parts) % 3 > 0: | |||||
| raise ValueError("invalid expression '{}'".format(expression)) | |||||
| for i in range(0, len(parts), 3): | |||||
| lhs, op, rhs = parts[i:i + 3] | |||||
| if op not in Filter.OPERATORS: | |||||
| raise ValueError("invalid operator '{}'".format(op)) | |||||
| yield lhs, op, rhs | |||||
| def __init__(self, criteria, filter=True): | |||||
| self._filter = filter | self._filter = filter | ||||
| self.criteria = {} | self.criteria = [] | ||||
| self.append(criteria) | |||||
| # Normalize all globs into regexs into lambdas | def append(self, criteria): | ||||
| for prop in criteria: | """Appends the filter with the given criteria. | ||||
| criterion = criteria[prop] | |||||
| :param criteria: Filter criteria | |||||
| :type criteria: iter | |||||
| """ | |||||
| if hasattr(criteria, 'items'): | |||||
| criteria = criteria.items() | |||||
| # Normalize all globs into regexs into lambdas | |||||
| for attr, criterion in criteria: | |||||
| if type(criterion) == str: | if type(criterion) == str: | ||||
| criterion = re.compile(fnmatch.translate(criterion)) | criterion = re.compile(fnmatch.translate(criterion)) | ||||
| if hasattr(criterion, '__call__'): | if not hasattr(criterion, '__call__'): | ||||
| self.criteria[prop] = criterion | criterion = partial(lambda c, v: c.search(v), criterion) | ||||
| else: | |||||
| self.criteria[prop] = lambda value: criterion.search(value) | self.criteria.append((attr, criterion)) | ||||
| def filter(self, record): | def filter(self, record): | ||||
| """Performs filtering on a given log record. | |||||
| :param record: Log record. | |||||
| :type record: LogRecord | |||||
| """ | |||||
| record = record.__dict__ | record = record.__dict__ | ||||
| matches = True | matches = True | ||||
| for prop in self.criteria: | for attr, criterion in self.criteria: | ||||
| if not self.criteria[prop](record.get(prop, '')): | if attr not in record or not criterion(record.get(attr)): | ||||
| matches = False | matches = False | ||||
| break | break | ||||
| if self._filter: | if self._filter: | ||||
| return not matches | return not matches | ||||
| else: | else: | ||||
| return matches | return matches | ||||
| def isfiltering(self, attribute): | |||||
| """Whether the filter has criteria for the given attribute.""" | |||||
| for attr, _ in self.criteria: | |||||
| if attr == attribute: | |||||
| return True | |||||
| return False | |||||
| class MuteReporter(ProgressReporter): | class MuteReporter(ProgressReporter): | ||||
| """A report that declines to report anything.""" | """A report that declines to report anything.""" | ||||
| def __init__(self, name='', expect=0, fd=sys.stderr): | def __init__(self, name='', expect=0, fd=sys.stderr): | ||||
| super(self.__class__, self).__init__(name) | super(self.__class__, self).__init__(name) | ||||
| def _progress(self): | def _progress(self): | ||||
| pass | pass | ||||
| ▲ Show 20 Lines • Show All 132 Lines • ▼ Show 20 Lines | def makePickle(self, record): | ||||
| text = re.sub(r'^', self.prefix + ' ', text, flags=re.MULTILINE) | text = re.sub(r'^', self.prefix + ' ', text, flags=re.MULTILINE) | ||||
| if len(text) > 65506: | if len(text) > 65506: | ||||
| text = text[:65506] | text = text[:65506] | ||||
| if text[-1] != '\n': | if text[-1] != '\n': | ||||
| text = text + '\n' | text = text + '\n' | ||||
| return text | return text | ||||
| def setup_loggers(cfg, console_level=logging.INFO): | def setup_loggers(cfg, console_level=logging.INFO, handlers=[]): | ||||
| """Setup the logging system. | """Setup the logging system. | ||||
| * Configure the root logger to use :class:`AnsiColorFormatter` | * Configure the root logger to use :class:`AnsiColorFormatter` | ||||
| * Optionally add a :class:`Udp2LogHandler` to send logs to a udp2log server | * Optionally add a :class:`Udp2LogHandler` to send logs to a udp2log server | ||||
| * Optional add a :class:`IRCSocketHandler` for the `scap.announce` log | * Optional add a :class:`IRCSocketHandler` for the `scap.announce` log | ||||
| channel to send messages to a tcpircbot server | channel to send messages to a tcpircbot server | ||||
| :param cfg: Dict of global configuration values | :param cfg: Dict of global configuration values | ||||
| :param console_level: Logging level for the local console appender | :param console_level: Logging level for the local console appender | ||||
| :param handlers: Additional handlers | |||||
| """ | """ | ||||
| # Set logger levels | # Set logger levels | ||||
| logging.root.setLevel(logging.DEBUG) | logging.root.setLevel(logging.DEBUG) | ||||
| logging.root.handlers[0].setLevel(console_level) | logging.root.handlers[0].setLevel(console_level) | ||||
| # Filter target output until we can properly filter it | # Filter target output from the main handler | ||||
| logging.root.handlers[0].addFilter(Filter(name='target.*')) | logging.root.handlers[0].addFilter(Filter({'name': 'target.*'})) | ||||
| if cfg['log_json']: | if cfg['log_json']: | ||||
| logging.root.handlers[0].setFormatter(JSONFormatter()) | logging.root.handlers[0].setFormatter(JSONFormatter()) | ||||
| else: | else: | ||||
| # Colorize log messages sent to stderr | # Colorize log messages sent to stderr | ||||
| logging.root.handlers[0].setFormatter(AnsiColorFormatter( | logging.root.handlers[0].setFormatter(AnsiColorFormatter( | ||||
| '%(asctime)s %(message)s', '%H:%M:%S')) | '%(asctime)s %(message)s', '%H:%M:%S')) | ||||
| if cfg['udp2log_host']: | if cfg['udp2log_host']: | ||||
| # Send a copy of all logs to the udp2log relay | # Send a copy of all logs to the udp2log relay | ||||
| udp_handler = Udp2LogHandler( | udp_handler = Udp2LogHandler( | ||||
| cfg['udp2log_host'], int(cfg['udp2log_port'])) | cfg['udp2log_host'], int(cfg['udp2log_port'])) | ||||
| udp_handler.setLevel(logging.DEBUG) | udp_handler.setLevel(logging.DEBUG) | ||||
| udp_handler.setFormatter(LogstashFormatter()) | udp_handler.setFormatter(LogstashFormatter()) | ||||
| logging.root.addHandler(udp_handler) | logging.root.addHandler(udp_handler) | ||||
| if cfg['tcpircbot_host']: | if cfg['tcpircbot_host']: | ||||
| # Send 'scap.announce' messages to irc relay | # Send 'scap.announce' messages to irc relay | ||||
| irc_logger = logging.getLogger('scap.announce') | irc_logger = logging.getLogger('scap.announce') | ||||
| irc_logger.addHandler(IRCSocketHandler( | irc_logger.addHandler(IRCSocketHandler( | ||||
| cfg['tcpircbot_host'], int(cfg['tcpircbot_port']))) | cfg['tcpircbot_host'], int(cfg['tcpircbot_port']))) | ||||
| for handler in handlers: | |||||
| logging.root.addHandler(handler) | |||||
Content licensed under Creative Commons Attribution-ShareAlike 3.0 (CC-BY-SA) unless otherwise noted; code licensed under GNU General Public License (GPL) or other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL
Arbitrary fields should still be included. See the _isvalid(field) method.