UberLogs
Writing good, usable logs is not an easy task. Why work hard when you can use UberLogs?
UberLogs does all the dumb work you have to do, to make your logs easy to parse:
- Human Readable, parsable log lines (with or without color)
- Machine redable, parsable log lines for your favorite data cruncher
- Variable formatting, so you don't have to write .format(...) or % (...) ever again
- Statement evaluation like in Ruby, Koltin, Python 3.6, etc'
- Handler to violently kill the process when a log on a specific level has been written
- Automatic twisted log rewriting to python.logging
Installation
$ pip install uberlogsMotivation
I rarely use any other logging appenders than the console one. Most of the time I send my logs to a data cruncher and write horrible regular expressions to parse the data.
To ease the pain, I started formatting my logs, so they'll be easy to parse: <message>; arg1=arg1val; arg2=arg2val But that meant I had to write the same format everywhere, and I found myself writing long, long log lines:
import logging
from collections import namedtuple
Eatable = namedtuple('Eatable', ['name', 'flavor', 'location'])
logger = logging.getLogger("test")
eatable = Eatable(name="bagel",
flavor="salty",
location="tel-aviv")
logger.info("I'm eating a {thing}; location: {location}; flavor: {flavor}".format(thing=eatable.name,
location=eatable.location,
flavor=eatable.flavor))
# 1970-1-1 18:24:17,578 - test - INFO - I'm eating a bagel; flavor: salty; location: tel-avivI had to find a better, more concise way of doing the same - that way is UberLogs:
import uberlogs
from collections import namedtuple
Eatable = namedtuple('Eatable', ['name', 'flavor', 'location'])
uberlogs.install()
logger = uberlogs.getLogger("test")
eatable = Eatable(name="bagel",
flavor="salty",
location="tel-aviv")
logger.info("I'm eating a {eatable.name}", flavor=eatable.flavor,location=eatable.location)
# 1970-1-1 18:26:17,578 - test - INFO - I'm eating a bagel; flavor: salty; location: tel-avivPerformance
A profile.py file exists that compares uberlog with logging. logs are written to stdout, while profiling is written to stderr.
The ITERATIONS environment variable is used to specify the number of test iterations.
For example, the current version output on my computer is:
$ ITERATIONS=10000 python profile.py 1> /dev/null
Profiling 10000 iterations [python 3.5.2]
-----------------------------------------
block took 0.666 seconds, 0.00% faster than 'std %' [std %]
block took 0.655 seconds, 0.02% faster than 'std %' [std .format()]
block took 0.851 seconds, 0.30% slower than 'std .format()' [uber .format()]
block took 0.863 seconds, 0.01% slower than 'uber .format()' [uber complex .format()]
block took 0.842 seconds, 0.28% slower than 'std .format()' [uber .format() with statement]
block took 0.881 seconds, 0.05% slower than 'uber .format() with statement' [uber complex .format() with statement]I recommend using line_profiler to see profiling data. The code has all the needed attributes to make it work out of the box.
All you need to do is:
- install:
pip install line_profiler - profile:
kernprof -l -v profile.py
Example
If you run this code...
from collections import namedtuple
import uberlogs
uberlogs.install(kill_on=uberlogs.level.CRITICAL)
logger = uberlogs.getLogger("test")
Person = namedtuple('Person', ['name', 'age'])
p = Person(name="oded", age=26)
# uberlogs processes variable formats in string.format(...) manner
logger.debug("Hey! my name is {p_name}, and my age is: {p_age}!",
p_name=p.name, p_age=p.age)
# it can also implicitly evaluate statements like in ruby or python 3.6
logger.info("Hey! my name is {p.name}, and my age is: {p.age}!")
# and it can even add extra information to logs, without explicitly telling it to!
logger.warning("Hey! my name is {p.name}, and my age is: {p.age}!",
extra=dict(motto="hakuna matata"))
# this line will violently kill the application with a return code of 1
# The app will close AFTER all other handlers are done processing this lines
# and it'll flush all data to stdout and stderr before doing so
#
# this is a very import behavior for production applications
logger.critical("Hey! my name is {p.name} and critical logs close this app!")You'll see this output:
1970-1-1 18:00:50,979 - test - DEBUG - Hey! my name is oded, and my age is: 26!
{
"file": "test.py",
"func": "<module>",
"level": "DEBUG",
"logger": "test",
"message": "Hey! my name is oded, and my age is: 26!",
"p_age": 26,
"p_name": "oded",
"time": "1970-1-1T18:00:50+00:00"
}
1970-1-1 18:00:50,979 - test - INFO - Hey! my name is oded, and my age is: 26!
{
"file": "test.py",
"func": "<module>",
"level": "INFO",
"logger": "test",
"message": "Hey! my name is oded, and my age is: 26!",
"p_age": 26,
"p_name": "oded",
"time": "1970-1-1T18:00:50+00:00"
}
1970-1-1 18:00:50,980 - test - WARNING - Hey! my name is oded, and my age is: 26!; motto: hakuna matata
{
"file": "test.py",
"func": "<module>",
"level": "WARNING",
"logger": "test",
"message": "Hey! my name is oded, and my age is: 26!",
"motto": "hakuna matata",
"p_age": 26,
"p_name": "oded",
"time": "1970-1-1T18:00:50+00:00"
}When you use UberLogs with the following configuration:
{
"version": 1,
"disable_existing_loggers": false,
"formatters": {
"json": {
"()": "uberlogs.JsonFormatter",
"indent": 3,
"parse_text": true,
"include_format_keywords": true
},
"concat": {
"format": "%(asctime)s - %(name)s - %(levelname)s - %(message)s",
"()": "uberlogs.ConcatFormatter",
"delimiter": "; ",
"operator": ": ",
"log_in_color": true,
"include_format_keywords": false,
"parse_text": true
}
},
"handlers": {
"console": {
"class": "logging.StreamHandler",
"level": "DEBUG",
"formatter": "concat",
"stream": "ext://sys.stdout"
},
"json_console": {
"class": "logging.StreamHandler",
"level": "DEBUG",
"formatter": "json",
"stream": "ext://sys.stdout"
}
},
"loggers": {},
"root": {
"level": "DEBUG",
"handlers": [
"console",
"json_console"
],
"propagate": "no"
}
}
