summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorLars Wirzenius <liw@liw.fi>2017-07-31 15:52:44 +0300
committerLars Wirzenius <liw@liw.fi>2017-07-31 15:52:52 +0300
commitf5927309b22d90bc40b3ae4ada68142c18fd57f1 (patch)
tree28de34e0cf65da55ce6e43d8d1fcafa24a54bed5
parent7cf35a044a13597fde5ba47e9e8c16b816615389 (diff)
downloadslog-f5927309b22d90bc40b3ae4ada68142c18fd57f1.tar.gz
Add: slog library
-rw-r--r--slog/__init__.py38
-rw-r--r--slog/counter.py34
-rw-r--r--slog/counter_tests.py50
-rw-r--r--slog/slog.py278
-rw-r--r--slog/slog_filter.py117
-rw-r--r--slog/slog_filter_tests.py267
-rw-r--r--slog/slog_tests.py258
-rw-r--r--slog/version.py2
8 files changed, 1044 insertions, 0 deletions
diff --git a/slog/__init__.py b/slog/__init__.py
new file mode 100644
index 0000000..7327eda
--- /dev/null
+++ b/slog/__init__.py
@@ -0,0 +1,38 @@
+# Copyright (C) 2017 Lars Wirzenius
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as
+# published by the Free Software Foundation, either version 3 of the
+# License, or (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+
+from .version import __version__, __version_info__
+from .counter import Counter
+
+from .slog import (
+ StructuredLog,
+ NullSlogWriter,
+ FileSlogWriter,
+ SyslogSlogWriter,
+ SlogHandler,
+ hijack_logging,
+)
+
+from .slog_filter import (
+ FilterAllow,
+ FilterDeny,
+ FilterFieldHasValue,
+ FilterFieldValueRegexp,
+ FilterHasField,
+ FilterInclude,
+ FilterAny,
+ construct_log_filter,
+)
diff --git a/slog/counter.py b/slog/counter.py
new file mode 100644
index 0000000..4760fe8
--- /dev/null
+++ b/slog/counter.py
@@ -0,0 +1,34 @@
+# Copyright 2015, 2016 Suomen Tilaajavastuu Oy
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+
+import _thread
+
+
+class Counter:
+
+ '''A threadsafe incrementing counter.'''
+
+ def __init__(self):
+ self._lock = _thread.allocate_lock()
+ self._counter = 0
+
+ def get(self):
+ return self._counter
+
+ def increment(self):
+ with self._lock:
+ self._counter += 1
+ return self._counter
diff --git a/slog/counter_tests.py b/slog/counter_tests.py
new file mode 100644
index 0000000..2c19fe1
--- /dev/null
+++ b/slog/counter_tests.py
@@ -0,0 +1,50 @@
+# Copyright 2016 QvarnLabs Ltd
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+
+import threading
+import unittest
+
+import slog
+
+
+class CounterTests(unittest.TestCase):
+
+ def test_counts_to_a_million_in_ten_threads(self):
+ max_count = 100000
+ num_threads = 2
+ counter = slog.Counter()
+
+ threads = []
+ for _ in range(num_threads):
+ ct = CountThread(max_count, counter)
+ ct.start()
+ threads.append(ct)
+ for ct in threads:
+ ct.join()
+
+ self.assertEqual(counter.get(), max_count * num_threads)
+
+
+class CountThread(threading.Thread):
+
+ def __init__(self, n, counter):
+ super(CountThread, self).__init__()
+ self.n = n
+ self.counter = counter
+
+ def run(self):
+ for _ in range(self.n):
+ self.counter.increment()
diff --git a/slog/slog.py b/slog/slog.py
new file mode 100644
index 0000000..81d2c61
--- /dev/null
+++ b/slog/slog.py
@@ -0,0 +1,278 @@
+# slog.py - structured logging
+#
+# Copyright 2016-2017 QvarnLabs Ab
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+
+import datetime
+import json
+import logging
+import os
+import time
+import traceback
+import _thread
+import syslog
+
+import slog
+
+
+class StructuredLog:
+
+ '''A structured logging system.
+
+ A structured log is one that can be easily parsed
+ programmatically. Traditional logs are free form text, usually
+ with a weakly enforced line structure and some minimal metadata
+ prepended to each file. This class produces JSON records instead.
+
+ See the separate manual for more background and examples of how to
+ use this system.
+
+ '''
+
+ def __init__(self):
+ self._msg_counter = slog.Counter()
+ self._context = {}
+ self._writers = []
+
+ def close(self):
+ for writer, _ in self._writers:
+ writer.close()
+ self._writers = []
+
+ def add_log_writer(self, writer, filter_rule):
+ self._writers.append((writer, filter_rule))
+
+ def set_context(self, new_context):
+ thread_id = self._get_thread_id()
+ self._context[thread_id] = new_context
+
+ def reset_context(self):
+ thread_id = self._get_thread_id()
+ self._context[thread_id] = None
+
+ def log(self, msg_type, **kwargs):
+ exc_info = kwargs.pop('exc_info', False)
+
+ log_obj = {
+ 'msg_type': msg_type,
+ }
+ for key, value in kwargs.items():
+ log_obj[key] = self._convert_value(value)
+
+ self._add_extra_fields(log_obj, exc_info)
+ for writer, filter_rule in self._writers:
+ if filter_rule.allow(log_obj):
+ writer.write(log_obj)
+
+ def _convert_value(self, value):
+ # Convert a value into an form that's safe to write. Meaning,
+ # it can't be binary data, and it is UTF-8 compatible, if it's
+ # a string of any sort.
+ #
+ # Note that we do not need to be able to parse the value back
+ # again, we just need to write it to a log file in a form that
+ # the user will understand. At least for now.
+ #
+ # We can't do this while encoding JSON, because the Python
+ # JSON library doesn't seem to allow us to override how
+ # encoding happens for types it already knows about, only for
+ # other types of values.
+
+ converters = {
+ int: self._nop_conversion,
+ float: self._nop_conversion,
+ bool: self._nop_conversion,
+ str: self._nop_conversion,
+ type(None): self._nop_conversion,
+
+ list: self._convert_list_value,
+ dict: self._convert_dict_value,
+ tuple: self._convert_tuple_value,
+ }
+
+ value_type = type(value)
+ assert value_type in converters, \
+ 'Unknown data type {}'.format(value_type)
+ func = converters[type(value)]
+ converted = func(value)
+ return converted
+
+ def _nop_conversion(self, value):
+ return value
+
+ def _convert_list_value(self, value):
+ return [self._convert_value(item) for item in value]
+
+ def _convert_tuple_value(self, value):
+ return tuple(self._convert_value(item) for item in value)
+
+ def _convert_dict_value(self, value):
+ return {
+ self._convert_value(key): self._convert_value(value[key])
+ for key in value
+ }
+
+ def _add_extra_fields(self, log_obj, stack_info):
+ log_obj['_msg_number'] = self._get_next_message_number()
+ log_obj['_timestamp'] = self._get_current_timestamp()
+ log_obj['_process_id'] = self._get_process_id()
+ log_obj['_thread_id'] = self._get_thread_id()
+ log_obj['_context'] = self._context.get(self._get_thread_id())
+ if stack_info:
+ log_obj['_traceback'] = self._get_traceback()
+
+ def _get_next_message_number(self):
+ return self._msg_counter.increment()
+
+ def _get_current_timestamp(self):
+ return datetime.datetime.utcnow().isoformat(' ')
+
+ def _get_process_id(self):
+ return os.getpid()
+
+ def _get_thread_id(self):
+ return _thread.get_ident()
+
+ def _get_traceback(self):
+ return traceback.format_exc()
+
+
+class SlogWriter: # pragma: no cover
+
+ def write(self, log_obj):
+ raise NotImplementedError()
+
+ def close(self):
+ raise NotImplementedError()
+
+
+class NullSlogWriter(SlogWriter): # pragma: no cover
+
+ def write(self, log_obj):
+ pass
+
+ def close(self):
+ pass
+
+
+class FileSlogWriter(SlogWriter):
+
+ def __init__(self):
+ self._log_filename = None
+ self._log_file = None
+ self._bytes_max = None
+ self._encoder = json.JSONEncoder(sort_keys=True)
+
+ def set_max_file_size(self, bytes_max):
+ self._bytes_max = bytes_max
+
+ def get_filename(self):
+ return self._log_filename
+
+ def get_rotated_filename(self, now=None):
+ prefix, suffix = os.path.splitext(self._log_filename)
+ if now is None: # pragma: no cover
+ now = time.localtime()
+ else:
+ now = tuple(list(now) + [0]*9)[:9]
+ timestamp = time.strftime('%Y%m%dT%H%M%S', now)
+ return '{}-{}{}'.format(prefix, timestamp, suffix)
+
+ def set_filename(self, filename):
+ self._log_filename = filename
+ self._log_file = open(filename, 'a')
+
+ def write(self, log_obj):
+ if self._log_file:
+ self._write_message(log_obj)
+ if self._bytes_max is not None:
+ self._rotate()
+
+ def _write_message(self, log_obj):
+ msg = self._encoder.encode(log_obj)
+ self._log_file.write(msg + '\n')
+ self._log_file.flush()
+
+ def _rotate(self):
+ pos = self._log_file.tell()
+ if pos >= self._bytes_max:
+ self._log_file.close()
+ rotated = self.get_rotated_filename()
+ os.rename(self._log_filename, rotated)
+ self.set_filename(self._log_filename)
+
+ def close(self):
+ self._log_file.close()
+ self._log_file = None
+
+
+class SyslogSlogWriter(SlogWriter): # pragma: no cover
+
+ def write(self, log_obj):
+ encoder = json.JSONEncoder(sort_keys=True)
+ s = encoder.encode(log_obj)
+ syslog.syslog(s)
+
+ def close(self):
+ pass
+
+
+class SlogHandler(logging.Handler): # pragma: no cover
+
+ '''A handler for the logging library to capture into a slog.
+
+ In order to capture all logging.* log messages into a structured
+ log, configure the logging library to use this handler.
+
+ '''
+
+ def __init__(self, log):
+ super(SlogHandler, self).__init__()
+ self.log = log
+
+ def emit(self, record):
+ attr_names = {
+ 'msg': 'msg_text',
+ }
+
+ log_args = dict()
+ for attr in dir(record):
+ if not attr.startswith('_'):
+ value = getattr(record, attr)
+ if not isinstance(value, (str, int, bool, float)):
+ value = repr(value)
+ log_args[attr_names.get(attr, attr)] = value
+ self.log.log('logging.' + record.levelname, **log_args)
+
+
+def hijack_logging(log, logger_names=None): # pragma: no cover
+ '''Hijack log messages that come via logging.* into a slog.'''
+
+ handler = SlogHandler(log)
+
+ for name in logger_names or []:
+ logger = logging.getLogger(name)
+ hijack_logger_handlers(logger, handler)
+
+ logger = logging.getLogger()
+ hijack_logger_handlers(logger, handler)
+
+
+def hijack_logger_handlers(logger, handler): # pragma: no cover
+ logger.setLevel(logging.DEBUG)
+ for h in logger.handlers:
+ logger.removeHandler(h)
+ logger.addHandler(handler)
diff --git a/slog/slog_filter.py b/slog/slog_filter.py
new file mode 100644
index 0000000..1115f05
--- /dev/null
+++ b/slog/slog_filter.py
@@ -0,0 +1,117 @@
+# slog_filter.py - structured logging filtering
+#
+# Copyright 2017 QvarnLabs Ab
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+
+import re
+
+
+class FilterRule: # pragma: no cover
+
+ def allow(self, log_obj):
+ raise NotImplementedError()
+
+
+class FilterAllow(FilterRule):
+
+ def allow(self, log_obj):
+ return True
+
+
+class FilterDeny(FilterRule):
+
+ def allow(self, log_obj):
+ return False
+
+
+class FilterHasField(FilterRule):
+
+ def __init__(self, field_name):
+ self._field_name = field_name
+
+ def allow(self, log_obj):
+ return self._field_name in log_obj
+
+
+class FilterFieldHasValue(FilterRule):
+
+ def __init__(self, field, value):
+ self._field = field
+ self._value = value
+
+ def allow(self, log_obj):
+ return self._field in log_obj and log_obj[self._field] == self._value
+
+
+class FilterFieldValueRegexp(FilterRule):
+
+ def __init__(self, field, pattern):
+ self._field = field
+ self._pattern = pattern
+
+ def allow(self, log_obj):
+ if self._field not in log_obj:
+ return False
+ value = str(log_obj[self._field])
+ return re.search(self._pattern, value) is not None
+
+
+class FilterInclude(FilterRule):
+
+ def __init__(self, rule_dict, rule):
+ self._rule = rule
+ self._include = rule_dict.get('include', True)
+
+ def allow(self, log_obj):
+ allow = self._rule.allow(log_obj)
+ return (self._include and allow) or (not self._include and not allow)
+
+
+class FilterAny(FilterRule):
+
+ def __init__(self, rules):
+ self._rules = rules
+
+ def allow(self, log_obj):
+ return any(rule.allow(log_obj) for rule in self._rules)
+
+
+def construct_log_filter(filters):
+ if not filters:
+ raise NoFilter()
+ rules = []
+ for spec in filters:
+ rule = None
+ if 'field' in spec:
+ if 'value' in spec:
+ rule = FilterFieldHasValue(spec['field'], spec['value'])
+ elif 'regexp' in spec:
+ rule = FilterFieldValueRegexp(
+ spec['field'], spec['regexp'])
+ elif 'field' in spec:
+ rule = FilterHasField(spec['field'])
+ else: # pragma: no cover
+ rule = FilterAllow()
+ if 'include' in spec:
+ rule = FilterInclude(spec, rule)
+ rules.append(rule)
+ return FilterAny(rules)
+
+
+class NoFilter(Exception):
+
+ def __init__(self):
+ super(NoFilter, self).__init__('No log filter specified')
diff --git a/slog/slog_filter_tests.py b/slog/slog_filter_tests.py
new file mode 100644
index 0000000..401d6a0
--- /dev/null
+++ b/slog/slog_filter_tests.py
@@ -0,0 +1,267 @@
+# slog_filter_tests.py - unit tests for structured logging tests
+#
+# Copyright 2017 QvarnLabs Ab
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+
+import unittest
+
+import slog
+
+
+class FilterHasFieldTests(unittest.TestCase):
+
+ def test_allows_if_field_is_there(self):
+ log_obj = {
+ 'foo': False,
+ }
+ rule = slog.FilterHasField('foo')
+ self.assertTrue(rule.allow(log_obj))
+
+ def test_doesnt_allow_if_field_is_not_there(self):
+ log_obj = {
+ 'foo': False,
+ }
+ rule = slog.FilterHasField('bar')
+ self.assertFalse(rule.allow(log_obj))
+
+
+class FilterFieldHasValueTests(unittest.TestCase):
+
+ def test_allows_when_field_has_wanted_value(self):
+ log_obj = {
+ 'foo': 'bar',
+ }
+ rule = slog.FilterFieldHasValue('foo', 'bar')
+ self.assertTrue(rule.allow(log_obj))
+
+ def test_doesnt_allow_when_field_has_unwanted_value(self):
+ log_obj = {
+ 'foo': 'bar',
+ }
+ rule = slog.FilterFieldHasValue('foo', 'yo')
+ self.assertFalse(rule.allow(log_obj))
+
+
+class FilterFieldValueRegexpTests(unittest.TestCase):
+
+ def test_allows_when_value_matches_regexp(self):
+ log_obj = {
+ 'foo': 'bar',
+ }
+ rule = slog.FilterFieldValueRegexp('foo', 'b.r')
+ self.assertTrue(rule.allow(log_obj))
+
+ def test_allows_when_value_matches_regexp_if_stringified(self):
+ log_obj = {
+ 'foo': 400,
+ }
+ rule = slog.FilterFieldValueRegexp('foo', '4.*')
+ self.assertTrue(rule.allow(log_obj))
+
+ def test_doesnt_allow_when_field_isnt_there(self):
+ log_obj = {
+ 'blarf': 'yo',
+ }
+ rule = slog.FilterFieldValueRegexp('foo', 'b.r')
+ self.assertFalse(rule.allow(log_obj))
+
+ def test_doesnt_allow_when_value_doesnt_match_regexp(self):
+ log_obj = {
+ 'foo': 'yo',
+ }
+ rule = slog.FilterFieldValueRegexp('foo', 'b.r')
+ self.assertFalse(rule.allow(log_obj))
+
+
+class FilterAllowTests(unittest.TestCase):
+
+ def test_allows_always(self):
+ rule = slog.FilterAllow()
+ self.assertTrue(rule.allow(None))
+
+
+class FilterDenyTests(unittest.TestCase):
+
+ def test_allows_denies(self):
+ rule = slog.FilterDeny()
+ self.assertFalse(rule.allow(None))
+
+
+class FilterIncludeTests(unittest.TestCase):
+
+ def test_allows_if_rule_allows_and_no_include(self):
+ allow = slog.FilterAllow()
+ include = slog.FilterInclude({}, allow)
+ self.assertTrue(include.allow(None))
+
+ def test_denies_if_rule_denies_and_no_include(self):
+ deny = slog.FilterDeny()
+ include = slog.FilterInclude({}, deny)
+ self.assertFalse(include.allow(None))
+
+ def test_allows_if_rule_allows_and_include_is_true(self):
+ allow = slog.FilterAllow()
+ include = slog.FilterInclude({'include': True}, allow)
+ self.assertTrue(include.allow({}))
+
+ def test_denies_if_rule_denies_and_include_is_true(self):
+ deny = slog.FilterDeny()
+ include = slog.FilterInclude({'include': True}, deny)
+ self.assertFalse(include.allow({}))
+
+ def test_denies_if_rule_allows_and_include_is_false(self):
+ allow = slog.FilterAllow()
+ include = slog.FilterInclude({'include': False}, allow)
+ self.assertFalse(include.allow({}))
+
+ def test_allows_if_rule_denies_and_include_is_false(self):
+ deny = slog.FilterDeny()
+ include = slog.FilterInclude({'include': False}, deny)
+ self.assertTrue(include.allow({}))
+
+
+class FilterAnyTests(unittest.TestCase):
+
+ def test_allows_if_any_rule_allows(self):
+ rules = [slog.FilterAllow()]
+ any_rule = slog.FilterAny(rules)
+ self.assertTrue(any_rule.allow(None))
+
+ def test_denies_if_all_rules_deny(self):
+ rules = [slog.FilterDeny(), slog.FilterAllow()]
+ any_rule = slog.FilterAny(rules)
+ self.assertTrue(any_rule.allow(None))
+
+
+class ConstructFilterTests(unittest.TestCase):
+
+ def test_raises_error_if_no_filters(self):
+ filters = []
+ with self.assertRaises(Exception):
+ slog.construct_log_filter(filters)
+
+ def test_handles_field_wanted(self):
+ filters = [
+ {
+ 'field': 'msg_type',
+ },
+ ]
+
+ rule = slog.construct_log_filter(filters)
+
+ allowed = {
+ 'msg_type': 'info',
+ }
+ self.assertTrue(rule.allow(allowed))
+
+ denied = {
+ 'blah_blah': 'http-response',
+ }
+ self.assertFalse(rule.allow(denied))
+
+ def test_handles_field_value_wanted(self):
+ filters = [
+ {
+ 'field': 'msg_type',
+ 'value': 'info',
+ },
+ ]
+
+ rule = slog.construct_log_filter(filters)
+
+ allowed = {
+ 'msg_type': 'info',
+ }
+ self.assertTrue(rule.allow(allowed))
+
+ denied = {
+ 'msg_type': 'http-response',
+ }
+ self.assertFalse(rule.allow(denied))
+
+ def test_handles_regexp_match_wanted(self):
+ filters = [
+ {
+ 'field': 'status',
+ 'regexp': '^4'
+ },
+ ]
+
+ rule = slog.construct_log_filter(filters)
+
+ allowed = {
+ 'status': 400,
+ }
+ self.assertTrue(rule.allow(allowed))
+
+ denied = {
+ 'status': 200,
+ }
+ self.assertFalse(rule.allow(denied))
+
+ def test_handles_not_included(self):
+ filters = [
+ {
+ 'field': 'status',
+ 'value': '400',
+ 'include': False,
+ },
+ ]
+
+ rule = slog.construct_log_filter(filters)
+
+ allowed = {
+ 'status': '200',
+ }
+ self.assertTrue(rule.allow(allowed))
+
+ denied = {
+ 'status': '400',
+ }
+ self.assertFalse(rule.allow(denied))
+
+ def test_returns_compound_filter(self):
+ filters = [
+ {
+ 'field': 'msg_type',
+ },
+ {
+ 'field': 'msg_type',
+ 'value': 'debug',
+ },
+ {
+ 'field': 'status',
+ 'regexp': '^4',
+ 'include': False,
+ },
+ ]
+
+ rule = slog.construct_log_filter(filters)
+
+ allowed = {
+ 'msg_type': 'info',
+ }
+ self.assertTrue(rule.allow(allowed))
+
+ also_allowed = {
+ 'msg_type': 'debug',
+ }
+ self.assertTrue(rule.allow(also_allowed))
+
+ denied = {
+ 'status': '400',
+ }
+ self.assertFalse(rule.allow(denied))
diff --git a/slog/slog_tests.py b/slog/slog_tests.py
new file mode 100644
index 0000000..cc18f15
--- /dev/null
+++ b/slog/slog_tests.py
@@ -0,0 +1,258 @@
+# slog_tests.py - unit tests for structured logging
+#
+# Copyright 2016 QvarnLabs Ab
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program. If not, see <http://www.gnu.org/licenses/>.
+
+
+import glob
+import json
+import os
+import shutil
+import tempfile
+import time
+import unittest
+
+import slog
+
+
+class StructuredLogTests(unittest.TestCase):
+
+ def setUp(self):
+ self.tempdir = tempfile.mkdtemp()
+
+ def tearDown(self):
+ shutil.rmtree(self.tempdir)
+
+ def create_structured_log(self):
+ filename = os.path.join(self.tempdir, 'slog.log')
+ writer = slog.FileSlogWriter()
+ writer.set_filename(filename)
+
+ log = slog.StructuredLog()
+ log.add_log_writer(writer, slog.FilterAllow())
+ return log, writer, filename
+
+ def read_log_entries(self, writer):
+ filename = writer.get_filename()
+ with open(filename) as f:
+ return [json.loads(line) for line in f]
+
+ def test_logs_in_json(self):
+ log, writer, _ = self.create_structured_log()
+ log.log('testmsg', foo='foo', bar='bar', number=12765)
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ obj = objs[0]
+ self.assertEqual(obj['msg_type'], 'testmsg')
+ self.assertEqual(obj['foo'], 'foo')
+ self.assertEqual(obj['bar'], 'bar')
+ self.assertEqual(obj['number'], 12765)
+
+ def test_logs_two_lines_in_json(self):
+ log, writer, _ = self.create_structured_log()
+ log.log('testmsg1', foo='foo')
+ log.log('testmsg2', bar='bar')
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 2)
+ obj1, obj2 = objs
+
+ self.assertEqual(obj1['msg_type'], 'testmsg1')
+ self.assertEqual(obj1['foo'], 'foo')
+
+ self.assertEqual(obj2['msg_type'], 'testmsg2')
+ self.assertEqual(obj2['bar'], 'bar')
+
+ def test_adds_some_extra_fields(self):
+ log, writer, _ = self.create_structured_log()
+ log.log('testmsg')
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ obj = objs[0]
+ self.assertEqual(obj['msg_type'], 'testmsg')
+ self.assertIn('_timestamp', obj)
+ self.assertIn('_process_id', obj)
+ self.assertIn('_thread_id', obj)
+ self.assertEqual(obj['_context'], None)
+
+ def test_adds_context_when_given(self):
+ log, writer, _ = self.create_structured_log()
+ log.set_context('request 123')
+ log.log('testmsg')
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ obj = objs[0]
+ self.assertEqual(obj['_context'], 'request 123')
+
+ def test_resets_context_when_requested(self):
+ log, writer, _ = self.create_structured_log()
+ log.set_context('request 123')
+ log.reset_context()
+ log.log('testmsg')
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ obj = objs[0]
+ self.assertEqual(obj['_context'], None)
+
+ def test_counts_messages(self):
+ log, writer, _ = self.create_structured_log()
+ log.log('testmsg')
+ log.log('testmsg')
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 2)
+ self.assertEqual(objs[0]['_msg_number'], 1)
+ self.assertEqual(objs[1]['_msg_number'], 2)
+
+ def test_logs_traceback(self):
+ log, writer, _ = self.create_structured_log()
+ log.log('testmsg', exc_info=True)
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ self.assertIn('_traceback', objs[0])
+
+ def test_logs_unicode(self):
+ log, writer, _ = self.create_structured_log()
+ log.log('testmsg', text='foo')
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ self.assertEqual(objs[0]['text'], 'foo')
+
+ def test_logs_nonutf8(self):
+ log, writer, _ = self.create_structured_log()
+ notutf8 = '\x86'
+ log.log('blobmsg', notutf8=notutf8)
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ self.assertEqual(objs[0]['notutf8'], notutf8)
+
+ def test_logs_list(self):
+ log, writer, _ = self.create_structured_log()
+ log.log('testmsg', items=[1, 2, 3])
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ self.assertEqual(objs[0]['items'], [1, 2, 3])
+
+ def test_logs_tuple(self):
+ log, writer, _ = self.create_structured_log()
+ log.log('testmsg', t=(1, 2, 3))
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ # Tuples get returned as s list.
+ self.assertEqual(objs[0]['t'], [1, 2, 3])
+
+ def test_logs_dict(self):
+ log, writer, _ = self.create_structured_log()
+ dikt = {
+ 'foo': 'bar',
+ 'yo': [1, 2, 3],
+ }
+ log.log('testmsg', dikt=dikt)
+ log.close()
+
+ objs = self.read_log_entries(writer)
+ self.assertEqual(len(objs), 1)
+ self.assertEqual(objs[0]['dikt'], dikt)
+
+ def test_logs_to_two_files(self):
+ filename1 = os.path.join(self.tempdir, 'slog1XS')
+ writer1 = slog.FileSlogWriter()
+ writer1.set_filename(filename1)
+
+ filename2 = os.path.join(self.tempdir, 'slog2')
+ writer2 = slog.FileSlogWriter()
+ writer2.set_filename(filename2)
+
+ log = slog.StructuredLog()
+ log.add_log_writer(writer1, slog.FilterAllow())
+ log.add_log_writer(writer2, slog.FilterAllow())
+
+ log.log('test', msg_text='hello')
+ objs1 = self.read_log_entries(writer1)
+ objs2 = self.read_log_entries(writer2)
+
+ self.assertEqual(objs1, objs2)
+
+
+class FileSlogWriterTests(unittest.TestCase):
+
+ def setUp(self):
+ self.tempdir = tempfile.mkdtemp()
+ self.filename = os.path.join(self.tempdir, 'foo.log')
+
+ def tearDown(self):
+ shutil.rmtree(self.tempdir)
+
+ def test_gets_initial_filename_right(self):
+ fw = slog.FileSlogWriter()
+ fw.set_filename(self.filename)
+ self.assertEqual(fw.get_filename(), self.filename)
+
+ def test_gets_rotated_filename_right(self):
+ fw = slog.FileSlogWriter()
+ fw.set_filename(self.filename)
+
+ now = time.struct_time((1969, 9, 1, 14, 30, 42, 0, 243, 0))
+ self.assertEqual(
+ fw.get_rotated_filename(now=now),
+ os.path.join(self.tempdir, 'foo-19690901T143042.log')
+ )
+
+ def test_creates_file(self):
+ fw = slog.FileSlogWriter()
+ filename = os.path.join(self.tempdir, 'slog.log')
+ fw.set_filename(filename)
+ self.assertTrue(os.path.exists(filename))
+
+ def test_rotates_after_size_limit(self):
+ fw = slog.FileSlogWriter()
+ filename = os.path.join(self.tempdir, 'slog.log')
+ fw.set_filename(filename)
+ fw.set_max_file_size(1)
+ fw.write({'foo': 'bar'})
+ filenames = glob.glob(self.tempdir + '/*.log')
+ self.assertEqual(len(filenames), 2)
+ self.assertTrue(filename in filenames)
+
+ rotated_filename = [x for x in filenames if x != filename][0]
+ objs1 = self.load_log_objs(filename)
+ objs2 = self.load_log_objs(rotated_filename)
+
+ self.assertEqual(len(objs1), 0)
+ self.assertEqual(len(objs2), 1)
+
+ def load_log_objs(self, filename):
+ with open(filename) as f:
+ return [json.loads(line) for line in f]
diff --git a/slog/version.py b/slog/version.py
new file mode 100644
index 0000000..0e742f9
--- /dev/null
+++ b/slog/version.py
@@ -0,0 +1,2 @@
+__version__ = '0.1'
+__version_info__ = (0, 1)