On Wed, 20 Mar 2002 16:16:28 -0500 Guido van Rossum <guido@python.org> wrote:

...

logger.info("A normal exception occurred", exc_info=sys.exc_info())

Or you could have a call logger.exception("message") that knows to call sys.exc_info(). That would reduce the boilerplate.

But how would logger.exception() know what log level to use? Jeremy

On Wed, 20 Mar 2002 22:57:44 -0000 "Vinay Sajip" <vinay_sajip@red-dove.com> wrote:

I have to declare a preference for Mark's and Guido's approach. The reason is - what is a "normal" exception? And if it is "normal", why do we need to see a stack trace for it?

ZEO is a component that lets clients on remote machines access a ZODB storage using a custon Python RMI. (The details aren't exactly important, except that it's a concrete example.) IOW, ZEO + ZODB is a client-server object database. It's possible for all sorts of things to go wrong for an individual RMI. There can be a problem marshalling or unmarshalling the objects. There can be a problem with executing the actual methods on the server. There can be a problem with application code that is executed as a result of calling some method on the server. Etc. Few of these errors are fatal. Some of them may be uninteresting most of the time. So I'd like to log tracebacks and vary the log level depending on the importance of the event that caused the exception. One particular example is a KeyError. The server will raise a KeyError if the client asks for an object that doesn't exist. There are clients that catch this error on the client side and handle it cleanly. It's not an important exception for them. But I'd like to log the traceback on the server to handle cases where the client isn't expecting it. I'd probably log this at debug() level. Most of the time, nobody cares about a KeyError. But it might occasionally be useful when debugging something. Jeremy

On Wed, 20 Mar 2002 23:29:04 -0000

I propose to add an additional method:

def logException(self, level, exc_info, msg, *args)

This should do the trick, I hope. The 0.4 version will include this method.

I really like the shorthands for log levels, e.g. logger.debug() instead of logger.log(DEBUG, ...). So I'd be disappointed if I couldn't use it when I want to log an exception. Jeremy

[Vinay Sajip wrote]

...

ZEO is a component that lets clients on remote machines access a ZODB storage using a custon Python RMI. (The details aren't exactly important, except that it's a concrete example.) Point taken. In my current implementation, there is a generalized logging method in class Logger:

def log(self, level, msg, *args):

I propose to add an additional method:

def logException(self, level, exc_info, msg, *args)

No need to pass in the exc_info if you are already specifying that an exception is being logged via log*Exception*. How about this (just an idea): def info(self, msgOrException, *args): if isinstance(msgOrException, Exception): # format the exception and msg, args = args[0], args[1:] else: # treat it like before try: # ... except Exception, ex: log.info(ex, "Eeeeek!") Trent -- Trent Mick TrentM@ActiveState.com

[Mark Hammond wrote]

[Trent]

...

How about this (just an idea): def info(self, msgOrException, *args): if isinstance(msgOrException, Exception): # format the exception and msg, args = args[0], args[1:] else: # treat it like before

try: # ... except Exception, ex: log.info(ex, "Eeeeek!")

I don't like this. I think it rare you will want to log an exception with no contextual message.

But you still *can* log contextual information. What I meant and should have shown is: def info(self, firstarg, *args): if isinstance(firstarg, Exception): exc = firstarg msg, args = args[0], args[1:] else: exc = None msg, args = firstarg, args # ... (if exc is not None then format the exception and append to # msg%args try: # ... except Exception, ex: log.info(ex, "Eeeeek! %s %s %s", var1, var2, var3) basically this log() implementation is just trying to do: def log(self, exception, msg, *args): #... def log(self, msg, *args): #... ...in a language that does not support method overloading. Kinda klugdy? Maybe, though I would rather have: def exception(self, msg, *args, *kwargs): if not kwargs.has_key("level"): level = logging.ERROR else: level = kwargs["level"] #... than: def debugException(...) def infoException(...) def warnException(...) def errorException(...) def fatalException(...) def logException(...) [Guido on logging an exception at a level other than ERROR]

If this use case is rare enough, maybe a better approach would be to let you format it yourself using the traceback module?

then just have: def exception(self, msg, *args): #... Startin' to sound good to me. Trent -- Trent Mick TrentM@ActiveState.com

...

def logException(self, level, exc_info, msg, *args)

No need to pass in the exc_info if you are already specifying that an exception is being logged via log*Exception*. Yes, except that you are assuming (I think) that logException would call sys.exc_info() to get the exception info. This is fine for most cases, but what about if the exception info needs to come from somewhere else (e.g. from a pickled message sent over the wire)? I haven't yet thought through all the issues about passing tracebacks etc. across sockets...my proposed interface just seemed a little more general.

