logging.handler.TimedRotatingFileHandler never rotates the log

Question

A have a script which synchronizes time on linux servers( CentOS 6) and writes offset in log. I want to make after 10 days the current log (ntp.log) copy to old (ntp.log-date), but this does not work. The script continues to write into one file and not rotating. It is run by cron every 5 minutes. I using python version 2.6. I specifically set the interval in seconds to check. What am i doing wrong?

#!/usr/bin/env python
import ntplib
import logging
from logging.handlers import TimedRotatingFileHandler
from time import ctime
import os
import socket

hostname = socket.gethostname()
logHandler = TimedRotatingFileHandler('/root/ntp/log/ntp.log', when='S', interval=300)
logFormatter = logging.Formatter('%(asctime)s %(message)s', datefmt='%d/%m/%Y %H:%M:%S')
logHandler.setFormatter(logFormatter)
logger = logging.getLogger('MyLogger')
logger.addHandler(logHandler)
logger.setLevel(logging.INFO)


c = ntplib.NTPClient()
response = c.request('1.rhel.pool.ntp.org')
logger.info('| %s time offset is | %s' % (hostname, response.offset))
datestr = ctime(response.tx_time)
os.system('date -s "%s"' % datestr)

I'd strongly advise using `ntpd` and `logrotate` rather than reinventing the wheel. `ntpd`'s logic is much more sound than periodic one-time "synchronizations". — ivan_pozdeev, Jun 01 '15 at 08:56
about `logrotate` must see, and i can't use `ntpd`, i need synchronization' logs — reddaemon, Jun 01 '15 at 09:17
`ntpd` works much smarter than just "synchronizations", it uses the "kernel time discipline" API and is designed to actually *make you forget about the synchronization stuff once and for all* (http://www.eecis.udel.edu/~mills/ntp/html/discipline.html#house : "If left running continuously, an NTP client on a fast LAN in a home or office environment can maintain synchronization nominally within one millisecond.") Don't worry, it logs it whenever it does anything with the system clock. — ivan_pozdeev, Jun 01 '15 at 09:28
Do you expect me to buy this as an excuse? I assure you, you won't manage to synchronize better than `ntpd` does. And if you don't *need* to sync regularly, why do you need to *report* it regularly? If you have to report *something*, then look closely at what *exactly* you're expected to report - and deduce a way to produce it without sacrificing the actual work. — ivan_pozdeev, Jun 01 '15 at 11:17
Btw, if you're still not convinced, here's the flaw in your algorithm: `response.tx_time` ([Transmit timestamp](https://tools.ietf.org/html/rfc1305)) is the time the received packet left the server. The time frame between its departure and `date` calling [`stime()`](http://linux.die.net/man/2/stime) is unaccounted for. — ivan_pozdeev, Jun 01 '15 at 12:05

ivan_pozdeev · Answer 1 · 2015-06-01T11:50:08.320

Leaving outside the fact your algorithm is plain incorrect, i'll answer the question regarding the logging issue.

Here's the related logging.handlers.TimedRotatingFileHandler logic:

def __init__(<...>):
    <...>
    if self.when == 'S':
        self.interval = 1 # one second
    <...>
    self.interval = self.interval * interval # multiply by units requested
    <...>
    if os.path.exists(filename):
        t = os.stat(filename)[ST_MTIME]
    else:
        t = int(time.time())
    self.rolloverAt = self.computeRollover(t)

def computeRollover(self, currentTime):
    result = currentTime + self.interval
    <special logic that doesn't apply in your case>
    return result

So, the rollover time in 'S' mode is computed from the file's mtime at the time of your script's init. mtime is modified each time you write to the file.

Thus, the rollover would only be done if you log after interval seconds since your script's start. Which is never the case since it runs for much less.

Possible fixes:

make the script run for that long, e.g. with an infinite loop as you suggested. If it's to run indefinitely, it should probably be made a daemon
change the rollover moment calculation algorithm
- this is not possible with the stock logic (the "special logic" in TimedRotatingFileHandler.computeRollover() only applies to 'MIDNIGHT' and 'Wn' cases), so you need to replace your handler's computeRollover()
- basically, you need to set the rollover time to the next "reference moment" after the current file's mtime.

Please tell me what I need to change to the algorithm worked like I need? — reddaemon, Jun 01 '15 at 10:39
Maybe i must run it not through cron and make infinite loop. Or I simply must increase interval? — reddaemon, Jun 01 '15 at 11:11
The infinite loop will work. I'll now look if other handler parameters will as well. — ivan_pozdeev, Jun 01 '15 at 11:20

kishore.jannarapu · Answer 2 · 2021-04-19T07:04:17.920

This may help you (rolling over the log if the log has been created in multiples of 10th day and the log last modified a day before)

 #!/usr/bin/env python
import ntplib
import logging
from logging.handlers import TimedRotatingFileHandler
from time import ctime
import os
import socket

hostname = socket.gethostname()
logHandler = TimedRotatingFileHandler('/root/ntp/log/ntp.log', when='D', interval=10)
logFormatter = logging.Formatter('%(asctime)s %(message)s', datefmt='%d/%m/%Y %H:%M:%S')
logHandler.setFormatter(logFormatter)
#Get File creation Time
log_ctime = datetime.fromtimestamp(os.path.getctime("/root/ntp/log/ntp.log")).date()
log_mtime = datetime.fromtimestamp(os.path.getmtime("/root/ntp/log/ntp.log")).date()
delta_c = datetime.now().date() - log_ctime 
delta_m = datetime.now().date() - log_mtime 
if delta_c.days %10 == 0 and delta_m.days>=1:
   logHandler.doRollover()
logger = logging.getLogger('MyLogger')
logger.addHandler(logHandler)
logger.setLevel(logging.INFO)


c = ntplib.NTPClient()
response = c.request('1.rhel.pool.ntp.org')
logger.info('| %s time offset is | %s' % (hostname, response.offset))
datestr = ctime(response.tx_time)
os.system('date -s "%s"' % datestr)

logging.handler.TimedRotatingFileHandler never rotates the log

2 Answers2