Logs are getting auto deleted after the date is changed.

Python Help
1

I have written a code that would rotate logs on midnight maintaing backup of 1 day. But the next day, the previous logs are getting deleted.

For example :
While I am checking logs on 14th Feb, I noticed that all the logs generated on 13th Feb, got deleted from instancelogs.log.2025-02-13. The first log generated on 14th Feb is getting stored in instancelogs.log.2025-02-13 file instead of instancelogs.log file , the remaining logs for 14th Feb are correctly stored in instancelogs.log file.

Please look into the issue as we are losing all the logs for 13th of Feb.

I am using below code to handle logs:

import logging
from logging.handlers import TimedRotatingFileHandler


#logger instances for PPT creator
LOG_FILE_PATH = "../STORE_LOGS/instancelogs.log"

instance_logger = logging.getLogger('instance_logger')

instance_logger_file_handler = None


instance_logger_file_handler = TimedRotatingFileHandler(LOG_FILE_PATH, when='midnight', interval=1, backupCount=1)
instance_logger_file_formatter = logging.Formatter(
    fmt="[%(asctime)s] - [%(levelname)s]  - [%(filename)s] - [%(funcName)s] - %(message)s",
    datefmt="%d-%m-%y %H:%M:%S")
instance_logger_file_handler.setFormatter(instance_logger_file_formatter)

instance_logger.setLevel(logging.DEBUG)
instance_logger.addHandler(instance_logger_file_handler)
2

From the docs:

If backupCount is nonzero, at most backupCount files will be kept, and if more would be created when rollover occurs, the oldest one is deleted.

backupCount=1 means “keep exactly one file”, which is the behavior you see.

3

@abessman As per my example, 13th Feb file was supposed to be the backup file.But that 1 day backup file is getting erased. That is the problem.

4

Per the documentation, backupCount is not the number of backup files, it is the number of files, total, including the current log file.

5

Scratch that, my reading of the docs is wrong. With this example:

import logging
from logging.handlers import TimedRotatingFileHandler
from time import sleep

LOG_FILE_PATH = "example.log"
logger = logging.getLogger("instance_logger")
handler = TimedRotatingFileHandler(LOG_FILE_PATH, when="S", interval=1, backupCount=5)
formatter = logging.Formatter(
    fmt="[%(asctime)s] - [%(levelname)s]  - [%(filename)s] - [%(funcName)s] - %(message)s",
    datefmt="%d-%m-%y %H:%M:%S",
)
handler.setFormatter(formatter)

logger.setLevel(logging.DEBUG)
logger.addHandler(handler)

while True:
    logger.debug("hello")
    sleep(0.5)

six log files exist at once, including a current log named ‘example.log’.

I apologize. I shall try and see if I can reproduce your issue.

6

It sounds like there are multiple rollover events occurring. The first rollover correctly moves instancelogs.log to instancelogs.log.<date> and creates a new instancelogs.log. Then a second rollover occurs, again moving the (mostly empty) instancelogs.log to instancelogs.log.<date>, overwriting the backup file.

I haven’t been able to reproduce this, but I imagine it could happen if your logging code is run in multiple concurrent instances.

7

But I am using single instance, no multiple concurrent instances are being used.

8

You would also expect to see duplicate log entries if there where multiple loggers active. I don’t suppose that is the case?

Are you manually calling instance_logger_file_handler.doRollover() at any point?

9

Not sure of duplicate entries for multiple loggers, haven’t tried that.
No I am not calling instance_logger_file_handler.doRollover() anywhere.

10

I haven’t been able to reproduce the issue, even with the exact example script you provided.

A few things you could try:

  1. Decrease the log rotation time. Does the issue still occur with rotation times of an hour, or even a minute?
  2. Change the rollover time. Instead of rolling over at midnight, you can use the atTime parameter to set the rollover to e.g. 3 AM.
  3. Override the default BaseRotatorHandler.rotator attribute to something which keeps track of the exact times it is called. This could verify whether the rollover really does happen multiple times, as I suspect.
11
  1. I have already tried decreasing log rotation time. The issue doesnot occur with 2 minutes or 10 minutes set as rotation time.
  2. Have changed the rollover time this time.

I have seen another issue, when today(on 17th Feb), yesterday’s logfile (16th Feb’s log file) is getting backedup with the name of 15th Feb (instancelogs.log.2025-02-15), where my backupcount is set to 1. This instancelogs.log.2025-02-15 file has got logs of 16th Feb and is present today on 17th feb

12

Hi @abessman
I believe you were correct, there are multiple concurrent instances. So sorry I missed this information.
I am running a script that imports the above logger script, using :
gunicorn --timeout 6000 -w 2 -k uvicorn.workers.UvicornWorker …
This workers are initializing the TimedRotationHandler twice handlers twice.

Is this the cause of the issue I am facing?
Can you suggest a fix for this?

13

I suspect so.

Use QueueHandler to write log messages to a multiprocessing.Queue from these workers, then use a single separate process to pass this queue to your TimedRotatingFileHandler.