This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: logging: need a way to discard Logger objects
Type: enhancement Stage:
Components: Library (Lib) Versions: Python 2.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: fdrake, georg.brandl, pitrou, tim.peters, vinay.sajip
Priority: normal Keywords:

Created on 2004-04-09 21:51 by fdrake, last changed 2022-04-11 14:56 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
logadapter.py fdrake, 2004-06-24 14:06 adapter class; shows what's tedious
Messages (26)
msg20460 - (view) Author: Fred Drake (fdrake) (Python committer) Date: 2004-04-09 21:51
There needs to be a way to tell the logging package
that an application is done with a particular logger
object.  This is important for long-running processes
that want to use a logger to represent a related set of
activities over a relatively short period of time
(compared to the life of the process).

This is useful to allow creating per-connection loggers
for internet servers, for example.  Using a
connection-specific logger allows the application to
provide an identifier for the session that can be
automatically included in the logs without having the
application encode it into each message (a far more
error prone approach).
msg20461 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2004-05-08 19:28
Logged In: YES 
user_id=308438

The problem with disposing of Logger objects 
programmatically is that you don't know who is referencing 
them. How about the following approach? I'm making no 
assumptions about the actual connection classes used; if you 
need to make it even less error prone, you can create 
delegating methods in the server class which do the 
appropriate wrapping.

class ConnectionWrapper:
	def __init__(self, conn):
		self.conn = conn
		
	def message(self, msg):
		return "[connection: %s]: %s" % 
(self.conn, msg)
		
		
and then use this like so...

class Server:

	def get_connection(self, request):
		# return the connection for this request
		
	def handle_request(self, request):
		conn = self.get_connection(request)
		# we use a cache of connection wrappers
		if conn in self.conn_cache:
			cw = self.conn_cache[conn]
		else:
			cw = ConnectionWrapper(conn)
			self.conn_cache[conn] = cw
		#process request, and if events need to 