How about this (just an idea): def info(self, msgOrException, *args): if isinstance(msgOrException, Exception): # format the exception and msg, args = args[0], args[1:] else: # treat it like before

try: # ... except Exception, ex: log.info(ex, "Eeeeek!") I have to admit I find these kinds of "special cases" worthy of caution. I'd much rather provide a parallel set of xxxException() methods - I think they would result in less "gotcha"s for the occasional (or inexperienced) user. Plus - at some point we are going to have to think about performance - and then we may regret overcomplicating the usual case code path for less common scenarios.

Regards Vinay

[Trent]

try: ... except: log.exception("My britches are burning!")

sure is a log nicer than

try: ... except: log.logException(sys.exc_info(), "My britches are burning!")

But you don't need to use the latter. For logging exceptions with a level of ERROR, the former construction works. For the case where you want to log an exception with (e.g.) a DEBUG level, then you would say log.logException(DEBUG, sys.exc_info(), "My britches are burning!") A little long-winded, perhaps, but not *that* bad. It has the benefit of making it clear that even though it's a DEBUG level call, exception info is to be sent to the log. Even in Jeremy's example of ZODB/ZEO, I would imagine that the number of instances where you need to make the second kind of logging call are relatively (i.e. proportionately) few - from his explanation I infer that he was talking about "catch-all" exception handlers which are usually at the higher levels of an application. Anyway, to change the subject a bit, what are your thoughts on configuration? As this is the area where the PEP and the present implementation are both a little weak, I'd like to know more about your ideas... Regards Vinay

[Jeremy Hylton wrote]

It seems quite plausible to decide to log an exception and then get another trivial exception raised and caught on the way to the logger. You would still want to log the original exception, so passing it explicitly is helpful sometimes.

Yes, I suppose so.

If I would implement debug() and other helper methods, I'd still like to see it as a keyword argument. I assume the various methods would be connected something like this:

class Logger: def log(self, msg, level, exc=None): "Log msg at level w/ optional traceback for exc."

def debug(self, msg, exc=None): self.log(msg, DEBUG_LEVEL, exc)

def exception(self, msg, exc=None): if exc is None: exc = sys.exc_info() self.log(msg, ERROR_LEVEL, exc)

This doesn't seem complicated or particularly slow.

