ConcurrentTimedRotatingFileHandler 1969-12-31 in filename

[qiaojiim]

When using ConcurrentTimedRotatingFileHandler in a multi-process python program,
abnormal timestamp exists in log filenames (e.g., 1969-12-31) as below.
What might be causing the problem?

-rw-r--r-- 1 root root 5.3K May 30 16:44 event_kafka_consumer.log.1969-12-31.1
-rw-r--r-- 1 root root  79K May 30 16:44 event_kafka_consumer.log.1969-12-31.2
...
-rw-r--r-- 1 root root    249638 May 31 20:06 event_kafka_consumer.log.1969-12-31.98
-rw-r--r-- 1 root root   7693191 May 31 20:12 event_kafka_consumer.log.1969-12-31.99
...
-rw-r--r-- 1 root root     88880 Jun  1 06:14 event_kafka_consumer.log.1969-12-31.124
-rw-r--r-- 1 root root    130243 Jun  1 06:14 event_kafka_consumer.log.1969-12-31.125
...
-rw-r--r-- 1 root root    315252 Jun  2 09:37 event_kafka_consumer.log.1969-12-31.213
-rw-r--r-- 1 root root  88980230 Jun  2 10:53 event_kafka_consumer.log.1969-12-31.214
...
-rw-r--r-- 1 root root  17401796 Jun  3 16:21 event_kafka_consumer.log.1969-12-31.285
-rw-r--r-- 1 root root    297617 Jun  3 16:21 event_kafka_consumer.log.1969-12-31.286
...
-rw-r--r-- 1 root root  11422341 Jun  4 10:51 event_kafka_consumer.log.1969-12-31.353
-rw-r--r-- 1 root root  63445024 Jun  4 11:52 event_kafka_consumer.log.1969-12-31.354
...
-rw-r--r-- 1 root root  16986463 Jun  5 12:28 event_kafka_consumer.log.1969-12-31.417
-rw-r--r-- 1 root root  13798764 Jun  5 12:42 event_kafka_consumer.log.1969-12-31.418
-rw-r--r-- 1 root root     90551 Jun  5 12:42 event_kafka_consumer.log.1969-12-31.419
...
-rw-r--r-- 1 root root  10630616 May 30 23:59 event_kafka_consumer.log.2025-05-30
-rw-r--r-- 1 root root  53839623 May 31 23:59 event_kafka_consumer.log.2025-05-31
-rw-r--r-- 1 root root  21550047 Jun  1 23:59 event_kafka_consumer.log.2025-06-01
-rw-r--r-- 1 root root  65094607 Jun  2 23:59 event_kafka_consumer.log.2025-06-02
-rw-r--r-- 1 root root  20106466 Jun  3 23:59 event_kafka_consumer.log.2025-06-03
-rw-r--r-- 1 root root   6093489 Jun  4 23:59 event_kafka_consumer.log.2025-06-04

Simplified code as below
Env is python=3.8 + concurrent-log-handler=0.9.26

def process_every_10min():
    logger = multiprocessing.get_logger()
    while True:
        time.sleep(10 * 60)

        logger.info(f'[process_every_10min] some log msg')

        # custom code
        process_report()


def main():
    # listening kafka
    consumer = KafkaConsumer(topic, **config)
    while True:
        try:
            for msg in consumer:
                # custom code
                process_event(msg)
        except Exception as e:
            logger.error(f'[main] exception, error={e}')


if __name__ == '__main__':
    logger = multiprocessing.get_logger()
    handler = ConcurrentTimedRotatingFileHandler(FileConf.event_kafka_consumer_log, when='midnight', backupCount=7)
    logger.addHandler(handler)

    process = multiprocessing.Process(target=process_every_10min)
    process.daemon = True
    process.start()

    main()

[Preston-Landers]

Timestamps around 1969-12 or 1970-01 are a sign that a time check somewhere is returning a value of 0 for the current time, which produces different results depending on the current time zone.

I'm going to be looking at the rollover code soon for issue #73 and will see if I can tell anything then. Thanks for the report.

[Preston-Landers]

Hey @qiaojiim, I'm looking into this a little more and I think I see some ways this could be more robust. However I do have some questions for you.

1. Are those the exact settings you're using? In particular, is maxBytes the default 0, utc=False, and backupCount=7?
2. You're using multiprocessing. It's important that the class initialization ConcurrentRotatingFileHandler(...) happens separately inside each child process. It looks like in your example it's maybe happening in the parent only.
3. Is it possible that some local environment issue is causing time.time() calls to return 0?

[qiaojiim]

Thanks for helping.
Here are more details for your questions.

1. Yes, I only set when='midnight' and backupCount=7 when initializing ConcurrentTimedRotatingFileHandler. Other parameters use the default values.
2. Oh, I missed that. I can try creating separate ConcurrentTimedRotatingFileHandler instances in each child process and re-check the log outputs.
3. Probably not. I only encounter this issue in a multi-process setup.

[Preston-Landers]

Definitely check how you're initializing the handler instances in each child. The README tries to address this issue but it's probably not super-clearly explained, so that could use some improvement.

That said, I did just release a 0.9.27 version which cleans up some of the logic around bad/suspect timestamp handling and generally tries to be more robust in this area. Go ahead and check it out.

One more thing - one thing that might lead to weird issues with file naming or rotation is changing around the logging settings frequently, like changing from hourly to daily rotation or back again, things like that - especially if there might be multiple processes running at the same time with different settings.

If you are still able to reproduce issues like this in the new release, go ahead and let me know here. Thanks!