No other suggestions?
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.
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?
Nick
On 5/9/2010 3:36 μμ, Nikolaos Milas wrote:
Thanks Christian,
{I am resending in HTML format, to avoid auto line breaks
which make terminal output illegible.}
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.
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.
>
>
|
_______________________________________________
Pdns-users mailing list
Pdns-users@mailman.powerdns.com
http://mailman.powerdns.com/mailman/listinfo/pdns-users