Yup, I agree. Except it'll look like this: class Logger: def log(self, level, msg, *args, **kwargs): "Log msg at level w/ optional traceback for 'exc' keyword arg." if level < self.getEffectiveLevel(): return # construct LogRecord # pass LogRecord onto appropriate Handlers def debug(self, msg, *args, **kwargs): self.log(DEBUG, msg, *args, **kwargs) def exception(self, msg, *args, **kwargs): if not kwargs.has_key("exc") kwargs["exc"] = sys.exc_info() self.log(ERROR, msg, *args, **kwargs) Jeremy, The methods use 'msg, *args' instead of just 'msg' to avoid string interpolation if the message will not be logged. I think that that is still important to keep, albeit it making the 'exc' keyword argument less explicit. Vinay, Here is why I really like this idea now. As per usual, any log message call has the 'msg, *args' arguments. But, in addition, arbitrary objects can be passed in as keyword arguments. These objects get slapped into the LogRecord's __dict__ and any subsequent Handler and/or Formatter can work with those objects. For example, if I want to log some arbitrarily complex object I can just add it to the log record. On the handling end, I could have a Formatter that knows how to deal with that object. For formatters that *don't* recognize certain objects, a reasonable default like using the pprint module could be used. Granted this isn't as generic as log4j's ObjectRenderer system but it allows the system to grow into that cleanly. Pros: - Jeremy is happy, he can easily log exceptions to specific levels using the nice info(), debug(), etc. routines. - logger.exception("Eeek: %s", arg) is there for easy use - logger.exception("Eeek: %s", arg, exc=sys.exc_info()) is there when one need be explicit about where exc_info comes from. Cons: - The signature ...**kwargs... doesn't make it clear that a special key for exception info will be handled. - This could be construed as too much generality. It may complicate the LogRecord and Formatter in that they have to deal with arbitrary keyword args. (Mind you, I don't think that that needs to be any issue. For a first pass any keyword arg other than 'exc', or whatever it is called, could be ignored.) Trent -- Trent Mick TrentM@ActiveState.com

[Vinay Sajip wrote]

[Trent]

...

Here is why I really like this idea now. As per usual, any log message call has the 'msg, *args' arguments. But, in addition, arbitrary objects can be passed in as keyword arguments. These objects get slapped into the LogRecord's __dict__ and any subsequent Handler and/or Formatter can work with those objects. For example, if I want to log some arbitrarily complex object I can just add it to the log record. On the handling end, I could have a Formatter that knows how to deal with that object. For formatters that *don't* recognize certain objects, a reasonable default like using the pprint module could be used.

I like this. I prefer the name "exc_info" (rather than "exc") for the key, as it is clearer that the result of sys.exc_info(), or equivalent, is being passed.

Agreed. I prefer 'exc_info' too.

How about the following? The kwargs is searched for "exc_info", and if found it is copied to the LogRecord [and removed from kwargs]. The kwargs dict is then bound to a "user_info" attribute of the LogRecord.

There is a potential minefield here - if we are allowing any logging record to be sent by wire to a remote logger, then the "user_info" needs to go too - and what if something in it can't be pickled? Given that it is really important that the logging system is silent except when explicitly asked to do something by a logging call, exceptions caught in the logging system are generally ignored by design. This means that pickling exceptions would not be raised, and I foresee difficulties for developers... The idea of allowing arbitrary objects into the LogRecord is very powerful and has much to commend it, but I think the pickling problem may need to be solved first.

What do you think?

How about pulling out exc_info above, as you described, and then just dumping the rest of the keyword args. No user_info, no mine field. If we come up with a "mine sweeper" later then we can decide to pass on other keywords if it looks reasonable and useful. So effectivly we are just trying to express: def log(self, level, msg, *args, exc_info=None): ... but have to use: def log(self, level, msg, *args, **kwargs): ... # dump anything but kwargs["exc_info"] because the former is a syntax problem. Thoughts? Trent p.s. Vinaj, when do you sleep? :) -- Trent Mick TrentM@ActiveState.com

Vinay Sajip wrote:

There is a potential minefield here - if we are allowing any logging record to be sent by wire to a remote logger, then the "user_info" needs to go too - and what if something in it can't be pickled? Given that it is really important that the logging system is silent except when explicitly asked to do something by a logging call, exceptions caught in the logging system are generally ignored by design. This means that pickling exceptions would not be raised, and I foresee difficulties for developers... The idea of allowing arbitrary objects into the LogRecord is very powerful and has much to commend it, but I think the pickling problem may need to be solved first.

You could have the logging methods return an int/bool, 1 if succesfully logged, 0 on failure. Let the caller decide what to do. You could even return a failure object or None. The failure object would contain (or be) the exception/problem. Neal

This violates the principle that logging should be "set and forget". Having the logger fail silently has, in past experience, caused fewer problems than having to handle errors from the logging system - yet another headache for the developer!

+1. (You could have a meta-logger where errors from the logger go -- e.g. default to stderr.) --Guido van Rossum (home page: http://www.python.org/~guido/)

[Neal Norwitz wrote]

Vinay Sajip wrote:

...

...

You could have the logging methods return an int/bool, 1 if succesfully logged, 0 on failure. Let the caller decide what to do. You could even return a failure object or None. The failure object would contain (or be) the exception/problem. This violates the principle that logging should be "set and forget". Having

[Neal Norwitz] the logger fail silently has, in past experience, caused fewer problems than having to handle errors from the logging system - yet another headache for the developer!

This is my point. It will almost always be ignored...unless the caller really needs to know the information. The logger will fail silently, only an object will be returned (no exception thrown) and the caller can safely ignore it.

You cannot necessarily know if there has been a problem with a logging call by the time the logging call returns. That logging call could be asynchronous. Trent -- Trent Mick TrentM@ActiveState.com

[Jeremy Hylton wrote]

...

...

...

...

...

"VS" == Vinay Sajip <vinay_sajip@red-dove.com> writes:

VS> I like this. I prefer the name "exc_info" (rather than "exc") VS> for the key, as it is clearer that the result of sys.exc_info(), VS> or equivalent, is being passed. How about the following? The VS> kwargs is searched for "exc_info", and if found it is copied to VS> the LogRecord [and removed from kwargs]. The kwargs dict is then VS> bound to a "user_info" attribute of the LogRecord.

Why do you need **kwargs at all? Can't the interface specify the complete set of optional arguments explicitly?

If, as I said, we want to keep the '*args' argument, how do we explicitly specify an 'exc_info' argument? def info(self, msg, *args, exc_info=None): ^------- SyntaxError Trent -- Trent Mick TrentM@ActiveState.com

[Jeremy Hylton wrote]

...

It seems quite plausible to decide to log an exception and then get another trivial exception raised and caught on the way to the logger. You would still want to log the original exception, so passing it explicitly is helpful sometimes.

[Trent]

Yes, I suppose so.

I'd like to call YAGNI on this. Also on the idea of being able to pass an exception to all logging levels. Also on the idea of passing the exc_info in rather than having the logger call sys.exc_info(). Instead, the logger should be subclassable or extensible so that Jeremy can implement this functionality if he really wants it. KISS. --Guido van Rossum (home page: http://www.python.org/~guido/)

[Guido van Rossum wrote]

...

[Jeremy Hylton wrote]

...

It seems quite plausible to decide to log an exception and then get another trivial exception raised and caught on the way to the logger. You would still want to log the original exception, so passing it explicitly is helpful sometimes.

[Trent]

...

Yes, I suppose so.

I'd like to call YAGNI on this. Also on the idea of being able to pass an exception to all logging levels. Also on the idea of passing the exc_info in rather than having the logger call sys.exc_info().

Instead, the logger should be subclassable or extensible so that Jeremy can implement this functionality if he really wants it.

KISS.

Alrigtie. Trent -- Trent Mick TrentM@ActiveState.com

[Jeremy, in response to Guido's YAGNI]

What's the point here? I've presented use cases, and I maintain a large body of ZODB/ZEO code that already uses these features. So it simply doesn't make sense to say "You Ain't Gonna Need It" because I already need it and zLOG already has it.

Okay, we can have our cake and eat it too. (You've gotta love Python.) Suppose the current module interface stays as it is: debug(), info(), warn(), error() and fatal() all take (self, msg, *args) as arguments. exception() has the same arg list but, since it knows it's called in an exception handling context, it passes sys.exc_info() along. Simple, clean interface. Here's log_test10.py, a working example script which shows how easy it is to roll your own logger. # -- log_test10.py --------------------------- import sys import locale locale.setlocale(locale.LC_ALL, '') from logging import * LOG_FORMAT = "%(asctime)s %(level)-5s %(message)s" DATE_FORMAT = "%x %X" class MyLogger(Logger): """ A simple example of a logger extension. """ def debug(self, msg, *args): """ This overridden method passes exception information for DEBUG level calls """ if self.manager.disable >= DEBUG: return if DEBUG >= self.getChainedPriority(): ei = sys.exc_info() if not ei[1]: ei = None self._log(DEBUG, msg, args, ei) del ei def config(): setLoggerClass(MyLogger) basicConfig() getRootLogger().handlers[0].setFormatter(Formatter(LOG_FORMAT, DATE_FORMAT)) def run(): logger = getLogger("mylogger") logger.info("Starting...") logger.debug("Debug message not in exception handler (no traceback)") logger.info("About to throw exception...") try: print "7" + 4 except Exception, e: logger.debug("Debug message inside exception handler (traceback)") logger.info("Done.") shutdown() if __name__ == "__main__": config() run() #-- end of log_test10.py --------------------------- When run, you get... -- output ------------------------- 21/03/02 23:33:04 INFO Starting... 21/03/02 23:33:05 DEBUG Debug message not in exception handler (no traceback) 21/03/02 23:33:05 INFO About to throw exception... 21/03/02 23:33:05 DEBUG Debug message inside exception handler (traceback) Traceback (innermost last): File "log_test10.py", line 45, in run print "7" + 4 TypeError: illegal argument type for built-in operation 21/03/02 23:33:05 INFO Done. -- output ------------------------- I rest my case (I hope...) Regards Vinay

...

...

...

...

"TM" == Trent Mick <trentm@ActiveState.com> writes:

TM> The argument for the former is: TM> (1) KISS and YAGNI I've said my piece for the most part, but this YAGNI stuff bugs me. YAGNI means: Always implement things when you actually need them, never when you just foresee that you need them. [From http://www.xprogramming.com/Practices/PracNotNeed.html] I actually need this feature. If the standard logger doesn't have it, we'll have to extend Zope with a Zope-specific logger that adds the feature. I'm not asking for a feature because I think it might be useful. Rather, I'd think that Kevin and I are offering some real-world experience. We've written or maintain large, production-quality applications that use logging. In Zope, it has been useful to log tracebacks for exceptions at levels other than error. And it has been necessary to pass an exception explicitly because sys.exc_info() would get stomped by a subsequent exception. Now, KISS is different. It may be that the kinds of things that Kevin and I are trying to do are so unusual that no one else will ever do it. By this argument, supporting a few cases from oddball customers makes your code harder to understand and maintain; perhaps other users will find the interface confusing because of the extra features. Jeremy

[Jeremy, on logging tracebacks at any level]

I actually need this feature. If the standard logger doesn't have it, we'll have to extend Zope with a Zope-specific logger that adds the feature. I'm not asking for a feature because I think it might be useful. Let me try and summarise - perhaps only for my own benefit :-)

1. Jeremy would like to be able to send traceback information from a logging call at any level. 2. Guido is not keen on passing in exc_info from client code - the logger should call sys.exc_info() automatically when required. And the "when" is the crux of it... 3. In the context of an exception handler, a developer may want to send different things to different loggers - e.g. #Assume the traceback will provide info on which table, record, etc. caused the problem adminEmailer.exception("A record lock prevented completion. Please deal with the mess.") #We'd like to tell the developers the exact context too, as a diagnostic aid developers.info("Yet another record locking problem was seen. Why oh why?") #No traceback needed for this, it's just for the record (no pun intended) dbstats.info("%-20s %s '%s'", "RECORD LOCK", self.table, self.key) In the first call, the logic of "when" is built into the choice of call. In the other two calls, we'd like to use the same method, but have it behave differently in the two cases. Now, the decision about tracebacks has to be made at *some* point. Let's assume that wherever that decision is made, we can just call the low-level logging method _log(), as defined below: class Logger: ... def _log(self, level, want_traceback, msg, args_tuple): """Low level logging method""" #Do the needful - if want_traceback is true, call sys.exc_info() and log traceback info ... So, the convenience methods become something like: def log(self, level, msg, *args): """For cases where the level needs to be computed by the caller at run time""" if self.enabledFor(level): self._log(level, 0, msg, args) def info(self, msg, *args): if self.enabledFor(INFO): self._log(INFO, 0, msg, args) #and analogously for DEBUG, WARN, ERROR, FATAL and then def exception(self, msg, *args): """Use when handling an exception""" if self.enabledFor(ERROR): self.log(ERROR, 1, msg, args) Now, I hope all would agree that for "normal" use, the interface is fairly minimal and in keeping with XP principles. In fact, some would argue that debug(), info() etc. are redundant - so you can think of them as syntactic sugar. Now to deal with the case of tracebacks at arbitrary levels, I implemented def logException(self, level, msg, *args): """The same as log, except that it sends a 1 to _log for want_traceback""" if self.enabledFor(level): self._log(level, 1, msg, args) But I think we all neglected to see that by implementing exception with one extra argument, the whole controversy goes away. Just remove logException and change exception so that it becomes def exception(self, level, msg, *args): """Use when handling an exception""" if self.enabledFor(level): self.log(level, 1, msg, args) We've effectively renamed logException() as exception(). There's not a lot to choose between logger.exception(INFO, msg, args) and logger.exception(msg, args) If people can't stomach having to put the level into every call to exception, then we can keep exception as it was [syntactic sugar] and reintroduce logException (perhaps change the name, it's a bit of a sore thumb). If any more syntactic sugar is wanted, then I think it's reasonable for people to roll their own classes. For example, some users want to use their own levels, no doubt for their own good reasons. The current implementation supports this. They can use log() and logException(), but debug(), info(), warn(), error(), fatal() and exception() are useless to them - and so exposed as the syntactic sugar they really are. So if users really want, they can define a level BAD_HAIR_DAY and a corresponding sugar method bad_hair_day(self, msg, *args) which calls either log() or logException(), as they please. It's not a job for the standard module, I'm sure all would agree. [Slightly OT] The above issues have generated an awful lot of discussion, and perhaps rightly so, but I'm conscious of time slipping by. I'd certainly like logging to make it into 2.3a1, and there are a lot of other, more important functional issues (such as: configurability) which need your thoughts and ideas. Can I make a plea for input in this area? I know that Python-dev people are busy people, so I don't know how many of you have had time to actually try out the implementation, but I think it would help the cause of PEP 282 if they gave specific feedback in other areas? For example: Packaging: I originally implemented it as a package with separate modules for logger, handler etc. and then consolidated into one module. I think one module is better, except for the specific handlers - they don't all need to be in the standard module. Perhaps MemoryHandler, StreamHandler and FileHandler. But others such as SysLogHandler, NTEventLogHandler, SMTPHandler, and perhaps even SocketHandler and DatagramHandler - should they be in the same module, or should they perhaps go into a separate "loghandlers" module which is also part of Python? Specific handler implementations: what improvements could be made? [Even more OT - for Monty Python fans] You know, it's really surprising that Python hasn't had a logging module before, especially given the "Lumberjack" song. I even thought of calling the package "Lumberjack" before the idea of putting it into core Python came up :-) Thanks & Regards Vinay Sajip

TM> The argument for the former is: TM> (1) KISS and YAGNI

[Jeremy]

I've said my piece for the most part, but this YAGNI stuff bugs me.

Then let me explain it some more. This logger module is not just for Zope, it's for all Python users. It's clear that for 99% of the uses, this *is* a case of YAGNI. Lots of standard Python modules lack advanced features so they can be more easy to understand or maintain. That's also the 80% principle, and I'm sticking to it. In many of those cases, users who need an advanced feature can easily add it by creating a subclass, or using other extensibility features (e.g. hooks). Occasionally, it's needed to rewrite the base functionality from scratch in order to add something new. If that happens too often, the library design should probably be revised. Zope is a sophisticated application that has needs that go far beyond those of most Python users. I'm very happy that it's proved possible to write Zope in Python. But I don't think it should be the measuring stick by which the functionality of the standard library must be measured. Here's another way to look at it. To support the base functionality, we need an X amount of code. To add the feature of logging exceptions at any level, we would need an additional Y amount. The number Y is much smaller than X, but not insignificant. If the size of a subclass that adds that feature is approximately equal to Y, I think it should be kept out of the base class in this case, because you can easily write that subclass for Zope. If writing such a subclass would require significantly more code than Y (the amount of code needed to integrate it directly into the base class), I agree that the base class needs to be reworked to make this easier to add, or even to support it outright. But I find that hard to believe in this case. [KISS] As a compromise, would it make sense to have 5 simple logging methods that indicate the level by their name and have no support for handling exceptions, and one more general function that takes an error level argument and an optional exc_info? That more general function would be useful in some other cases (e.g. for programs that want to tweak the logging levels for certain loggable events) and adding it is much less disturbing to the simplicity of the standard interface than adding exc_info support to each of the simple methods. It would mean that ZEO would have to use a slightly more expensive (because it's more general) interface in the one or two cases where it wants to log an exception at the info level. I doubt that these exceptions happen often enough to notice the difference. --Guido van Rossum (home page: http://www.python.org/~guido/)

This really isn't about YAGNI then. It's about some customers' needs being too complex to handle in the standard library.

Why isn't that YAGNI? To me it feels like this is YAGNI for most users; we're designing a library module here, not a Zope component. I'd be happy to find a different principle with a catchy name (maybe the 80% principle or KISS are better) but I still think your use case is pretty unusual. --Guido van Rossum (home page: http://www.python.org/~guido/)

On Fri, Mar 22, 2002, Guido van Rossum wrote:

Why isn't that YAGNI? To me it feels like this is YAGNI for most users; we're designing a library module here, not a Zope component.

I'd be happy to find a different principle with a catchy name (maybe the 80% principle or KISS are better) but I still think your use case is pretty unusual.

+1 on "80%" Three reasons: * "Explicit is better than implicit" * YAGNI is a falsehood when directed at someone who does need the feature, even though you're using the plural "you" * I can never remember what YAGNI stands for; it's not that common, even here on python-dev -- Aahz (aahz@pythoncraft.com) <*> http://www.pythoncraft.com/ "We should forget about small efficiencies, about 97% of the time. Premature optimization is the root of all evil." --Knuth

[Aahz]

... * I can never remember what YAGNI stands for; it's not that common, even here on python-dev

That's why it's needed here, although it came from a culture building payroll apps, not programming infrastructure. Heck, if Unix dweebs had applied YAGNI, ls wouldn't have 51 useless options <wink>.

Skip Montanaro <skip@pobox.com>:

I believe the first couple Unix programmers did, though I doubt they thought of it in precisely that acronym. It was the masses that followed (probably influenced by some expatriate VMS programmers) who got carried away with adding thirty-leven options to every little filter. <wink><wink>

No, it wasn't the masses. It was the FSF. At this point, most people have forgotten what the Unix toolkit was like before the GNU project replaced most of it. Many, many fewer options per filter... -- <a href="http://www.tuxedo.org/~esr/">Eric S. Raymond</a>

Tim> Heck, if Unix dweebs had applied YAGNI, ls wouldn't have 51 useless Tim> options <wink>.

I believe the first couple Unix programmers did, though I doubt they thought of it in precisely that acronym. It was the masses that followed (probably influenced by some expatriate VMS programmers) who got carried away with adding thirty-leven options to every little filter. <wink><wink>

Skip

I remember that way back at CWI we called "the BSD disease" -- after our sysadmin had installed 4.0 BSD on our VAX, we were appalled by the code size growth of most common utilities. --Guido van Rossum (home page: http://www.python.org/~guido/)

...

...

...

...

"JH" == Jeremy Hylton <jeremy@zope.com> writes:

JH> I've never used a logging library before I used Zope, and JH> never really thought I needed one. (Perhaps it would have JH> been useful in Grail.) It seems that prints are good enough JH> for small applications and that more complex logging libraries JH> are mostly useful for sophisticated applications. If logging JH> is mostly useful for sophisticated applications, it would be a JH> mistake to declare their requirements as too complex. On the JH> other hand, maybe Zope should continue to use its own logging JH> tools. I think Jeremy has a good point here. IME, logging itself is unnecessary for for many Python programs, be they library modules or simple scripts. Once you get into doing things like writing web applications, or long running servers, where you typically don't have a stdout or stderr, the print approach fails, and you end up inventing a logging mechanism. I thought/hoped the whole point of this PEP was to give such application authors a common way to spell its logging facilities, so that end-users can have a common way to configure the logging of the applications they're installing and administering. All one line hacks eventually turn into scripts. All scripts eventually turn into multi-user applications. All multi-user applications eventually turn into web apps. All web apps eventually become distributed. ;) -Barry

Hi, Tim Peters:

It seems that having a logger module *at all* is a YAGNI for 99% of users 99% of the time. That suggests that, if it's a good idea to have one anyway, it should cater to the 1% of users who need it 1% of the time. This

I disagree. How many programs write to stderr with some undefined stuff which is either too much or not enough information? Probably lots. The next user then wants to use that same program as a daemon and needs to figure out how to get the stuff to Syslog safely. The next one wants to use it as a module, link it into HTTP and needs to figure out how to package some of the text into an HTML error message. Thus, my take is that as soon as you have a sensible system to do logging with, far more than the 1% of people who "need logging" now will adapt to it.

makes me uncomfortable about rejecting requirements from people who actually use logging heavily.

I'd make the simple stuff easy and the complicated stuff possible. This approach suggests that the PEP in its current form is too complicated: - Formatters are associated with handlers -- it makes no sense to XML-format a Syslog message, and the default is going to be "msg % args" anyway. - Filters are handlers which don't print anything. Instead, they throw a StopLogging exception. Thoughts? -- Matthias Urlichs | noris network AG | http://smurf.noris.de/ -- The price of success in philosophy is triviality. -- C. Glymour.

Jim> It can't be YAGNI if there is a need. Like many other people who have implemented web server type beasts, I added a logging capability to my XML-RPC server. I will wager that if you survey others who have written similar tools (from small servers to big things on the scale of Webware, Quixote, or Zope) that they have all implemented some sort of logging facility. It is definitely not something people aren't going to need (I *hate* that acronym - I'll keep spelling it out, thank you). Mine logger was written just for use with a single application, so doesn't have the bells and whistles others have apparently found indispensable. I would dump it in a flash if something was made available in the standard library even if it meant rewriting every line that makes calls to my current logger. My only functional request is that it be able to integrate with the Unix syslog facility so I can control where messages go with the same "tool" (a text editor + /etc/syslog.conf) that I've used for years. Skip

...

...

...

...

"JF" == Jim Fulton <jim@zope.com> writes:

JF> Yup. I look forward to changing all out zLOG calls to use the JF> new standard logger. More important, I look forward to having JF> all the other cool Python software I reuse use the same JF> logging facility I use. :) Here, here! -Barry

[Barry Scott]

Getting the logging system right is not easy. From the design discussions we have been through for a C++ logging system recently I would argue that the importance order is wrong.

FRom PEP 282 DEBUG INFO WARN ERROR FATAL

Suggested DEBUG WARN INFO ERROR FATAL

The reasoning is that INFO messages affirms actions (Example: user logged on, call placed), whereas WARN messages can frequently be ignored. (Example: disk space is running low, old interface used)

Of course if you implement them a categories instead of an ordered sequence the user can turn on and off the categories that are interesting. In the proposed implementation, you can implement whatever order you need for your application. But the suggested order in PEP282 makes more sense to me because INFO messages require no specific actions, whereas WARN messages do invite actions. Of course they can be ignored, though sometimes at peril of inviting disaster (e.g. if disk space actually gets exhausted). So the rationale is -

DEBUG - detail information, of use to developers trying to diagnose the cause of a problem. INFO - give you a warm feeling that things are going according to plan. WARN upwards - indication that some remedial action is required, with an indication of how bad things could get. Regards Vinay

...

...

...

...

"GE" == Greg Ewing <greg@cosc.canterbury.ac.nz> writes:

Jim> It can't be YAGNI if there is a need. | Maybe the term should be MPAGNI (Most People AGNI) or | MOTTYAGNI (Most Of The Time YAGNI). Or YANIUYDATYHI (you ain't gonna need it until you do, and then you'll hate it). pronounced-yani-yoo-daddy-hi-ly y'rs, -B

On Tue, Mar 26, 2002, Greg Ewing wrote:

Jim> It can't be YAGNI if there is a need.

Maybe the term should be MPAGNI (Most People AGNI) or MOTTYAGNI (Most Of The Time YAGNI).

Which takes us right back to my +1 on "80%". -- Aahz (aahz@pythoncraft.com) <*> http://www.pythoncraft.com/ "We should forget about small efficiencies, about 97% of the time. Premature optimization is the root of all evil." --Knuth

Jeremy Hylton wrote:

...

...

...

...

...

"TM" == Trent Mick <trentm@ActiveState.com> writes:

TM> [Guido van Rossum wrote]

...

...

...

[Jeremy Hylton wrote]

...

It seems quite plausible to decide to log an exception and then get another trivial exception raised and caught on the way to the logger. You would still want to log the original exception, so passing it explicitly is helpful sometimes.

[Trent]

...

Yes, I suppose so.

I'd like to call YAGNI on this. Also on the idea of being able to pass an exception to all logging levels. Also on the idea of passing the exc_info in rather than having the logger call sys.exc_info().

Instead, the logger should be subclassable or extensible so that Jeremy can implement this functionality if he really wants it.

What's the point here? I've presented use cases, and I maintain a large body of ZODB/ZEO code that already uses these features. So it simply doesn't make sense to say "You Ain't Gonna Need It" because I already need it and zLOG already has it.

The feature is simple to explain and implement, and seems to have low implementation cost. So I certainly think it meets the simplest thing that could possibly work criteria.

Yes, this is an important feature. Thanks Jeremy. :) BTW, the PEP really should reference zLOG. It didn't the last time I looked. Jim -- Jim Fulton mailto:jim@zope.com Python Powered! CTO (888) 344-4332 http://www.python.org Zope Corporation http://www.zope.com http://www.zope.org

ZEO is a component that lets clients on remote machines access a ZODB storage using a custon Python RMI. (The details aren't exactly important, except that it's a concrete example.) IOW, ZEO + ZODB is a client-server object database.

It's possible for all sorts of things to go wrong for an individual RMI. There can be a problem marshalling or unmarshalling the objects. There can be a problem with executing the actual methods on the server. There can be a problem with application code that is executed as a result of calling some method on the server. Etc.

Few of these errors are fatal. Some of them may be uninteresting most of the time. So I'd like to log tracebacks and vary the log level depending on the importance of the event that caused the exception.

One particular example is a KeyError. The server will raise a KeyError if the client asks for an object that doesn't exist. There are clients that catch this error on the client side and handle it cleanly. It's not an important exception for them. But I'd like to log the traceback on the server to handle cases where the client isn't expecting it. I'd probably log this at debug() level. Most of the time, nobody cares about a KeyError. But it might occasionally be useful when debugging something.

If this use case is rare enough, maybe a better approach would be to let you format it yourself using the traceback module? --Guido van Rossum (home page: http://www.python.org/~guido/)

[Barry Warsaw wrote]

This reminds me of another use case for logging, which may or may not be covered by PEP 282.

When an uncaught exception happens in Mailman (i.e. it percolates up to the "main loop" of the current process), I always want to log it somewhere because it definitely indicates a bug.

If this exception happens in the web interface, I will usually log the exception in some file, and also format the exception into html for output in the browser, /except/ when a `stealth mode' is enabled. The traceback can be considered sensitive information, so when debugging we turn stealth mode off, but we always ship with stealth mode on. In stealth mode, we still always log the traceback to a file, but we never output the traceback onto the web page.

It would also be great if I can create a logger that knows how to tee its output to multiple sinks.

For sure. A Logger object maintains a list of Handlers. You could have one WebInterfaceHandler and one FileHandler attached to your Logger.

If I understand the PEP correctly, I think I would use two standard formatters, a plaintext formatter and an html formatter. I'd then have two custom handlers, one which outputs to html mindful of the current stealth mode, and one which tees the LogRecord to two sub-handlers (i.e. the stealth-mode-aware handler, and the normal to-file handler).

I don't know if I understand the example case here: do you not even log _to file_ in stealth mode? In any case I would handle this by attaching a Filter object to any Handler that should *not* log in stealth mode: class StealthModeFilter(logging.Filter): """Note this is using the Filter interface in the version of the PEP that I haven't re-released yet.""" def filter(self, record): if record.exc_info and inStealthMode(): return None # drop the record else: return record

Does this seem reasonable given PEP 282's current proposal?

Sure. It depends on how you lay out your code whether the formatting and display of the web interface is done via the logging module. I don't think that that would be the right fit. The logging to file definitely fits into the logging module's purview. Trent -- Trent Mick TrentM@ActiveState.com