logging.rst (3486B)
1 .. _mach_logging: 2 3 ======= 4 Logging 5 ======= 6 7 Mach configures a built-in logging facility so commands can easily log 8 data. 9 10 What sets the logging facility apart from most loggers you've seen is 11 that it encourages structured logging. Instead of conventional logging 12 where simple strings are logged, the internal logging mechanism logs all 13 events with the following pieces of information: 14 15 * A string *action* 16 * A dict of log message fields 17 * A formatting string 18 19 Essentially, instead of assembling a human-readable string at 20 logging-time, you create an object holding all the pieces of data that 21 will constitute your logged event. For each unique type of logged event, 22 you assign an *action* name. 23 24 Depending on how logging is configured, your logged event could get 25 written a couple of different ways. 26 27 JSON Logging 28 ============ 29 30 Where machines are the intended target of the logging data, a JSON 31 logger is configured. The JSON logger assembles an array consisting of 32 the following elements: 33 34 * Decimal wall clock time in seconds since UNIX epoch 35 * String *action* of message 36 * Object with structured message data 37 38 The JSON-serialized array is written to a configured file handle. 39 Consumers of this logging stream can just perform a readline() then feed 40 that into a JSON deserializer to reconstruct the original logged 41 message. They can key off the *action* element to determine how to 42 process individual events. There is no need to invent a parser. 43 Convenient, isn't it? 44 45 Logging for Humans 46 ================== 47 48 Where humans are the intended consumer of a log message, the structured 49 log message are converted to more human-friendly form. This is done by 50 utilizing the *formatting* string provided at log time. The logger 51 simply calls the *format* method of the formatting string, passing the 52 dict containing the message's fields. 53 54 When *mach* is used in a terminal that supports it, the logging facility 55 also supports terminal features such as colorization. This is done 56 automatically in the logging layer - there is no need to control this at 57 logging time. 58 59 In addition, messages intended for humans typically prepends every line 60 with the time passed since the application started. 61 62 Logging HOWTO 63 ============= 64 65 Structured logging piggybacks on top of Python's built-in logging 66 infrastructure provided by the *logging* package. We accomplish this by 67 taking advantage of *logging.Logger.log()*'s *extra* argument. To this 68 argument, we pass a dict with the fields *action* and *params*. These 69 are the string *action* and dict of message fields, respectively. The 70 formatting string is passed as the *msg* argument, like normal. 71 72 If you were logging to a logger directly, you would do something like: 73 74 .. code-block:: python 75 76 logger.log(logging.INFO, 'My name is {name}', 77 extra={'action': 'my_name', 'params': {'name': 'Gregory'}}) 78 79 The JSON logging would produce something like:: 80 81 [1339985554.306338, "my_name", {"name": "Gregory"}] 82 83 Human logging would produce something like:: 84 85 0.52 My name is Gregory 86 87 Since there is a lot of complexity using logger.log directly, it is 88 recommended to go through a wrapping layer that hides part of the 89 complexity for you. The easiest way to do this is by utilizing the 90 LoggingMixin: 91 92 .. code-block:: python 93 94 import logging 95 from mach.mixin.logging import LoggingMixin 96 97 class MyClass(LoggingMixin): 98 def foo(self): 99 self.log(logging.INFO, 'foo_start', {'bar': True}, 100 'Foo performed. Bar: {bar}')