"""Custom rotating log handler for CloudSync. Upload is decoupled from rotation: the actual CS-log upload is driven by ``HeartBeatProvider`` on its 20-second tick when the idempotent lane is idle. This class's sole responsibility is rotation. Clock-jump tolerant rotation. ``logging.handlers.TimedRotatingFileHandler`` computes ``rolloverAt`` from the REAL wall-clock at boot and never revisits that decision unless a rollover actually fires. On devices where operators simulate day transitions by setting the system clock to 23:59 and waiting, the stdlib ``rolloverAt`` stays anchored to the real boot time and never matches the simulated time, so rotations are silently skipped (confirmed against CPython 3.11). This handler replaces the stdlib trigger with a UTC-date-equality check: rotation fires whenever the current UTC date differs from the date on which the active log file was opened. Any clock jump — forward, backward, or past multiple midnight boundaries — is honored at the very next log emit. Collision safety: if the rotated-file suffix already exists on disk (operator set clock backward then forward again across the same date), a numeric counter is appended so no prior rotated file is silently overwritten. """ import logging import sys from logging.handlers import TimedRotatingFileHandler from cloudsync.utils.helpers import * from cloudsync.utils.globals import * # Re-import the datetime and time MODULES last, aliased. cloudsync.utils.helpers # does ``from datetime import *`` (rebinding "datetime" to the # ``datetime.datetime`` class) and ``from time import time, sleep`` # (rebinding "time" to the ``time.time`` function). Star-imports above # would therefore shadow our module references; aliasing keeps the # module accessors unambiguous. import datetime as _dt_module import time as _time_module class CustomTimedRotatingFileHandlerHandler(TimedRotatingFileHandler): """ Handler for logging to a file, rotating the log file at timed intervals. The ``set_network_provider`` / ``set_error_provider`` / ``set_configuration`` setters are retained as pass-through no-ops because ``LoggingConfig`` still invokes them from ``cloud_sync.py``. """ def __init__(self, filename, prelogger: Logger, *args, **kwargs): super().__init__(filename, *args, **kwargs) self.network_request_handler = None self.error_handler = None self.g_config = None # Track the UTC date of the currently-active file. Rotation # decisions compare this against datetime.now(utc).date() on every # emit, so any clock jump is caught immediately regardless of the # stdlib's boot-locked rolloverAt. self._active_log_date = self._current_utc_date() prelogger.info("CUSTOM LOG HANDLER INITIATED") @staticmethod def _current_utc_date(): return _dt_module.datetime.now(_dt_module.timezone.utc).date() def shouldRollover(self, record): """Rotate whenever the UTC date changes, ignoring self.rolloverAt (which is a boot-time fixed value that does not adapt to simulated clock jumps).""" try: return self._current_utc_date() != self._active_log_date except Exception: # Defensive: any failure here must not break logging itself. # Fall back to the stdlib check so at least real midnights # still rotate. try: return super().shouldRollover(record) except Exception: return False def doRollover(self): """Rotate using the current simulated time, not self.rolloverAt. Computes the rotated-file suffix from the UTC date of the log being rotated out (the data's original date). Guarantees no silent overwrite of a pre-existing file with the same suffix (collisions happen when operators set the clock backward then forward across the same date boundary). """ if self.stream: self.stream.close() self.stream = None current_time = int(_time_module.time()) # The active log was accumulating since self._active_log_date. # Use that as the suffix so the rotated filename reflects the # data's date, not the wall-clock moment of rotation. suffix_date = self._active_log_date suffix_str = suffix_date.strftime(self.suffix) dfn = self.rotation_filename(self.baseFilename + "." + suffix_str) # Collision safety: preserve any pre-existing rotated file with # the same suffix (operator clock-jumped across a date that was # already rotated earlier). base_dfn = dfn counter = 1 while os.path.exists(dfn): dfn = "{0}.{1}".format(base_dfn, counter) counter += 1 try: self.rotate(self.baseFilename, dfn) except Exception: # If rotation fails (e.g., source missing), don't leave the # handler in a half-closed state - reopen and let the next # emit retry. if not self.delay: self.stream = self._open() raise if not self.delay: self.stream = self._open() # Update the active-date marker to the NEW current UTC date. # The very next emit compares against this and knows not to # re-rotate until the UTC date changes again. self._active_log_date = self._current_utc_date() # Keep stdlib's internal bookkeeping consistent, though we do # not rely on rolloverAt for rotation decisions. try: self.rolloverAt = self.computeRollover(current_time) except Exception: pass def force_rotate_if_date_changed(self): """Force a rotation when the UTC date has advanced past ``self._active_log_date``, even when no log emit has happened in the interim. The stdlib ``TimedRotatingFileHandler`` invokes ``shouldRollover()`` only from inside ``emit()``. A silent-day device (``logLevel=ERROR`` and not erroring) never emits, so it never rotates, so the heartbeat opportunistic-upload pathway has nothing to send. This method is the heartbeat's hook to force a rotation on those silent days. Writes a self-describing marker line into the active stream before rotating, so the rotated file is non-empty (an empty rotated file would be indistinguishable from a corrupted log to downstream tooling). Marker shape matches the file's default formatter (logging.py:default_formatter) but is constructed manually because we write directly to the stream — emitting a record would re-enter the very handler we're rotating. Same-UTC-date is the fast path no-op (called every heartbeat tick, ~20 s). Lock-guarded under ``self.lock`` (the stdlib handler's internal RLock) so it serialises with concurrent ``emit()`` calls. Any exception raised inside is swallowed — rotation failure MUST NOT propagate to break the heartbeat tick. """ try: current_date = self._current_utc_date() except Exception: return if current_date == self._active_log_date: return with self.lock: # Re-check inside the lock: a concurrent emit() may have # already triggered a stdlib rotation that updated # _active_log_date. try: if self._current_utc_date() == self._active_log_date: return except Exception: return try: prior_date = self._active_log_date # Resolve effective log-level word from the handler's # own threshold (set by LoggingConfig.set_log_level via # self.log_handler.setLevel). try: level_word = logging.getLevelName(self.level).lower() if not level_word or level_word.startswith("level "): level_word = "unknown" except Exception: level_word = "unknown" # Resolve device serial. g_config is set via # set_configuration() but may be None at startup or in # a test harness — fall back to the same string the # CorrelationFilter falls back to (logging.py). try: if self.g_config is not None: hd_serial = self.g_config[CONFIG_DEVICE][ CONFIG_DEVICE_HD_SERIAL] else: hd_serial = "unregistered" except Exception: hd_serial = "unregistered" marker = ( "[{date} 23:59:59,999] INFO [] [{sn}] in logs_handler: " "No logs available for the covered interval with log " "level {level} | " "{{logs_handler.py:force_rotate_if_date_changed}}\n" ).format( date=prior_date.isoformat(), sn=hd_serial, level=level_word, ) if self.stream is None: # Delay-open mode and no emit has happened yet on # this active file. Open so the marker has somewhere # to land. self.stream = self._open() self.stream.write(marker) try: self.stream.flush() except Exception: pass self.doRollover() except Exception as exc: # Best-effort: rotation failure MUST NOT propagate. The # next heartbeat tick retries. Logging through the # regular logger could recurse into the very handler in # a bad state, so write the warning directly to stderr # (mirrors stdlib Handler.handleError's default). try: sys.stderr.write( "WARNING force_rotate_if_date_changed failed: " "{0}\n".format(exc)) except Exception: pass def set_network_provider(self, network_request_handler): self.network_request_handler = network_request_handler def set_error_provider(self, error_handler): self.error_handler = error_handler def set_configuration(self, g_config): self.g_config = g_config