[Pdns-users] Strange time drift in log

[Nikolaos Milas]

  Thanks Christian,

This problem happens only with pdns server logging. I've never had a 
similar problem on this or on any of the other servers I'm managing 
(mainly CentOS), all with the same locale, with various daemons and syslog.

The pdns daemons running are as follows:

   # ps -ef | grep pdns

    UID        PID  PPID  C STIME TTY          TIME CMD
    102       2265     1  0 13:02 ?        00:00:00
    /usr/sbin/pdns_recursor --daemon
    root      2854     1  0 15:10 ?        00:00:00
    /usr/sbin/pdns_server --daemon --guardian=yes
    pdns      2856  2854  0 15:10 ?        00:00:00
    /usr/sbin/pdns_server-instance --daemon --guardian=yes

Threads:
# ps axjf | grep pdns

      PPID   PID  PGID   SID TTY      TPGID STAT   UID   TIME COMMAND
         1  2265  2265  2265 ?           -1 Ss     102   0:00
    /usr/sbin/pdns_recursor --daemon
         1  2854  2854  2854 ?           -1 Ssl      0   0:00
    /usr/sbin/pdns_server --daemon --guardian=yes
      2854  2856  2854  2854 ?           -1 Sl     101   0:00  \_
    /usr/sbin/pdns_server-instance --daemon --guardian=yes


It might help in troubleshooting to observe that *only* the pdns server 
start- and stop- related messages are logged with correct time 
(Europe/Athens, i.e. *EEST*). *All* normal operation messages are logged 
with UTC time.

It might also help that the time drift happens after the message: 
"Creating backend connection for TCP".

See below:

Stop server (messages with correct time):

    Sep  5 14:48:34 vdns pdns[2706]: Scheduling exit on remote request
    Sep  5 14:48:34 vdns pdns[2706]: Guardian is killed, taking down
    children with us

Start server (messages with correct time):

    Sep  5 14:48:46 vdns pdns[2764]: Listening on controlsocket in
    '/var/run/pdns.controlsocket'
    Sep  5 14:48:46 vdns pdns[2766]: Guardian is launching an instance
    Sep  5 14:48:46 vdns pdns[2766]: Reading random entropy from
    '/dev/urandom'
    Sep  5 14:48:46 vdns pdns[2766]:  [LdapBackend] This is the ldap
    module version 2.9.22 (Aug 23 2009, 10:47:15) reporting
    Sep  5 14:48:46 vdns pdns[2766]: This is a guarded instance of pdns
    Sep  5 14:48:46 vdns pdns[2766]: UDP server bound to xxx.xxx.xxx.xxx:53
    Sep  5 14:48:46 vdns pdns[2766]: TCP server bound to xxx.xxx.xxx.xxx:53
    Sep  5 14:48:46 vdns pdns[2766]: PowerDNS 2.9.22 (C) 2001-2009
    PowerDNS.COM BV (Aug 23 2009, 10:49:35, gcc 4.1.2 20080704 (Red Hat
    4.1.2-44)) starting up
    Sep  5 14:48:46 vdns pdns[2766]: PowerDNS comes with ABSOLUTELY NO
    WARRANTY. This is free software, and you are welcome to redistribute
    it according to the terms of the GPL version 2.
    Sep  5 14:48:46 vdns pdns[2766]: Set effective group id to 103
    Sep  5 14:48:46 vdns pdns[2766]: Set effective user id to 101
    Sep  5 14:48:46 vdns pdns[2766]: DNS Proxy launched, local port
    20388, remote xxx.xxx.xxx.xxx:53
    Sep  5 14:48:46 vdns pdns[2766]: Creating backend connection for TCP

Entering normal operation (messages with wrong time - pdns has switched 
to UTC):

    Sep  5 11:48:46 vdns pdns[2766]: [LdapBackend] LDAP servers = localhost
    Sep  5 11:48:46 vdns pdns[2766]: Launched webserver on
    xxx.xxx.xxx.xxx:8081
    Sep  5 11:48:46 vdns pdns[2766]: [LdapBackend] Ldap connection succeeded
    Sep  5 11:48:46 vdns pdns[2766]: About to create 3 backend threads
    for UDP
    Sep  5 11:48:46 vdns pdns[2766]: [LdapBackend] LDAP servers = localhost
    Sep  5 11:48:46 vdns pdns[2766]: [LdapBackend] Ldap connection succeeded
    Sep  5 11:48:46 vdns pdns[2766]: [LdapBackend] LDAP servers = localhost
    Sep  5 11:48:46 vdns pdns[2766]: [LdapBackend] Ldap connection succeeded
    Sep  5 11:48:46 vdns pdns[2766]: [LdapBackend] LDAP servers = localhost
    Sep  5 11:48:46 vdns pdns[2766]: [LdapBackend] Ldap connection succeeded
    Sep  5 11:48:46 vdns pdns[2766]: Done launching threads, ready to
    distribute questions
    Sep  5 11:49:25 vdns pdns[2766]: Distributor misses a thread (4<3),
    spawning new one
    Sep  5 11:49:25 vdns pdns[2766]: [LdapBackend] LDAP servers = localhost
    Sep  5 11:49:25 vdns pdns[2766]: [LdapBackend] Ldap connection succeeded
    Sep  5 11:50:21 vdns pdns[2766]: Not authoritative for
    'example.com', sending servfail to xxx.xxx.xxx.xxx (recursion was
    desired)

Stop server (messages with correct time):

    Sep  5 15:08:40 vdns pdns[2764]: Scheduling exit on remote request
    Sep  5 15:08:41 vdns pdns[2764]: Guardian is killed, taking down
    children with us


Nick


On 5/9/2010 12:50 πΌ, Christian Hofstaedtler wrote:
>
> If this is a problem which only happens with pdns, it might be worth
> figuring out which threads appear to send log messages with the wrong
> timezone.
>
>