From da64eace18c8af1c06fe4c319b6a5302119071d0 Mon Sep 17 00:00:00 2001 From: Lukas Sismis Date: Fri, 25 Sep 2026 17:41:41 +0200 Subject: [PATCH] util/log: rotate calendar intervals on local-time boundaries With rotate-interval set to minute, hour or day, rotations were not aligned to the local time boundaries. The first rotation was computed by SCGetSecondsUntil(), which overshoots the next hour by one minute (hh:01:00) and the next day by one hour and one minute (01:01:00). Every following rotation was re-armed with a fixed interval (e.g. 86400 s) from the time of the rotation. Local days are not always 86400 s long, so the day rotation also moved by the DST shift on every DST transition and stayed there until the next one. A file named after a date then held events of the next day. Instead, this commit rotates logs when the local minute, hour or date changes. The daily rotation now happens at local midnight. On SIGHUP, the period is recorded before the file is reopened, so a boundary (the next minute/hour/day) passing during the reopen leads to an extra reopen instead of a missed rotation. Ticket: #9139 --- doc/userguide/output/eve/eve-json-output.rst | 11 +- src/runmode-unittests.c | 2 + src/util-logopenfile.c | 230 +++++++++++++++++-- src/util-logopenfile.h | 20 +- src/util-time.c | 12 + src/util-time.h | 1 + 6 files changed, 254 insertions(+), 22 deletions(-) diff --git a/doc/userguide/output/eve/eve-json-output.rst b/doc/userguide/output/eve/eve-json-output.rst index f25a496f6e..daa4f549b5 100644 --- a/doc/userguide/output/eve/eve-json-output.rst +++ b/doc/userguide/output/eve/eve-json-output.rst @@ -485,6 +485,12 @@ Eve-log can be configured to rotate based on time. The example above creates a new log file each minute, where the filename contains a timestamp. Other supported ``rotate-interval`` values are ``hour`` and ``day``. +These values rotate the log file when the minute, hour or date of the local time +changes. For example, ``day`` rotates at local midnight, also across daylight +saving time changes, or at the first local time of the new date where such a +change skips midnight. When the clock is set back at the end of daylight saving +time, the repeated hour is part of the same hour period, so with ``hour`` a +single file holds both passes of that hour. In addition to this, it is also possible to specify the ``rotate-interval`` as a relative value. One example is to rotate the log file each X seconds. @@ -498,7 +504,10 @@ relative value. One example is to rotate the log file each X seconds. The example above rotates eve-log each 30 seconds. This could be replaced with ``30m`` to rotate every 30 minutes, ``30h`` to rotate every 30 hours, ``30d`` -to rotate every 30 days, or ``30w`` to rotate every 30 weeks. +to rotate every 30 days, or ``30w`` to rotate every 30 weeks. Relative values +are counted from startup or the last SIGHUP and are not aligned to the local +time, so e.g. ``24h`` or ``1d`` do not rotate at local midnight like ``day`` +does. .. _multiple-eve-instances: diff --git a/src/runmode-unittests.c b/src/runmode-unittests.c index fde9c66483..78265e4b27 100644 --- a/src/runmode-unittests.c +++ b/src/runmode-unittests.c @@ -69,6 +69,7 @@ #include "util-cidr.h" #include "util-coredump-config.h" #include "util-unittest-helper.h" +#include "util-logopenfile.h" #include "util-rule-vars.h" #include "util-classification-config.h" #include "util-threshold-config.h" @@ -134,6 +135,7 @@ static void RegisterUnittests(void) { UTHRegisterTests(); SCTimeRegisterTests(); + LogFileRegisterTests(); StreamTcpRegisterTests(); SigRegisterTests(); SCReputationRegisterTests(); diff --git a/src/util-logopenfile.c b/src/util-logopenfile.c index a84e9a85e4..b9a3929244 100644 --- a/src/util-logopenfile.c +++ b/src/util-logopenfile.c @@ -32,6 +32,8 @@ #include "util-conf.h" #include "util-path.h" #include "util-misc.h" +#include "util-time.h" +#include "util-unittest.h" #include "log-maintenance.h" #if defined(HAVE_SYS_UN_H) && defined(HAVE_SYS_SOCKET_H) && defined(HAVE_SYS_TYPES_H) @@ -209,6 +211,75 @@ static void SCLogFileFlush(LogFileCtx *log_ctx) SCMutexUnlock(&log_ctx->fp_mutex); } +/** + * \brief Get a number identifying the local day, hour or minute of tm + * + * The number is only compared for equality to detect that the local period + * changed, it is not a count of elapsed time. Counting 366 days per year keeps + * the number unique for every tm_yday (0-365), as with 365, Dec 31 of a leap + * year would get the same number as Jan 1 of the next year. + */ +static int64_t LogFileRotatePeriod(LogFileRotateUnit unit, const struct tm *tm) +{ + const int64_t day = (int64_t)tm->tm_year * 366 + tm->tm_yday; + const int64_t hour = day * 24 + tm->tm_hour; + const int64_t minute = hour * 60 + tm->tm_min; + + if (unit == LOGFILE_ROTATE_ON_NEW_DAY) { + return day; + } + if (unit == LOGFILE_ROTATE_ON_NEW_HOUR) { + return hour; + } + return minute; +} + +/** + * \brief Record the rotation period of now and schedule the next rotation check + * + * Calendar units (minute, hour, day) are checked at the start of every local + * minute, relative intervals when the interval has passed. + */ +static void LogFileRotateArm(LogFileCtx *log_ctx, time_t now) +{ + if (log_ctx->rotate_unit == LOGFILE_ROTATE_ON_FIXED_PERIOD) { + log_ctx->rotate_time = now + log_ctx->rotate_interval; + return; + } + + struct tm local_tm; + struct tm *tms = SCLocalTime(now, &local_tm); + if (tms == NULL) { + return; + } + log_ctx->rotate_time = now + 60 - tms->tm_sec; + log_ctx->rotate_period = LogFileRotatePeriod(log_ctx->rotate_unit, tms); +} + +/** + * \brief Update the rotation state to now and report if the log file must be rotated + * + * Calendar units rotate when the local time period changes, so rotation stays + * aligned with local midnight across DST transitions. + * + * \retval true if the log file must be rotated + */ +static bool LogFileRotateUpdate(LogFileCtx *log_ctx, time_t now) +{ + if (now < log_ctx->rotate_time) { + return false; + } + + if (log_ctx->rotate_unit == LOGFILE_ROTATE_ON_FIXED_PERIOD) { + log_ctx->rotate_time = now + log_ctx->rotate_interval; + return true; + } + + const int64_t prev_period = log_ctx->rotate_period; + LogFileRotateArm(log_ctx, now); + return log_ctx->rotate_period != prev_period; +} + /** * \brief Handle log file rotation checks and updates * \param log_ctx Log file context @@ -218,16 +289,14 @@ static bool HandleLogRotation(LogFileCtx *log_ctx) { if (log_ctx->rotation_flag) { log_ctx->rotation_flag = 0; - SCConfLogReopen(log_ctx); - if (log_ctx->flags & LOGFILE_ROTATE_INTERVAL) { - log_ctx->rotate_time = time(NULL) + log_ctx->rotate_interval; + if (log_ctx->rotate_unit != LOGFILE_ROTATE_NONE) { + LogFileRotateArm(log_ctx, time(NULL)); } + SCConfLogReopen(log_ctx); return true; - } else if (log_ctx->flags & LOGFILE_ROTATE_INTERVAL) { - time_t now = time(NULL); - if (now >= log_ctx->rotate_time) { + } else if (log_ctx->rotate_unit != LOGFILE_ROTATE_NONE) { + if (LogFileRotateUpdate(log_ctx, time(NULL))) { SCConfLogReopen(log_ctx); - log_ctx->rotate_time = now + log_ctx->rotate_interval; return true; } } @@ -537,29 +606,24 @@ int SCConfLogOpenGeneric( /* Rotate log file based on time */ const char *rotate_int = SCConfNodeLookupChildValue(conf, "rotate-interval"); if (rotate_int != NULL) { - time_t now = time(NULL); - log_ctx->flags |= LOGFILE_ROTATE_INTERVAL; - /* Use a specific time */ if (strcmp(rotate_int, "minute") == 0) { - log_ctx->rotate_time = now + SCGetSecondsUntil(rotate_int, now); - log_ctx->rotate_interval = 60; + log_ctx->rotate_unit = LOGFILE_ROTATE_ON_NEW_MINUTE; } else if (strcmp(rotate_int, "hour") == 0) { - log_ctx->rotate_time = now + SCGetSecondsUntil(rotate_int, now); - log_ctx->rotate_interval = 3600; + log_ctx->rotate_unit = LOGFILE_ROTATE_ON_NEW_HOUR; } else if (strcmp(rotate_int, "day") == 0) { - log_ctx->rotate_time = now + SCGetSecondsUntil(rotate_int, now); - log_ctx->rotate_interval = 86400; + log_ctx->rotate_unit = LOGFILE_ROTATE_ON_NEW_DAY; } /* Use a timer */ else { + log_ctx->rotate_unit = LOGFILE_ROTATE_ON_FIXED_PERIOD; log_ctx->rotate_interval = SCParseTimeSizeString(rotate_int); if (log_ctx->rotate_interval == 0) { FatalError("invalid rotate-interval value"); } - log_ctx->rotate_time = now + log_ctx->rotate_interval; } + LogFileRotateArm(log_ctx, time(NULL)); } filetype = SCConfNodeLookupChildValue(conf, "filetype"); @@ -1138,3 +1202,135 @@ int LogFileWrite(LogFileCtx *file_ctx, MemBuffer *buffer) return 0; } + +/* the test needs POSIX TZ rules, which Windows does not support */ +#if defined(UNITTESTS) && !defined(OS_WIN32) +/** + * \brief Call the rotation check for the 10 seconds around every quarter hour + * from 1 hour before to 26 hours after the DST switch, as if a log + * record was written each of these seconds, and check that it rotates + * exactly when the filename pattern expands to a new name. + * + * All timezones in use have UTC offsets in multiples of 15 minutes, so the + * switch and every local hour and day start fall on a UTC quarter hour. The + * 26 hours reach the first local midnight after the switch, where a day + * rotation with a fixed length of 86400 seconds would be off by the DST shift. + */ +static int LogFileRotateTestAroundSwitch( + LogFileRotateUnit unit, const char *pattern, time_t dst_switch) +{ + const time_t start = dst_switch - 3600; + const time_t end = dst_switch + 26 * 3600; + + LogFileCtx ctx; + memset(&ctx, 0, sizeof(ctx)); + ctx.rotate_unit = unit; + LogFileRotateArm(&ctx, start); + + char file_name[32]; + FAIL_IF(SCTimeToStringPattern(start, pattern, file_name, sizeof(file_name)) != 0); + int rotations = 0; + + for (time_t quarter = start + 900; quarter < end; quarter += 900) { + for (time_t now = quarter - 5; now < quarter + 5; now++) { + char expected_name[32]; + FAIL_IF(SCTimeToStringPattern(now, pattern, expected_name, sizeof(expected_name)) != 0); + const bool name_changed = strcmp(expected_name, file_name) != 0; + + const bool rotated = LogFileRotateUpdate(&ctx, now); + FAIL_IF(rotated != name_changed); + + if (rotated) { + strlcpy(file_name, expected_name, sizeof(file_name)); + rotations++; + } + } + } + /* a window without any name change would prove nothing */ + FAIL_IF(rotations == 0); + PASS; +} + +/** \brief Set the timezone of the process, NULL for the system default */ +static void LogFileRotateTestSetTimezone(const char *tz) +{ + if (tz != NULL) { + setenv("TZ", tz, 1); + } else { + unsetenv("TZ"); + } + tzset(); + SCLocalTimeCacheReset(); +} + +/** \brief Check the rotation of all units around both DST switches of tz */ +static int LogFileRotateTestTimezone(const char *tz, time_t dst_start, time_t dst_end) +{ + const struct { + LogFileRotateUnit unit; + const char *pattern; + } units[] = { + { LOGFILE_ROTATE_ON_NEW_MINUTE, "%Y-%m-%d-%H:%M" }, + { LOGFILE_ROTATE_ON_NEW_HOUR, "%Y-%m-%d-%H" }, + { LOGFILE_ROTATE_ON_NEW_DAY, "%Y-%m-%d" }, + }; + + LogFileRotateTestSetTimezone(tz); + for (size_t u = 0; u < ARRAY_SIZE(units); u++) { + FAIL_IF_NOT(LogFileRotateTestAroundSwitch(units[u].unit, units[u].pattern, dst_start) == 1); + FAIL_IF_NOT(LogFileRotateTestAroundSwitch(units[u].unit, units[u].pattern, dst_end) == 1); + } + PASS; +} + +/** \test minute, hour and day rotations follow the local time, also around + * DST transitions of timezones with unusual rules */ +static int LogFileRotateTest01(void) +{ + /* POSIX TZ rules of timezones with DST, and their DST switches in 2026 */ + const struct { + const char *tz; + time_t dst_start; + time_t dst_end; + } timezones[] = { + /* America/New_York: 2026-03-08 07:00 and 2026-11-01 06:00 UTC */ + { "EST5EDT,M3.2.0,M11.1.0", 1772953200, 1793512800 }, + /* America/Havana, DST start skips midnight: 2026-03-08 and 2026-11-01 05:00 UTC */ + { "CST5CDT,M3.2.0/0,M11.1.0/1", 1772946000, 1793509200 }, + /* Europe/Prague: 2026-03-29 and 2026-10-25 01:00 UTC */ + { "CET-1CEST,M3.5.0,M10.5.0/3", 1774746000, 1792890000 }, + /* Australia/Sydney: 2026-10-03 and 2026-04-04 16:00 UTC */ + { "AEST-10AEDT,M10.1.0,M4.1.0/3", 1791043200, 1775318400 }, + /* Australia/Lord_Howe, 30 minute DST: 2026-10-03 15:30 and 2026-04-04 15:00 UTC */ + { "<+1030>-10:30<+11>-11,M10.1.0,M4.1.0", 1791041400, 1775314800 }, + /* Pacific/Chatham, switches at 02:45 and 03:45: 2026-09-26 and 2026-04-04 14:00 UTC */ + { "<+1245>-12:45<+1345>,M9.5.0/2:45,M4.1.0/3:45", 1790431200, 1775311200 }, + }; + + const char *env_tz = getenv("TZ"); + char *orig_tz = env_tz != NULL ? SCStrdup(env_tz) : NULL; + FAIL_IF(env_tz != NULL && orig_tz == NULL); + + int result = 1; + for (size_t i = 0; i < ARRAY_SIZE(timezones); i++) { + if (LogFileRotateTestTimezone( + timezones[i].tz, timezones[i].dst_start, timezones[i].dst_end) != 1) { + result = 0; + break; + } + } + + /* restore the timezone before reporting, also when a check failed */ + LogFileRotateTestSetTimezone(orig_tz); + SCFree(orig_tz); + FAIL_IF_NOT(result == 1); + PASS; +} +#endif /* UNITTESTS && !OS_WIN32 */ + +void LogFileRegisterTests(void) +{ +#if defined(UNITTESTS) && !defined(OS_WIN32) + UtRegisterTest("LogFileRotateTest01", LogFileRotateTest01); +#endif +} diff --git a/src/util-logopenfile.h b/src/util-logopenfile.h index 314673ff37..869a4471c9 100644 --- a/src/util-logopenfile.h +++ b/src/util-logopenfile.h @@ -73,6 +73,14 @@ typedef struct LogFileEntry_ { TAILQ_ENTRY(LogFileEntry_) entries; } LogFileEntry; +typedef enum LogFileRotateUnit_ { + LOGFILE_ROTATE_NONE = 0, + LOGFILE_ROTATE_ON_FIXED_PERIOD, /* relative interval, e.g. 30s */ + LOGFILE_ROTATE_ON_NEW_MINUTE, + LOGFILE_ROTATE_ON_NEW_HOUR, + LOGFILE_ROTATE_ON_NEW_DAY, +} LogFileRotateUnit; + /** Global structure for Output Context */ typedef struct LogFileCtx_ { union { @@ -126,12 +134,17 @@ typedef struct LogFileCtx_ { uint64_t reconn_timer; /** The next time to rotate log file, if rotate interval is - specified. */ + specified. For calendar units, the next time to check if the + local time period changed. */ time_t rotate_time; /** The interval to rotate the log file */ uint64_t rotate_interval; + LogFileRotateUnit rotate_unit; + /** Local time period of the open file, for calendar units */ + int64_t rotate_period; + /**< Used by some alert loggers like the unified ones that append * the date onto the end of files. */ char *prefix; @@ -177,9 +190,6 @@ typedef struct LogFileCtx_ { /* Min time (msecs) before trying to reconnect a Unix domain socket */ #define LOGFILE_RECONN_MIN_TIME 500 -/* flags for LogFileCtx */ -#define LOGFILE_ROTATE_INTERVAL 0x04 - /* Default EVE output buffering size */ #define LOGFILE_EVE_BUFFER_SIZE 0 @@ -199,4 +209,6 @@ void LogFileUnregister(LogFileCtx *ctx); void LogFileFlushAll(void); void LogFileRotateAll(void); +void LogFileRegisterTests(void); + #endif /* SURICATA_UTIL_LOGOPENFILE_H */ diff --git a/src/util-time.c b/src/util-time.c index 868d8ff50a..9bf8890577 100644 --- a/src/util-time.c +++ b/src/util-time.c @@ -429,6 +429,18 @@ void CreateTimeString(const SCTime_t ts, char *str, size_t size) #endif /* defined(__OpenBSD__) */ +#ifdef UNITTESTS +/** \brief Forget the local times cached by the calling thread, e.g. after the + * timezone was changed */ +void SCLocalTimeCacheReset(void) +{ +#ifdef TLS + memset(last_local_time, 0, sizeof(last_local_time)); + memset(cached_minute_start, 0, sizeof(cached_minute_start)); +#endif +} +#endif + /** * \brief Convert broken-down time to seconds since Unix epoch. * diff --git a/src/util-time.h b/src/util-time.h index a9dec3adac..2e577ca4b5 100644 --- a/src/util-time.h +++ b/src/util-time.h @@ -139,6 +139,7 @@ SCTime_t TimeGet(void); void TimeSet(SCTime_t); void TimeSetToCurrentTime(void); void TimeSetIncrementTime(uint32_t); +void SCLocalTimeCacheReset(void); #endif bool TimeModeIsReady(void);