Python logging configuration issue

I have a main script called data.py, which will call logger.py (for log configuration) and login.py (for login)

# data.py

from logger import configure_logger
from login import *
if __name__ == "__main__":
    script_name = (f"C:\\datalog") #save logfile in a different directory than script location
    logger = configure_logger(script_name)
    logger.info(f"This log is from data.py")

# logger.py

import logging
from datetime import datetime as dt
def configure_logger(script_name):
    py_name = ((__file__.split('\\')[-1]).split('.')[0]).upper()
    log_format = f'%(asctime)s - %(levelname)s - {py_name} - %(message)s'
    logging.basicConfig(filename=f"{script_name}_{dt.now().strftime('%Y%m%d-%H_%M_%S')}.log", level=logging.INFO, format=log_format)
    logger = logging.getLogger()
    return logger

# login.py

from logger import configure_logger
import os
import sys
script_name = os.path.splitext(os.path.basename(sys.argv[0]))[0]
logger = configure_logger(script_name)
logger.info(f"This log is from login.py")

My expected output in datalog_<date_timestamp>.log:

2023-09-28 14:20:27,767 - INFO - LOGIN - This log is from login.py
2023-09-28 14:20:27,768 - INFO - DATA - This log is from data.py

Bu above script is producing output like below to data_<date_timestamp>.log: (not expected filename and name in logfile)

2023-09-28 14:20:27,767 - INFO - LOGGER - This log is from login.py
2023-09-28 14:20:27,768 - INFO - LOGGER - This log is from data.py

My login and logger module are common and it will be called from multiple main script like data.py. I need to create logfile based on the name mentioned in my main script (in this case - data.py) and for each log entry I would like to include the name as original script which is executing it. For example, if login.py is running, I need to include LOGIN as the name and if it is running from data.py, it has to be DATA

How can I achieve this?

Solution

So there are a few issues. First, __file__ is being evaluated exactly where it is occurring which is in logger.py. Second logging.basicConfig is being called twice. The second call is simply being ignored. You can test this by importing sleep from time and adding sleep(3) before your call to configure_logger in data.py. The seconds will roll over resulting in different filenames, but only the first file is created. Lastly you're passing completely different vales for script_name, though, as mentioned above, the second call just gets ignored.

Filename Without Modification

If you can tolerate it being lowercase and having a .py extension, you can use the built-in filename parameter available for the log format. This allows you to completely drop the logger.py file as well as the calls to getLogger()

# data.py

import logging
from datetime import datetime as dt

# Only put this here if logging needs to happen in imported modules OUTSIDE of functions
log_basename = "./datalog"
log_format = f'%(asctime)s - %(levelname)s - %(filename)s - %(message)s'
logging.basicConfig(filename=f"{log_basename}_{dt.now().strftime('%Y%m%d-%H_%M_%S')}.log", level=logging.INFO, format=log_format)

from login import *
if __name__ == "__main__":
    logging.info(f"This log is from data.py")

# login.py

import logging
logging.info(f"This log is from login.py")

This gives the output:

2023-09-28 04:33:46,382 - INFO - login.py - This log is from login.py
2023-09-28 04:33:46,382 - INFO - data.py - This log is from data.py

As the comment suggests, putting the logging configuration before the imports is against convention. If all logging will happen from within functions or your main block, logging should be set up after imports. Alternatively, you can move it back into its own file and import it again.

import logging

from datetime import datetime as dt
from login import *

def setup_logging():
    log_basename = "./datalog"
    log_format = f'%(asctime)s - %(levelname)s - %(filename)s - %(message)s'
    logging.basicConfig(filename=f"{log_basename}_{dt.now().strftime('%Y%m%d-%H_%M_%S')}.log", level=logging.INFO, format=log_format)

if __name__ == "__main__":
    setup_logging()
    login_foo()
    logging.info(f"This log is from data.py")

# login.py

import logging

def login_foo():
    logging.info(f"This log is from login.py")

Filename With Case Changes

If changing the case and removing the .py extension is important, you can use a context filter to add a modified filename variable to the logger's dictionary.

# data.py

import logging
from datetime import datetime as dt
from login import *

class ContextFilter(logging.Filter):
    def filter(self, record):
        record.FILENAME = record.filename[:-3].upper()
        return True


def setup_logging():
    log_basename = "./datalog"
    log_format = f'%(asctime)s - %(levelname)s - %(FILENAME)s - %(message)s'
    logging.basicConfig(filename=f"{log_basename}_{dt.now().strftime('%Y%m%d-%H_%M_%S')}.log", level=logging.INFO, format=log_format)
    f = ContextFilter()
    logging.getLogger().addFilter(f)


if __name__ == "__main__":
    setup_logging()
    login_foo()
    logging.info(f"This log is from data.py")

This provides the exact desired output.

2023-09-28 05:24:56,256 - INFO - LOGIN - This log is from login.py
2023-09-28 05:24:56,256 - INFO - DATA - This log is from data.py