<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
<meta content="text/html; charset=UTF-8" http-equiv="Content-Type">
</head>
<body bgcolor="#ffffff" text="#000000">
<font size="-1"><font face="Palatino Linotype">Thanks Christian,ÃÂ {I
am resending in HTML format, to avoid auto line breaks which
make terminal output illegible.}<br>
<br>
This problem happened to me 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.<br>
<br>
The pdns daemons running are as follows:<br>
<br>
<font face="Courier New, Courier, monospace">ÃÂ # ps -ef | grep
pdns<br>
<br>
ÃÂ ÃÂ UIDÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ PIDÃÂ PPIDÃÂ C STIME TTYÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ TIME CMD<br>
ÃÂ ÃÂ 102ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 2265ÃÂ ÃÂ ÃÂ ÃÂ 1ÃÂ 0 13:02 ?ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 00:00:00
/usr/sbin/pdns_recursor --daemon<br>
ÃÂ ÃÂ rootÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 2854ÃÂ ÃÂ ÃÂ ÃÂ 1ÃÂ 0 15:10 ?ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 00:00:00
/usr/sbin/pdns_server --daemon --guardian=yes<br>
ÃÂ ÃÂ pdnsÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 2856ÃÂ 2854ÃÂ 0 15:10 ?ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 00:00:00
/usr/sbin/pdns_server-instance --daemon --guardian=yes<br>
</font><br>
Threads:<br>
<font face="Courier New, Courier, monospace"><br>
# ps axjf | grep pdns<br>
<br>
ÃÂ ÃÂ ÃÂ ÃÂ PPIDÃÂ ÃÂ PIDÃÂ PGIDÃÂ ÃÂ SID TTYÃÂ ÃÂ ÃÂ ÃÂ ÃÂ TPGID STATÃÂ ÃÂ UIDÃÂ ÃÂ TIME
COMMAND<br>
ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 1ÃÂ 2265ÃÂ 2265ÃÂ 2265 ?ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ -1 SsÃÂ ÃÂ ÃÂ ÃÂ 102ÃÂ ÃÂ 0:00
/usr/sbin/pdns_recursor --daemon<br>
ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 1ÃÂ 2854ÃÂ 2854ÃÂ 2854 ?ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ -1 SslÃÂ ÃÂ ÃÂ ÃÂ ÃÂ 0ÃÂ ÃÂ 0:00
/usr/sbin/pdns_server --daemon --guardian=yes<br>
ÃÂ ÃÂ ÃÂ ÃÂ 2854ÃÂ 2856ÃÂ 2854ÃÂ 2854 ?ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ ÃÂ -1 SlÃÂ ÃÂ ÃÂ ÃÂ 101ÃÂ ÃÂ 0:00ÃÂ
\_/usr/sbin/pdns_server-instance --daemon --guardian=yes</font><br>
<br>
It might help in troubleshooting to observe that <b>only</b>
the pdns server start- and stop- related messages are logged
with correct time (Europe/Athens, i.e. <b>EEST</b>). <b>All</b>
normal operation messages are logged with UTC time.<br>
<br>
It might also help that the time drift happens after the
message: "Creating backend connection for TCP".<br>
<br>
See below:<br>
<br>
Stop server (messages with correct time):<br>
<br>
<font face="Courier New, Courier, monospace">ÃÂ ÃÂ SepÃÂ 5 14:48:34
vdns pdns[2706]: Scheduling exit on remote request<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:34 vdns pdns[2706]: Guardian is killed, taking
down children with us</font><br>
<br>
Start server (messages with correct time):<br>
<br>
<font face="Courier New, Courier, monospace">ÃÂ ÃÂ SepÃÂ 5 14:48:46
vdns pdns[2764]: Listening on controlsocket in
'/var/run/pdns.controlsocket'<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: Guardian is launching an
instance<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: Reading random entropy
from '/dev/urandom'<br>
ÃÂ ÃÂ 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<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: This is a guarded instance
of pdns<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: UDP server bound to
xxx.xxx.xxx.xxx:53<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: TCP server bound to
xxx.xxx.xxx.xxx:53<br>
ÃÂ ÃÂ 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<br>
ÃÂ ÃÂ 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.<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: Set effective group id to
103<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: Set effective user id to
101<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: DNS Proxy launched, local
port 20388, remote xxx.xxx.xxx.xxx:53<br>
ÃÂ ÃÂ SepÃÂ 5 14:48:46 vdns pdns[2766]: Creating backend
connection for TCP</font><br>
<br>
Entering normal operation (messages with wrong time - pdns has
switched to UTC):<br>
<br>
<font face="Courier New, Courier, monospace">ÃÂ ÃÂ SepÃÂ 5 11:48:46
vdns pdns[2766]: [LdapBackend] LDAP servers = localhost<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: Launched webserver on
xxx.xxx.xxx.xxx:8081<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: [LdapBackend] Ldap
connection succeeded<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: About to create 3 backend
threads for UDP<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: [LdapBackend] LDAP servers
= localhost<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: [LdapBackend] Ldap
connection succeeded<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: [LdapBackend] LDAP servers
= localhost<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: [LdapBackend] Ldap
connection succeeded<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: [LdapBackend] LDAP servers
= localhost<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: [LdapBackend] Ldap
connection succeeded<br>
ÃÂ ÃÂ SepÃÂ 5 11:48:46 vdns pdns[2766]: Done launching threads,
ready to distribute questions<br>
ÃÂ ÃÂ SepÃÂ 5 11:49:25 vdns pdns[2766]: Distributor misses a
thread (4<3), spawning new one<br>
ÃÂ ÃÂ SepÃÂ 5 11:49:25 vdns pdns[2766]: [LdapBackend] LDAP servers
= localhost<br>
ÃÂ ÃÂ SepÃÂ 5 11:49:25 vdns pdns[2766]: [LdapBackend] Ldap
connection succeeded<br>
ÃÂ ÃÂ SepÃÂ 5 11:50:21 vdns pdns[2766]: Not authoritative for
'example.com', sending servfail to xxx.xxx.xxx.xxx (recursion
was desired)</font><br>
<br>
Stop server (messages with correct time):<br>
<br>
<font face="Courier New, Courier, monospace">ÃÂ ÃÂ SepÃÂ 5 15:08:40
vdns pdns[2764]: Scheduling exit on remote request<br>
ÃÂ ÃÂ SepÃÂ 5 15:08:41 vdns pdns[2764]: Guardian is killed, taking
down children with us<br>
</font><br>
Nick<br>
<br>
<br>
On 5/9/2010 12:50 ÃÂÃÅ, Christian Hofstaedtler wrote:<br>
><br>
> If this is a problem which only happens with pdns, it might
be worth<br>
> figuring out which threads appear to send log messages with
the wrong<br>
> timezone.<br>
><br>
><br>
<br>
</font></font>
</body>
</html>