be logged, you can e.g.
		logger.debug(cw.message("Network packet 
truncated at %d bytes"), n)
		#The logged message will contain the 
connection ID
msg20462 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2004-06-09 09:28
Logged In: YES 
user_id=308438

Fred, any more thoughts on this? Thanks, Vinay
msg20463 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2004-06-09 16:01
Logged In: YES 
user_id=31435

Assigned to Fred, because Vinay wants his input (in general, 
a bug should be assigned to the next person who needs 
to "do something" about it, and that can change over time).
msg20464 - (view) Author: Fred Drake (fdrake) (Python committer) Date: 2004-06-10 16:50
Logged In: YES 
user_id=3066

Sorry for the delay in following up.

I'll re-visit the software where I wanted this to see how
it'll work out in practice.
msg20465 - (view) Author: Fred Drake (fdrake) (Python committer) Date: 2004-06-24 04:13
Logged In: YES 
user_id=3066

Looking at this again, after adjusting the application I
have that used the connection-specific loggers, I decided
that a different approach better solves the problem.

What you've shown requires exactly what I wanted to avoid:
having to make a gesture at each logging call (to transform
the message).  Instead of doing this, I ended up writing a
wrapper for the logger objects that implement the methods
log(), debug(), info(), warn(), warning(), error(),
exception(), critical(), and fatal().  These methods each
transform the message before calling the underlying logger.

It would be really nice to have something like this that
isolates the final call to Logger._log() so specific
implementations can simply override _log() (or some other
helper routine that gets all the info) and maybe the
__init__().  I don't think that's completely necessary, but
would probably make it a lot easier to implement this pattern.

There's probably some useful documentation improvements that
could be made to help people avoid the issue of leaking loggers.
msg20466 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2004-06-24 10:58
Logged In: YES 
user_id=308438

How about if I add a LoggerAdapter class which takes a 
logger in the __init__ and has logging methods debug(), info() 
etc. [and including _log()] which delegate to the underlying 
logger? Then you could subclass the Adapter and just 
override the methods you needed. Would that fit the bill? Of 
course the package can use a Logger-derived class, but this 
would apply to all loggers where the LoggerAdapter could be 
used for just some of the loggers in a system.
msg20467 - (view) Author: Fred Drake (fdrake) (Python committer) Date: 2004-06-24 14:06
Logged In: YES 
user_id=3066

I've attached a file showing the class I came up with.  I
don't consider this to be a good wrapper, just what worked.

I think one of the problems is that what I really want to
override is the makeRecord() method, not the logging methods
themselves.  There's too much logic in those dealing with
the disabling and level filtering that I don't want to
duplicate, but as soon as I pass the calls on to the
underlying logger, I can no longer change the makeRecord().

It would be possible to inject a new makeRecord() while my
methods are active (in my definition for log() in the
sample), and restore the original in a finally clause, but
that feels... icky.

The advantage of overriding makeRecord() is that formatter
can deal with with how the additional information is added
to the log because more information is made available on the
record.
msg20468 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2004-06-24 15:28
Logged In: YES 
user_id=308438

Suppose I add a callable "recordMaker" to logging, and modify 
makeRecord() to call it with logger + the args passed to 
makeRecord(). If it's necessary to add extra attrs to the 
LogRecord, this can be done by replacing recordMaker with 
your own callable. Seems less icky - what do you think? If 
you think it'll fly, are there any other args you think I need to 
pass into the callable?
msg20469 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2004-06-29 22:10
Logged In: YES 
user_id=308438

I just had a further thought: is the approach below any good 
to you? Apart from not being able to use the root logger, it 
seems to meet your need.

import logging

class MyLogger(logging.Logger):
  def makeRecord(self, name, level, fn, lno, msg, args, 
exc_info):
    record = logging.Logger.makeRecord(self, name, level, fn, 
lno, msg, args, exc_info)
    record.magicnumber = 0xDECAFBAD    # special number
    return record

logging._loggerClass = MyLogger

h = logging.StreamHandler()
logger = logging.getLogger("mylogger")
h.setFormatter(logging.Formatter("%(asctime)s %(levelname)
s %(magicnumber)X %(message)s"))
logger.addHandler(h)
logger.warn("There's a custom attribute in my message!")
msg20470 - (view) Author: Fred Drake (fdrake) (Python committer) Date: 2004-07-01 03:53
Logged In: YES 
user_id=3066

Vinay:  I don't think that will work.  Another issue that
crops up once I start looking into the Logger class is that
findCaller() won't do (what I think is) the Right Thing when
wrappers and subclasses are involved.

After reviewing my application, I think the only thing the
application really needs to control is the creation of the
record objects, but that has to happen on the wrapper, or
there's no way to get the necessary information into the
record (without seriously performing surgery on the
underlying logger).

I think I've come up with a base class that does the Right
Thing, but I need to write up an explanation of why it works
the way it does.  It's not massively mysterious, but does
end up dealing with more than I really like worrying about.
 I don't have any more time for this tonight, but will write
up what I have and post it here in the next few days.

It shouldn't be hard to refactor what's in logging.Logger
and my base class to share most of the code.  Having the
base class in the logging package would avoid having to use
a separate findCaller() implementation.

Boosting the priority to make sure this stays on my radar.
msg20471 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2004-09-22 13:43
Logged In: YES 
user_id=308438

Hi Fred,

Any update on this? If you haven't the time (which I quite
understand), please post the code which does the Right Thing
(or mail it to me) without an explanation, and I'll try to
understand it.
msg20472 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2005-03-17 10:53
Logged In: YES 
user_id=308438

Hi Fred,

Any update on this? If you haven't the time (which I quite
understand), please post the code which does the Right Thing
(or mail it to me) without an explanation, and I'll try to
understand it.
msg59305 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2008-01-05 19:17
This could probably be solved with an optional argument to getLogger()
and a weakref. Do you want me to write a patch?
msg59352 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2008-01-06 10:39
There's probably no need. Fred's initial reason for wanting this (usage
of connection-specific loggers, which would be an anti-pattern in my
book) was later solved by him using an application-specific wrapper.
Also, changes made to logging after this issue was created make it
easier to include context information (e.g. connection IDs) in logging
calls.

So: I don't think it is good behaviour for any application to create a
large (=> potentially unbounded) set of loggers. The number of loggers
created should be dependent on the granularity of logging which the
application developer wants to use. If this approach is followed, the
number of loggers is unlikely to lead to memory hogging by the logging
package. So, I propose to close this ticket now, but anyone can of
course reopen it if they think there is still an issue here which needs
addressing.

I will review the docs to see if I need to clarify that loggers should
not be created on a per-connection (or analogous) basis.
msg59365 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2008-01-06 12:48
Well, I have met this problem too some time ago, so could you please
reopen the bug?

Saying creating a lot of connection-bound logger objects is an
"antipattern" doesn't help. It's the only simple way of doing something
useful: have a logging target with different messages based on IP
address (or whatever else, e.g. user name).

Also, when you say "changes made to logging after this issue was created
make it easier to include context information (e.g. connection IDs) in
logging calls", that doesn't address the problem, because you have to
include that "context information" in every logging class while what you
really want to do is to include it once in the call to getLogger()...
msg59367 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2008-01-06 12:51
s/in every logging class/in every logging call/, sorry.
msg59372 - (view) Author: Georg Brandl (georg.brandl) * (Python committer) Date: 2008-01-06 14:14
Reopening.
msg59444 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2008-01-07 14:06
Antoine, I take your point, but there are a number of ways of doing what
you want, apart from the "extra" context argument:

1. Use your own logger classes which do what you want. It's probably
best to make this a wrapper class so you can define different ones for
different needs.
2. Use a non-string as your message. The "message" object passed to
logging can be any object - str() is called on this to get the actual
message.
3. You can use custom Formatter and/or Filter objects to manipulate the
logged message and/or LogRecord instances.

You could pass context information in a number of different ways, but
using a threadlocal might be convenient where the platform supports it.

Any of these approaches should work, and there should be no need to have
a pattern where lots of logging.Logger instances need to be created just
to output context information.
msg59446 - (view) Author: Fred Drake (fdrake) (Python committer) Date: 2008-01-07 14:31
Ideally, it would be best if loggers didn't live forever behind the
scenes if they have no non-default configuration, but documenting their
long-lived nature and the recommended alternate ways to deal with
getting additional context information into the results.
msg59481 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2008-01-07 19:12
Hi Vinay,

Thanks for your reply.

I think it's important to rephrase the problem in a simple way. The
basic pattern is that there is a class C (say, a TCP connection class)
where a specific part of each log line should from an instance-specific
"contextual string" (say, an IP address). Given the current logging API,
this means each instance of C will want either a separate Logger object,
or a separate Formatter object, or a separate LogRecord subclass, etc.

Now the problem is:
1. creating a separate Logger object per instance of C leads to memory leaks
2. creating a separate Formatter, Filter etc. does not work because the
shared logger (whatever it is) has no means to decide which Formatter or
Filter instance it should use depending on the caller (perhaps I'm wrong
about this one? explanations welcome :-))
3. creating thread-local objects (e.g. Formatters), not only is a quite
ugly solution IMO, but it doesn't suit every situation. For example, if
you use an event loop (asyncore, Twisted), all objects will live in the
same thread yet require distinct Formatters.

So the only mildly satisfying solution right now is:
4. create a specific Logger class wrapper which will require the caller
to pass its "contextual string" to them so that the wrapper has the
appropriate context information. This does almost the right thing
(except for one supplementary parameter for each logging call), but is
still a bit of code to type and get right.

Now to make it easier for the developer I see two solutions:
  A. enhance the logging module with an API to create non-persistent
loggers. That's what I was originally proposing to work on.
  B. provide a generic implementation of the afore-mentioned wrapper
(see solution 4), ready to use for the most common purposes. Basically,
the generic wrapper would be instantiated with a pattern (say :
"1.2.3.4: %(msg)s") which would be used to modify the msg for each
logger call

I'd be willing to implement either of those two solutions, depending on
which we decide is better :-) What do you think?
msg59499 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2008-01-07 21:46
Ok, but let's continue the discussion on comp.lang.python, as this is
probably not the best place for an extended discussion. I'll post there
soon with a proposal.
msg59500 - (view) Author: Fred Drake (fdrake) (Python committer) Date: 2008-01-07 21:52
Please be sure to post a link to the thread here, as not everyone here
reads comp.lang.python.
msg59506 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2008-01-07 23:18
I don't follow comp.lang.python either, so I'd be grateful if you give a
link to the gmane thread ;)

