improvements for the logging package

[Rotem]

Hi,

while working on something in my current project I have made several
improvements to the logging package in Python, two of them are worth
mentioning:
1. addition of a logging record field %(function)s, which results in
the name
of the entity which logged the record. My version even deduces the
class name in the case which the logger is a bound method, and assuming
the name of the "self" variable is indeed "self".

This ability can be turned off, for performance reasons, and is useful
for debugging phases.

2. log coloring formatter (useful for console output) - support for log
lines like BLUE<<text>>, etc.

Now, I asked several friends of mine who program in Python often, and
they told me they could use these features very much.

I'm taking a risk here, that maybe someone already proposed this in
this group, but I'll ask either way:
Has anyone thought of posting a PEP about this? Do you think I should?

I have made a great use of the logging package, and would certainly
like to see it evolve and include more features.

[Trent Mick]

[Rotem wrote]

while working on something in my current project I have made several
improvements to the logging package in Python, two of them are worth
mentioning:
1. addition of a logging record field %(function)s, which results in
the name
of the entity which logged the record. My version even deduces the
class name in the case which the logger is a bound method, and assuming
the name of the "self" variable is indeed "self".

This ability can be turned off, for performance reasons, and is useful
for debugging phases.

2. log coloring formatter (useful for console output) - support for log
lines like BLUE<<text>>, etc.

Now, I asked several friends of mine who program in Python often, and
they told me they could use these features very much.

I'm taking a risk here, that maybe someone already proposed this in
this group, but I'll ask either way:
Has anyone thought of posting a PEP about this? Do you think I should?
Cool. Your additions sound useful.
This might be a bit small for a PEP (though I am hardly an authority).
You could post your patch on a new bug on SourceForge.

http://sourceforge.net/tracker/?group_id=5470
I have made a great use of the logging package, and would certainly
like to see it evolve and include more features.

Something to consider that would help to get the logging package more
used would be to write up your experiences with it: write a tutorial or
HOWTO or improvements of the core logging docs. Currently the logging
package looks fairly uninviting/untractable to new users.

Cheers
Trent

--
Trent Mick
Tr****@ActiveSt ate.com

[skip]

while working on something in my current project I have made several
improvements to the logging package in Python, two of them are worth
mentioning:

...
Trent> Cool. Your additions sound useful.

Perhaps so, but the logging module seems like such an unpythonic beast to
me. How about cleaning it up (*) before we add more to it? Stuff like
colorizing seems like it belongs in its own module (presuming a reasonably
general markup scheme can be agreed upon) so it can be used outside the
logging package.

(*) Stuff that seems very odd to me:

- It's a package, but contrary to any other package I've ever seen, most
of its functionality is implemented in __init__.py. __init__.py is
roughly four times larger than the next largest (bsddb, which is a
beast because BerkDB has gotten so big over the years and the
module/package has strived to remain backwards-compatible).

- It's still too hard to use. The obvious 'hello world' example

import logging
logging.info('h ello world')

ought to just work (implicitly add a stream handler connected to
stderr to the root logger).

- Its functionality is partitioned in sometimes odd ways. For example,
it has a handlers module, but what I presume would be the most
commonly used handler (StreamHandler) is not defined there. It's in
(you have three guesses and the first two don't count) __init__.py
instead of in logging.handler s. Consequently, browsing in the obvious
way fails to find the StreamHandler class.

- It doesn't use PEP 8 style as far as naming is concerned, instead
doing some sort of Java or C++ or Perl camelCase thing. Eschewing PEP
8 is fine for other stuff, but code in the Python core (especially new
code like the logging module) should strive to adhere to PEP 8, since
many people will use the core code as a pattern for their own code.

Skip

[Trent Mick]

[sk**@pobox.com wrote]

Perhaps so, but the logging module seems like such an unpythonic beast to
me. How about cleaning it up (*) before we add more to it?
Yes. I was also trying to encourage Rotem to get involved in other parts
of the logging module/package later on in my email. :)
Stuff like colorizing seems like it belongs in its own module
(presuming a reasonably general markup scheme can be agreed upon) so
it can be used outside the logging package.
Yah, you are probably right. Most additions to the logging system could
easily live as their own separate pieces.
(*) Stuff that seems very odd to me:

- It's a package, but contrary to any other package I've ever seen, most
of its functionality is implemented in __init__.py. __init__.py is
roughly four times larger than the next largest (bsddb, which is a
beast because BerkDB has gotten so big over the years and the
module/package has strived to remain backwards-compatible).
I'm not defending the implementation, but does this cause any particular
problems?

The obvious 'hello world' example

import logging
logging.info('h ello world')

