472,782 Members | 1,270 Online
Bytes | Software Development & Data Engineering Community
Post Job

Home Posts Topics Members FAQ

Join Bytes to post your question to a community of 472,782 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 2365
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
by: Rina0 | last post by:
Cybersecurity engineering is a specialized field that focuses on the design, development, and implementation of systems, processes, and technologies that protect against cyber threats and...
3
isladogs
by: isladogs | last post by:
The next Access Europe meeting will be on Wednesday 2 August 2023 starting at 18:00 UK time (6PM UTC+1) and finishing at about 19:15 (7.15PM) The start time is equivalent to 19:00 (7PM) in Central...
0
by: erikbower65 | last post by:
Using CodiumAI's pr-agent is simple and powerful. Follow these steps: 1. Install CodiumAI CLI: Ensure Node.js is installed, then run 'npm install -g codiumai' in the terminal. 2. Connect to...
0
by: kcodez | last post by:
As a H5 game development enthusiast, I recently wrote a very interesting little game - Toy Claw ((http://claw.kjeek.com/))。Here I will summarize and share the development experience here, and hope it...
0
by: Taofi | last post by:
I try to insert a new record but the error message says the number of query names and destination fields are not the same This are my field names ID, Budgeted, Actual, Status and Differences ...
14
DJRhino1175
by: DJRhino1175 | last post by:
When I run this code I get an error, its Run-time error# 424 Object required...This is my first attempt at doing something like this. I test the entire code and it worked until I added this - If...
0
by: Rina0 | last post by:
I am looking for a Python code to find the longest common subsequence of two strings. I found this blog post that describes the length of longest common subsequence problem and provides a solution in...
0
by: lllomh | last post by:
How does React native implement an English player?
0
by: Mushico | last post by:
How to calculate date of retirement from date of birth

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.