<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
<meta content="text/html; charset=UTF-8" http-equiv="Content-Type">
<title></title>
</head>
<body bgcolor="#ffffff" text="#000000">
<font size="-1"><font face="Palatino Linotype">No other suggestions?<br>
<br>
In the meantime, just in case, I have tried switching from the
2.9.22 rpm which I had found in a repository, to the more
standard 2.9.21-4 rpm included in the 'extras' CentOS
repositories, but the behavior is exactly the same. <br>
<br>
I am thinking that this problem could probably be linked to the
LDAP backend. Has anyone else noticed this time shift in pdns
logging when using non-UTC as server time, esp. with LDAP? <br>
<br>
Nick<br>
</font></font><br>
On 5/9/2010 3:36 ÃÅÃÅ, Nikolaos Milas wrote:
<blockquote cite="mid:4C838ECE.5000900@admin.noa.gr" type="cite">
<meta content="text/html; charset=UTF-8" http-equiv="Content-Type">
<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> </blockquote>
</body>
</html>