Bug 4152 - Logs shows wrong time when using log-time-ascii: yes
Logs shows wrong time when using log-time-ascii: yes
Status: RESOLVED FIXED
Product: unbound
Classification: Unclassified
Component: server
1.7.3
All Linux
: P5 normal
Assigned To: unbound team
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2018-09-11 11:54 CEST by j.vogt
Modified: 2018-10-25 15:52 CEST (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description j.vogt 2018-09-11 11:54:21 CEST
Hello

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	172.217.168.78

;; 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
logfile: "/var/log/unbound/unbound.log"
log-time-ascii: yes
log-queries: yes
log-replies: yes
val-log-level: 1
verbosity: 1

However, it is not allways the wrong time logged, it seems to me tha when thread0 is used, the time is correct.
Comment 1 Wouter Wijngaards 2018-09-11 12:20:04 CEST
Hi,

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
Comment 2 j.vogt 2018-09-11 12:36:19 CEST
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.

Best regards
Josef
Comment 3 j.vogt 2018-09-11 17:20:26 CEST
> 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

Best regards
Josef
Comment 4 Wouter Wijngaards 2018-10-25 15:52:18 CEST
Hi Josef,

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