Dovecot: Time moved forwards

X

xtaz

Not related to the original problem, but will hijack the thread slightly now it's solved. Is anyone seeing messages like this since 2.3.17?

dovecot[46267]: master: Warning: Time moved forwards by 0.105716 seconds - adjusting timeout
s.

Happens to me about every 3 hours or so. NTP is perfectly synced, no issues, no jumping around. 2.3.16 didn't show this message. Curious if it's just me or not.
 
xtaz said:
Not related to the original problem, but will hijack the thread slightly now it's solved.
Click to expand...
Split off to its own thread. Because A) the original thread title indicates a very different issue. B) it's been marked as "Solved". And C) your issue is not about installing ports/packages, so it's in the wrong section. Thus your issue is just going to get ignored.
 
xtaz said:
Time moved forwards by 0.105716 seconds
Click to expand...
Ah, apparently it's the World Atomic Clock issue... your NTP servers apparently report the difference between their system clock and the world standard difference... also, in the US, at least, there's such a thing as Daylight Savings Time, and this past Sunday (Nov. 7, 2021) in US, clocks needed to be set back an hour. I'm probably not explaining very well, but I think that's the gist of the issue.
 
It's not just you, i have the same message in the logs
Code: 
Nov  9 00:34:56 mail dovecot[947]: master: Warning: Time moved forwards by 0.420688 seconds - adjusting timeouts.
Nov  9 01:06:35 mail dovecot[947]: master: Warning: Time moved forwards by 0.125714 seconds - adjusting timeouts.
Nov  9 04:06:14 mail dovecot[947]: master: Warning: Time moved forwards by 0.132886 seconds - adjusting timeouts.
Nov  9 04:16:37 mail dovecot[947]: master: Warning: Time moved forwards by 0.262978 seconds - adjusting timeouts.
Nov  9 05:04:02 mail dovecot[947]: master: Warning: Time moved forwards by 0.242597 seconds - adjusting timeouts.
Nov  9 05:06:34 mail dovecot[947]: master: Warning: Time moved forwards by 0.154964 seconds - adjusting timeouts.
Nov  9 05:26:35 mail dovecot[947]: master: Warning: Time moved forwards by 0.165462 seconds - adjusting timeouts.
Nov  9 05:34:07 mail dovecot[947]: master: Warning: Time moved forwards by 0.167397 seconds - adjusting timeouts.
Nov  9 06:12:46 mail dovecot[947]: master: Warning: Time moved forwards by 0.176904 seconds - adjusting timeouts.
Nov  9 07:15:06 mail dovecot[947]: master: Warning: Time moved forwards by 0.446817 seconds - adjusting timeouts.
Nov  9 08:11:25 mail dovecot[947]: master: Warning: Time moved forwards by 0.443603 seconds - adjusting timeouts.
Nov  9 09:43:12 mail dovecot[947]: master: Warning: Time moved forwards by 0.368009 seconds - adjusting timeouts.
 
Yeah OK. Sorry about the thread hijack!

We did move to DST last weekend but my maillog has rotated too much to go back that far now. I can't recall if it was doing it before the DST change.

I've tried restarting both dovecot and chrony which I use for ntp, hasn't made any difference. But OK. If someone else is seeing the same message then it's not just me at least.

My clock is synced to a much more accurate level than what dovecot is reporting as well. Dovecot is reporting it to one decimal place, whereas it's synced to within 4 decimal places.

System time : 0.000128243 seconds slow of NTP time
 
Can confirm this on 12.2-RELEASE:
Code: 
# grep "Time moved" /var/log/maillog*
/var/log/maillog.1:Nov  8 16:15:26 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.100464 seconds - adjusting timeouts.
/var/log/maillog.1:Nov  8 17:30:42 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.104240 seconds - adjusting timeouts.

xtaz said:
We did move to DST last weekend but my maillog has rotated too much to go back that far now. I can't recall if it was doing it before the DST change.
Click to expand...
DST doesn't affect dovecot as it relies on system time (as all services usually do), which is always UTC. DST and time zones are only applied to representations in userspace (e.g. log entries). This is also explained in this dovecot wiki entrance about the "Time moved backwards" error: https://wiki.dovecot.org/TimeMovedBackwards

