Avoid `logger=logging.getLogger(__name__)`

Question

We set up logging like the django docs told us:

https://docs.djangoproject.com/en/2.1/topics/logging/#using-logging

# import the logging library
import logging

# Get an instance of a logger
logger = logging.getLogger(__name__)

def my_view(request, arg1, arg):
    ...
    if bad_mojo:
        # Log an error message
        logger.error('Something went wrong!')

I want to avoid this line in every Python file which wants to log:

logger = logging.getLogger(__name__)

I want it simple:

logging.error('Something went wrong!')

But we want to keep one feature: We want to see the Python file name in the logging output.

Up to now we use this format:

'%(asctime)s %(name)s.%(funcName)s +%(lineno)s: %(levelname)-8s [%(process)d] %(message)s'

Example output:

2016-01-11 12:12:31 myapp.foo +68: ERROR Something went wrong

How to avoid logger = logging.getLogger(__name__)?

Cricoid

Normally, I get annoyed at the you-shouldnt-be-doing-this comments on a question. Here though, I have to say that it seems like a bad idea. "Simple", in the Pythonic sense and logging do not really line up. Logging is Java-inspired, and while powerful, is tricky to use. I originally and mistakenly did just what you proposed and was using logging.error() and the like. That ended up biting me in configuration and filtering ability because that is just not the way it is intended to be used. YMMV but I would look elsewhere for simplification. You are saving 1 line per module? What for? – Virgate

That one line is what allows per module configuration of logging. Like, for example, lowering the logging threshold (i.e. more verbose) on a module you are currently troubleshooting without affecting others. Throw it out and a lot of the rationale for using the delivered logging module becomes questionable. – Virgate

My reply to your "That one line is what allows per module configuration of logging.": I like DevOps: developers should know how to operate (example nagios) and operators should know how to develop. Next thing I like: distinguish between both. Configuring logging is "operation". Python code is "development". That's why I don't want to modify the code to change the logging configuration. – Cricoid

@guettli, you seem to misunderstand how logging is configured. This __name__ becomes something like 'abc.qwe.zxc', by default, everything logged is captured by the root logger, and then in a separate config file you can assign a specific logger to 'abc.qwe' namespace and tell it not to propagate the event to the root logger, but mute or log into a separate handler (file) instead. You do not have to modify source code to configure logging. And since the module is basically a log4j for python, most admins and developers understand how to configure loffing in your application. – Maquis

Answer 1

You can use logging.basicConfig to define the default interface available through logging as follows:

import logging
logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(name)s.%(funcName)s +%(lineno)s: %(levelname)-8s [%(process)d] %(message)s',
                    )

This definition will now be used whenever you do the following anywhere in your application:

import logging
logging.error(...)

While __name__ is not available, the equivalent (and other options) are available through the default LogRecord attributes that can be used for error string formatting - including module, filename and pathname. The following is a two-script demonstration of this in action:

scripta.py

import logging
logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(module)s %(name)s.%(funcName)s +%(lineno)s: %(levelname)-8s [%(process)d] %(message)s',
                    )

from scriptb import my_view

my_view()

scriptb.py

import logging

def my_view():
    # Log an error message
    logging.error('Something went wrong!')

The logging definition is defined in scripta.py, with the added module parameter. In scriptb.py we simply need to import logging to get access to this defined default. When running scripta.py the following output is generated:

2016-01-14 13:22:24,640 scriptb root.my_view +9: ERROR    [14144] Something went wrong!

Which shows the module (scriptb) where the logging of the error occurs.

According to this answer you can continue to use any per-module configuration of logging from Django, by turning off Django handling and setting up the root handler as follows:

# settings.py - django config
LOGGING_CONFIG = None # disables Django handling of logging
LOGGING = {...}  # your standard Django logging configuration

import logging.config
logging.config.dictConfig(LOGGING)

Moscow

Wow, if it is that easy, I ask myself why the django developers promote the more complicated way with logger=logging.getLogger(__name__). Django docs: docs.djangoproject.com/en/1.9/topics/logging/#using-logging – Cricoid

The .getLogger(__name__) style allows for filtering and handling of different (e.g. per-module, per app) loggers within the Django framework - which you lose by using .basicConfig(...). For example see the Configure Logging section on the page you linked. You'll have to decide whether this loss of configuration matters to your use-case. – Moscow

I've just updated the answer with some information found on another question - apparently you can use the same structured logging, using .dictConfig with a dictionary definition. – Moscow

Just a note that if you never call logging.getLogger(__name__) then the %(name)s portion of the log entry will always be root. – Daggerboard

Answer 2

what about pathname? from https://docs.python.org/2/library/logging.html#formatter-objects

/Users/jluc/kds2/wk/explore/test_so_41.py

import logging

#another module, just to have another file...
import test_so_41b

#not so much to use basicConfig as a quick usage of %(pathname)s
logging.basicConfig(level=logging.DEBUG,
                    format='%(pathname)s %(asctime)s %(levelname)s %(message)s',
                    # filename='/tmp/myapp.log',
                    # filemode='w',
                    )

logging.debug('A debug message')
logging.info('Some information')
logging.warning('A shot across the bows')

test_so_41b.dosomething("hey there")

/Users/jluc/kds2/wk/explore/test_so_41b.py

import logging

def dosomething(msg):
    logging.info(msg)

audrey:explore jluc$ python test_so_41.py

output:

test_so_41.py 2016-01-16 14:46:57,997 DEBUG A debug message
test_so_41.py 2016-01-16 14:46:57,997 INFO Some information
test_so_41.py 2016-01-16 14:46:57,997 WARNING A shot across the bows
/Users/jluc/kds2/wk/explore/test_so_41b.py 2016-01-16 14:46:57,997 INFO hey there

Virgate