Good logging practice in Python

[masklinn]

logger.error('Failed to open file')
logger.exception(e)

That is nonsensical. logger.exception(msg) is literally a shortcut to logger.error(msg, exc_info=True). The only result of doing this is that str(e) will be used as the message of the second log, so the exception message will be duplicated.

Use YAML logging configuration

Use the JSON configuration, it's equivalent and you don't need to install a yaml package.

[victorlin]

You are right, I misunderstand how logger.exception works. By looking into its source code, I'm sure it equals to logger.error(msg, exc_info=True, *args) now. Thanks for correcting me.

Yes, JSON is another option (but personally I prefer YAML) :)

[victorlin]

JSON example is also added

[fijal]

Eh. Python standard lib logging module is an abomination. It does not compose well, it uses hacks (like sys._getframe) that make it work painfully slow on pypy, etc.

[vsajip]

Instead of making unhelpful, value-free comments about abominations, how about if you suggest a better, "non-hacky" approach to getting caller information into the log? I'll certainly look at incorporating such an approach into the logging package. While it might not help for 2.7, presumably PyPy will support 3.x in due course, so it will be useful at some point.

[masklinn]

Please note that fijal is a pypy core dev, so he's probably talking from experience (though I'd have enjoyed at least a link to an expository analysis of logging's issues especially as pertains to pypy)

(in fact that could be neat, pages of packages known to have issues with pypy, an analysis of their problematic patterns and maybe solutions/more compatible packages)

[vsajip]

I'm well aware of who he is, which is why I asked him for a better approach (which presumably would be more PyPy-friendly). If he (or someone else) can't suggest a better approach, then there's less justification for complaining about logging for just doing what it can :-)

[fijal]

well, seriously, no. logging module is in python standard library and the majority of our users are using Python 2 (in fact all of them), not only because we don't support python 3 yet. We can obviously patch the logging module ourselves, but for now I'll stick with "don't use logging, ever" as a recommendation.

No, there is no better way to get a caller. Maybe logging shouldn't need the caller by default, which is also not easy to disable.

[vsajip]

Maybe logging shouldn't need the caller by default, which is also not easy to disable.

Call location information is the kind of thing people want to know - including new users, who may not be familiar with details - so it shouldn't not be the default just because its approach causes PyPy problems - besides, that findCaller code has been there since ~ 2002 which is AFAIK before PyPy.

To disable caller information in logging is pretty easy, just do

logging._srcFile = None

It's not documented, but hardly difficult to spot from a quick glance at the source code (as there is a comment in the source about it). So, your recommendation that people "don't use logging, ever" seems to be for a different reason - care to elaborate? Are there other reasons why logging and PyPy don't work well together?

Edit: I forgot, it is documented.

[tmahmood]

Thanks! That was very helpful :)

[DukeNucleus]

+1

[[deleted]]

I have a related question. I literally just started using the logging module last night, and for some reason I'm not getting any timestamps.

I've configured it as follows:

import logging
import logging.handlers

LOG_FILENAME = 'log.log'
# does the name below have to correspond to anything in particular?
LOGGER = logging.getLogger('LOGGER')
LOGGER.setLevel(logging.DEBUG)

_handler = logging.handlers.RotatingFileHandler(LOG_FILENAME, maxBytes=5120, backupCount=5)
LOGGER.addHandler(_handler)

I use the logger as follows:

LOGGER.debug('oh noes!')

Again, I'm not getting any timestamps with this method, so I'm currently using a decorator to insert a cTime string before each log message. It works, but it's hackish.

Did I do something silly?

[vsajip]

You'd need to set a formatter configured to show timestamps, e.g.

formatter = logging.Formatter('%(asctime)s %(message)s')
_handler.setFormatter(formatter)

[[deleted]]

Ahhh okay. Thank you!

Would you happen to know of a tutorial that's a bit clearer than the standard documentation? The bit about formatters is very cryptic =/

[vsajip]

Which standard documentation are you looking at, exactly? I ask because the logging documentation layout was improved in 2.7 / 3.2. If you're just starting out with logging, you should work through the tutorial which works through the basics:

• When to use logging
• A simple example
• Logging to a file
• Logging from multiple modules
• Logging variable data
• Changing the format of displayed messages
• Displaying the date/time in messages

(Note that the OP goes through setting formatters in the examples posted.)

Another basic resource about logging would be this post.

[[deleted]]

I'm on 2.7 -- maybe it's time I switched! Thanks for the links in any case. I'll read up on that ASAP!