Re: logging producing redundant entries


Thanks, Peter and alex23,

The metalog test shows that the code is only being executed once at a time.

And if I take those lines and put them in a shell script (fixing the FileHandler - sorry about the bad copy there), they work as expected, producing a single log entry.

So I'm left with:

- logging code that works properly in isolation in a shell script
- zope extension code that gets called only once (metalog test)
- logging code produces multiple entries when executed in extension
- logging code seems to produce more and more entries over time

Am I somehow accumulating a growing list of loggers by having this code at the top of a zope Extension? If I cause the extension to be re-evaluated, do I somehow attach another logger? (I'm grasping at straws...)

I've tried the following to only call getLogger once, but it doesn't seem to help:

try:
_logger
except NameError:
_logger = logging.getLogger('login')
etc...

Thanks again for any suggestions. I'm pretty well baffled.
j

Peter Otten wrote:
Jed Parsons wrote:

I'm using the logging module for the first time. I'm using it from
within Zope Extensions.

My problem is that, for every event logged, the logger is producing
multiple identical entries with the timestamp the same down to the
millisecond.

Is this something I'm doing wrong?

Log snippet:

2006-03-30 16:20:14,173 INFO: Login: Jed Parsons
2006-03-30 16:20:14,173 INFO: Login: Jed Parsons
2006-03-30 16:20:14,173 INFO: Login: Jed Parsons
2006-03-30 16:20:14,173 INFO: Login: Jed Parsons
2006-03-30 16:20:14,173 INFO: Login: Jed Parsons
2006-03-30 16:20:14,173 INFO: Login: Jed Parsons
2006-03-30 16:20:14,173 INFO: Login: Jed Parsons
2006-03-30 16:20:14,173 INFO: Login: Jed Parsons

I would like only one of the above lines in my log file; not all those
copies.

I'm using this simple logging setup at the top of a zope Extension module:

import logging
# basicConfig for python 2.3
logging.basicConfig()
_logger = logging.getLogger("login")
_logger.setLevel(logging.DEBUG)
_handler = logging.FileHandler(LOG_ROOT, 'login.log'))
_formatter = logging.Formatter("%(asctime)s %(levelname)s:
%(message)s")
_handler.setFormatter(_formatter)
_logger.addHandler(_handler)

So these are global to the module. The log lines above were produced by
what I expected would be a single call to _logger.info() in a function
in the module:

_logger.info("Login: %s %s" % (firstname, lastname))

Can anyone explain what I'm doing wrong? Many thanks,

Please cut and paste -- the FileHandler arguments are wrong and there is an
extra ')'. As alex23 said, basicConfig() adds a handler, but that logs to
stderr by default. You seem to be executing the code given above multiple
times. You can verify that by prepending your snippet with

f = open("metalog.txt", "a")
f.write("configuring handler\n")
f.close()

If metalog.txt contains multiple lines after your program has terminated
(you may have to shut down Zope -- don't know about that), a quick fix
might be

import logging
if not logging.root.handlers:
# your setup code

Peter

--
Jed Parsons Industrial Light + Magic (415) 746-2974

grep(do{for(ord){(!$_&&print"$s\n")||(($O+=(($_-1)%6+1)and
grep(vec($s,$O++,1)=1,1..int(($_-6*6-1)/6))))}},(split(//,
"++,++2-27,280,481=1-7.1++2,800+++2,8310/1+4131+1++2,80\0. What!?")));
.

Relevant Pages

  • Re: logging producing redundant entries
    ... It's a good thing for Zope to reload modules when you touch them, but I didn't anticipate that this would be a side-effect. ... logging code produces multiple entries when executed in extension ... If I cause the extension to be re-evaluated, do I somehow attach another logger? ...
    (comp.lang.python)
  • Re: logging producing redundant entries
    ... The metalog test shows that the code is only being executed once at a time. ... logging code produces multiple entries when executed in extension ... If I cause the extension to be re-evaluated, do I somehow attach another logger? ...
    (comp.lang.python)