python logging file is not working when using logg

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')

Answer 1

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')

Answer 2

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',)

Answer 3

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.

Answer 4

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.