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 (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!?"))); 7 2279
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
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
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!?")));
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
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
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 (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!?")));
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 This discussion thread is closed Replies have been disabled for this discussion. Similar topics
5 posts
views
Thread by Ravi Shankar |
last post: by
|
reply
views
Thread by Tero Saarni |
last post: by
|
4 posts
views
Thread by Stanley Cheung |
last post: by
|
6 posts
views
Thread by Corinne |
last post: by
|
3 posts
views
Thread by Udi |
last post: by
|
reply
views
Thread by rshekhtm |
last post: by
|
5 posts
views
Thread by Shiao |
last post: by
| |
17 posts
views
Thread by Cramer |
last post: by
| | | | | | | | | | |