7. Logging¶
More detail about ways to use logging can be found in the rootpy logger module,
see rootpy.logger
.
7.1. Python logging basics¶
In Python’s standard library there is a logging
module. It’s good to make
use of this, because it means that you can interoperate with a large range of
tools which already use it. rootpy
extends the default logger to add
a range of useful utilities, but underlying it is the normal logging behaviour.
Python’s logging
module allows you to define a hierarchy of loggers.
Confusingly, the base of the hierarchy is called root
. Each logger in a
hierarchy has a .level
(one of CRITICAL
, ERROR
, WARNING
,
INFO
, DEBUG
, NOTSET
), which defines the minimum severity of messages
which will be passed onto the handlers.
Handlers can be attached to specific loggers, or anywhere in the hierarchy. For
example, a handler attached to the logger logging.root
would recieve all
messages which meet the root
logger’s minimum level.
Handlers have a level
, independently of a logger. This means that a handler
can be configured to only receive certain messages.
By default, Python configures no handlers. This means that ordinarily, after
emitting a brief one-time warning about no handlers being configured, messages
get sent into the void, never to be heard from again. In addition, the default
state of the logging.root
logger is WARNING
, so at first, no messages
less severe than that (INFO
and DEBUG
) will be processed.
This makes it reasonable to leave log.debug
statements in non-performance
critical code, since by default they aren’t shown.
7.2. Capturing ROOT messages with rootpy.logger
¶
rootpy provides a mechanism to capture ROOT’s log messages and if appropriate, raise an error. This can be a big boon for debugging and makes it possible to do things which were not previously possible, such as capture messages to show them where they are needed (think of web services, for example).
As a trivial example, it means that this:
In [2]: r = ROOT.TFile("test.root")
Error in <TFile::TFile>: file test.root does not exist
In [3]: r.myanalysisdata
---------------------------------------------------------------------------
AttributeError Traceback (most recent call last)
<ipython-input-3-c06f1156de1b> in <module>()
----> 1 r.myanalysisdata
AttributeError: TFile object has no attribute 'myanalysisdata'
Now does this:
In [3]: import rootpy
In [4]: f = ROOT.TFile("test.root")
> Warning: No logger for 'ROOT', adding a default
> Suppress with 'import logging; logging.basicConfig()'
ERROR:ROOT.TFile.TFile:file test.root does not exist
---------------------------------------------------------------------------
ROOTError Traceback (most recent call last)
<ipython-input-4-e2c494f4c26e> in <module>()
----> 1 f = ROOT.TFile("test.root")
<ipython-input-4-e2c494f4c26e> in <module>()
----> 1 f = ROOT.TFile("test.root")
.../rootpy/logger/roothandler.py in python_logging_error_handler(level, abort, location, msg)
50 # We can't raise an exception from here because ctypes/PyROOT swallows it.
51 # Hence the need for dark magic, we re-raise it within a trace.
---> 52 raise ROOTError(level, location, msg)
53 except RuntimeError:
54 _, exc, traceback = sys.exc_info()
ROOTError: level=3000, loc='TFile::TFile', msg='file test.root does not exist'
This means that the code fails early, even better it’s at the point of the problem. It uses python’s logging mechanism, so now it’s possible to filter messages with ease.
Warning
The astute amongst you might have noticed a passing mention of dark magic. This feature is still a little experimental, and is currently limited to CPython 2.6-2.7.
Note
If errors don’t give you backtraces as you expect, it might be necessary to:
import rootpy.logger.magic as M; M.DANGER.enabled = True
The first thing to note is the warning mentioning a lack of a default logger. To suppress this, configure logging any way you please, or use the snippet from the warning itself.
import logging
# Most verbose log level
logging.basicConfig(level=logging.DEBUG)
Once that is done, you can use python’s normal logging API to suppress or highlight log messages coming from particular places with ease:
import logging
# Suppress "debug"-level notices from TCanvas that it has saved a .png
logging.getLogger("ROOT.TCanvas").setLevel(logging.WARNING)
If you want to get the stack trace at the point where any ROOT message is coming from, you can decrease the abort level to the minimum:
import ROOT
ROOT.gErrorAbortLevel = 0
7.3. What else does rootpy’s logging do for me?¶
rootpy.logger
adds a check to ensure that a handler is configured
against the rootpy
logging namespace and, if not, installs a default one.
There is some syntactic sugar to obtain loggers in a given namespace:
import rootpy
# logger in the rootpy logging namespace
# (whose parent is python's `logging.root`)
log = rootpy.log
log["child"] # logger in the rootpy.child namespace
log["/ROOT"] # ROOT
log["/ROOT.TFile"] # ROOT.TFile
rootpy.logger
can also help you identify where messages are coming
from, using rootpy.logger.extended_logger.ExtendedLogger.show_stack()
.
log["/"].setLevel(log.NOTSET)
# Show stack traces for
log["/ROOT"].show_stack()