diff --git a/config_template.py b/config_template.py index 93e8f3a6..cfd070fc 100644 --- a/config_template.py +++ b/config_template.py @@ -72,3 +72,4 @@ class Config(object): THREAD_POOL_MAX = 100 LOG_LEVEL = "INFO" + LOG_FORMAT = "plain/text" diff --git a/core/logger.py b/core/logger.py index ebcda01d..d42e4fb7 100644 --- a/core/logger.py +++ b/core/logger.py @@ -1,10 +1,111 @@ -import logging -import logging.handlers -import graypy import os import sys +import json +import graypy +import socket +import logging +import traceback +import logging.handlers + +from config import config +from datetime import datetime +from core.utils.network_utils import ping + + +class LogstashFormatter(logging.Formatter): + + def __init__(self, message_type=None, tags=None, fqdn=False): + self.message_type = message_type if message_type else "vmmaster" + self.tags = tags if tags is not None else [] + + if fqdn: + self.host = socket.getfqdn() + else: + self.host = socket.gethostname() + + def get_extra_fields(self, record): + # The list contains all the attributes listed in + # http://docs.python.org/library/logging.html#logrecord-attributes + skip_list = ( + 'args', 'asctime', 'created', 'exc_info', 'exc_text', 'filename', + 'funcName', 'id', 'levelname', 'levelno', 'lineno', 'module', + 'msecs', 'msecs', 'message', 'msg', 'name', 'pathname', 'process', + 'processName', 'relativeCreated', 'thread', 'threadName', 'extra') + + if sys.version_info < (3, 0): + easy_types = (basestring, bool, dict, float, int, long, list, type(None)) + else: + easy_types = (str, bool, dict, float, int, list, type(None)) + + fields = {} + + for key, value in record.__dict__.items(): + if key not in skip_list: + if isinstance(value, easy_types): + fields[key] = value + else: + fields[key] = repr(value) + + return fields + + def get_debug_fields(self, record): + fields = { + 'stack_trace': self.format_exception(record.exc_info), + 'lineno': record.lineno, + 'process': record.process, + 'thread_name': record.threadName, + } + + if not getattr(record, 'funcName', None): + fields['funcName'] = record.funcName + + if not getattr(record, 'processName', None): + fields['processName'] = record.processName + + return fields + + @classmethod + def format_source(cls, message_type, host, path): + return "%s://%s/%s" % (message_type, host, path) + + @classmethod + def format_timestamp(cls, time): + tstamp = datetime.utcfromtimestamp(time) + return tstamp.strftime("%Y-%m-%dT%H:%M:%S") + ".%03d" % (tstamp.microsecond / 1000) + "Z" + + @classmethod + def format_exception(cls, exc_info): + return ''.join(traceback.format_exception(*exc_info)) if exc_info else '' + + @classmethod + def serialize(cls, message): + if sys.version_info < (3, 0): + return json.dumps(message) + else: + return bytes(json.dumps(message), 'utf-8') -from .config import config + def format(self, record): + message = { + '@timestamp': self.format_timestamp(record.created), + '@version': '1', + 'message': record.getMessage(), + 'host': self.host, + 'path': record.pathname, + 'tags': self.tags, + 'type': self.message_type, + + # Extra Fields + 'level': record.levelname, + 'logger_name': record.name, + } + + message.update(self.get_extra_fields(record)) + + # If exception, add debug info + if record.exc_info: + message.update(self.get_debug_fields(record)) + + return self.serialize(message) class StreamToLogger(object): @@ -22,11 +123,39 @@ def write(self, buf): self.logger.log(self.log_level, line.rstrip()) -def setup_logging( - logname='', logdir=None, logfile_name='vmmaster.log', - scrnlog=True, txtlog=True, loglevel=None -): - if loglevel is None: +def add_screen_handler(log, log_formatter): + console_handler = logging.StreamHandler() + console_handler.setFormatter(log_formatter) + log.addHandler(console_handler) + + +def add_text_handler(log, log_formatter, logdir, logfile_name): + txt_handler = logging.handlers.RotatingFileHandler( + os.path.join(logdir, logfile_name), + maxBytes=config.LOG_SIZE, + backupCount=5 + ) + txt_handler.setFormatter(log_formatter) + log.addHandler(txt_handler) + log.info("Logger initialised.") + + +def add_graylog_handler(log, log_formatter): + host, port = config.GRAYLOG + + if ping(host, port): + graylog_handler = graypy.GELFHandler(host=host, port=port) + graylog_handler.setFormatter(log_formatter) + log.addHandler(graylog_handler) + log.info("GRAYLOG Handler initialised.") + else: + log.warn('GRAYLOG URL not available') + + +def setup_logging(logname='', logdir=None, logfile_name='vmmaster.log', + scrnlog=True, txtlog=True, loglevel=None, + message_type="vmmaster", tags=None, fqdn=False): + if not loglevel: loglevel = logging.getLevelName(config.LOG_LEVEL.upper()) logdir = os.path.abspath(logdir) @@ -37,51 +166,30 @@ def setup_logging( log = logging.getLogger(logname) log.setLevel(loglevel) - if scrnlog: - log_format = \ - "%(asctime)s - %(levelname)-7s :: %(name)-6s :: %(message)s" - else: - log_format = "%(asctime)s - %(levelname)-7s :: %(message)s" - - log_formatter = logging.Formatter(log_format) - - if txtlog: - txt_handler = logging.handlers.RotatingFileHandler( - os.path.join(logdir, logfile_name), - maxBytes=config.LOG_SIZE, - backupCount=5 + if hasattr(config, "LOG_FORMAT") and config.LOG_FORMAT == 'json': + log_formatter = LogstashFormatter( + message_type=message_type, tags=tags, fqdn=fqdn ) - txt_handler.setFormatter(log_formatter) - log.addHandler(txt_handler) - - log.info("Logger initialised.") + else: + log_format = \ + "%(asctime)s - %(levelname)-7s :: %(name)-6s :: %(message)s" \ + if scrnlog else "%(asctime)s - %(levelname)-7s :: %(message)s" + log_formatter = logging.Formatter(log_format) if scrnlog: - console_handler = logging.StreamHandler() - console_handler.setFormatter(log_formatter) - log.addHandler(console_handler) + add_screen_handler(log, log_formatter) - if config.LOG_LEVEL.lower(): - stdout_logger = logging.getLogger('STDOUT') - slout = StreamToLogger(stdout_logger, logging.INFO) - sys.stdout = slout + if txtlog: + add_text_handler(log, log_formatter, logdir, logfile_name) if hasattr(config, 'GRAYLOG'): - from core.utils.network_utils import ping - - host = config.GRAYLOG[0] - port = config.GRAYLOG[1] + add_graylog_handler(log, log_formatter) - if ping(host, port): - graylog_handler = graypy.GELFHandler(host=host, port=port) - graylog_handler.setFormatter(log_formatter) - log.addHandler(graylog_handler) - else: - log.info('GRAYLOG URL not available') + stdout_logger = logging.getLogger('STDOUT') + sys.stdout = StreamToLogger(stdout_logger, loglevel) stderr_logger = logging.getLogger('STDERR') - slerr = StreamToLogger(stderr_logger, logging.ERROR) - sys.stderr = slerr + sys.stderr = StreamToLogger(stderr_logger, logging.ERROR) return log diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py new file mode 100644 index 00000000..8ab57890 --- /dev/null +++ b/tests/unit/test_logger.py @@ -0,0 +1,45 @@ +# coding: utf-8 +import json +import logging +from io import BytesIO +from tests.unit.helpers import BaseTestCase +from lode_runner import dataprovider +from core.logger import LogstashFormatter + + +class LogStreamHandlerTest(BaseTestCase): + def setUp(self): + self.logger = logging.getLogger('logging-test') + self.logger.setLevel(logging.DEBUG) + self.buffer = BytesIO() + self.logHandler = logging.StreamHandler(self.buffer) + self.logger.addHandler(self.logHandler) + + @dataprovider([ + "test message", + "{0}" + ]) + def test_properties(self, msg): + props = { + "message": msg, + "@version": "1", + "level": "INFO" + } + self.logHandler.setFormatter(LogstashFormatter()) + self.logger.info(msg) + log_json = json.loads(self.buffer.getvalue()) + self.assertEqual(log_json.get("@version"), props["@version"]) + self.assertEqual(log_json.get("tags"), list()) + self.assertTrue(isinstance(log_json.get("@timestamp"), unicode)) + self.assertEqual(log_json["message"], msg) + + @dataprovider([ + {"custom_field": 1}, + {"@1": "1"} + ]) + def test_extra_properties(self, extra): + self.logHandler.setFormatter(LogstashFormatter()) + self.logger.info("test message", extra=extra) + log_json = json.loads(self.buffer.getvalue()) + key = extra.keys()[0] + self.assertEqual(log_json.get(key), extra[key])