| msg20460 - (view) |
Author: Fred Drake (fdrake)  |
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) * |
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) * |
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) * |
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) |
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) |
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) * |
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) |
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) * |
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) * |
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) |
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) * |
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) * |
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) * |
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) * |
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) * |
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) * |
Date: 2008-01-06 12:51 |
| s/in every logging class/in every logging call/, sorry. |
|
|
| msg59372 - (view) |
Author: Georg Brandl (georg.brandl) * |
Date: 2008-01-06 14:14 |
| Reopening. |
|
|
| msg59444 - (view) |
Author: Vinay Sajip (vinay.sajip) * |
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) |
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) * |
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) * |
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) |
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) * |
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) * |
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) * |
Date: 2008-01-18 15:58 |
| LoggerAdapter class added to trunk. Documentation also updated. |
|
|