python logging file is not working when using logging.basicConfig

Question

I have the following lines of code that initialize logging. I comment one out and leave the other to be used. The problem that I'm facing is that the one that is meant to log to the file not logging to file. It is instead logging to the console. Please help.

For logging to Console:

logging.basicConfig(level=logging.INFO,
        format='%(asctime)s [%(levelname)s] (%(threadName)-10s) %(message)s',)

for file logging

logging.basicConfig(filename='server-soap.1.log',level=logging.INFO,
        format='%(asctime)s [%(levelname)s] (%(threadName)-10s) %(message)s')

Middy

your file logging example works fine for me. is the file writable? do you call your config and log calls in the right order? – Leftwich

Thanks Gryphius. Yes, the definition was ok. But I found that the problem was regarding the ordering of my imports and logging. I needed to define the logging before importing the various libraries. – Middy

Answer 1

I found out what the problem was. It was in the ordering of the imports and the logging definition.

The effect of the poor ordering was that the libraries that I imported before defining the logging using logging.basicConfig() defined the logging. This therefore took precedence to the logging that I was trying to define later using logging.basicConfig()

Below is how I needed to order it:

import logging
## for file logging
logging.basicConfig(filename='server-soap.1.log',
        level=logging.INFO,
        format='%(asctime)s %(levelname)s %(threadName)-10s %(message)s',)

from pysimplesoap.server import SoapDispatcher, SOAPHandler
from BaseHTTPServer import HTTPServer
import time,random,datetime,pytz,sys,threading
from datetime import timedelta
#DB
import psycopg2, psycopg2.extras
from psycopg2.pool import ThreadedConnectionPool

#ESB Call
from suds import WebFault
from suds.client import Client

But the faulty ordering that I initially had was:

from pysimplesoap.server import SoapDispatcher, SOAPHandler
from BaseHTTPServer import HTTPServer
import logging
import time,random,datetime,pytz,sys,threading
from datetime import timedelta
#DB
import psycopg2, psycopg2.extras
from psycopg2.pool import ThreadedConnectionPool

#ESB Call
from suds import WebFault
from suds.client import Client

## for file logging

logging.basicConfig(filename='server-soap.1.log',
        level=logging.INFO,
        format='%(asctime)s %(levelname)s %(threadName)-10s %(message)s',)

Middy

Tricky one. This drove me crazy! – Downstairs

OMG! dude I needed this. I've spent days trying to solve this problem. Thank you so much. – Hellraiser

Drove me crazy too. I find some comment of logging.basicConfig, it says:This function does nothing if the root logger already has handlers configured. It is a convenience method intended for use by simple scripts to do one-shot configuration of the logging package. – Excavator

why is this the case tho. – Pescara

@Middy I put a minus because the ordering of imports is not a problem here. The problem is that basicConfig should be called in your program not in libraries – Lanie

Sorry to just comment the same thing, but OMG this drove me crazy for way too along as well! What made it worse was that it only showed up in Docker?? Outside of Docker the exact same code honoured the basicConfig() call?? – Mountainside

This is weird because it breaks PEP guidelines on codes within imports, but is the only solution i guess. Maybe there could be a warning message "basicConfig already called" or something. – Unmoor

this drove me crazy as well but i guess it kind of makes sense...in my case i just made sure that logging configuration is done in the main python file, and not in any of the sub-modules – Attu

Yes ! The documentation says: "As it’s intended as a one-off simple configuration facility, only the first call (of logging.basicConfig) will actually do anything: subsequent calls are effectively no-ops." docs.python.org/3/howto/… – Foliaceous

Thanks! I spent 3 hours here. For something that was known since 2013! I knew that Python sucks, but this is a whole new level. – Improvisation

Answer 2

"Changed in version 3.8: The force argument was added." I think it's a better choice for new version.

For older Version(< 3.8):

From the source code of logging I found the flows:

This function does nothing if the root logger already has handlers

configured. It is a convenience method intended for use by simple scripts
to do one-shot configuration of the logging package.

So, if some module we import called the basicConfig() method before us, our call will do nothing.

A solution I found can work is that you can reload logging before your own calling to basicConfig(), such as

def init_logger(*, fn=None):

    # !!! here
    from imp import reload # python 2.x don't need to import reload, use it directly
    reload(logging)

    logging_params = {
        'level': logging.INFO,
        'format': '%(asctime)s__[%(levelname)s, %(module)s.%(funcName)s](%(name)s)__[L%(lineno)d] %(message)s',
    }

    if fn is not None:
        logging_params['filename'] = fn

    logging.basicConfig(**logging_params)
    logging.error('init basic configure of logging success')

