Dovecot says time moves backwards

Discussion in 'ISPConfig 3 Priority Support' started by Taleman, Jun 16, 2020.

  1. Taleman

    Taleman Well-Known Member HowtoForge Supporter

    Yesterday suddenly this started appearing in mail.log:
    Code:
    Jun 15 18:07:36 posti dovecot: log: Warning: Time moved backwards by 3495 seconds.
    Jun 15 18:07:36 posti dovecot: imap: Fatal: Time just moved backwards by 3484 seconds. This might cause a lot of problems, so I'll just kill myself now. http://wiki2.dovecot.org/TimeMovedBackwards
    Jun 15 18:07:36 posti dovecot: master: Warning: Time moved backwards by 3496 seconds, waiting for 180 secs until new services are launched again.
    Jun 15 18:07:36 posti dovecot: imap-login: Warning: Time moved backwards by 3450 seconds.
    Jun 15 18:07:36 posti dovecot: anvil: Warning: Time moved backwards by 3496 seconds.
    Jun 15 18:07:36 posti dovecot: config: Warning: Time moved backwards by 3496 seconds.
    Jun 15 18:07:36 posti dovecot: pop3-login: Warning: Time moved backwards by 3513 seconds.
    Jun 15 18:07:36 posti dovecot: pop3: Fatal: Time just moved backwards by 3513 seconds. This might cause a lot of problems, so I'll just kill myself now. http://wiki2.dovecot.org/TimeMovedBackwards
    Jun 15 18:07:36 posti dovecot: auth: Warning: Time moved backwards by 3496 seconds.
    Jun 15 18:07:36 posti dovecot: ssl-params: Warning: Time moved backwards by 3495 seconds.
    Jun 15 18:07:36 posti dovecot: imap: Fatal: Time just moved backwards by 3484 seconds. This might cause a lot of problems, so I'll just kill myself now. http://wiki2.dovecot.org/TimeMovedBackwards
    Jun 15 18:07:36 posti dovecot: imap: Fatal: Time just moved backwards by 3484 seconds. This might cause a lot of problems, so I'll just kill myself now. http://wiki2.dovecot.org/TimeMovedBackwards
    Jun 15 18:07:36 posti dovecot: imap-login: Warning: Time moved backwards by 3484 seconds.
    Jun 15 18:07:36 posti dovecot: imap-login: Warning: Time moved backwards by 3484 seconds.
    It stopped after a while:
    Code:
    Jun 15 18:23:46 posti dovecot: imap-login: Warning: Time moved backwards by 1714 seconds.
    Jun 15 18:23:46 posti dovecot: imap: Fatal: Time just moved backwards by 1719 seconds. This might cause a lot of problems, so I'll just kill myself now. http://wiki2.dovecot.org/TimeMovedBackwards
    Jun 15 18:23:46 posti dovecot: imap-login: Warning: Time moved backwards by 1714 seconds.
    Jun 15 18:23:47 posti dovecot: imap: Fatal: Time just moved backwards by 1718 seconds. This might cause a lot of problems, so I'll just kill myself now. http://wiki2.dovecot.org/TimeMovedBackwards
    Jun 15 18:23:47 posti dovecot: imap-login: Warning: Time moved backwards by 1714 seconds.
    Jun 15 18:36:29 posti dovecot: imap: Fatal: Time just moved backwards by 1714 seconds. This might cause a lot of problems, so I'll just kill myself now. http://wiki2.dovecot.org/TimeMovedBackwards
    Jun 15 18:36:29 posti dovecot: imap: Fatal: Time just moved backwards by 1714 seconds. This might cause a lot of problems, so I'll just kill myself now. http://wiki2.dovecot.org/TimeMovedBackwards
    
    This host is virtual host running on Proxmox 5. Not a container, full virtual host. Not running ntpdate on ntp on the virtual host.
    I read the dovevot wiki page, but do not understand why this would happen on this host. Any idea what caused it and what to do?
     
  2. Taleman

    Taleman Well-Known Member HowtoForge Supporter

    I found time jump forwards also:
    Code:
    # grep forwards /var/log/mail.log
    Jun 15 17:58:24 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:25 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:25 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:25 posti dovecot: imap: Warning: Time jumped forwards 3487 seconds
    Jun 15 17:58:25 posti dovecot: imap: Warning: Time jumped forwards 3488 seconds
    Jun 15 17:58:29 posti dovecot: imap: Warning: Time jumped forwards 3514 seconds
    Jun 15 17:58:33 posti dovecot: imap: Warning: Time jumped forwards 3514 seconds
    Jun 15 17:58:39 posti dovecot: imap: Warning: Time jumped forwards 3514 seconds
    Jun 15 17:58:40 posti dovecot: imap: Warning: Time jumped forwards 3514 seconds
    Jun 15 17:58:41 posti dovecot: imap: Warning: Time jumped forwards 3514 seconds
    Jun 15 17:58:41 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:41 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:42 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:42 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:42 posti dovecot: imap: Warning: Time jumped forwards 3514 seconds
    Jun 15 17:58:44 posti dovecot: imap: Warning: Time jumped forwards 3514 seconds
    Jun 15 17:58:44 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:44 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:44 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:45 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:46 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:49 posti dovecot: imap: Warning: Time jumped forwards 3514 seconds
    Jun 15 17:58:50 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:58:50 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 17:59:39 posti dovecot: imap: Warning: Time jumped forwards 1829 seconds
    Jun 15 17:59:42 posti dovecot: imap: Warning: Time jumped forwards 1984 seconds
    Jun 15 18:05:19 posti dovecot: imap: Warning: Time jumped forwards 2593 seconds
    Jun 15 18:05:19 posti dovecot: imap: Warning: Time jumped forwards 2592 seconds
    Jun 15 18:18:23 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 18:20:03 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    Jun 15 18:20:03 posti dovecot: imap: Warning: Time jumped forwards 3513 seconds
    
    The timestamps in mail.log do not jump back and forth, so the time the log application sees flows steadily forwards. I do not understand why dovecot thinks time is jumping willy nilly here and there.
     
  3. till

    till Super Moderator Staff Member ISPConfig Developer

    This is most likely caused by the virtualization software which causes the system time to drift inside the VM and when either proxmox or system corrects it from time to time, then Dovecot logs this error. In my opinion, that's something that needs to be solved or configured in proxmox. Which virtualization software/type do you use in proxmox.
     
  4. Taleman

    Taleman Well-Known Member HowtoForge Supporter

    They are not containeres, kvm virtual hosts. This has not happened before, and I have tried to configure the timekeeping on Proxmox properly.
    But, now that I look at systemctl status systemd-timesyncd it shows
    Code:
    Jun 14 18:09:16 ns61053275 systemd-timesyncd[16190]: Network configuration changed, trying to establish connection.
    Jun 14 18:09:16 ns61053275 systemd-timesyncd[16190]: Synchronized to time server 213.251.128.249:123 (ntp.ovh.net).
    Jun 14 18:15:16 ns61053275 systemd-timesyncd[16190]: Network configuration changed, trying to establish connection.
    Jun 14 18:15:16 ns61053275 systemd-timesyncd[16190]: Synchronized to time server 213.251.128.249:123 (ntp.ovh.net).
    Jun 14 18:15:17 ns61053275 systemd-timesyncd[16190]: Network configuration changed, trying to establish connection.
    Jun 14 18:15:17 ns61053275 systemd-timesyncd[16190]: Synchronized to time server 213.251.128.249:123 (ntp.ovh.net).
    Jun 14 18:17:56 ns61053275 systemd-timesyncd[16190]: Network configuration changed, trying to establish connection.
    Jun 14 18:17:56 ns61053275 systemd-timesyncd[16190]: Synchronized to time server 213.251.128.249:123 (ntp.ovh.net).
    Jun 14 18:17:57 ns61053275 systemd-timesyncd[16190]: Network configuration changed, trying to establish connection.
    Jun 14 18:17:57 ns61053275 systemd-timesyncd[16190]: Synchronized to time server 213.251.128.249:123 (ntp.ovh.net).
    
    Looks like something happened yesterday in providers network that caused this issue with timesync.
     
  5. till

    till Super Moderator Staff Member ISPConfig Developer

    If it did not happen before, then it might be worth waiting a few days and if it does not get better, then try to find a solution.
     

Share This Page