diff --git a/CHANGELOG b/CHANGELOG index 3adeb08..5b1697e 100644 --- a/CHANGELOG +++ b/CHANGELOG @@ -1,3 +1,9 @@ +v0.9.3 +===== +* Adding ColorPlainTextStreamHandler for easy-to-read colorized logs +* ColorJsonStreamHandler is the new ColorStreamHandler +* Fixing the caller location code (broken in Python 3.x migration) + v0.9.2 ===== * Log level JSON key was not being emphasized when color handler was on (broken in Python 3.x migration) diff --git a/Makefile b/Makefile index b5020c8..ddffd3c 100644 --- a/Makefile +++ b/Makefile @@ -4,7 +4,6 @@ install: poetry install build: - poetry run mdToRst README.md > README.rst poetry build lint: @@ -16,5 +15,8 @@ lint: test: @poetry run nosetests +visual: + @poetry run nosetests -s + info: @poetry env info diff --git a/README.md b/README.md index ff259a9..e57e202 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,8 @@ Sift Log - JSON logging adapter for Python (now in color) =============== +![](https://raw.githubusercontent.com/papito/siftlog-py/master/assets/screen.png) + ## Features * Tag log statements with arbitrary values for easier grouping and analysis * Add keyword arguments that are converted to JSON values @@ -50,7 +52,7 @@ logger.addHandler(handler) log = SiftLog(logger) ``` -In this fashion, you can direct the JSON logs to [any logging handler](https://docs.python.org/2/library/logging.handlers.html) +In this fashion, you can direct the JSON logs to [any logging handler](https://docs.python.org/2/library/logging.handlers.html). #### Color For enhanced flamboyancy, attach the `ColorStreamHandler` to your logger. The output will not have color if the logs @@ -66,11 +68,12 @@ logger.addHandler(handler) log = SiftLog(logger) ``` +For development, you can opt in to use `ColorPlainTextStreamHandler`, for logs that are easier to parse visually. + ##### Performance While the above should play, it's highly recommended that the color handler is only -attached conditionally for local development. Too many log statements could otherwise become -expensive in terms of CPU. +attached conditionally for local development. ##### Different colors @@ -148,6 +151,7 @@ SiftLog.log.MESSAGE = "MESSAGE" `Poetry` is used to manage the dependencies. Most things can be accessed via the Makefile, if you have Make installed. +Without Make, just inspect the Makefile for the available commands. # use the right Python poetry use path/to/python/3.8-ish @@ -157,5 +161,7 @@ Most things can be accessed via the Makefile, if you have Make installed. make install # run tests make test + # run visual tests (same as tests but with output) + make visual # formatting, linting, and type checking make lint diff --git a/README.rst b/README.rst deleted file mode 100644 index 61b62c6..0000000 --- a/README.rst +++ /dev/null @@ -1,269 +0,0 @@ -Sift Log - JSON logging adapter for Python (now in color) -=============== - -# Features -========== - -* Tag log statements with arbitrary values for easier grouping and analysis - -* Add keyword arguments that are converted to JSON values - -* Variable substitution - -* Specifies where log calls are made from - -* Meant to be used with core Python logging (formatters, handlers, etc) - -* Colorized logs on a console (POSIX only) - -* `TRACE` log level built-in - -# Examples -========== -### A simple log message -======================== - -```python - -log.info('Hello') - -``` - -`{"msg": "Hello", "time": "12-12-14 10:12:01 EST", "level": "INFO", "loc": "test:log_test:20"}` - -### Logging with tags -===================== - -```python - -log.debug('Creating new user', 'MONGO', 'STORAGE') - -``` - -`{"msg": "Creating new user", "time": "12-12-14 10:12:09 EST", "tags": ["MONGO", "STORAGE"], "level": "DEBUG", "loc": "test:log_test:20"}` - -### Appending more data -======================= - -```python - -log.debug('Some key', is_admin=True, username='papito') - -``` - -`{"msg": "Some key", "is*admin": true, "username": "papito", "time": "12-12-14 10:12:04 EST", "level": "DEBUG", "loc": "test:log*test:20"}` - -### String substitution -======================= - -```python - -log.debug('User "$username" admin? $is*admin', is*admin=False, username='fez') - -``` - -`{"msg": "User \"fez\" admin? False", "username": "fez", "is*admin": false, "time": "12-12-14 10:12:18 EST", "level": "DEBUG", "loc": "test:log*test:20"}` - - -# Setup -======= -### Logging to console -====================== - -```python - -import sys - -import logging - -from siftlog import SiftLog - -logger = logging.getLogger() - -logger.setLevel(logging.INFO) - -handler = logging.StreamHandler(sys.stdout) - -logger.addHandler(handler) - -log = SiftLog(logger) - -``` - -In this fashion, you can direct the JSON logs to `any logging handler `_ - -### Color -========= - -For enhanced flamboyancy, attach the `ColorStreamHandler` to your logger. The output will not have color if the logs - -are being output to a file, or on systems that are not POSIX (will not work on Windows for now). - -```python - -from siftlog import SiftLog, ColorStreamHandler - -logger = logging.getLogger() - -handler = ColorStreamHandler(sys.stdout) - -logger.addHandler(handler) - -log = SiftLog(logger) - -``` - -#### Performance -================ - -While the above should play, it's highly recommended that the color handler is only - -attached conditionally for local development. Too many log statements could otherwise become - -expensive in terms of CPU. - - -#### Different colors -===================== - -You can change font background, text color, and boldness: - -```python - -from siftlog import ColorStreamHandler - -handler = ColorStreamHandler(sys.stdout) - -handler.set_color( - - logging.DEBUG, bg=handler.WHITE, fg=handler.BLUE, bold=True - -) - -``` - -#### Supported colors -===================== - - * ColorStreamHandler.BLACK - - * ColorStreamHandler.RED - - * ColorStreamHandler.GREEN - - * ColorStreamHandler.YELLOW - - * ColorStreamHandler.BLUE - - * ColorStreamHandler.MAGENTA - - * ColorStreamHandler.CYAN - - * ColorStreamHandler.WHITE - -### Constants (re-occuring values) -================================== - -You can define constants that will appear in every single log message. This is useful, for example, if you'd like to log process PID and hostname with every log message (recommended). This is done upon log adapter initialization: - -```python - -import os - -from siftlog import SiftLog - -log = SiftLog(logger, pid=os.getpid(), env='INTEGRATION') - -``` - -`{"msg": "And here I am", "time": "12-12-14 11:12:24 EST", "pid": 37463, "env": "INTEGRATION", "level": "INFO"}` - - -### Custom time format -====================== - -```python - -log = SiftLog(logger) - -SiftLog.TIME_FORMAT = '%d-%m-%y %H:%m:%S %Z' - -``` - -Define the format as accepted by `time.strftime() `_](https://docs.python.org/2/library/time.html#time.strftime) - -### Custom location format -========================== - -```python - -log = SiftLog(logger) - -SiftLog.LOCATION*FORMAT = '$module:$method:$line*no' - -``` - -The format should be a string containing any of the following variables: - - * `$file` - - * `$line_no` - - * `$method` - - * `$module` - -### Custom core key names -========================= - -Core keys, such as `msg` and `level` can be overridden, if they clash with common keys you might be using. - -The following can be redefined: - - * SiftLog.MESSAGE (default `msg`) - - * SiftLog.LEVEL (default `level`) - - * SiftLog.LOCATION (default `loc`) - - * SiftLog.TAGS (default `tags`) - - * SiftLog.TIME (default `time`) - -As in: - -```python - -log = SiftLog(logger) - -SiftLog.log.MESSAGE = "MESSAGE" - -``` - -# Development flow -================== - -`Poetry` is used to manage the dependencies. - -Most things can be accessed via the Makefile, if you have Make installed. - - # use the right Python - - poetry use path/to/python/3.8\-ish - - # make sure correct Python is used - - make info - - # install dependencies - - make install - - # run tests - - make test - - # formatting, linting, and type checking - - make lint - diff --git a/assets/screen.png b/assets/screen.png new file mode 100644 index 0000000..dee52b6 Binary files /dev/null and b/assets/screen.png differ diff --git a/pyproject.toml b/pyproject.toml index 6c9b23f..67f1c68 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [tool.poetry] name = "siftlog-py" -version = "0.9.2" +version = "0.9.3" description = "Structured JSON logging" license = "MIT" @@ -11,7 +11,7 @@ authors = ["Andrei Taranchenko "] keywords = ["logging", "logs"] include = [ - "LICENSE", "README.rst" + "LICENSE", "README.md" ] packages = [ diff --git a/siftlog/__init__.py b/siftlog/__init__.py index 9b9f50e..0528295 100644 --- a/siftlog/__init__.py +++ b/siftlog/__init__.py @@ -1,4 +1,5 @@ import inspect +import itertools import json import logging import os @@ -18,8 +19,9 @@ class SiftLog(logging.LoggerAdapter): TIME = "time" TIME_FORMAT = "%d-%m-%y %H:%m:%S %Z" LOCATION_FORMAT = "$module:$method:$line_no" + TRACE = 5 # for typing convenience - def __init__(self, logger, **kwargs): + def __init__(self, logger: logging.Logger, **kwargs): super(SiftLog, self).__init__(logger, {}) self._constants = kwargs @@ -68,7 +70,8 @@ def get_caller_info(self): return Template(self.LOCATION_FORMAT).safe_substitute(caller) - def _get_caller_info(self): + @staticmethod + def _get_caller_info(): # pull the frames from the current stack, reversed, # since it's easier to find the first siftlog frame frames = [ @@ -76,10 +79,12 @@ def _get_caller_info(self): for idx, frm in enumerate(reversed(inspect.stack())) ] - # the first siftlog frame from back of the stack - siftlog_frame = next( - x for x in frames if lambda idx, f, m: m and m.__name__ != "siftlog" + # travel the stack from behind, looking for the first siftlog frame + res = itertools.dropwhile( + lambda frame: frame[2] and frame[2].__name__ != "siftlog", frames ) + # the first siftlog frame from back of the stack + siftlog_frame = next(res) # its index siftlog_frame_idx = siftlog_frame[0] @@ -179,6 +184,9 @@ class ColorStreamHandler(logging.StreamHandler): logging.CRITICAL: (RED, WHITE, True), } + csi = "\x1b[" + reset = "\x1b[0m" + @staticmethod def set_color(level=None, bg=None, fg=None, bold=False): assert level @@ -197,9 +205,6 @@ def set_color(level=None, bg=None, fg=None, bold=False): ColorStreamHandler._LEVEL_MAP[level] = (bg, fg, bold) - csi = "\x1b[" - reset = "\x1b[0m" - @property def is_tty(self): isatty = getattr(self.stream, "isatty", None) @@ -224,10 +229,7 @@ def emit(self, record): def output_colorized(self, message): self.stream.write(message) - # noinspection DuplicatedCode - def colorize(self, message, record): - json_rec = json.loads(message) - + def get_fabulous_params(self, record) -> List[str]: if record.levelno in self._LEVEL_MAP: # bold the JSON keys bg, fg, bold = self._LEVEL_MAP[record.levelno] @@ -240,26 +242,30 @@ def colorize(self, message, record): if bold: params.append("1") - if params: - if SiftLog.MESSAGE in json_rec: - msg = '"{0}": "{1}"'.format( - SiftLog.MESSAGE, json_rec[SiftLog.MESSAGE] - ) + return params + + return [] + + def make_fabulous(self, message, record): + json_rec = json.loads(message) + # bold the JSON keys + bold_params = ["1"] + + for key in json_rec.keys(): + if record.levelno in self._LEVEL_MAP and key == SiftLog.MESSAGE: + fabulous_params = self.get_fabulous_params(record) + if fabulous_params and SiftLog.MESSAGE in json_rec: + msg = '"{0}"'.format(json_rec[SiftLog.MESSAGE]) color_msg = "".join( - (self.csi, ";".join(params), "m", msg, self.reset) + (self.csi, ";".join(fabulous_params), "m", msg, self.reset) ) message = message.replace(msg, color_msg) - for key in json_rec.keys(): - if key in [SiftLog.MESSAGE]: - continue - - # bold the JSON keys - params: List[str] = ["1"] - - val = '"%s":' % key + val = '"{0}":'.format(key) color_val = ( - '"' + "".join((self.csi, ";".join(params), "m", key, self.reset)) + '":' + '"' + + "".join((self.csi, ";".join(bold_params), "m", key, self.reset)) + + '":' ) message = message.replace(val, color_val) @@ -271,5 +277,49 @@ def format(self, record): message = message.strip() lines = len(message.split("\n")) if lines == 1: - message = self.colorize(message, record) + message = self.make_fabulous(message, record) + return message + + +class ColorJsonStreamHandler(ColorStreamHandler): # alias + pass + + +class ColorPlainTextStreamHandler(ColorStreamHandler): + def make_fabulous(self, message, record): + json_rec: Dict[str, str] = json.loads(message) + fabulous_params: List[str] = self.get_fabulous_params(record) + + if fabulous_params and SiftLog.LEVEL in json_rec: + message = "".join( + ( + self.csi, + ";".join(fabulous_params), + "m", + json_rec[SiftLog.LEVEL], + self.reset, + ": ", + json_rec[SiftLog.MESSAGE], + ) + ) + + # bold the rest of the keys + bold_params: List[str] = ["1"] + for key, val in json_rec.items(): + if key in [SiftLog.LEVEL, SiftLog.MESSAGE]: + continue + + message += "".join( + ( + ", [", + self.csi, + ";".join(bold_params), + "m", + key, + self.reset, + "] ", + str(val), + ) + ) + return message diff --git a/siftlog/tests/test_color.py b/siftlog/tests/test_json_color.py similarity index 76% rename from siftlog/tests/test_color.py rename to siftlog/tests/test_json_color.py index b5dc832..934bb32 100644 --- a/siftlog/tests/test_color.py +++ b/siftlog/tests/test_json_color.py @@ -2,14 +2,15 @@ import sys import unittest -from siftlog import ColorStreamHandler, SiftLog +from siftlog import ColorJsonStreamHandler, SiftLog -class TestColor(unittest.TestCase): +# noinspection DuplicatedCode +class TestJsonColor(unittest.TestCase): def test_defaults(self): logger = logging.getLogger() - logger.setLevel(logging.TRACE) - handler = ColorStreamHandler(sys.stdout) + logger.setLevel(SiftLog.TRACE) + handler = ColorJsonStreamHandler(sys.stdout) logger.addHandler(handler) log = SiftLog(logger) @@ -22,8 +23,8 @@ def test_defaults(self): def test_changed_key_names(self): logger = logging.getLogger() - logger.setLevel(logging.TRACE) - handler = ColorStreamHandler(sys.stdout) + logger.setLevel(SiftLog.TRACE) + handler = ColorJsonStreamHandler(sys.stdout) logger.addHandler(handler) log = SiftLog(logger) SiftLog.MESSAGE = "m" @@ -40,28 +41,28 @@ def test_changed_key_names(self): log.critical("critical", "tag1", "tag2", key1="key1", key2="key2") def test_incorrect_usage(self): - handler = ColorStreamHandler(sys.stdout) + handler = ColorJsonStreamHandler(sys.stdout) - with self.assertRaises(RuntimeError) as cm: + with self.assertRaises(RuntimeError): handler.set_color("blah", bg=handler.GREEN, fg=handler.WHITE, bold=True) - with self.assertRaises(RuntimeError) as cm: + with self.assertRaises(RuntimeError): handler.set_color(logging.INFO, bg="bad", fg=handler.WHITE, bold=True) - with self.assertRaises(RuntimeError) as cm: + with self.assertRaises(RuntimeError): handler.set_color(logging.INFO, bg=handler.BLACK, fg="bad", bold=True) - with self.assertRaises(RuntimeError) as cm: + with self.assertRaises(RuntimeError): handler.set_color( logging.INFO, bg=handler.BLACK, fg=handler.WHITE, bold="bad" ) def test_correct_usage(self): - handler = ColorStreamHandler(sys.stdout) + handler = ColorJsonStreamHandler(sys.stdout) handler.set_color(logging.INFO, bg=handler.GREEN, fg=handler.WHITE, bold=True) - handler.set_color(logging.TRACE, bg=handler.CYAN, fg=handler.RED, bold=False) + handler.set_color(SiftLog.TRACE, bg=handler.CYAN, fg=handler.RED, bold=False) handler.set_color(logging.DEBUG, bg=handler.WHITE, fg=handler.BLUE, bold=True) logger = logging.getLogger() - logger.setLevel(logging.TRACE) + logger.setLevel(SiftLog.TRACE) logger.addHandler(handler) log = SiftLog(logger) diff --git a/siftlog/tests/test_log.py b/siftlog/tests/test_log.py index e96b3f5..82c7d7f 100644 --- a/siftlog/tests/test_log.py +++ b/siftlog/tests/test_log.py @@ -10,10 +10,11 @@ class TestLogger(unittest.TestCase): @classmethod def setUpClass(cls): - cls.logger = SiftLog(None) + cls.core_logger = logging.getLogger("siftlog_test") + cls.sift_logger = SiftLog(cls.core_logger) def test_arbitrary_constants(self): - logger = SiftLog(None, pid=12345, app="APP NAME") + logger = SiftLog(self.core_logger, pid=12345, app="APP NAME") res = json.loads(logger._get_log_stmt(logging.INFO, None)) self.assertEquals(res["pid"], 12345) @@ -21,35 +22,39 @@ def test_arbitrary_constants(self): def test_simple_log_statement(self): stmt = "simple log statement" - res = json.loads(self.logger._get_log_stmt(logging.DEBUG, stmt)) + res = json.loads(self.sift_logger._get_log_stmt(logging.DEBUG, stmt)) - self.assertEquals(res[self.logger.MESSAGE], stmt) + self.assertEquals(res[self.sift_logger.MESSAGE], stmt) def test_with_string_formatting(self): stmt = "simple log statement with variable $var" data = {"var": 1} - res = json.loads(self.logger._get_log_stmt(logging.DEBUG, stmt, **data)) + res = json.loads(self.sift_logger._get_log_stmt(logging.DEBUG, stmt, **data)) - self.assertEquals(res[self.logger.MESSAGE], Template(stmt).substitute(data)) + self.assertEquals( + res[self.sift_logger.MESSAGE], Template(stmt).substitute(data) + ) def test_tags(self): - res = self.logger._get_log_stmt(logging.DEBUG, "", "TAG1", "TAG2") + res = self.sift_logger._get_log_stmt(logging.DEBUG, "", "TAG1", "TAG2") res = json.loads(res) - self.assertEquals(len(res[self.logger.TAGS]), 2) + self.assertEquals(len(res[self.sift_logger.TAGS]), 2) def test_custom_adapter(self): - datetime_handler = lambda obj: ( - obj.isoformat() - if isinstance(obj, datetime.datetime) or isinstance(obj, datetime.date) - else None - ) + def datetime_handler(obj): + + if isinstance(obj, datetime.datetime) or isinstance(obj, datetime.date): + return obj.isoformat() + else: + return None class CustomAdapter(SiftLog): def to_json(self, data): return json.dumps(data, default=datetime_handler) - logger = CustomAdapter(None) + test_logger = logging.getLogger("siftlog_test") + logger = CustomAdapter(test_logger) res = logger._get_log_stmt( logging.DEBUG, "$created", created=datetime.datetime.now() @@ -58,10 +63,12 @@ def to_json(self, data): self.assertNotEquals(res[logger.LEVEL], "ERROR") def test_core_fields(self): - logger = SiftLog(None) + test_logger = logging.getLogger("siftlog_test") + logger = SiftLog(test_logger) logger.MESSAGE = "m" logger.LEVEL = "l" res = logger._get_log_stmt(logging.DEBUG, "") res = json.loads(res) self.assertTrue(logger.MESSAGE in res) - self.assertTrue(logger.LEVEL in res) + self.assertTrue(logger.MESSAGE in res) + self.assertTrue(logger.LOCATION in res) diff --git a/siftlog/tests/test_plain_color.py b/siftlog/tests/test_plain_color.py new file mode 100644 index 0000000..8768d1b --- /dev/null +++ b/siftlog/tests/test_plain_color.py @@ -0,0 +1,72 @@ +import logging +import sys +import unittest + +from siftlog import ColorPlainTextStreamHandler, SiftLog + +# noinspection DuplicatedCode + + +class TestPlainTextColor(unittest.TestCase): + def test_defaults(self): + logger = logging.getLogger() + logger.setLevel(SiftLog.TRACE) + handler = ColorPlainTextStreamHandler(sys.stdout) + logger.addHandler(handler) + log = SiftLog(logger) + + log.trace("trace", "tag1", "tag2", key1="key1", key2="key2") + log.debug("debug", "tag1", "tag2", key1="key1", key2="key2") + log.info("info", "tag1", "tag2", key1="key1", key2="key2") + log.warn("warn", "tag1", "tag2", key1="key1", key2="key2") + log.warning("warning", "tag1", "tag2", key1="key1", key2="key2") + log.critical("critical", "tag1", "tag2", key1="key1", key2="key2") + + def test_changed_key_names(self): + logger = logging.getLogger() + logger.setLevel(SiftLog.TRACE) + handler = ColorPlainTextStreamHandler(sys.stdout) + logger.addHandler(handler) + log = SiftLog(logger) + SiftLog.MESSAGE = "m" + SiftLog.LOC = "from" + SiftLog.LEVEL = "lvl" + SiftLog.TIME = "@" + SiftLog.TAGS = "t" + + log.trace("trace", "tag1", "tag2", key1="key1", key2="key2") + log.debug("debug", "tag1", "tag2", key1="key1", key2="key2") + log.info("info", "tag1", "tag2", key1="key1", key2="key2") + log.warn("warn", "tag1", "tag2", key1="key1", key2="key2") + log.warning("warning", "tag1", "tag2", key1="key1", key2="key2") + log.critical("critical", "tag1", "tag2", key1="key1", key2="key2") + + def test_incorrect_usage(self): + handler = ColorPlainTextStreamHandler(sys.stdout) + + with self.assertRaises(RuntimeError): + handler.set_color("blah", bg=handler.GREEN, fg=handler.WHITE, bold=True) + with self.assertRaises(RuntimeError): + handler.set_color(logging.INFO, bg="bad", fg=handler.WHITE, bold=True) + with self.assertRaises(RuntimeError): + handler.set_color(logging.INFO, bg=handler.BLACK, fg="bad", bold=True) + with self.assertRaises(RuntimeError): + handler.set_color( + logging.INFO, bg=handler.BLACK, fg=handler.WHITE, bold="bad" + ) + + def test_correct_usage(self): + handler = ColorPlainTextStreamHandler(sys.stdout) + + handler.set_color(logging.INFO, bg=handler.GREEN, fg=handler.WHITE, bold=True) + handler.set_color(SiftLog.TRACE, bg=handler.CYAN, fg=handler.RED, bold=False) + handler.set_color(logging.DEBUG, bg=handler.WHITE, fg=handler.BLUE, bold=True) + + logger = logging.getLogger() + logger.setLevel(SiftLog.TRACE) + logger.addHandler(handler) + log = SiftLog(logger) + + log.trace("trace", "tag1", "tag2", key1="key1", key2="key2") + log.debug("debug", "tag1", "tag2", key1="key1", key2="key2") + log.info("info", "tag1", "tag2", key1="key1", key2="key2")