Dovecot: Time moved forwards

Drat, I was wrong, just had another instance appear it the logs, albeit, not happening as frequently.
 
sko said:
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.
Click to expand...
Agreed, though I don't see it "at every single mail". I looked at the commits you posted, and at the code around them, but could not find anything obvious.
 
RypPn said:

Time moved forwards - dovecot - dovecot.org

dovecot.org dovecot.org

Re: Failing to archive many messages - dovecot - dovecot.org

dovecot.org dovecot.org

Clues?
Click to expand...

From the first link:
Has nothing to do with epoll. Dovecot uses kqueue on FreeBSD. This indicates
clock issues, you should use ntpd to avoid this, alternatively your VM/machine
is lagging and clock is jumping forward.

Aki
Click to expand...

At least we know it uses kqueue on FreeBSD, but that boilerplate "solution" is simply useless. Hosts are perfectly synced, yet the errors still flood the log with wildly varying offsets, even if the messages are only a few seconds apart:
Code: 
May  7 06:15:00 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.199006 seconds - adjusting timeouts.
May  7 06:15:07 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.265371 seconds - adjusting timeouts.
[...]
May  7 07:22:08 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.395615 seconds - adjusting timeouts.
May  7 07:22:39 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.409265 seconds - adjusting timeouts.
[...]
May  7 09:33:10 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.155254 seconds - adjusting timeouts.
May  7 09:33:18 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.319233 seconds - adjusting timeouts.
[...]
May  7 11:32:08 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.127303 seconds - adjusting timeouts.
May  7 11:32:12 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.236399 seconds - adjusting timeouts.
[...]
May  7 12:07:12 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.479545 seconds - adjusting timeouts.
May  7 12:07:23 dovecot dovecot[76104]: master: Warning: Time moved forwards by 0.357021 seconds - adjusting timeouts.

I just picked a few examples I saw while scrolling through the log.
I initially thought this occurs at every processed mail, because the number of occurences of those messages in the logfiles roughly matched the number of mails that host processes in the same timeframe (i.e. a single day). But actually those messages seem to occur roughly 30 seconds after every "imap-login: Disconnected:" or "imap(user)<pid><mailid>: Disconnected" log entry. So it seems imap disconnects are triggering that bogus code, not processed mails.

ntpdate always adjusts time in the range of 3-4 orders of magnitudes lower when called manually than dovecot claims it is off:
Code: 
# service ntpd stop && ntpdate pool.ntp.org
Stopping ntpd.
Waiting for PIDS: 12290.
 7 May 12:29:15 ntpdate[56703]: adjust time server 131.188.3.223 offset -0.000112 sec

So the mechanism dovecot is using is definitely broken and needs to be fixed/disabled or at least its bogus log messages muted...

I am on leave this week, so I hopefully find the time putting together a bug report with all the details to clearly show the host clock isn't at fault.
 
Still waiting for "moderator approval" of my message to the dovecot mailing list... because apparently they don't accept plaintext messages:
Code: 
The message's content type was not explicitly allowed
 
You must log in or register to reply here.
Back
Top