Caridadcarie

Notice: You should reload this logging module before import others. – Bjork

This force argument was needed in my case. Found it in doc: docs.python.org/3/library/logging.html#logging.basicConfig – Isolate

Answer 3

I got the same error, I fixed it by passing the following argument to the basic config.

logging.basicConfig(
    level="WARNING",
    format="%(asctime)s - %(name)s - [ %(message)s ]",
    datefmt='%d-%b-%y %H:%M:%S',
    force=True,
    handlers=[
        logging.FileHandler("debug.log"),
        logging.StreamHandler()
    ])

Here as you can see passing force=True overrides any other BasicConfigs

Shanley

"Changed in version 3.8: The force argument was added." I think it's a better choice for new version – Caridadcarie

Finally, after much head-scratching, this worked! I was looking for a quicker/simpler solution than having to instantiate with logger = logging.getLogger('abc'). – Johansen

This should be marked as the accepted answer. Thanks so much, adding force=True did the trick. – Razid

If you say force =True, how does this change affect other libraries that use the logging module? – Showroom

@PythonMaester I think it will force the libraries to use the logging config created by us – Shanley

@AlenPaulVarghese this means whatever those libraries will be logging will end up in my debug.log file. This process does not sit well with me – Showroom

For me this option is NOT working. Logging calls in __init__() methods are still not there. So, the Force option has only a partial effect. – Improvisation

Answer 4

In case basicConfig() does not work:

logger = logging.getLogger('Spam Logger')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)
# add the handlers to logger
logger.addHandler(ch)
logger.addHandler(fh)

# 'application' code
logger.debug('debug Spam message')
logging.debug('debug Spam message')
logger.info('info Ham message')
logger.warning('warn Eggs message')
logger.error('error Spam and Ham message')
logger.critical('critical Ham and Eggs message')

which gives me the following output:

2019-06-20 11:33:48,967 - Spam Logger - DEBUG - debug Spam message
2019-06-20 11:33:48,968 - Spam Logger - INFO - info Ham message
2019-06-20 11:33:48,968 - Spam Logger - WARNING - warn Eggs message
2019-06-20 11:33:48,968 - Spam Logger - ERROR - error Spam and Ham message
2019-06-20 11:33:48,968 - Spam Logger - CRITICAL - critical Ham and Eggs message

For the sake of reference, Python Logging Cookbook is readworthy.

Charioteer

Just want to emphasize that the logger.setLevel() is crucial, because this cost me an hour as I did not notice in the answer; ie even if your handlers have DEBUG level, the default for logger is WARN so your INFO and DEBUG won't come through without the logger.setLevel(). – Thesda

Seems least "hackish" from provided answers. – Bryon

... which does not set the root logger while basicConfig() does.. Downvote. – Improvisation

Answer 5

Another solution that worked for me is instead of tracing down which module might be importing logging or even calling basicConfig before me is to just call setLevel after basicConfig again.

import os
import logging

RUNTIME_DEBUG_LEVEL = os.environ.get('RUNTIME_DEBUG_LEVEL').upper()
LOGGING_KWARGS = {
    'level': getattr(logging, RUNTIME_DEBUG_LEVEL)
}

logging.basicConfig(**LOGGING_KWARGS)
logging.setLevel(getattr(logging, RUNTIME_DEBUG_LEVEL))

Sort of crude, seems hacky, fixed my problem, worth a share.

Goulet

I don't get it, what's the point of the basicConfig call then? – Aboral

Calling basicConfig sets up other aspects of logging besides effective level. docs.python.org/2/library/logging.html#logging.basicConfig – Goulet

Answer 6

IF YOU JUST WANT TO SET THE LOG LEVEL OF ALL LOGGERS

---

instead of ordering your imports after logging config:

just set level on the root level:

# Option 1:
logging.root.setLevel(logging.INFO)

# Option 2 - make it configurable:
# env variable + default value INFO
logging.root.setLevel(os.environ.get('LOG_LEVEL', logging.INFO))

Guardrail

Answer 7

Like vacing's answer mentioned, basicConfig has no effect if the root logger already has handlers configured.

I was using pytest which seems to set handlers which means the default logging setup with loglevel WARNING is active -- so it appears my app fails to log, but this only happens when executing unit tests with pytest. In a normal app run logs are produced as expected which is enough for my use case.

Golgotha