Maybe this is what the message states and only a (informational) warning that has been enabled recently with version 2.3.17?
 
sko said:
Maybe this is what the message states and only a (informational) warning that has been enabled recently with version 2.3.17?
Click to expand...
Problem is those are huge time slews. The deltas should really be less than 10 milliseconds. Something's odd. The fact there are no Google results for this suggests this may be a problem specific to Freebsd. Might be worth asking on the Dovecot mail list.
 
Jose said:
The fact there are no Google results for this suggests this may be a problem specific to Freebsd.
Click to expand...
Doesn't appear to be that common though:
Code: 
root@mail:~ # grep "Time moved" /var/log/maillog*
root@mail:~ # pkg version -vRx dovecot
Updating SirDice repository catalogue...
SirDice repository is up to date.
All repositories are up to date.
dovecot-2.3.17_1                   =   up-to-date with remote
dovecot-pigeonhole-0.5.17          =   up-to-date with remote
 
For reference:
Code: 
# ntpdate -q ntp.transip.nl
server 2a01:7c8:123::123, stratum 1, offset +0.000149, delay 0.02618
server 2a01:7c8:123:1::123, stratum 1, offset +0.000043, delay 0.02751
server 37.97.255.10, stratum 1, offset +0.000167, delay 0.02715
server 37.97.255.1, stratum 1, offset +0.000191, delay 0.02603
10 Nov 17:34:12 ntpdate[52568]: adjust time server 37.97.255.1 offset +0.000191 sec
# ps -ax | grep ntp
  817  -  I<s      0:00.31 /usr/local/sbin/ntpd -f /usr/local/etc/ntpd.conf
  818  -  I<s      0:00.99 ntpd: ntp engine (ntpd)
  820  -  Is       0:00.00 ntpd: dns engine (ntpd)
52605  5  S+       0:00.00 grep ntp
 
From the Dovecot changelog
Dovecot now logs a warning if time seems to jump forward at least
100 milliseconds.
Click to expand...

My offset time is
offset -0.001126, delay 0.03377
Click to expand...
So i don't see why it's detected by dovecot and logged. Also noticed that it's logged only during low traffic hours or when the CPU is mostly IDLE on two different mail servers (different hardware).

Here's the log for 24h period from yesterday

Code: 
% bzcat maillog.0.bz2 | grep timeouts
Nov  9 00:27:30 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.118760 seconds - adjusting timeouts.
Nov  9 00:57:30 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.104417 seconds - adjusting timeouts.
Nov  9 02:39:29 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.114164 seconds - adjusting timeouts.
Nov  9 02:41:12 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.117475 seconds - adjusting timeouts.
Nov  9 04:38:21 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.100457 seconds - adjusting timeouts.
Nov  9 04:47:02 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.122583 seconds - adjusting timeouts.
Nov  9 04:51:14 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.106600 seconds - adjusting timeouts.
Nov  9 18:13:54 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.114932 seconds - adjusting timeouts.
Nov  9 20:21:05 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.111471 seconds - adjusting timeouts.
Nov  9 20:23:57 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.123350 seconds - adjusting timeouts.
Nov  9 21:39:38 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.123967 seconds - adjusting timeouts.
Nov  9 22:47:15 mx1 dovecot[462]: master: Warning: Time moved forwards by 0.119459 seconds - adjusting timeouts.