I hope we can find an useful solution to this limitation, logging is a
very important task and the stdlib should satisfy all common wishes IMO.
msg59527 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2008-01-08 09:24
I've posted a proposal to python-list: you can view via

http://groups.google.co.uk/group/comp.lang.python/browse_frm/thread/336eb031c85758fa

or 

http://article.gmane.org/gmane.comp.python.general/553877
msg60097 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2008-01-18 15:58
LoggerAdapter class added to trunk. Documentation also updated.
History
Date User Action Args
2022-04-11 14:56:03adminsetgithub: 40133
2008-01-18 15:58:16vinay.sajipsetstatus: open -> closed
resolution: fixed
messages: + msg60097
2008-01-08 09:24:14vinay.sajipsetmessages: + msg59527
2008-01-07 23:18:55pitrousetmessages: + msg59506
2008-01-07 21:52:26fdrakesetmessages: + msg59500
2008-01-07 21:46:25vinay.sajipsetmessages: + msg59499
2008-01-07 19:12:03pitrousetmessages: + msg59481
2008-01-07 14:31:28fdrakesetmessages: + msg59446
2008-01-07 14:08:12vinay.sajipsetpriority: high -> normal
2008-01-07 14:06:29vinay.sajipsetmessages: + msg59444
2008-01-06 14:14:05georg.brandlsetstatus: closed -> open
assignee: fdrake -> vinay.sajip
resolution: out of date -> (no value)
messages: + msg59372
nosy: + georg.brandl
2008-01-06 12:51:24pitrousetmessages: + msg59367
2008-01-06 12:48:36pitrousetmessages: + msg59365
2008-01-06 10:39:17vinay.sajipsetstatus: open -> closed
resolution: out of date
messages: + msg59352
2008-01-05 19:17:46pitrousetnosy: + pitrou
messages: + msg59305
2008-01-04 04:42:37christian.heimessetversions: + Python 2.6
2004-04-09 21:51:40fdrakecreate