logging producing redundant entries

[Jed Parsons]

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!?")));