Code: 
% bzcat maillog.0.bz2 | grep timeouts
Nov  9 00:34:56 mail dovecot[947]: master: Warning: Time moved forwards by 0.420688 seconds - adjusting timeouts.
Nov  9 01:06:35 mail dovecot[947]: master: Warning: Time moved forwards by 0.125714 seconds - adjusting timeouts.
Nov  9 04:06:14 mail dovecot[947]: master: Warning: Time moved forwards by 0.132886 seconds - adjusting timeouts.
Nov  9 04:16:37 mail dovecot[947]: master: Warning: Time moved forwards by 0.262978 seconds - adjusting timeouts.
Nov  9 05:04:02 mail dovecot[947]: master: Warning: Time moved forwards by 0.242597 seconds - adjusting timeouts.
Nov  9 05:06:34 mail dovecot[947]: master: Warning: Time moved forwards by 0.154964 seconds - adjusting timeouts.
Nov  9 05:26:35 mail dovecot[947]: master: Warning: Time moved forwards by 0.165462 seconds - adjusting timeouts.
Nov  9 05:34:07 mail dovecot[947]: master: Warning: Time moved forwards by 0.167397 seconds - adjusting timeouts.
Nov  9 06:12:46 mail dovecot[947]: master: Warning: Time moved forwards by 0.176904 seconds - adjusting timeouts.
Nov  9 07:15:06 mail dovecot[947]: master: Warning: Time moved forwards by 0.446817 seconds - adjusting timeouts.
Nov  9 08:11:25 mail dovecot[947]: master: Warning: Time moved forwards by 0.443603 seconds - adjusting timeouts.
Nov  9 09:43:12 mail dovecot[947]: master: Warning: Time moved forwards by 0.368009 seconds - adjusting timeouts.
Nov  9 21:40:03 mail dovecot[947]: master: Warning: Time moved forwards by 0.348405 seconds - adjusting timeouts.
Nov  9 22:48:05 mail dovecot[947]: master: Warning: Time moved forwards by 0.115411 seconds - adjusting timeouts.
Nov  9 23:13:06 mail dovecot[947]: master: Warning: Time moved forwards by 0.119546 seconds - adjusting timeouts.
 
Mine is bare metal, and my NTP sync is pretty accurate. I don't have any CPU power management enabled.

Code: 
System time     : 0.000030218 seconds slow of NTP time
Last offset     : -0.000077508 seconds
RMS offset      : 0.000084565 seconds

According to the NTP stats there's no huge 0.1 slews at all.
 
Have you tried stopping chrony from running and seeing if it continues to happen? Your RTC should be keeping time accurately enough to be able to leave it off for several days.
 
Update:
I don't see this as often as others in this thread:
Code: 
# grep "moved forward" /var/log/maillog*
/var/log/maillog:Nov 16 00:23:31 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.111175 seconds - adjusting timeouts.
/var/log/maillog:Nov 16 15:38:16 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.104987 seconds - adjusting timeouts.
/var/log/maillog.0:Nov 15 13:48:46 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.100828 seconds - adjusting timeouts.
/var/log/maillog.0:Nov 15 16:23:18 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.145804 seconds - adjusting timeouts.
/var/log/maillog.2:Nov 13 03:57:49 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.100584 seconds - adjusting timeouts.
/var/log/maillog.4:Nov 11 10:35:09 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.123763 seconds - adjusting timeouts.
/var/log/maillog.5:Nov 10 17:09:45 dovecot dovecot[34877]: master: Warning: Time moved forwards by 0.128817 seconds - adjusting timeouts.

yet I was still curious if there is any hint on *why* those warnings are generated. Unfortunately the commit only states this could be helpful figuring out performance problems [1]. I haven't looked at the code, but is it possible that dovecot keeps an internal timer and (more or less) regularly compares it to the system time? This might explain the relatively huge jumps compared to the actual deviation that NTP reports/adjusts.


edit:

the comment in the parent commit [2] talks about using epoll to measure timeouts:
/* Dovecot attempts to detect also when time suddenly jumps forwards.
This is done by getting the minimum timeout wait in epoll() (or similar)
and then seeing if the current time after epoll() is past the timeout.
This can't be very exact, so likely the difference is always at least
1 microsecond. In high load situations it can be somewhat higher.
Dovecot generally doesn't have very important short timeouts, so to avoid
logging many warnings about this, use a rather high value. */
Click to expand...

There is no epoll on FreeBSD. So is this solved differently (kqueue?) on FreeBSD? Might this be the reason why we see bigger jumps than expected/filtered by the minimum threshold (100000) set for IOLOOP_TIME_MOVED_FORWARDS_MIN_USECS?



[1] https://github.com/dovecot/core/commit/0768778bb6e820013709f42d4aa845e161a119f4
[2] https://github.com/dovecot/core/commit/24216a4924d03756cb66f18f285ab8e8023b2e2a
 
