added-logging-as-logstash-format

config_template.py

@@ -72,3 +72,4 @@ class Config(object):
     THREAD_POOL_MAX = 100
 
     LOG_LEVEL = "INFO"
+    LOG_FORMAT = "plain/text"

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
 

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])