Lithoxyl¶
Lithoxyl is a next-generation instrumentation toolkit for Python applications, offering a semantic, action-oriented approach to logging and metrics collection. Lithoxyl integration is compact and performant, minimizing impact on codebase readability and system performance.
Sections¶
Lithoxyl Overview¶
Lithoxyl is next-generation logging and instrumentation for Python. This practical tutorial walks new users through the fundamentals necessary to get up and running with Lithoxyl in under 10 minutes.
Motivating factors¶
Lithoxyl began as a response to the tired traditions of logging. Traditions that included omission, procrastination, and only adding it once things break.
Logging is not the last step anymore. Lithoxyl makes instrumentation worthwhile from day 1, so all your projects are designed for introspection. Lithoxyl achieves this by taking full advantage of Python’s rich syntax and runtime, providing features ranging from metrics collection to structured logging to interactive debugging hooks.
The Lithoxyl approach is practical. After running pip install
lithoxyl
, integrating Lithoxyl comes down to two steps:
instrumentation and configuration. First, instrumentation.
Instrumenting with Actions¶
With Lithoxyl, all instrumentation, including logging, starts with knowing your application. We want to find the important parts of your application and wrap them in microtransactions, called Actions.
Much more than print statements, Actions are lightweight objects that track the state of code execution, from timing information to uncaught exceptions. Each Action also has a name and a level, to enable aggregation and filtering.
Actions are created with Loggers. We get into creating and configuring Loggers later in the overview, but here’s a basic example of creating an info-level Action with a preconfigured Logger:
import backend # some convenient backend logic for brevity
from log import app_log # preconfigured Lithoxyl Logger
def create_entry(name):
with app_log.info('adding entry by name'):
name = name.strip()
backend.add_by_name(name)
return True
As you can see, the transactionality of Actions translates well to
Python’s with context manager syntax. A single line of logging
code succinctly records the beginning and ending of this code
block. Even better, there’s no chance of missing an unexpected
exception. For instance, if name is not a string, and .strip()
raises an AttributeError
, then that exception is guaranteed to
be captured and recorded.
You can do so much more with actions. Using dictionary syntax, arbitrary data can be added to the action. And while actions finish with a success status and autogenerate a message if no exception is raised, failures and exceptions can also be set manually:
import backend
from log import app_log
def set_entry_state(name, state):
with app_log.info('setting entry state') as act:
act['name'] = name
status = backend.STATE_MAP[state.lower()]
success = backend.set_entry_state(name, state)
if not success:
act.failure('set {name} status to {state} failed', state=state)
return success
As seen above, actions can also have a custom completion message, which supports templating with new-style formatting syntax, using data from within the action’s data map (name), as well as arguments and keyword arguments (state).
Note
Even if message formatting fails, the log message will still be recorded. Only the failing segments will be left unformatted. As a rule, Lithoxyl degrades gracefully, to minimize impact to your application’s primary functionality.
Furthermore, in cases like this, where you want the whole function
logged, you can use the logger’s wrap()
method.:
import backend
from log import app_log
@app_log.wrap('critical', inject_as='act')
def delete_entry(name, act):
try:
ret = backend.delete_entry_by_name(name.strip())
except backend.EntryNotFound:
# log soft error, let other exceptions raise through
act.failure('no entry with name: {}', name)
ret = False
return ret
Note the decorator syntax, as well as the ability to inject the action as one of the arguments of the function. This reduces the instrumentation’s code footprint even further.
That about covers creating and interacting with actions. Now we turn to the origin and destination of the actions we create and populate: Loggers and Sinks.
Creating Loggers¶
Actions make up most of an application’s interaction with Lithoxyl, but it would not be very easy to create an Action without a Logger.
As we learned above, before an Action can be populated, it must be created, and Actions are created through Logger. As for the Logger itself, here is how it is created:
from lithoxyl import Logger
app_log = Logger('entry_system')
Like that, the Logger we’ve been using above is ready to be imported. A Logger is a lightweight, simple object, requiring only a name. They are designed to be created once, configured, and imported by other modules. That said, they are conceptually very useful.
Loggers generally correspond to parts or aspects of the application. Small- to medium-sized applications can be fully instrumented with just one Logger, but as applications grow, they tend to add aspects. For example, if file access grows increasingly important to an application, it would make sense to add a dedicated low-level log just for instrumenting file access:
file_log = Logger('file_access')
In short, Loggers themselves are simple, and designed to be fit to your application, no matter how many aspects it may have. On their own, they are conceptually useful, but without Sinks, they are all potential.
Configuring Sinks¶
So far, we have discovered two uses of the Lithoxyl Logger:
- Creating actions
- Segmenting and naming aspects of an application
Now, we are ready to add the third: publishing log events to the
appropriate handlers, called Sinks. Actions can carry all manner of
messages and measurements. That variety is only surpassed by the
Sinks, which handle aggregation and persistence, through log files,
network streams, and much more. Before getting into those
complexities, let’s configure our app_log
with a simple but very
useful sink:
from lithoxyl import AggregateSink
agg_sink = AggregateSink(limit=100)
app_log.add_sink(agg_sink)
Now, by adding an instance of the AggregateSink to the app_log
, we
have a technically complete system. At any given point after this, the
last 100 events that passed through our application log will be
available inside agg_sink
. However, AggregateSinks only provide
in-memory storage, meaning data must be pulled out, either through a
monitoring thread or network service. Most developers expect
persistent logging to streams (stdout/stderr) and files. Lithoxyl is
more than capable.
Logging Sensibly¶
For developers who want a sensible and practical default Sink, Lithoxyl provides the SensibleSink. The Sensible Suite chapter has a full introduction, so let’s just cover the basics.
The Sensible approach has 3 steps:
- Filter - Optionally ignore events for a given Sink.
- Format - Convert an event into a string.
- Emit - Output the formatted string to a file, database, network, etc.
While totally pluggable and overridable, the Sensible suite ships with types for each of these:
from lithoxyl import (SensibleFilter,
SensibleFormatter,
StreamEmitter,
SensibleSink)
# Create a filter that controls output verbosity
fltr = SensibleFilter(success='critical',
failure='info',
exception='debug')
# Create a simple formatter with just two bits of info:
# The time since startup/import and end event message.
# These are just two of the built-in "fields",
# and the syntax is new-style string formatting syntax.
fmtr = SensibleFormatter('+{import_delta_s} - {end_message}')
# Create an emitter to write to stderr. 'stdout' and open file objects
# also behave predictably.
emtr = StreamEmitter('stderr')
# Tie them all together. Note that filters accepts an iterable
sink = SensibleSink(filters=[fltr], formatter=fmtr, emitter=emtr)
# Add the sink to app_log, a vanilla Logger created above
app_log.add_sink(sink)
In these six lines of code, using only built-in Lithoxyl types, we create a filter, formatter, and emitter, then we bind them all together with a SensibleSink. The output is first filtered by our SensibleFilter, which only shows critical-level successes and info-level failures, but shows all exceptions. Our SensibleFormatter provides a simple but practical output, giving us a play-by-play timing and message. That message is output to stderr by our StreamEmitter. Just don’t forget to add our newly-created SensibleSink to the app_log.
As configured, the app_log will now write to stderr output that looks like:
+0.015255 - "load credential succeeded"
+0.179199 - "client authorization succeeded"
+0.344523 - "load configuration succeeded"
+0.547119 - "optional backup failed"
+1.258266 - "processing task succeeded"
Ain’t it a thing of beauty? Here we see the SensibleFormatter at work. It may not look like much, but there is a powerful feature at work.
The ambitious aim underlying the Sensible approach is to create human-readable structured logs. These are logs that are guaranteed to be uniformly formatted and escaped, allowing them to be loaded for further processing steps, such as collation with other logs, ETL into database/OLAP, and calculation of system-wide statistics. Extending the flow of logged information opens up many new roads in debugging, optimization, and system robustification, easily justifying a bit of extra up-front setup.
Here we only used two fields, import_time_s and end_message. The list of Sensible built-in fields is quite expansive and worth a look when designing your own log formats.
The Action¶
Actions are Lithoxyl’s primary interface for instrumenting your
application. Actions are created with a
Logger
instance, and are used to wrap
functions and code blocks.
At their most basic, Actions have a:
- name - A string description of the behavior being wrapped.
- level - An indicator of the importance of the action (debug, info, critical).
- status - The state of the action (begin, success, failure, exception).
- duration - The time between the begin and end events of a completed action, i.e., the time between entering and exiting a code block.
To track this information, Lithoxyl wraps important pieces of your application in microtransactions called Actions:
with log.info('user creation', username=name) as act:
succeeded = _create_user(name)
if not succeeded:
act.failure()
This pattern is using an info-level Action as a context manager. The indented part of the code after the with statement is the code block managed by the Action. Here is how the basics of the Action are populated in our example:
- name - “user creation”
- level - INFO
- status - failure if
_create_user(name)
returns a falsey value, exception if it raises an exception, otherwise defaults to success.
- duration - Set automatically, duration is the time difference
- from before the execution of the first line of the code block to after the execution of the last line in the code block, or the
r.failure()
call, depending on the outcome of_create_user(name)
.
There’s quite a bit going on, but Lithoxyl has several tricks that let it flow with the semantics of applications. First, let’s learn a bit about these attributes, starting with the Action level.
Action level¶
Levels are a basic indicator of how important a block of application logic is. Lithoxyl has three built-in levels. In order of increasing importance:
- debug - Of interest to developers. Supplementary info for when something goes wrong.
- info - Informational. Can be helpful to know even when there are no problems.
- critical - Core functionality. Essential details at all times.
When instrumenting with Lithoxyl, the developer is always asking, how significant is the success of this code block, how catastrophic is a failure in this function?
It’s only natural that instrumented code will start with more critical actions. The most important parts should be instrumented first. Eventually the instrumentation spreads to lower levels.
Note
As a general tendency, as code gets closer to the operating system, the corresponding Action also gets a lower level. High-level operations get higher levels of Actions. Start high and move lower as necessary.
Action status¶
The Lithoxyl Action has an eventful lifetime. Even the most basic usage sees the Action going from creation to beginning to one of the ending states: success, failure, or exception.
First, simply creating an Action does not “begin” it. An action begins when it is entered with a with statement, as we saw in the example above. Entering an action creates a timestamp and makes it the parent of future actions, until it is ended.
There are three end statuses:
- success - The action described by the action completed without issue. This is the automatic default when no exception is raised.
- failure - The action did not complete successfully, and the failure was expected and/or handled within the application.
- exception - The action terminated unexpectedly, likely with a Python exception. This is the automatic default when an exception is raised within an action context manager.
The split between failure and exception should be familiar to users of standard testing frameworks like py.test. Test frameworks distinguish between a test that fails and a test that could not be fully run because the test code raised an unexpected exception. Lithoxyl brings these semantics into an application’s runtime instrumentation.
Action API¶
Actions are usually constructed through Loggers, but it can help to know the underlying API and see the obvious parallels.
-
class
lithoxyl.action.
Action
(logger, level, name, data=None, reraise=True, parent=None, frame=None)[source]¶ The Action type is one of the core Lithoxyl types, and the key to instrumenting application logic. Actions are usually instantiated through convenience methods on
Logger
instances, associated with their level (e.g.,critical()
).Parameters: - logger – The Logger instance responsible for creating and publishing the Action.
- level – Log level of the Action. Generally one of
DEBUG
,INFO
, orCRITICAL
. Defaults toNone
. - name (str) – A string description of some application action.
- data (dict) – A mapping of non-builtin fields to user
values. Defaults to an empty dict (
{}
) and can be populated after Action creation by accessing the Action like adict
. - reraise (bool) – Whether or not the Action should catch and
reraise exceptions. Defaults to
True
. Setting toFalse
will cause all exceptions to be caught and logged appropriately, but not reraised. This should be used to eliminatetry
/except
verbosity. - frame – Frame of the callpoint creating the Action. Defaults to the caller’s frame.
Most of these parameters are managed by the Actions and respective
Logger
themselves. While they are provided here for advanced use cases, usually only the name and raw_message are provided.Actions are
dict
-like, and can be accessed as mappingsand used to store additional structured data:
>>> action['my_data'] = 20.0 >>> action['my_lore'] = -action['my_data'] / 10.0 >>> from pprint import pprint >>> pprint(action.data_map) {'my_data': 20.0, 'my_lore': -2.0}
-
exception
(message=None, *a, **kw)[source]¶ Mark this Action as having had an exception. Also sets the Action’s message template similar to
Action.success()
andAction.failure()
.Unlike those two attributes, this method is rarely called explicitly by application code, because the context manager aspect of the Action catches and sets the appropriate exception fields. When called explicitly, this method should only be called in an
except
block.
-
failure
(message=None, *a, **kw)[source]¶ Mark this Action failed. Also set the Action’s message template. Positional and keyword arguments will be used to generate the formatted message. Keyword arguments will also be added to the Action’s
data_map
attribute.
Action concurrency¶
TODO
The Logger¶
The Logger
is the application developer’s primary
interface to using Lithoxyl. It is used to conveniently create
Actions
and publish them to sinks
.
-
class
lithoxyl.logger.
Logger
(name, sinks=None, **kwargs)[source]¶ The
Logger
is one of three core Lithoxyl types, and the main entrypoint to creatingAction
instances, and publishing those actions to sinks.Parameters: - name (str) – Name of this Logger.
- sinks (list) – A list of sink objects to be attached to
the Logger. Defaults to
[]
. Sinks can be added later withLogger.add_sink()
. - module (str) – Name of the module where the new Logger instance will be stored. Defaults to the module of the caller.
Most Logger methods and attributes fal into three categories:
Action
creation, Sink registration, and Event handling.
Action creation¶
The Logger is primarily used through its
Action
-creating convenience methods named
after various log levels: debug()
, info()
,
and critical()
.
Each creates a new action with a given name, passing any
additional keyword arguments on through to the
lithoxyl.action.Action
constructor.
The action level can also be passed in:
Sink registration¶
Another vital aspect of Loggers is the registration and management of Sinks.
-
Logger.
sinks
¶ A copy of all sinks set on this Logger. Set sinks with
Logger.set_sinks()
.
Event handling¶
The event handling portion of the Logger API exists for Logger-Sink interactions.
The Sink¶
In Lithoxyl’s system of instrumentation, Actions are used to carry messages, data, and timing metadata through the Loggers to their destination, the Sinks. This chapter focuses in on this last step.
Writing a simple Sink¶
Sinks can grow to be very involved, but a useful Sink can be as simple as:
import sys
class DotSink(object):
def on_end(self, end_event):
sys.stdout.write('.')
sys.stdout.flush()
Note that our new Sink does not have to inherit from any special
object. DotSink is a correct and capable Sink, ready to be
instantiated and installed with Logger.add_sink()
, just like in
the overview. Once added to your Logger,
every time an Action ends, a dot will be written out to your console.
In this example, on_end
is the handler for just one of Lithoxyl’s
events. The next section takes a look at all five of them.
Events¶
Lithoxyl Events are state changes associated with a particular Action. Five types of events can happen in the Lithoxyl system:
begin - The beginning of an Action, whether manually or through entering a context-managed block of code.
The begin event corresponds to the method signature
on_begin(self, begin_event)
. Designed to be called once per Action.end - The completion of an Action, whether manually (
success()
andfailure()
) or through exiting a context-managed block of code. There are three ways an Action can end, success, failure, and exception, but all of them result in an end event.The end event corresponds to the method signature
on_end(self, end_event)
. Designed to be called once per Action.exception - Called immediately when an exception is raised from within the context-managed block, or when an exception is manually handled with Action.exception(). Actions ending in exception state typically fire two events, one for handling the exception, and one for ending the Action.
The exception event corresponds to the Sink method signature
on_exception(self, exc_event, exc_type, exc_obj, exc_tb)
. Designed to be called up to once.warn - The registration of a warning within an Action.
Corresponds to the Sink method signature
on_warn(self, warn_event)
. Can be called an arbitrary number of times.comment - The registration of a comment from a Logger. Comments are used for publishing metadata associated with a Logger.
The comment event corresponds to the Sink method signature
on_comment(self, comment_event)
. See here for more about comments. Can be called an arbitrary number of times.
A Sink handles the event by implementing the respective method. The event objects that accompany every event are meant to be practically immutable; their values are set once, at creation.
The Sensible Suite¶
Structured logging creates logs with a consistent format, allowing them to be loaded later for further processing and analysis.
One of Lithoxyl’s primary uses is as a toolkit for creating these structured logs. The Sensible Suite is the first generalized approach to offer structured logging without sacrificing human readability.
Let’s look at an example. Perhaps the most common structured log is the HTTP server access log, such as the one created by Apache or nginx. A couple entries from that log might look like:
78.178.243.200 - - [22/Jun/2013:15:02:31 -0700] "GET /favicon.ico HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/27.0.1453.116 Safari/537.36" "-"
119.63.193.132 - - [22/Jun/2013:14:19:36 -0700] "GET / HTTP/1.1" 200 9755 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 6.0)" "-"
It’s a bit on the wide side, but here we see:
- The IP of the client
- The local date and time the request was received
- The request line, including the method, path, and version
- The response code returned to the client
- The size of the response in bytes
- The user agent from the client browser
With the Sensible suite, each of these values becomes a field, represented by SensibleField objects. The Sensible suite comes with over twenty built-in fields to cover most use cases, and sensible default handling for other values. These fields are used to create a template for the SensibleFormatter, which knows how to turn a Lithoxyl Action into a structured string. Let’s see how it all comes together by creating an equivalent log that uses Lithoxyl built-in behavior:
from lithoxyl import SensibleFormatter, FileEmitter, Logger
a_log = Logger('access_log')
a_fmtr = SensibleFormatter('{ip} - [{iso_begin_local}] {req_line} {resp_code} {resp_len} {user_agent}')
a_sink = SensibleSink(formatter=fmtr, emitter=FileEmitter('access.log'))
a_log.add_sink(a_sink)
No arcane configuration format here. Everything is configured through
explicit Python code. The a_log
logger has only one sink right
now, a SensibleSink that ties together three entities, in their
running order:
- Filters - This list of objects checks each event, and returns True/False depending on whether it should be logged. See the
SensibleFilter
for more info.- Formatter - Turns events that make it through the filters into strings. The
SensibleFormatter
is the canonical formatter of the suite, though you’re free to provide your own.- Emitters - Writes formatted strings into files or network streams. Emitters are not strictly a Sensible construct; several can be found in the
emitters
module.
The flow through the SensibleSink is clear: Filtration → Formatting →
Output. Any actions passing through the a_log
Logger will have
their end events logged to access.log.
The Sensible Interfaces¶
To achieve human-readable strutured logging, Lithoxyl’s Sensible suite uses four key types with a sensible naming scheme:
- The
SensibleSink
- The
SensibleFilter
- The
SensibleFormatter
- The
SensibleField
The first three are used fairly regularly, but SensibleField is mostly behind the scenes. That said, the built-in fields can in many ways the most important part. See the Sensible Fields section below for details on those.
Sensible Fields¶
There are many built-in Sensible Fields, for a variety of use cases. First, some example code to set the context for the field examples:
logger = Logger('test_logger')
with logger.critical('test_task', reraise=False) as act:
time.sleep(0.7)
act['item'] = 'cur_item'
act.failure('task status: {status_str}')
raise ValueError('unexpected value for {item}')
return act
And now the fields themselves:
Name Description Example logger_name The name of the Logger, as set in the constructor. Quoted. "test_logger"
logger_id An automatic integer ID. See Action concurrency. 3
action_name Short string description of the action. Quoted. "test_task"
action_id An automatic integer ID. See Action concurrency. 17
action_guid A globally unique ID string. See Action concurrency. c3124107db02ff33dbde8e85
status_str The full name of action status. See Action status. exception
status_char A single-character action status. See Action status. E
level_name Full name of the action level. critical
level_name_upper Full name of the action level, in uppercase. See Action level. CRITICAL
level_char Single-character form of the action level. C
level_number The integer value associated with the action level. 90
data_map JSON-serialized form of all values in the Action data map. {"item": "cur_item"}
data_map_repr repr()-serialized form of all values in the Action data map. {"item": "cur_item"}
begin_message The message associated with the event’s action’s begin event. "test_task beginning"
begin_message_raw Same as begin_message, before formatting. "test_task beginning"
end_message The message associated with the event’s action’s end event. "test_task raised ... ue for cur_item',)"
end_message_raw Same as end_message, before formatting. "test_task raised ... lue for {item}',)"
event_message The message associated with the event. "test_task raised ... ue for cur_item',)"
event_message_raw Same as event_message, before formatting. "test_task raised ... lue for {item}',)"
duration_s Duration in floating point number of seconds. 0.701
duration_ms Duration in floating point number of milliseconds (ms). 700.908
duration_us Duration in floating point number of microseconds (us). 700907.946
duration_auto Duration in floating point with automatic unit (s/ms/us). 700.908ms
module_name The name of the module where the action was created. "__main__"
module_path The path of the module where the action was created. "misc/gen_field_table.py"
func_name The name of the function that created the action get_test_action
line_number The line number where the action was created. 26
exc_type The name of the exception type, if an exception was caught. ValueError
exc_message The exception message, if there was one. Quoted. "unexpected value for {item}"
exc_tb_str The exception’s full traceback, if there was one. Quoted. "Traceback (most r ... ue for {item}')\n"
exc_tb_list A JSON representation of the exception traceback. Quoted. "[Callpoint('get_t ... for {item}')\")]"
process_id The integer process ID. See os.getpid()
.19828
There can be some subtle nuances when designing your log structure. For instance, when choosing which message to use for an event, you almost certainly want event_message, which works equally well with all event types, including begin, end, comment, and warn.
Timestamp fields¶
Timestamps are so important to logging, especially structured logging, that they get a table of their own:
Name Description Example iso_begin The full ISO8601 begin event UTC timestamp, with timezone. 2016-05-22T10:41:06.470354+0000
iso_end The full ISO8601 end event UTC timestamp, with timezone. 2016-05-22T10:41:07.171262+0000
iso_begin_notz The begin event ISO UTC timestamp, without timezone. 2016-05-22T10:41:06.470354
iso_end_notz The end event ISO UTC timestamp, without timezone. 2016-05-22T10:41:07.171262
iso_begin_local The begin event ISO local timestamp, with timezone. 2016-05-22T03:41:06.470354-0700
iso_end_local The end event ISO local timestamp, with timezone. 2016-05-22T03:41:07.171262-0700
iso_begin_local_notz The begin event ISO local timestamp, without timezone. 2016-05-22T03:41:06.470354
iso_end_local_notz The end event ISO local timestamp, without timezone. 2016-05-22T03:41:07.171262
iso_begin_local_noms The begin event ISO local timestamp, without subsecond timing. 2016-05-22T03:41:06 PDT
iso_end_local_noms The end event ISO local timestamp, without subsecond timing. 2016-05-22T03:41:07 PDT
iso_begin_local_noms_notz The begin event local times, without subsecond or timezone. 2016-05-22T03:41:06
iso_end_local_noms_notz The end event local times, without subsecond or timezone. 2016-05-22T03:41:07
The timestamp fields above are geared toward long-running processes like servers. For shorter running processes, it’s often more readable and more useful to know the time between the log message and process start.
Name Description Example import_delta_s Floating-point number of seconds since lithoxyl import. 2.887265
import_delta_ms Floating-point number of milliseconds since lithoxyl import. 2887.265
Creating custom fields¶
Most custom data does not require new fields. Unrecognized fields are treated as quoted and escaped string data. If you want to change that representation, you can create a SensibleField and either register it locally with a Formatter, or globally, using sensible.register_field().
The Logging Tradition¶
For experienced engineers, it can help to understand Lithoxyl by taking a hard look at the past and current state of logging.
Logging in General¶
Without getting into Python specifics, most ecosystems have pretty low standards for logging. Logging is an afterthought, added when the application misbehaves and needs to be debugged. Just having any logging can easily put an application in the top quartile for quality.
And worse yet, the opposite can be true. Logging’s place in software is so low that having logging is often a yellow flag for lower-quality code in need of constant debugging. If the code needed so much logging, it must have had a lot of problems.
This is the past and present reality of logging in general.
Logging in Python¶
This will be frank, so first things first: all due respect to Vinay Sajip and all the Python contributors who worked on Python logging. Without their work, there is no telling where we would be today. Now, the critique.
The built-in logging
module itself followed this afterthought
pattern. Little more than a knockoff of Log4j, logging
pays
virtually no mind to performance, practicality, or the fact that
Python is not Java.
Application instrumentation is important. Good metrics are worth more than their weight in CPU cycles. By running a high-level language like Python, a design decision has already been made to achieve a richer, more featureful environment.
With that in mind, it is critical that Python libraries take the semantic high road. Always emphasize maintainability, introspectability, and reliability in Python code.
Because application instrumentation is vital to all these areas, the
approach and framework used must be closely matched. The built-in
logging
library is a frumpy, secondhand suit, thrifted and
worn without even a thorough cleaning. Lithoxyl is new, tailored to
fit Python and its many, many modern applications.
The Lithoxyl Response¶
Python’s power lets us do better. And we can’t stop with just logging. We need to look at instrumentation as a whole.
Tradition is to add logging to indicate breakage. Little more than print statements and tracebacks piped to files.
Modern instrumentation is more than a debugging utility.
Lithoxyl provides structured data and online statistics to unlock your application’s potential. Lithoxyl is a development tool, worth using from day one. Good instrumentation focuses on the whole application lifecycle. It helps with debugging problems, but it also offers direction when the sun is shining and the monitoring is green. Lithoxyl is the Pythonic step toward that bright, introspectable future.
Frequently Asked Questions¶
Lithoxyl’s new approach answers quite a lot of questions, but raises a few others. These questions fall into two categories, Design and Background.
Design questions¶
Some questions are hard because they are ultimately decided by your application’s design. Lithoxyl is mostly an API to instrumentation. There are many right ways.
What is the difference between failure status and exception status?¶
There are a couple angles to answer this. First, it is pretty rare to
set an exception status manually, as exception information is usually
populated automatically when there are uncaught exceptions. That
contrasts with failure()
, which is seen more often.
So when to call failure()
? As with many design
questions, an example is often best. With an HTTP server, returning a
4xx or even a 503 can be viewed as failures outside of the control of
the application, which is performing fine. A 500, on the other hand,
is generally unexpected and deserves an exception status.
Why does Lithoxyl sometimes fail silently?¶
Built-in to the design of Lithoxyl itself, there are several deviations from what one might consider standard practice. With most libraries, one expects that code will “fail fast”. However, failing fast does not work well for instrumentation code.
Lithoxyl assumes that you are instrumenting a system which has behavior other than logging and statistics collection. Your system’s primary functions take priority. Instrumentation must degrade gracefully.
This means if your message is malformed Lithoxyl will do its best to output the most that it can and no exception will be raised. If your logging service is down, maybe the Sink queues the message, but eventually that queues bounds will be overrun and messages may silently drop.
This graceful degradation takes place at all the runtime integration points, i.e., action usage within your application code. For Sink and Logger configuration, actions which are typically performed at startup and import time, exceptions are still raised as usual. In fact, it is considered good Lithoxyl practice to forward-check these configurations. This means checking that callable arguments are
If you discover a runtime scenario that should degrade with more grace or a configuration-time scenario which could prevent runtime failures through more forward checking, please do file an issue.
Glossary¶
- action
- An instance of the
Action
type, and one of the three fundamental Lithoxyl types. TheAction
type is rarely instantiated directly, instead they are created by loggers, manipulated, and automatically published to sinks. - emitter
- An object capable of publishing formatted messages out of the process. Emitters commonly publish to network services, local services, and files. The last step in the Sensible Filter-Format-Emit logging process.
- event
An occurence associated with a Logger and Action. One of:
- begin - The start of an Action.
- end - The completion of an Action (success, failure, or exception)
- warn - A warning related to an Action.
- comment - A metadata event associated with a Logger
- exception - An unhandled exception during an Action.
Sinks implement methods to handle each of these events.
- formatter
- An object responsible for transforming a action into a string, ready to be encoded and emitted
- lithoxyl
- Mineralized wood.
- logger
- An instance of the
Logger
type. Responsible for facilitating the creation and publication of actions. Generally there is one logger per aspect of an application. For example, a request logger and a database query logger. - sink
- Any object implementing the Sink protocol for handling events. Typically subscribed to actions by being attached to a logger. Some basic types of sinks include action emitters, statistics collectors, and profilers.
- status
The completion state of an action, meant to represent one of four possible task outcomes:
- Begin - not yet completed
- Success - no exceptions or failures
- Failure - anticipated or application-level unsuccessful completion (e.g., invalid username)
- Exception - unanticipated or lower-level unsuccessful completion (e.g., database connection interrupted)
- with
- Python’s compact context manager syntax, roughly approximating a “try-finally” block. With blocks have enter and exit hooks that enable tracking of Action events, no matter whether the wrapped code executes successfully or raises an exception.