logging module example

[Chris Smith]

Hola, pythonisas:
The documentation for the logging module is good, but a bit obscure.
In particular, there seems to be a lot of action at a distance.
The fact that getLogger() can actually be a call to Logger.__init__(),
which is mentioned in para 6.29.1, also bears stressing on 6.29. I
grasp _why_ you'd implement it that way, but I may not be the only
coder who feels queasy with the word 'get' being used both to fetch
an instance and to trigger instantiation.
Anyway, after poring over the documentation, unit test, and source code,
I'd like to show a sample script that will eventually be used
in my vanity project, with four loggers of increasing granularity.
I realize there are probably more ways to do this (logging seemingly
sporting perl-esque flexibility so please weigh in with thoughts.
Perhaps now I can go back and get this to work with the
logging.config interface.
Best,
Chris

#----begin log_test.py------------------
import logging

#Set up a hierarchy such that we have:
#root - everything, including function arguments
#`trunk - function calls
# `branch - application state
# `leaf - externally visible actions

forest = ["root","trunk","branch","leaf"]
#relate our logger names to levels
lumber_jack = {forest[0] : logging.DEBUG
,forest[1] : logging.INFO
,forest[2] : logging.WARNING
,forest[3] : logging.ERROR }
#Used to build up the log names into a hierarchy
log_name = []

for log in forest:
mounty = logging.FileHandler("%s%s.txt" % ("/home/smitty/mddl/",log))
log_name.append(log)
print "Instantiating %s" % ".".join(log_name)
timber = logging.getLogger(".".join(log_name))
timber.setLevel(lumber_jack[log])
timber.addHandler(mounty)
if lumber_jack[log] == logging.DEBUG:
timber.debug( "%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.INFO:
timber.info( "%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.WARNING:
timber.warning("%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.ERROR:
timber.error( "%s's a lumberjack, and he's OK." % log)

#Force a logging event from the handler for the current logger.
# This hanlder event short-circuits the up-stream propogation
# of the log record, as seen in the file outputs.
mounty.emit( logging.LogRecord( timber
, 0
, "/mnt/dmz/proj/mddl4/mddl.py"
, 37
, "burp?"
, None
, None ))

#----end log_test.py------------------

#--------
#output:
#--------
Instantiating root
Instantiating root.trunk
Instantiating root.trunk.branch
Instantiating root.trunk.branch.leaf

#-------
#The four files:
#-------
$cat root.txt
root's a lumberjack, and he's OK.
burp?
trunk's a lumberjack, and he's OK.
branch's a lumberjack, and he's OK.
leaf's a lumberjack, and he's OK.

$cat trunk.txt
trunk's a lumberjack, and he's OK.
burp?
branch's a lumberjack, and he's OK.
leaf's a lumberjack, and he's OK.

$cat branch.txt
branch's a lumberjack, and he's OK.
burp?
leaf's a lumberjack, and he's OK.

$cat leaf.txt
leaf's a lumberjack, and he's OK.
burp?

 

[Diez B. Roggisch]

Hola, pythonisas:
The documentation for the logging module is good, but a bit obscure.
In particular, there seems to be a lot of action at a distance.
The fact that getLogger() can actually be a call to Logger.__init__(),
which is mentioned in para 6.29.1, also bears stressing on 6.29. I
grasp _why_ you'd implement it that way, but I may not be the only
coder who feels queasy with the word 'get' being used both to fetch
an instance and to trigger instantiation.

The reason for this "distance" is simply that you should be able to get
a grip on a logger from wherever you are, explicitly _without_ first
having to instantiate it and possibly pass it around. Think of this
little example:

class Mixin(object):
def foo(self):
logger = logging.getLogger("MixinLogger")
logger.debug("I'm foo!")

def bar(self):
logger = logging.getLogger("MixinLogger")
logger.debug("I'm bar!")

class User(Mixin):

def some_random_method(self):
if relative_moon_humidity() > .8:
self.foo()
else:
self.bar()


So the decoupling makes lots of sense in logging IMHO.

Anyway, after poring over the documentation, unit test, and source code,
I'd like to show a sample script that will eventually be used
in my vanity project, with four loggers of increasing granularity.
I realize there are probably more ways to do this (logging seemingly
sporting perl-esque flexibility so please weigh in with thoughts.
Perhaps now I can go back and get this to work with the
logging.config interface.

forest = ["root","trunk","branch","leaf"]
#relate our logger names to levels
lumber_jack = {forest[0] : logging.DEBUG
,forest[1] : logging.INFO
,forest[2] : logging.WARNING
,forest[3] : logging.ERROR }
#Used to build up the log names into a hierarchy
log_name = []

for log in forest:
mounty = logging.FileHandler("%s%s.txt" % ("/home/smitty/mddl/",log))
log_name.append(log)
print "Instantiating %s" % ".".join(log_name)
timber = logging.getLogger(".".join(log_name))
timber.setLevel(lumber_jack[log])
timber.addHandler(mounty)
if lumber_jack[log] == logging.DEBUG:
timber.debug( "%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.INFO:
timber.info( "%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.WARNING:
timber.warning("%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.ERROR:

That looks as an misunderstanding or somewhat strange usage of the
logging-api. It is _very_ uncommon to have loggers level depending on
_data_. Instead you just invoke

logger.debug(some_data)

and set the level elsewhere. That is a somewhat static rleationship -
all forests are supposed to share _one_ logging instance, with it's
current log-level. And you don't check for the level being DEBUG or
whatever. You just log, and if the level is above (or below, whatever
stance you take) the currently set level for that logger, the message
gets displayed.

All in all it seems that you have some difficulties with the loggers
being a sort of global objects. Keep that in mind when developing using
them.

Regards,

Diez

 

[Chris Smith]

Diez> The reason for this "distance" is simply that you should be
Diez> able to get a grip on a logger from wherever you are,
Diez> explicitly _without_ first having to instantiate it and
Diez> possibly pass it around. Think of this little example:

[snip]

Diez> So the decoupling makes lots of sense in logging IMHO.

Absolutely. The fact that it does eventually make sense, however, doesn't
preclude a bout of confusion at the fact that some_lager didn't
already exist before

pint = logging.getLogger( some_lager )

and that the logging module will merrily brew some_lager on the spot.
I submit that the documentation might be improved by including your
example on 6.29, gearing the neophyte up for how this (can we agree it
operates on slightly different principles than most?) module operates.


[snip]

Diez> That looks as an misunderstanding or somewhat strange usage
Diez> of the logging-api. It is _very_ uncommon to have loggers
Diez> level depending on _data_. Instead you just invoke

Diez> logger.debug(some_data)

Diez> and set the level elsewhere. That is a somewhat static
Diez> releationship - all forests are supposed to share _one_
Diez> logging instance, with it's current log-level. And you don't
Diez> check for the level being DEBUG or whatever. You just log,
Diez> and if the level is above (or below, whatever stance you
Diez> take) the currently set level for that logger, the message
Diez> gets displayed.

My use-case is a desire to interpret an input file, and log traces at
varying output depth. I used the default labels, just to keep the
sample script small. However, I will (once I have grokked
that corner of the module more fully) follow your advice there, for
I'm really only talking about four densities of debug information.
Thank you for this feedback.

Diez> All in all it seems that you have some difficulties with the
Diez> loggers being a sort of global objects. Keep that in mind
Diez> when developing using them.

Yep, got to play the tune sloppy a few times before it's tight.
Nochmals vielen Dank.
Chris

 

[Chris Smith]

One thing that made little sense to me when I was first working on
this is the following variation on the original script:

#--begin test script--
import logging

forest = ["root","trunk","branch","leaf"]
lumber_jack = {forest[0] : logging.DEBUG
,forest[1] : logging.INFO
,forest[2] : logging.WARNING
,forest[3] : logging.ERROR }
log_name = []
for log in forest:
mounty = logging.FileHandler("%s%s.txt" % ("/home/smitty/mddl/",log))
log_name.append(log)
print "Instantiating %s" % ".".join(log_name)
timber = logging.getLogger(".".join(log_name))

#Comment out explit setting of level for logger
#timber.setLevel(lumber_jack[log])

#Commented out totally, called without argument, or called with
# logging.NOTSET all produce same output

#timber.setLevel(logging.NOTSET)
timber.addHandler(mounty)
if lumber_jack[log] == logging.DEBUG:
timber.debug( "%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.INFO:
timber.info( "%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.WARNING:
timber.warning("%s's a lumberjack, and he's OK." % log)
elif lumber_jack[log] == logging.ERROR:
timber.error( "%s's a lumberjack, and he's OK." % log)
mounty.emit( logging.LogRecord( timber
, 0
, "/mnt/dmz/proj/mddl4/mddl.py"
, 37
, "burp?"
, None
, None ))
#--end test script--

#---
#expected output
#---
$ cat root.txt
root's a lumberjack, and he's OK.
burp?
trunk's a lumberjack, and he's OK.
branch's a lumberjack, and he's OK.
leaf's a lumberjack, and he's OK.
$ cat trunk.txt
trunk's a lumberjack, and he's OK.
burp?
branch's a lumberjack, and he's OK.
leaf's a lumberjack, and he's OK.
$ cat branch.txt
branch's a lumberjack, and he's OK.
burp?
leaf's a lumberjack, and he's OK.
$ cat leaf.txt
leaf's a lumberjack, and he's OK.
burp?


#---
#actual output
#---
$ cat root.txt
burp?
branch's a lumberjack, and he's OK.
leaf's a lumberjack, and he's OK.
$ cat trunk.txt
burp?
branch's a lumberjack, and he's OK.
leaf's a lumberjack, and he's OK.
$ cat branch.txt
branch's a lumberjack, and he's OK.
burp?
leaf's a lumberjack, and he's OK.
$ cat leaf.txt
leaf's a lumberjack, and he's OK.
burp?


#-------
At any rate, I see now that I want to use logging.setLevel() to lay
in my own, more descriptive, levels, and then the straight
logging.log() function to do that for me.
Ah, the learning curve.
Best,
Chris