logging producing redundant entries

[Jed Parsons]

Hi,

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,
j
--
Jed Parsons Industrial Light + Magic [phone]

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

[alex23]

Jed Parsons wrote:

My problem is that, for every event logged, the logger is producing
multiple identical entries with the timestamp the same down to the
millisecond. import logging
# basicConfig for python 2.3
logging.basicConfig() [...] _logger.addHandler(_handler)
I think the problem might be that basicConfig does a lot more than you
seem to be aware:
basicConfig( ) :
Does basic configuration for the logging system by creating a StreamHandler with
a default Formatter and adding it to the root logger. The functions debug(), info(),
warning(), error() and critical() will call basicConfig() automatically if no handlers
are defined for the root logger.

So basicConfig is creating a default handler and you're then adding
another, so two entries for every event.

Hope this helps.

- alex23

[Peter Otten]

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]

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 [phone]

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

[Peter Otten]

Jed Parsons wrote:

Am I somehow accumulating a growing list of loggers by having this code
at the top of a zope Extension?

I'd rather look after the number of handlers which is probably growing and
causing your problem. Normally it shouldn't matter how often you repeat
the logging.getLogger(name) call as long as the name is always the same.
For easier diagnosis you can include the loggername ("%(name)s") in the
message.

Do you maintain a hierarchy of loggers (names with dots) with a handler for
each logger? Then it might help to set the loggers' 'propagate' attribute
to False.

Peter

[Kent Johnson]

Jed Parsons wrote:

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...)
It sounds like Zope is reloading your extension. Each time it is
reloaded you will attach another logger.
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...

No, that won't work if it really is a reload, _logger will never be
defined. Can you put the logging setup somewhere else, in a module that
is only loaded once? Or inspect _logger.handlers to see if it already
contains a FileHandler to your log file, and only add it if it is not
there already.

Kent

[Jed Parsons]

Thanks, Kent and Peter,

Definitely making progress here. I've got propagate = 0, and am testing
for handlers before doing any addHandler business. (The handlers test
seems to make the most difference.)

I'm down to two entries per time now! And prodding Zope to reload the
module doesn't cause the number to increase.

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.

Thanks again for your help. Cheers,
j

Kent Johnson wrote:

Jed Parsons wrote:

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...)

It sounds like Zope is reloading your extension. Each time it is
reloaded you will attach another logger.

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...

No, that won't work if it really is a reload, _logger will never be
defined. Can you put the logging setup somewhere else, in a module that
is only loaded once? Or inspect _logger.handlers to see if it already
contains a FileHandler to your log file, and only add it if it is not
there already.

Kent

--
Jed Parsons Industrial Light + Magic [phone]

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

[Kent Johnson]

Jed Parsons wrote:

Thanks, Kent and Peter,

Definitely making progress here. I've got propagate = 0, and am testing
for handlers before doing any addHandler business. (The handlers test
seems to make the most difference.)

I'm down to two entries per time now! And prodding Zope to reload the
module doesn't cause the number to increase.

Do you have a second module that is setting up the same logging?

Kent