473,324 Members | 2,400 Online
Bytes | Software Development & Data Engineering Community
Post Job

Home Posts Topics Members FAQ

Join Bytes to post your question to a community of 473,324 software developers and data experts.

logging producing redundant entries


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!?")));
Mar 31 '06 #1
7 2400
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

Mar 31 '06 #2
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
Mar 31 '06 #3

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!?")));
Mar 31 '06 #4
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
Mar 31 '06 #5
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
Mar 31 '06 #6


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!?")));
Mar 31 '06 #7
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
Apr 1 '06 #8

This thread has been closed and replies have been disabled. Please start a new discussion.

Similar topics

5
by: Ravi Shankar | last post by:
Hi all, I have an enterprise application. I am using Apache Log4J for the logging purposes. WHen a request is received by the application, it goes throug servlets and many classes, and the...
0
by: Tero Saarni | last post by:
I'm using Logging in my library module for producing trace log of certain events. For being more useful these log entries should be associated with the filename and line number of *users* code...
4
by: Stanley Cheung | last post by:
hi all, I want to implement logging for a mailinglist application. the mailinglist will auto send out from a queuing table and user want to know the updated status for how many emails have sent....
6
by: Corinne | last post by:
Over the last year I have designed a database to store information in the school I work in. It has now replaced the commercially produced programme we were using. I should like to market this and...
3
by: Udi | last post by:
Hi All, I'm developping an application that has a very strong logging requirement - we should be able to log up to 5000 messages per second, most of them are reletively small -(16 - 30 Words)...
0
by: rshekhtm | last post by:
Hi everyone, I would like to get your opinion on a technique I came up with when faced with the problem of redundant code in every web method (authentication, logging, exception handling)....
5
by: Shiao | last post by:
Hi, I am getting duplicate log entries with the logging module. The following behaves as expected, leading to one log entry for each logged event: logging.basicConfig(level=logging.DEBUG,...
0
by: alan4cast | last post by:
I'm not a really new programmer, but I'm still working on learning all of the .net things that I should know. So when I came across this one, I started to dig into it so see if I could figure it...
17
by: Cramer | last post by:
I plan to implement an exception logging feature in an ASP.NET Web application that writes encountered exceptions to disk. The exception data will be stored as XML. I am planning on having each...
0
isladogs
by: isladogs | last post by:
The next Access Europe meeting will be on Wednesday 6 Mar 2024 starting at 18:00 UK time (6PM UTC) and finishing at about 19:15 (7.15PM). In this month's session, we are pleased to welcome back...
1
isladogs
by: isladogs | last post by:
The next Access Europe meeting will be on Wednesday 6 Mar 2024 starting at 18:00 UK time (6PM UTC) and finishing at about 19:15 (7.15PM). In this month's session, we are pleased to welcome back...
0
by: Vimpel783 | last post by:
Hello! Guys, I found this code on the Internet, but I need to modify it a little. It works well, the problem is this: Data is sent from only one cell, in this case B5, but it is necessary that data...
0
by: jfyes | last post by:
As a hardware engineer, after seeing that CEIWEI recently released a new tool for Modbus RTU Over TCP/UDP filtering and monitoring, I actively went to its official website to take a look. It turned...
1
by: PapaRatzi | last post by:
Hello, I am teaching myself MS Access forms design and Visual Basic. I've created a table to capture a list of Top 30 singles and forms to capture new entries. The final step is a form (unbound)...
1
by: CloudSolutions | last post by:
Introduction: For many beginners and individual users, requiring a credit card and email registration may pose a barrier when starting to use cloud servers. However, some cloud server providers now...
1
by: Defcon1945 | last post by:
I'm trying to learn Python using Pycharm but import shutil doesn't work
0
by: af34tf | last post by:
Hi Guys, I have a domain whose name is BytesLimited.com, and I want to sell it. Does anyone know about platforms that allow me to list my domain in auction for free. Thank you
0
isladogs
by: isladogs | last post by:
The next Access Europe User Group meeting will be on Wednesday 3 Apr 2024 starting at 18:00 UK time (6PM UTC+1) and finishing by 19:30 (7.30PM). In this session, we are pleased to welcome former...

By using Bytes.com and it's services, you agree to our Privacy Policy and Terms of Use.

To disable or enable advertisements and analytics tracking please visit the manage ads & tracking page.