Is there any solution for this?
I am on FreeBSD 13.3 with dovecot-2.3.21_4 built from ports andd have the same warning:
Code: 
Apr 26 08:42:29 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.181936 seconds - adjusting timeouts.
Apr 26 08:43:39 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.146834 seconds - adjusting timeouts.
Apr 26 08:48:40 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.489300 seconds - adjusting timeouts.
Apr 26 08:51:02 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.360819 seconds - adjusting timeouts.
Apr 26 08:52:30 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.122254 seconds - adjusting timeouts.
Apr 26 08:56:42 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.258556 seconds - adjusting timeouts.
Apr 26 08:57:42 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.108032 seconds - adjusting timeouts.
Apr 26 09:01:02 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.470992 seconds - adjusting timeouts.
Apr 26 09:02:43 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.319990 seconds - adjusting timeouts.
Apr 26 09:03:00 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.105709 seconds - adjusting timeouts.
Apr 26 09:03:43 mstore17 dovecot[41779]: master: Warning: Time moved forwards by 0.120402 seconds - adjusting timeouts.
The more emails coming in, the more often warning.
 
TBH I have completely forgotten about this, but:

Code: 
root@dovecot:~ # bzgrep "Time moved forwards" /var/log/maillog.0.bz2 | wc -l
     558


There's still zero information about this to be found - the sole search result on duckduckgo for 'Dovecot "Time moved forwards"' is this thread.
Given that this even happens on perfectly ntp-synced hosts, I suspect the mechanism dovecot uses to determine time drift is broken. So maybe a PR to disable it (or at least the bogus warnings) should be filed?
 
Also seeing this on our mailservers and as sko reported, we should report this to dovecot mailing lists.
Dovecot's documentation also briefly notes about time moving forwards (which is less critical than time moving backwards from what I can understand):

[...]
Dovecot v2.0 also notices when time unexpectedly jumps forwards. In that situation it logs a warning and also updates timeouts.

The reason why imap/pop3 processes get killed and new ones can’t be created for a while is to avoid problems related to timestamps. Some issues are:

  • Uniqueness of Maildir filenames and dbox global unique identifiers relies on a growing timestamp.
  • Dotlock files’ staleness is detected by looking at its mtime.
  • Timestamps are stored internally all around in memory (as well as in index files) and compared to current time. Those checks may or may not be buggy if current time shrinks.
While killing mail processes doesn’t fully solve any of those issues, they’re at least less likely to happen then.
Click to expand...
 
I'd probably want to use local mechanisms to suppress that message - as in tell the mail daemon to not write this one to /var/log/maillog... And make some good notes on how that was done so that it can be turned on and off easily.
 
MAM said:
Yeah, there should be a fix for this. This syslog spamming is annoying me too and of course, I do not want to turn off warnings of the mail service...
Click to expand...
Well, there's ways to fine-tune that syslog and maillog spamming, but it does require spending some time with it, and getting a good handle on what should be turned off, what's better kept on, and the like. If maillog is getting spammed too often, that may be a sign of a DDOS (and require a very different course of action).
 
I get these, albeit very infrequently. Then again, my mail volume is very low. One thing I noticed that is interesting is that the time diff never reaches 0.5 seconds.
 
Jose said:
I get these, albeit very infrequently. Then again, my mail volume is very low. One thing I noticed that is interesting is that the time diff never reaches 0.5 seconds.
Click to expand...
That's because I suspect the mechanism dovecot uses is borked and in fact responsible for all those (alleged) time diffs.
As said: this even happens on a perfectly synced host that has very little time deviation according to ntp - but dovecot claims it is constantly off (at *every single mail* that is delivered) by several orders of magnitude more than ntp is stating/adjusting.
 
What causes this and the mechanism behind it, I am unsure of, but I certainly experience the same symptoms.

In an effort to narrow down where this happens, I found an old backup containing dovecot and dovecot-pigeonhole 1.3.20 build info. Guess what, no spamming of the logs, so this is specific to 1.3.21

I'm obviously feeling a little exposed using a slightly older version so I hope we can bottom this one out appropriately.

I'd open a PR for it, but other than showing the "Time moved forward" in my logs, I have not much else to offer, so maybe driven by a more technical mind would be better.
 
You must log in or register to reply here.
Back
Top