Helpful logging with python

About me
●
Thomas Aglassinger
●
Software developer
– Industry experience since 2001 in various areas (health care,
banking, e-commerce, customer relationship management)
– Casual open source developer
– 2 x MSc
●
Links
– http://www.roskakori.at
– @TAglassinger
– https://github.com/roskakori

Agenda
●
Take a look at each log level
– INFO
– ERROR
– CRITICAL
– WARNING
– DEBUG
●
When to use it?
●
Templates / guidelines for helpful log messages

Motivation for INFO messages
●
Quickly see what application is doing right now
(or was doing at a certain point in time)
●
Trace back what caused a certain error
●
High level
●
If possible using business terms (process,
document, file, customer record, ...)
●
Small amount of messages to avoid information
overflow and excessive impact on log storage

When to use INFO
●
With high level components: business relevant actions and decisions
that influence the result
– Business process start / end
– Input received / output sent
– Major branches in process logic
●
With low level components: essential operations
– Incoming requests
– Start / end of transactions (database, files, network, …)
– Connection to other services or resources (database)
– Important state changes ( configuration changes, log in, session context, …)
– Start / end of complex calculation, important results
– Progress information (download, calculation, ...)

Perspective of log messages
●
Word log messages from the perspective of the
application
●
I = the application
●
you = the reader of the log
●
In line with usability engineering (i.e. status
messages, progress bars, error dialogs)

Detecting errors
1) Detect yourself with „if“:
2) Detect error raised by called function using
„except“:
if actual_value != expected_value:
…
try:
do_something()
except OSError as error:
...

Solving errors
●
Provide information for the log reader to reflect
about the situation that lead to an error
●
State: spell out what the data where provided /
processed
→ particularly helpful to detect slips and lapses
●
Context: spell out what the software actually was
doing
→ particularly helpful to detect lapses and
mistakes

Describing the error context
●
Message should describe the context in which the error was
detected
●
Description should be self contained
– Object that caused error, e.g. file, customer number,
session number
– Action that was attempted to be performed, e.g. reading,
writing, calculation, creating, connecting, …
– Parameters or values that were attempted to be processed
●
Previous log messages should only help to find out how this
context was reached

Template for error messages
1) Detect yourself with „if“:
2) Detect error raised by called function using
„except“:
if actual_value != expected_value:
_log.error('some value is %s but must be %s',
actual_value, expected_value)
try:
do_something()
_log.error('cannot do something: %s', error)

Variants for „detect yourself“
●
Value cannot be processed: „some value is %s but must…“
– … be between 0 and 100
– … be one of: red, green, blue
– … match format YYYY-MM-DD
●
Value not found in a large set of possible values:
– „cannot find customer number 1234“
– „cannot find customer number 1234; possible similar customer numbers: 1243, 1324“
●
Missing required value:
– „date of birth must be specified“
– „data of birth must be specified for age validation“ (explains why value is required)
●
Unterminated context of recursive descent parsers:
– „string started in line 17, column 23 must be terminated with quote“
– avoid useless “unexpected end of file”

Log or raise error?
●
Log error: Few parts of the code will log errors
– __main__ before sys.exit(1)
– self contained request handlers / dispatchers that
simply continue with next independent request
– form validation → show error and remain in form
●
Raising error:
– guidelines for wording error message apply
– can’t do anything about it anyway, just report it to the
caller

Log and raise error: anti pattern
●
Spams log with redundant and thus confusing error
messages
# BAD EXAMPLE, don't use this template
def process_customers(customers_path: str):
try:
with open(customers_path, encoding='utf-8') as customers_file:
for line in customers_file:
process_customer(line)
_log.error('cannot process customer data in "%s"', customers_path)
raise

Log and raise error: valid scenario
●
Frameworks for REST API that convert exception into
HTTP response:
1.Server raises exception
2.REST Framework converts
exception into 4xx or 5xx
HTTP response and thus
reports error to the client
3.Unless server also logs exception, information
about error would only be available to client

Further reading on error handling
●
Lösungsorientierte Fehlerbehandlung (with
Python)
●
How to write good error messages (with many
examples)

Critical errors
●
When application has to exit in unclean manner
– Resource leaks
– Data loss
●
Typical before involuntary server shutdown
●
Inappropriate for:
– Unprocessable single request / command / user input
– Errors during program startup, e.g. missing command
line option or broken syntax in configuration file

Wording critical messages
CRITICAL: cannot reconnect to database some.db: <some database error>
INFO: shutting down server
●
Messages worded similar to ERROR
●
Example:

Warnings hint at design issues
●
INFO is „good“
●
ERROS is „bad“
●
WARNING is …?

Wording warnings
●
Mix of error and info should reflect in the wording
●
Error part: describes what happened and was
expected
●
Info part: describes what is being done / has been
done to improve the situation

Transient errors
●
External errors that might be going away after a
while because the cause went away
●
Might be able to solve with retries
●
Example:
WARNING:example: Cannot connect to database some.db, trying
to reconnect (attempt 2 of 5)

Reduced quality of service
●
In environment with multiple redundant
components that can perform the same task
●
Example:
– replicas of search platform
– stateless micro services
request

Reduced quality of service
●
In environment with multiple redundant
components that can perform the same task
●
Example:
– replicas of search platform
– stateless micro services
●
Example:
request
WARNING:example: Cannot connect to search
server abcd17. Temporarily removing server from
pool and delegating request to server abcd18

Debug messages
●
Target audience
– debug: developers familiar with the code
– any other log level: devops, operations, users, …
●
Wording
– if possible similar to INFO
– otherwise: whatever rocks your boat
●
names of classes, methods, variables
●
dumps of XML, JSON, request headers
●
escaped string, hexadecimal garble
●
...

Enabling debug logging
●
Only temporarily while tracking down an issue
●
Otherwise: too much strain on storage and
collection of logs
●
Enable only for loggers that are expected to
contain relevant information
●
Consider adding a mechanic to your application
that allows to change log levels during runtime

Summary
●
INFO:
– “doing” vs “did“
– Focus on business logic
– Keep amount of messages low
●
ERROR:
– “cannot do something: something must be something else“
– Log vs raise, avoid log and raise
●
CRITICAL: like error but only if the application cannot recover
●
WARNING
– Might hint at design issues
– Few valid situations
– Combines error and info message
●
DEBUG
– For developers
– Log whatever is necessary

Questions and answers
Thomas Aglassinger
http://www.roskakori.at
@TAglassinger

Helpful logging with python

In this document

More Related Content

What's hot

Similar to Helpful logging with python

More from roskakori

Recently uploaded

Helpful logging with python