dovecot - Oct 2009 - "Time just moved backwards" in Dovecot in a Xen DomU

On Mon, 2009-10-05 at 18:54 -0700, PGNet Dev wrote:
> i'm running Dovecot in a Xen DomU,
..
> @ my Dom0,
> 
> 	ps ax | grep ntp\.conf
> 		 5696 ?        Ss     1:05 /usr/sbin/ntpd -p /var/run/ntp/ntpd.pid
> -g -u ntp:ntp -i /var/lib/ntp -c /etc/ntp.conf
And no ntpd in your DomU?
> not clear to me as to what/where the problem actually is.  i've not
> seen an other dameons report any time issues; of course, i'm not sure
> they're _checking_ :-/
I'm not aware of any other daemon that explicitly checks and complains
about it. They might randomly break though. :)
> any suggestions as to what/how to fix?
If no one here can give you a good answer, I'd try some Xen mailing
list. I'm sure a lot of people are running Dovecot in Xen without time
problems. If you do find out the problem, please let us know also.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20091005/fd810689/attachment-0002.bin>

i've

	dovecot --version
		1.2.5
	hg log | grep changeset | head -n 1
		changeset:   9407:a3e16df805e3

in my logs, i'm seeing

	...
	Oct 05 16:51:40 dovecot: Error: Time just moved backwards by 1
seconds. I'll sleep now until we're back in present.
http://wiki.dovecot.org/TimeMovedBackwards
	Oct 05 17:07:22 dovecot: Error: Time just moved backwards by 1
seconds. I'll sleep now until we're back in present.
http://wiki.dovecot.org/TimeMovedBackwards
	Oct 05 17:23:15 dovecot: Error: Time just moved backwards by 1
seconds. I'll sleep now until we're back in present.
http://wiki.dovecot.org/TimeMovedBackwards
	Oct 05 17:38:23 dovecot: Error: Time just moved backwards by 1
seconds. I'll sleep now until we're back in present.
http://wiki.dovecot.org/TimeMovedBackwards
	...

i'm running Dovecot in a Xen DomU,

	uname -a
		Linux mail 2.6.27.29-0.1-xen #1 SMP 2009-08-15 17:53:59 +0200 x86_64
x86_64 x86_64 GNU/Linux

reading @, http://wiki.dovecot.org/TimeMovedBackwards

	Bugs/Issues
	    * With Xen you should run ntpd only in dom0. Other domains should
synchronize time automatically (see this Xen FAQ).

@ my Dom0,

	ps ax | grep ntp\.conf
		 5696 ?        Ss     1:05 /usr/sbin/ntpd -p /var/run/ntp/ntpd.pid
-g -u ntp:ntp -i /var/lib/ntp -c /etc/ntp.conf

and,

	grep localtime /etc/xen/vm/mail.cfg
		localtime    = 0

looking at my ntp logs around the same time(s).

 ...
 5 Oct 16:41:17 ntpd[5696]: synchronized to 64.125.78.85, stratum 1
 5 Oct 16:51:38 ntpd[5696]: time reset -2.140133 s
 5 Oct 16:56:40 ntpd[5696]: synchronized to 66.220.9.122, stratum 1
 5 Oct 17:01:28 ntpd[5696]: synchronized to 64.125.78.85, stratum 1
 5 Oct 17:07:20 ntpd[5696]: time reset -2.137760 s
 5 Oct 17:11:49 ntpd[5696]: synchronized to 204.152.184.72, stratum 1
 5 Oct 17:15:01 ntpd[5696]: synchronized to 207.200.81.113, stratum 1
 5 Oct 17:20:49 ntpd[5696]: synchronized to 66.220.9.122, stratum 1
 5 Oct 17:23:14 ntpd[5696]: time reset -2.221749 s
 5 Oct 17:27:57 ntpd[5696]: synchronized to 64.125.78.85, stratum 1
 5 Oct 17:32:52 ntpd[5696]: synchronized to 207.200.81.113, stratum 1
 5 Oct 17:38:22 ntpd[5696]: time reset -2.104476 s
 5 Oct 17:42:48 ntpd[5696]: synchronized to 66.220.9.122, stratum 1
 ...

1 second is not a terribly big deal, but it IS an error ...

not clear to me as to what/where the problem actually is.  i've not
seen an other dameons report any time issues; of course, i'm not sure
they're _checking_ :-/

any suggestions as to what/how to fix?

thanks!

hi,

On Mon, Oct 5, 2009 at 4:02 PM, Timo Sirainen <tss at iki.fi>
wrote:
> And no ntpd in your DomU?
nope.

 service ntp status
  Checking for network time protocol daemon (NTPD):   unused
>> any suggestions as to what/how to fix?
>
> If no one here can give you a good answer, I'd try some Xen mailing
> list. I'm sure a lot of people are running Dovecot in Xen without time
> problems. If you do find out the problem, please let us know also.
i've been poring over the lists ... found nothing yet :-/

On 6/10/2009 12:54 PM, PGNet Dev wrote:
> <snip - from dom0>
> looking at my ntp logs around the same time(s).
>
>   ...
>   5 Oct 16:41:17 ntpd[5696]: synchronized to 64.125.78.85, stratum 1
>   5 Oct 16:51:38 ntpd[5696]: time reset -2.140133 s
>   5 Oct 16:56:40 ntpd[5696]: synchronized to 66.220.9.122, stratum 1
>   5 Oct 17:01:28 ntpd[5696]: synchronized to 64.125.78.85, stratum 1
>   5 Oct 17:07:20 ntpd[5696]: time reset -2.137760 s
>   5 Oct 17:11:49 ntpd[5696]: synchronized to 204.152.184.72, stratum 1
>    
This indicates that ntpd is actually stepping the time 2 seconds into 
the past approx every 900 seconds. So dovecot is correct that time has 
moved backwards. You need to stop time moving backwards :-).
[so not dovecot's fault, and likely not xen's fault either]

I'm no ntp expert, but I wonder if searching for 900s in the ntpd man 
page might help (caught my eye due to the step every 15 minutes - 
network congestion and excessive jitter causing stepping)? Otherwise 
perhaps a problem with a bad hardware driver stalling in the middle of 
an interrupt occasionally. Sorry - can't provide any further pointers. 
It is highly dependent on your hardware, kernel & drivers. If you have 
any other physical servers and they are also having 'time reset' error 
messages, then the problem is some odd network configuration - partial 
drop-outs and/or high jitter.

Unfortunately -x will not be a solution here as slew cannot possibly 
correct for a drift as big as 2 in every 900 seconds.

You may want to try just a single upstream ntp server as a debugging 
step (identify it by IP, not by a pool DNS record) and/or use the prefer 
keyword against your favourite.

Cheers,
Rob Middleton.