On 30. Aug 2024, at 19.00, dco2024--- via dovecot
This is not limited to FreeBSD. I'm seeing it on Gentoo Linux. Kernel is 6.6.47-gentoo-x86_64, dovecot 2.3.21.1 (d492236fa0). The warning is logged once every 12-15 hours.
Syslog: 2024-08-24 18:03:49 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100068 seconds - adjusting timeouts. 2024-08-25 06:18:49 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100063 seconds - adjusting timeouts. 2024-08-26 06:52:16 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100062 seconds - adjusting timeouts. 2024-08-26 18:57:54 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100068 seconds - adjusting timeouts. 2024-08-27 07:24:34 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100061 seconds - adjusting timeouts. 2024-08-27 19:38:48 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100060 seconds - adjusting timeouts. 2024-08-28 20:21:44 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100071 seconds - adjusting timeouts. 2024-08-29 08:41:44 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100070 seconds - adjusting timeouts. 2024-08-29 21:04:37 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100071 seconds - adjusting timeouts. 2024-08-30 09:30:36 UTC myhost dovecot: master: Warning: Time moved forwards by 0.100066 seconds - adjusting timeouts.
Chrony ntp keeps the time in sync and the time has been in sync to within 30us of UTC for many days. I noticed that it reports that the unadjusted system clock is about 2.31 ppm fast of UTC. Doing the math for dovecot's 12 hour warning interval: 12 hours * 3600 secs/hour * 2.3/1000000 = 0.0998 seconds. Could it be that dovecot is effectively measuring intervals of the uncorrected system clock time instead of the longer term adjusted time, and it complains when the accumulated NTP adjustments sum to 0.1 seconds.
I don't see how that would be possible. The check is using only just generated timestamps, not anything from a long time ago. I wonder if this kind of a simple patch would be good enough of a fix: diff --git a/src/lib/ioloop.c b/src/lib/ioloop.c index 98c2dc2bf4..a63f861330 100644 --- a/src/lib/ioloop.c +++ b/src/lib/ioloop.c @@ -18,6 +18,7 @@ Dovecot generally doesn't have very important short timeouts, so to avoid logging many warnings about this, use a rather high value. */ #define IOLOOP_TIME_MOVED_FORWARDS_MIN_USECS (100000) +#define IOLOOP_TIME_MOVED_FORWARDS_MIN_USECS_LARGE (1000000) time_t ioloop_time = 0; struct timeval ioloop_timeval; @@ -654,9 +655,13 @@ static void io_loop_handle_timeouts_real(struct ioloop *ioloop) /* the callback may have slept, so check the time again. */ i_gettimeofday(&ioloop_timeval); } else { + int max_diff = diff_usecs < IOLOOP_TIME_MOVED_FORWARDS_MIN_USECS_LARGE ? + IOLOOP_TIME_MOVED_FORWARDS_MIN_USECS : + IOLOOP_TIME_MOVED_FORWARDS_MIN_USECS_LARGE; + diff_usecs = timeval_diff_usecs(&ioloop->next_max_time, &ioloop_timeval); - if (unlikely(-diff_usecs >= IOLOOP_TIME_MOVED_FORWARDS_MIN_USECS)) { + if (unlikely(-diff_usecs >= max_diff)) { io_loops_timeouts_update(-diff_usecs); /* time moved forward */ ioloop->time_moved_callback(&ioloop->next_max_time,