ought to just work (implicitly add a stream handler connected to
stderr to the root logger).
Maybe. Unless that causes troubles for real use. Having lazy
configuration like this means that it can be a subtle thing for
top-level application code to setup the proper logging configuration.

I cringe a little bit when I see this presented as the "hello world"
example. My basic hello world tends to be:

import logging
log = logging.getLogg er("name-of-my-module-or-script")

# use log.{debug|info |warn|error}() in module/script...
#...

if __name__ == "__main__":
logging.basicCo nfig()
#...

and then I wish again that the default output were a bit nicer for my
most common usage -- which is logging to the command line in scripts --
rather than looking more like to web server error/access logs.

I think the usability of the logging module could be much improved with
a nicer introduction to it (i.e. docs). It's not really a "hello world"
type of tool. Its usefulness only really shows in larger use cases.

- Its functionality is partitioned in sometimes odd ways. For example,
it has a handlers module, but what I presume would be the most
commonly used handler (StreamHandler) is not defined there. It's in
(you have three guesses and the first two don't count) __init__.py
instead of in logging.handler s. Consequently, browsing in the obvious
way fails to find the StreamHandler class.

- It doesn't use PEP 8 style as far as naming is concerned, instead
doing some sort of Java or C++ or Perl camelCase thing. Eschewing PEP
8 is fine for other stuff, but code in the Python core (especially new
code like the logging module) should strive to adhere to PEP 8, since
many people will use the core code as a pattern for their own code.

Perhaps Vijay (who did all the implementation) can comment on these.
Unfortunately backwards-compat might restrict some cleanups to the
package, but perhaps not too much. I did a poor job of keeping up with
the package after I laid out an initial design, er copied an initial
design from Java's log4j package (and I'm not even a Java guy). :(

Trent

--
Trent Mick
Tr****@ActiveSt ate.com

[Grig Gheorghiu]

I recommend py.log (part of the py lib) as an example of a pythonic
implementation of logging. It uses a keyword-based mechanism and it
distinguishes between "producers" of log messages (i.e. your app) and
"consumers" of log messages (i.e. stdout, stderr, a database, a mail
server, etc.)

You can do things like:

import py
py.log.default( 'hello world') [default] hello world log = py.log.Producer ("myapp")
log.info('hello again') [myapp:info] hello again log.hello('agai n')

[myapp:hello] again

See
<http://agiletesting.bl ogspot.com/2005/06/keyword-based-logging-with-py-library.html>
for more details.

Grig

[skip]

- It's a package, but contrary to any other package I've ever seen,
most of its functionality is implemented in __init__.py.
Trent> I'm not defending the implementation, but does this cause any
Trent> particular problems?

No, it just seems symptomatic of some potential organizational problems.
import logging
logging.info('h ello world')

ought to just work (implicitly add a stream handler connected to
stderr to the root logger).
Trent> Maybe. Unless that causes troubles for real use.

Maybe there's a bug then (or maybe the docs still need work). When I
executed (all of these examples were typed at an interactive prompt):

import logging
logging.info('h ello world')

I get no output. Looking at the doc for the basicConfig() function, I see:

The functions debug(), info(), warning(), error() and critical() will
call basicConfig() automatically if no handlers are defined for the root
logger.

If I read that right, my "hello world" example ought to work. I tried:

import logging
logging.getLogg er("main")
logging.info("h ello world")

and

import logging
logging.basicCo nfig()
logging.info("h ello world")

and

import logging
logging.basicCo nfig()
log = logging.getLogg er("main")
log.info("hello world")

Shouldn't one of these have emitted a "hello world" to stderr? (Maybe not.
Maybe I need to explicitly add handlers to non-root loggers.)

Trent> Having lazy configuration like this means that it can be a subtle
Trent> thing for top-level application code to setup the proper logging
Trent> configuration.

Again, based on my reading of the basicConfig doc, it seems like the logging
package is supposed to already do that.

Trent> I think the usability of the logging module could be much
Trent> improved with a nicer introduction to it (i.e. docs). It's not
Trent> really a "hello world" type of tool. Its usefulness only really
Trent> shows in larger use cases.

