From f5927309b22d90bc40b3ae4ada68142c18fd57f1 Mon Sep 17 00:00:00 2001 From: Lars Wirzenius Date: Mon, 31 Jul 2017 15:52:44 +0300 Subject: Add: slog library --- slog/__init__.py | 38 +++++++ slog/counter.py | 34 ++++++ slog/counter_tests.py | 50 +++++++++ slog/slog.py | 278 ++++++++++++++++++++++++++++++++++++++++++++++ slog/slog_filter.py | 117 +++++++++++++++++++ slog/slog_filter_tests.py | 267 ++++++++++++++++++++++++++++++++++++++++++++ slog/slog_tests.py | 258 ++++++++++++++++++++++++++++++++++++++++++ slog/version.py | 2 + 8 files changed, 1044 insertions(+) create mode 100644 slog/__init__.py create mode 100644 slog/counter.py create mode 100644 slog/counter_tests.py create mode 100644 slog/slog.py create mode 100644 slog/slog_filter.py create mode 100644 slog/slog_filter_tests.py create mode 100644 slog/slog_tests.py create mode 100644 slog/version.py 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 . + + +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 . + + +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 . + + +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 . + + +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 . + + +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 . + + +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 . + + +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) -- cgit v1.2.1