Bugzilla – Bug 4152
Logs shows wrong time when using log-time-ascii: yes
Last modified: 2018-10-25 15:52:18 CEST
When logging to a file and using "log-time-ascii: yes", the log shows sometimes the wrong time.
On the client side:
# dig @217.xxx.xxx.xxx google.com
;; ANSWER SECTION:
google.com. 300 IN A 184.108.40.206
;; Query time: 799 msec
;; SERVER: 217.xxx.xxx.xxx#53(217.xxx.xxx.xxx)
;; WHEN: Die Sep 11 11:45:07 CEST 2018
On the server side:
Sep 11 11:41:05 unbound[19301:3] info: 217.xxx.xxx.xxx google.com. A IN
Sep 11 11:41:05 unbound[19301:3] info: 217.xxx.xxx.xxx google.com. A IN NOERROR 0.798167 0 55
Logging is configured as follows:
# Log to file
However, it is not allways the wrong time logged, it seems to me tha when thread0 is used, the time is correct.
Unbound uses localtime_r to print out the time for the logs. For timezone it sets the timezone at the start of the program (in thread 0) with tzset. That should carry over to the other threads.
It logs fine for me, and also with multiple threads and also with a timezone set to a different timezone.
Somehow a thread in unbound gets a different time or timezone briefly, on your system?
Best regards, Wouter
Thanks for your answer.
Well, I did not notice this behaviour until I set up a test machine where I do only rarely lookups.
It seems as if every time thread0 is used, the time is updated again and all the threads use this time until thread0 is used again.
This is of course no problem for a busy server.
> It logs fine for me, and also with multiple threads and also with a timezone
> set to a different timezone.
> Somehow a thread in unbound gets a different time or timezone briefly, on
> your system?
Any hints how I could check this? I used a minimal install of RHEL 7.5 and compiled the packages from Fedora.
I just found out that this happens only when setting so-reuseport: yes
I get the correct log times when setting so-reuseport: no
The log prints out the value from time system call. But in some cases it prints out a value stored from a previous lookup of the time using the gettimeofday system call; and this lookup is done once per iteration of the event loop. Normally, this means the time is correct, and gets updated every time the event loop loops.
This is what is causing the problem, this value is not getting updated frequently enough.
The fix is to use the time(2) call every time. This is slower, but prints the correct time every time.
Best regards, Wouter