Skip to content

Commit

Permalink
Fixed failed log rotation due to wrong log file creation time recording
Browse files Browse the repository at this point in the history 
POSIX provides only access, modification and metadata change times. Timed rotation should be based on creation time, available sometimes as os.stat(path).st_birthtime
When not available, the modification time will be used as it was before, but the min_days option will be disabled.
  • Loading branch information
@mambelli
mambelli committed Nov 20, 2024
1 parent 037a801 commit 14ecb50
Show file tree
Hide file tree
Showing 4 changed files with 88 additions and 41 deletions.
1 change: 1 addition & 0 deletions CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ Changes since the last release
- Disabled shebang mangling in rpm_build to avoid gwms-python not finding the shell (Issue #436, PR #437)
- Dynamic creation of HTCondor IDTOKEN password (Issue #440, PR #441)
- Autodetect CONDOR_OS in the manual_glidein_submit tool (Issue #449, PR #453)
- Failed log rotation due to wrong file creation time (Issue #451, PR #457)

### Testing / Development

Expand Down
31 changes: 21 additions & 10 deletions doc/factory/configuration.html
View file
Original file line number Diff line number Diff line change
Expand Up @@ -158,7 +158,7 @@ <h2>Example Configuration</h2>
entry_parallel_workers="0"&gt;</a
><br />
<blockquote>
<a href="#">&lt;log_retention &gt;</a><br />
<a href="#log_retention">&lt;log_retention &gt;</a><br />
<blockquote>
<a href="#"
>&lt;condor_logs max_days="14.0" max_mbytes="100.0"
Expand All @@ -181,13 +181,13 @@ <h2>Example Configuration</h2>
backup_count="5" /&gt;</a
><br />
</blockquote>
<a href="#">&lt;/process_logs &gt;</a><br />
<a href="#"
<a href="#process_logs">&lt;/process_logs &gt;</a><br />
<a href="#log_retention"
>&lt;summary_logs max_days="31.0" max_mbytes="100.0"
min_days="3.0" /&gt;</a
><br />
</blockquote>
<a href="#">&lt;/log_retention &gt;</a><br />
<a href="#log_retention">&lt;/log_retention &gt;</a><br />
<a href="#monitor"
>&lt;monitor base_dir="/var/www/html/glidefactory/monitor"
flot_dir="/opt/javascriptrrd-0.6.3/flot"
Expand Down Expand Up @@ -579,6 +579,7 @@ <h3 class="western"><a name="args_global"></a>Global arguments</h3>
</ul>
</li>
<li>
<a name="log_retention" />
<a name="process_logs" />
<div class="xml">
&lt;glidein&gt;&lt;log_retention&gt;&lt;process_logs&gt;&lt;process_log
Expand Down Expand Up @@ -624,20 +625,25 @@ <h3 class="western"><a name="args_global"></a>Global arguments</h3>
<br /><br />
<b>Log Retention and Rotation Policy:</b>
<br /><br />
Log files are rotated based on a time and size of the log files as
follows:
Log files can be rotated based on the time and size of the log files
as follows:
<ul>
<li>
If the log file size reaches <i>max_bytes</i> it will be rotated
(NOTE: the value will be truncated and 0 means no rotation).
(NOTE: the value will be truncated and 0 means no size-based
rotation).
</li>
<li>
If the log file size is less that <i>max_bytes</i> but the file
is older than max_days, it will be rotated.
is older than max_days, it will be rotated. Use floats for
fractions of a day, the value will be converted in seconds, 0
means no time-based rotation
</li>
<li>
<i>min_days</i> is not used and is there for backwards
compatibility.
<i>min_days</i> Used in combination with max_bytes to delay file
size rotation until min_days are gone by. Use floats for
fractions of a day, the value will be converted in seconds, 0
means no delay (default).
</li>
<li>
Rotated files may be compressed. Supported compressions are Gzip
Expand All @@ -648,6 +654,11 @@ <h3 class="western"><a name="args_global"></a>Global arguments</h3>
be kept and older ones are deleted. Defaults to 5.
</li>
</ul>
NOTE: Time-based rotation and rotation delay use the file creation
time which may not be available on your system or file system. In
that case, the delay is disabled and time-based location will use
the log file modification time when the logger is restarted. This
may lead to incorrect time-based rotation.
</li>
<li>
<a name="condor_tarball" />
Expand Down
32 changes: 21 additions & 11 deletions doc/frontend/configuration.html
View file
Original file line number Diff line number Diff line change
Expand Up @@ -154,9 +154,9 @@ <h2>Example Configuration</h2>
enable_attribute_expansion="False"&gt;</a
><br />
<blockquote>
<a href="#">&lt;log_retention &gt;</a><br />
<a href="#log_retention">&lt;log_retention &gt;</a><br />
<blockquote>
<a href="#">&lt;process_logs &gt;</a><br />
<a href="#process_logs">&lt;process_logs &gt;</a><br />
<blockquote>
<a href="#process_logs"
>&lt;process_log structured="False" extension="info"
Expand All @@ -169,9 +169,9 @@ <h2>Example Configuration</h2>
msg_types="DEBUG,ERR,WARN" backup_count="5" /&gt;</a
><br />
</blockquote>
<a href="#">&lt;/process_logs &gt;</a><br />
<a href="#process_logs">&lt;/process_logs &gt;</a><br />
</blockquote>
<a href="#">&lt;/log_retention &gt;</a><br />
<a href="#log_retention">&lt;/log_retention &gt;</a><br />
<a href="#match"
>&lt;match match_expr="True"
start_expr="$(JOBSTR_ATTR)&lt;$$(JOBSTR_VAL)"
Expand Down Expand Up @@ -518,6 +518,7 @@ <h2 class="western"><a name="management"></a>Frontend Configuration</h2>
</p>
</li>
<li>
<a name="log_retention" />
<a name="process_logs" />
<div class="xml">
&lt;frontend&gt;&lt;log_retention&gt;&lt;process_logs&gt;&lt;process_log
Expand Down Expand Up @@ -557,20 +558,25 @@ <h2 class="western"><a name="management"></a>Frontend Configuration</h2>
<br /><br />
<b>Log Retention and Rotation Policy:</b>
<br /><br />
Log files are rotated based on a time and size of the log files as
follows:
Log files can be rotated based on the time and size of the log files
as follows:
<ul>
<li>
If the log file size reaches <i>max_bytes</i> it will be rotated
(NOTE: the value will be truncated and 0 means no rotation).
(NOTE: the value will be truncated and 0 means no size-based
rotation).
</li>
<li>
If the log file size is less that <i>max_bytes</i> but the file
is older than max_days it will be rotated.
is older than max_days, it will be rotated. Use floats for
fractions of a day, the value will be converted in seconds, 0
means no time-based rotation
</li>
<li>
<i>min_days</i> is not used and is there for backwards
compatibility.
<i>min_days</i> Used in combination with max_bytes to delay file
size rotation until min_days are gone by. Use floats for
fractions of a day, the value will be converted in seconds, 0
means no delay (default).
</li>
<li>
Rotated files may be compressed. Supported compressions are Gzip
Expand All @@ -581,8 +587,12 @@ <h2 class="western"><a name="management"></a>Frontend Configuration</h2>
be kept and older ones are deleted. Defaults to 5.
</li>
</ul>
NOTE: Time-based rotation and rotation delay use the file creation
time which may not be available on your system or file system. In
that case, the delay is disabled and time-based location will use
the log file modification time when the logger is restarted. This
may lead to incorrect time-based rotation.
</li>

<li>
<p>
<a name="wmscollector" />
Expand Down
65 changes: 45 additions & 20 deletions lib/logSupport.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,6 @@
import logging
import os
import re
import stat
import sys # for alternate_log
import time

Expand Down Expand Up @@ -85,16 +84,16 @@ class GlideinHandler(BaseRotatingHandler):
And the size is measured in Bytes (MBytes in the constructor parameter can be
fractional)
@type filename: string
@ivar filename: Full path to the log file. Includes file name.
@type interval: int
@ivar interval: Number of seconds to keep log file before rotating
@type maxBytes: int
@param maxBytes: Maximum size of the logfile in Bytes before file rotation (used with min days)
@type min_lifetime: int
@param min_lifetime: Minimum number of seconds (used with max bytes)
@type backupCount: int
@ivar backupCount: How many backups to keep
Attributes:
filename (str|Path): The full path of the log file. Includes file name. Passed to BaseRotatingHandler
interval (int): Max number of seconds before file rotation. 0 to disable timed rotation
min_lifetime (int): Minimum number of seconds before file rotation (used with maxBytes)
maxBytes (int): Maximum size of the logfile in bytes before file rotation (used with min days)
0 to disable file size rotation
backupCount (int): Number of backups to keep
compression (str): Compression to use (gz, zip, depending on available compression modules)
rolloverAt (int): time of the next time-based rollover in seconds from Epoch. 0 to disable
rollover_not_before (int): time to wait before the next size-based rollover in seconds from Epoch
"""

def __init__(self, filename, maxDays=1.0, minDays=0.0, maxMBytes=10.0, backupCount=5, compression=None):
Expand All @@ -103,13 +102,16 @@ def __init__(self, filename, maxDays=1.0, minDays=0.0, maxMBytes=10.0, backupCou
1. Interval entered is in days or fractions of it (internally converted to seconds)
2. No special encoding
3. No delays are set
4. Timestamps are not in UTC
4. Timestamps are in seconds since the epoch (can be converted in UTC with time.gmtime and
local with time.localtime)
Args:
filename (str|Path): The full path of the log file
maxDays (float): Max number of days before file rotation (fraction of day accepted, used in unit test)
filename (str|Path): The full path of the log file. Includes file name.
maxDays (float): Max number of days before file rotation (fraction of day accepted, used in unit test).
0 to disable timed rotation
minDays (float): Minimum number of days before file rotation (used with max MBytes)
maxMBytes (float): Maximum size of the logfile in MB before file rotation (used with min days)
0 to disable file size rotation
backupCount (int): Number of backups to keep
compression (str): Compression to use (gz, zip, depending on available compression modules)
"""
Expand Down Expand Up @@ -137,14 +139,36 @@ def __init__(self, filename, maxDays=1.0, minDays=0.0, maxMBytes=10.0, backupCou
self.suffix = "%Y-%m-%d_%H-%M"
self.extMatch = re.compile(r"^\d{4}-\d{2}-\d{2}_\d{2}-\d{2}(\.gz|\.zip)?$")

begin_interval_time_mtime = 0
if os.path.exists(filename):
begin_interval_time = os.stat(filename)[stat.ST_MTIME]
fstats = os.stat(filename)
begin_interval_time_mtime = fstats.st_mtime
try:
begin_interval_time = fstats.st_birthtime
except AttributeError:
# Creation time is very tricky. Not all OS or file systems provide file creation information
# POSIX specifies atime (access), mtime (modification), and ctime (inode/metadata change time)
# Mac OS has creation time and ext4 does but not always is reliable
# Furthermore, when opening in write the file is truncated and rewritten, w/o changing creation time
# anyway, for these log files, the old file is moved at log rotation, so the new log write will start
# a new file.
# When 0, timed rotation is disabled.
begin_interval_time = 0
else:
begin_interval_time = int(time.time())
self.rolloverAt = begin_interval_time + self.interval
self.rollover_not_before = 0
if self.min_lifetime > 0:
# Not before rollover is disabled in configuration (min_lifetime is 0) or if creation time is not available
if begin_interval_time > 0 and self.min_lifetime > 0:
self.rollover_not_before = begin_interval_time + self.min_lifetime
self.rolloverAt = 0
# Timed rollover is disabled in configuration when interval is 0
if self.interval > 0:
# If creation time is not available, resorting to modification time (will work while the logger is running,
# not when restarted frequently because the log file keeps being modified)
if begin_interval_time == 0:
self.rolloverAt = begin_interval_time_mtime + self.interval
else:
self.rolloverAt = begin_interval_time + self.interval

def shouldRollover(self, record, empty_record=False):
"""Determine if rollover should occur.
Expand Down Expand Up @@ -172,13 +196,14 @@ def shouldRollover(self, record, empty_record=False):
if disable_rotate:
return False

do_timed_rollover = False
t = int(time.time())
if t >= self.rolloverAt:

do_timed_rollover = False
if 0 < self.rolloverAt <= t: # 0 means that timed rollover is disabled
do_timed_rollover = True

do_size_rollover = False
if self.maxBytes > 0 and t >= self.rollover_not_before: # are we rolling over?
if self.maxBytes > 0 and t >= self.rollover_not_before: # are we rolling over for size?
if empty_record:
msg = ""
else:
Expand Down

0 comments on commit 14ecb50

Please sign in to comment.