diff options
| -rw-r--r-- | README | 64 | ||||
| -rw-r--r-- | debuglog.py | 77 | ||||
| -rwxr-xr-x | debuglogtool | 18 | ||||
| -rw-r--r-- | example.debuglog | 213 | ||||
| -rw-r--r-- | example.py | 18 | ||||
| -rwxr-xr-x | speed-test | 10 |
6 files changed, 400 insertions, 0 deletions
@@ -0,0 +1,64 @@ +README for debug logging +======================== + +Log files can be used for at least two purposes: for the program user +(or sysadmin) to have a rough idea of what is happening and for the +programmer to get a very detailed idea of what is happening, in order +to find and fix problems. + +For the debugging programmer, especially, it would be helpful if +the log file was in a machine parseable format. `debuglog` is a +little helper class to make such log files. They're not intended +to be useful for non-programmers. + +Some assumptions: + +* It is not necessary to log everything during a program run. Instead, + saving the last N log messages and writing those when the software + crashes is enough. +* Log levels are not fine grained enough. It's better to have a + machine parseable format that lends itself to more detailed filtering. + Therefore, save everything and filter afterwards. + +`debuglog` consists of two parts: + +1. A Python module, `debuglog`, with a class that collects structured + log messages, and writes them (when requested) to a file as JSON. +2. A script, `debuglogtool`, that reads the JSON file and filters it + in some ways. + +The structured log messages are key/value pairs. For example: + + dlog = debuglog.DebugLog() + ... + dlog.log(msg='Opening input file', filename=filename, cwd=os.getcwd()) + +The `log` method gets any number of keyword arguments. These are saved +as a JSON record, with all values converted to strings. + +The JSON log file can, of course, be filtered by any code that understands +JSON, if what `debuglogtool` provides is not sufficiently powerful. + +Example: + + debuglogtool -e msg='Opening input file' -e 'filename~/\.JPG$/' *.debuglog + +The above would output all JSON records that have a field called `msg` +with a value that is exactly the string "Opening input file", and +additionally have a field called `filename` which matches the regular +expression given. All such records are written out entirely, as a JSON +list. If there are no matches, nothing is output, and the exit code is +non-zero. + +A single expression can use the following operators: + +* `=` for exact string equality. +* `!=` for string inequality. +* `~` for regexp matching (regexp to be surrounded by slashes). +* `!~` for regexp NOT matching. + +Regular expressions are PCRE. + +Each expression is given with the `-e` option (`--expression`). +All expressions must match. There is no way to express full Boolean +logic, at this time. diff --git a/debuglog.py b/debuglog.py new file mode 100644 index 0000000..7b34270 --- /dev/null +++ b/debuglog.py @@ -0,0 +1,77 @@ +import collections +import json + + +class DebugLog(object): + + '''Debug logging class. + + The Python standard library contains the library called logging, + which is fine for general purpose logging. For logs meant to help + developers analyse problems, they are less than ideal. + + * Log files are essentially free-form text, with only minimal + structure (timestamps), and that is unreliable to parse when + log messages may contain newlines. + * It is not very efficient. + * Typically, a log grows quite large, making it use a lot of disk + space. This is wasteful when most developers would only need + the end of the log, at the point of a crash, to solve most problems. + (But sometimes the whole log from the whole runtime would be good.) + + This class provides a different kind of logging. The log file is only + written when requested, not continously, and is stored in a ring buffer, + meaning only the last messages are written, with earlier ones forgotten. + This is fine for crash logs. The logs are written in a format that is + easily machine parseable (JSON). + + ''' + + DEFAULT_RING_BUFFER_SIZE = 1000 + + def __init__(self): + self._max_buffer_size = self.DEFAULT_RING_BUFFER_SIZE + self.clear() + + def set_ring_buffer_size(self, num_entries): + self._max_buffer_size = num_entries + while len(self._ring_buffer) > self._max_buffer_size: + self._ring_buffer.popleft() + + def add_to_preamble(self, **kwargs): + self._preamble.append(kwargs) + + def log(self, **kwargs): + self._ring_buffer.append(kwargs) + + def write_ring_buffer(self, filename_or_handle): + + def write(f): + f.write('[\n') + first = True + for q in [self._preamble, self._ring_buffer]: + for entry in q: + if first: + first = False + else: + f.write(',\n') + json.dump(entry, f, indent=4) + f.write('\n]\n') + + if hasattr(filename_or_handle, 'write'): + write(filename_or_handle) + else: + with open(filename_or_handle, 'a') as f: + write(f) + + def clear(self): + self._preamble = collections.deque([], self._max_buffer_size) + self._ring_buffer = collections.deque([], self._max_buffer_size) + + +if __name__ == '__main__': + x = DebugLog() + x.add_to_preamble(version='1.2') + x.log(msg='yoyoyo', url='foobar') + x.log(msg='blahblah', data=123) + x.write_ring_buffer('/dev/stdout') diff --git a/debuglogtool b/debuglogtool new file mode 100755 index 0000000..526a41a --- /dev/null +++ b/debuglogtool @@ -0,0 +1,18 @@ +#!/usr/bin/python + +import json, sys + + +records = json.load(sys.stdin) + +result = [] + +for expr in sys.argv[1:]: + key, value = expr.split('=', 1) + for record in records: + if key in record and record[key] == value: + if record not in result: + result.append(record) + +json.dump(result, sys.stdout, indent=2) +sys.stdout.write('\n') diff --git a/example.debuglog b/example.debuglog new file mode 100644 index 0000000..f6b0a82 --- /dev/null +++ b/example.debuglog @@ -0,0 +1,213 @@ +[ +{ + "msg": "Program starts", + "version": "1.2.3" +}, +{ + "msg": "Environment variable", + "name": "GNOME_DESKTOP_SESSION_ID", + "value": "this-is-deprecated" +}, +{ + "msg": "Environment variable", + "name": "LOGNAME", + "value": "liw" +}, +{ + "msg": "Environment variable", + "name": "USER", + "value": "liw" +}, +{ + "msg": "Environment variable", + "name": "PROMPT_COMMAND", + "value": "prompt_command" +}, +{ + "msg": "Environment variable", + "name": "GNOME_KEYRING_CONTROL", + "value": "/home/liw/.cache/keyring-ID7J4Z" +}, +{ + "msg": "Environment variable", + "name": "PATH", + "value": "/usr/lib/ccache:/home/liw/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/home/liw/bin" +}, +{ + "msg": "Environment variable", + "name": "PS1", + "value": "\\[\u001b(B\u001b[m\u001b[1m\\]\\u@\\h\\$ \\[\u001b(B\u001b[m\\]" +}, +{ + "msg": "Environment variable", + "name": "WINDOWPATH", + "value": "7" +}, +{ + "msg": "Environment variable", + "name": "SSH_AGENT_PID", + "value": "3819" +}, +{ + "msg": "Environment variable", + "name": "LANG", + "value": "en_GB.UTF-8" +}, +{ + "msg": "Environment variable", + "name": "TERM", + "value": "xterm" +}, +{ + "msg": "Environment variable", + "name": "SHELL", + "value": "/bin/bash" +}, +{ + "msg": "Environment variable", + "name": "XDG_SESSION_COOKIE", + "value": "a91924761abd3ffe52f85cb351ab0004-1370288306.863663-612229231" +}, +{ + "msg": "Environment variable", + "name": "LANGUAGE", + "value": "en_GB:en" +}, +{ + "msg": "Environment variable", + "name": "SESSION_MANAGER", + "value": "local/havelock:@/tmp/.ICE-unix/3778,unix/havelock:/tmp/.ICE-unix/3778" +}, +{ + "msg": "Environment variable", + "name": "SHLVL", + "value": "1" +}, +{ + "msg": "Environment variable", + "name": "VIRSH_DEFAULT_CONNECT_URI", + "value": "qemu:///system" +}, +{ + "msg": "Environment variable", + "name": "DISPLAY", + "value": ":0" +}, +{ + "msg": "Environment variable", + "name": "WINDOWID", + "value": "33610828" +}, +{ + "msg": "Environment variable", + "name": "EDITOR", + "value": "vi" +}, +{ + "msg": "Environment variable", + "name": "DEBEMAIL", + "value": "liw@liw.fi" +}, +{ + "msg": "Environment variable", + "name": "HOME", + "value": "/home/liw" +}, +{ + "msg": "Environment variable", + "name": "USERNAME", + "value": "liw" +}, +{ + "msg": "Environment variable", + "name": "SSH_AUTH_SOCK", + "value": "/home/liw/.cache/keyring-ID7J4Z/ssh" +}, +{ + "msg": "Environment variable", + "name": "GDMSESSION", + "value": "gnome-xmonad" +}, +{ + "msg": "Environment variable", + "name": "LESSCHARSET", + "value": "utf-8" +}, +{ + "msg": "Environment variable", + "name": "DBUS_SESSION_BUS_ADDRESS", + "value": "unix:abstract=/tmp/dbus-cmMWaPC837,guid=1a095966f70d121bf402e9e851acf0b3" +}, +{ + "msg": "Environment variable", + "name": "_", + "value": "/usr/bin/python" +}, +{ + "msg": "Environment variable", + "name": "XAUTHORITY", + "value": "/var/run/gdm3/auth-for-liw-vh5n6o/database" +}, +{ + "msg": "Environment variable", + "name": "DESKTOP_SESSION", + "value": "gnome-xmonad" +}, +{ + "msg": "Environment variable", + "name": "GPG_AGENT_INFO", + "value": "/home/liw/.cache/keyring-ID7J4Z/gpg:0:1" +}, +{ + "msg": "Environment variable", + "name": "GNOME_KEYRING_PID", + "value": "3760" +}, +{ + "msg": "Environment variable", + "name": "OLDPWD", + "value": "/home/liw" +}, +{ + "msg": "Environment variable", + "name": "HISTCONTROL", + "value": "ignoredups" +}, +{ + "msg": "Environment variable", + "name": "XDG_DATA_DIRS", + "value": "/usr/share/gnome:/usr/local/share/:/usr/share/" +}, +{ + "msg": "Environment variable", + "name": "PWD", + "value": "/home/liw/debuglog" +}, +{ + "msg": "Environment variable", + "name": "COLORTERM", + "value": "gnome-terminal" +}, +{ + "msg": "Environment variable", + "name": "PAGER", + "value": "less" +}, +{ + "msg": "Environment variable", + "name": "LC_COLLATE", + "value": "fi_FI.UTF-8" +}, +{ + "msg": "first" +}, +{ + "msg": "second" +}, +{ + "msg": "third" +}, +{ + "msg": "fourth" +} +] diff --git a/example.py b/example.py new file mode 100644 index 0000000..d90af3e --- /dev/null +++ b/example.py @@ -0,0 +1,18 @@ +import os + +import debuglog + + +dlog = debuglog.DebugLog() + +dlog.add_to_preamble(msg='Program starts', version='1.2.3') +for name in os.environ: + dlog.add_to_preamble( + msg='Environment variable', name=name, value=os.environ[name]) +dlog.set_ring_buffer_size(3) +dlog.log(msg='first') +dlog.log(msg='second') +dlog.log(msg='third') +dlog.log(msg='fourth') + +dlog.write_ring_buffer('example.debuglog') diff --git a/speed-test b/speed-test new file mode 100755 index 0000000..50e6c78 --- /dev/null +++ b/speed-test @@ -0,0 +1,10 @@ +#!/bin/sh + + +set -eu + + +python -O -m timeit -n 1000000 \ + -s 'import debuglog' \ + -s 'x = debuglog.DebugLog()' \ + 'x.log(msg="foobar", url="yoyoyo")' |