# Dovecot: Time moved forwards



## xtaz (Nov 9, 2021)

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.


----------



## Jose (Nov 9, 2021)

xtaz said:


> Not related to the original problem, but will hijack the thread slightly now it's solved.


Why not start a new thread? It don't cost nothin'.


----------



## SirDice (Nov 9, 2021)

xtaz said:


> Not related to the original problem, but will hijack the thread slightly now it's solved.


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.


----------



## astyle (Nov 9, 2021)

xtaz said:


> Time moved forwards by 0.105716 seconds


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.


----------



## VladiBG (Nov 9, 2021)

It's not just you, i have the same message in the logs

```
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.
```


----------



## xtaz (Nov 9, 2021)

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


----------



## sko (Nov 10, 2021)

Can confirm this on 12.2-RELEASE:

```
# 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.


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?


----------



## Jose (Nov 10, 2021)

sko said:


> Maybe this is what the message states and only a (informational) warning that has been enabled recently with version 2.3.17?


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.


----------



## SirDice (Nov 10, 2021)

Jose said:


> The fact there are no Google results for this suggests this may be a problem specific to Freebsd.


Doesn't appear to be that common though:

```
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
```


----------



## SirDice (Nov 10, 2021)

For reference:

```
# 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
```


----------



## VladiBG (Nov 10, 2021)

From the Dovecot changelog


> Dovecot now logs a warning if time seems to jump forward at least
> 100 milliseconds.



My offset time is


> offset -0.001126, delay 0.03377


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


```
% 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.
```


```
% 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.
```


----------



## Jose (Nov 10, 2021)

Maybe a power management CPU frequency thing?


----------



## msplsh (Nov 11, 2021)

Is this on bare metal or a VM?


----------



## xtaz (Nov 11, 2021)

Mine is bare metal, and my NTP sync is pretty accurate. I don't have any CPU power management enabled.


```
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.


----------



## msplsh (Nov 11, 2021)

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.


----------



## sko (Nov 16, 2021)

Update:
I don't see this as often as others in this thread:

```
# 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
> ...



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


----------