I agree about the docs. Whatever the "hello world" example is (I clearly
haven't figured it out yet), it ought to be right at the top of the docs.

If logging isn't trivial to use, then many simple apps won't use logging.
Consequently, when they grow, logging has to be retrofitted.
- Its functionality is partitioned in sometimes odd ways. For
example, it has a handlers module, but what I presume would be the
most commonly used handler (StreamHandler) is not defined there.

- It doesn't use PEP 8 style as far as naming is concerned, instead
doing some sort of Java or C++ or Perl camelCase thing.

Trent> Perhaps Vijay (who did all the implementation) can comment on
Trent> these. Unfortunately backwards-compat might restrict some
Trent> cleanups to the package, but perhaps not too much. I did a poor
Trent> job of keeping up with the package after I laid out an initial
Trent> design, er copied an initial design from Java's log4j package
Trent> (and I'm not even a Java guy). :(

It was probably the log4j roots that provided the non-PEP 8 naming. I
suspect the naming could be improved while providing backward compatibility
aliases and deprecating those names.

[Trent Mick]

[sk**@pobox.com wrote]

>> - It's a package, but contrary to any other package I've ever seen,
>> most of its functionality is implemented in __init__.py.
Trent> I'm not defending the implementation, but does this cause any
Trent> particular problems?

No, it just seems symptomatic of some potential organizational problems.
Fair enough. I'm all for having consistent and well structure code in
the stdlib.

>> import logging
>> logging.info('h ello world')
>>
>> ought to just work (implicitly add a stream handler connected to
>> stderr to the root logger).

Trent> Maybe. Unless that causes troubles for real use.

Maybe there's a bug then (or maybe the docs still need work). When I
executed (all of these examples were typed at an interactive prompt):

import logging
logging.info('h ello world')

I get no output. Looking at the doc for the basicConfig() function, I see:

The functions debug(), info(), warning(), error() and critical() will
call basicConfig() automatically if no handlers are defined for the root
logger.

Unfortunately your getting caught by the default logging level being
WARN, so that any log level below that is tossed.

import logging
logging.basicCo nfig()
logging.error(" help!")
logging.warn("s tay away from the river")
logging.info("n ice sunset, eh?")

Running that generates:

ERROR:root:help !
WARNING:root:st ay away from the river
Trent> Having lazy configuration like this means that it can be a subtle
Trent> thing for top-level application code to setup the proper logging
Trent> configuration.

Again, based on my reading of the basicConfig doc, it seems like the logging
package is supposed to already do that.
Sort of. I guess all it implies is that if application code wants
to do special log handler setup then it needs to make sure to work in
the case of basicConfig() having been called and not.

The configuration stuff is quite subtle. The docs need to give
good best practices for a could coverage of reasonable use cases.
Nothing catastrophic will happen with a weird logging configuration --
probably just more log messages that you'd want.

It was probably the log4j roots that provided the non-PEP 8 naming.
Definitely.
I suspect the naming could be improved while providing backward
compatibility aliases and deprecating those names.

Do you mean naming like "makeLogRec ord" etc? I thought PEP 8 said
camelCase (or whatever it is called) was okay?
Trent

--
Trent Mick
Tr****@ActiveSt ate.com

[skip]

Trent> Unfortunately your getting caught by the default logging level
Trent> being WARN, so that any log level below that is tossed.

Ah, okay. I'll pick back through the docs and see what I missed, then maybe
add a description of the minimal steps needed to get going.

I suspect the naming could be improved while providing backward
compatibility aliases and deprecating those names.

Trent> Do you mean naming like "makeLogRec ord" etc?

Yes.

Trent> I thought PEP 8 said camelCase (or whatever it is called) was
Trent> okay?

Hmmm... In the section entitled "Naming Conventions" I see:

Function Names

Function names should be lowercase, possibly with words separated by
underscores to improve readability. mixedCase is allowed only in
contexts where that's already the prevailing style (e.g. threading.py),
to retain backwards compatibility.

Method Names and Instance Variables

The story is largely the same as with functions: in general, use
lowercase with words separated by underscores as necessary to improve
readability.

Since the logging package currently uses mixedCase it would appear it
shouldn't revert to lower_case. I'm thinking it should have probably used
lower_case from the start though. I see no real reason to have maintained
compatibility with log4j. Similarly, I think PyUnit (aka unittest) should
probably have used lower_case method/function names. After all, someone
went to the trouble of PEP-8-ing the module name when PyUnit got sucked into
the core. Why not the internals as well?

I realize I'm playing the devil's advocate here. If a module that's been
stable outside the core for awhile gets sucked into Python's inner orbit,
gratuitous breakage of the existing users' code should be frowned upon,
otherwise people will be hesitant to be early adopters. There's also the
matter of synchronizing multiple versions of the module (outside and inside
the core). Still, a dual naming scheme with the non-PEP-8 names deprecated
should be possible.

In the case of the logging module I'm not sure that applies. If I remember
correctly, it was more-or-less written for inclusion in the core. In that
case it should probably have adhered to PEP 8 from the start. Maybe going
forward we should be more adamant about that when an external module becomes
a candidate for inclusion in the core.

Skip

[Trent Mick]

[sk**@pobox.com wrote]

Trent> I thought PEP 8 said camelCase (or whatever it is called) was
Trent> okay?

Hmmm... In the section entitled "Naming Conventions" I see:

Function Names

Function names should be lowercase, possibly with words separated by
underscores to improve readability. mixedCase is allowed only in
contexts where that's already the prevailing style (e.g. threading.py),
to retain backwards compatibility.

Method Names and Instance Variables

The story is largely the same as with functions: in general, use
lowercase with words separated by underscores as necessary to improve
readability.
I swear that has changed since I last read that. :)
....checking... Guess I haven't read it in about 2 years. This patch:

Sat Mar 20 06:42:29 2004 UTC (17 months, 2 weeks ago) by kbk

Patch 919256
Clarify and standardize the format for names of modules,
functions, methods, and instance variables.

Consistent, I hope, with discussion on python-dev

http://mail.python.org/pipermail/pyt...ch/043257.html

http://mail.python.org/pipermail/pyt...ch/043259.html

Made this change:

http://cvs.sourceforge.net/viewcvs.p...1=1.20&r2=1.21

Function Names

- Plain functions exported by a module can either use the CapWords
- style or lowercase (or lower_case_with _underscores). There is
- no strong preference, but it seems that the CapWords style is
- used for functions that provide major functionality
- (e.g. nstools.WorldOp en()), while lowercase is used more for
- "utility" functions (e.g. pathhack.kos_ro ot()).
+ Function names should be lowercase, possibly with underscores to
+ improve readability. mixedCase is allowed only in contexts where
+ that's already the prevailing style (e.g. threading.py), to retain
+ backwards compatibility.
Since the logging package currently uses mixedCase it would appear it
shouldn't revert to lower_case. I'm thinking it should have probably used
lower_case from the start though. I see no real reason to have maintained
compatibility with log4j. Similarly, I think PyUnit (aka unittest) should
probably have used lower_case method/function names. After all, someone
went to the trouble of PEP-8-ing the module name when PyUnit got sucked into
the core. Why not the internals as well?
Perhaps because of the timing.

If I remember
correctly, it was more-or-less written for inclusion in the core.

Yah. It was added before Guido more clearly stated that he thought
modules should have a successful life outside the core before being
accepted in the stdlib.

Trent

--
Trent Mick
Tr****@ActiveSt ate.com

[Vinay Sajip]

sk**@pobox.com wrote:

Perhaps so, but the logging module seems like such an unpythonic beast to
me. How about cleaning it up (*) before we add more to it? Stuff like
colorizing seems like it belongs in its own module (presuming a reasonably
general markup scheme can be agreed upon) so it can be used outside the
logging package.
How is it unpythonic, exactly? I agree that colorizing, etc. is
probably best located in its own module.
(*) Stuff that seems very odd to me:

- It's a package, but contrary to any other package I've ever seen, most
of its functionality is implemented in __init__.py. __init__.py is
roughly four times larger than the next largest (bsddb, which is a
beast because BerkDB has gotten so big over the years and the
module/package has strived to remain backwards-compatible).
I agree that __init__.py is rather large, but I wasn't aware of any
guidelines restricting its size. Having a smaller __init__.py and e.g.
putting the bulk of the code in a subpackage such as logging.core was
considered; I didn't see the point of doing that, though! And the
module certainly received a reasonable amount of peer review on
python-dev before going into the standard library.
- It's still too hard to use. The obvious 'hello world' example

import logging
logging.info('h ello world')

ought to just work (implicitly add a stream handler connected to
stderr to the root logger).
As Trent pointed out in another post, one extra line with a
basicConfig() call would provide the behaviour that you want. This is
surely not too much to have to add. The default level of WARNING was
deliberately chosen to avoid excessive verbosity in the general case.
- Its functionality is partitioned in sometimes odd ways. For example,
it has a handlers module, but what I presume would be the most
commonly used handler (StreamHandler) is not defined there. It's in
(you have three guesses and the first two don't count) __init__.py
instead of in logging.handler s. Consequently, browsing in the obvious
way fails to find the StreamHandler class.
It's partitioned that way so that the most commonly used handlers are
in the core package, and the less commonly used ones are in the
handlers package. This seems reasonable to me - you don't incur the
footprint of the less common handlers just to do console and file based
logging.
- It doesn't use PEP 8 style as far as naming is concerned, instead
doing some sort of Java or C++ or Perl camelCase thing. Eschewing PEP
8 is fine for other stuff, but code in the Python core (especially new
code like the logging module) should strive to adhere to PEP 8, since
many people will use the core code as a pattern for their own code.

I would not have been too unhappy to change the naming to unix_like
rather than CamelCase. Nobody on python-dev asked for it to be done.
The code was mostly written before the idea of putting it into Python
came up - Trent had independently written PEP-282 and I had done a fair
amount of work on the module before getting the idea that, by adhering
to PEP 282, it could be put forward as an addition to the Python
standard library.

Regards,

Vinay