Timestamp leak

[KVInventoR]

Looks like I have 1 more bug

Found that over sometime I have delay in logs with timestamps and system time.

My current config is:

egrep -v "^$|^[[:space:]]*#" /etc/dnstap_receiver.conf
trace:
    file: null
    verbose: false
web-api:
    enable: true
    api-key: changeme
    login: admin
    password: changeme
    local-address: 127.0.0.1
    local-port: 8080
geoip:
    enable: true
    city-database: /GeoLite2-City.mmdb
statistics:
    default-counters:
     - clients
     - domains
     - query
     - response
     - qps
     - response/noerror
     - response/nxdomain
    default-top:
     - noerror/query
     - nxdomain/response
input:
  tcp-socket:
    local-address: 127.0.0.1
    local-port: 6000
    access-control-list:
     - 0.0.0.0/0
    tls-support: false
    tls-server-cert: null
    tls-server-key: null
  unix-socket:
    path: null
filter:
  qname-regex: null
  dnstap-identities: null
output:
  stdout:
    enable: false
    format: text
  file:
    enable: true
    format: text
    file: /var/log/dnstap.log
    file-max-size: 500M
    file-count: 5
  metrics:
    enable: false
    interval: 30
    cumulative: true
    file: null
    file-max-size: 100M
    file-count: 5
  tcp-socket:
    enable: false
    format: text
    delimiter: "\n"
    retry: 5
    remote-address: null
    remote-port: null
  syslog:
    enable: false
    transport: udp
    format: text
    retry: 5
    remote-address: null
    remote-port: null

Python 3.7.3 (default, Jul 25 2020, 13:03:44)
[GCC 8.3.0] on linux

to reproduce the issue I used next:

rm /var/log/dnstap.log &&
timeout 720s /usr/bin/python3 -u /usr/local/bin/dnstap_receiver -c /etc/dnstap_receiver.conf; tail -n 5 /var/log/dnstap.log; echo $(date)
2020-12-12T14:56:00.360466+00:00 alpha-vm01 CLIENT_QUERY NOERROR 178.20.157.236 38707 INET UDP 51b ceph03.com.ua. A UA -
2020-12-12T14:56:00.362466+00:00 alpha-vm01 CLIENT_RESPONSE NOERROR 178.20.157.236 38707 INET UDP 67b ceph03.com.ua. A UA -
2020-12-12T14:56:00.385256+00:00 alpha-vm01 CLIENT_QUERY NOERROR 212.90.167.146 52788 INET UDP 44b 59.120.142.45.in-addr.arpa. PTR UA Kyiv
2020-12-12T14:56:00.390525+00:00 alpha-vm01 CLIENT_QUERY NOERROR 213.190.194.214 33117 INET UDP 53b like-it.link. A PT Funchal
2020-12-12T14:56:00.397980+00:00 alpha-vm01 CLIENT_QUERY NOERROR 178.20.156.237 40626 INET UDP 50b utils.com.ua. A UA -
Sat 12 Dec 2020 04:59:15 PM EET

My timezone is UTC+2 but as you can see, there is a lag between system time and the last record in log file, 3 minutes.

[dmachard]

The timestamp in logs is extracted directly from the dnstap messages. Knowing this it can be completely different from your system time.

[KVInventoR]

sorry, probably I give a bad explanation of this issue, let's skip difference between timezones.

general issue, that when I run dnstap_receiver in first time my system time and log timestap is the same (diff only timezones), but after sometime, like as in my previous example, after 10 minutes the difference between logs timestamp and system time more than 3 minutes.

if I will restart dnstap_receiver again, there won't be any difference and after sometime I will have the same issue with time leak more than 3 minutes.

For me this issue seems related to system load, I tested the same configuration with low load and didn't have such kind of issue, but when load was increased, I got a time leak beetween logs and system time.

[dmachard]

Thanks for explanation, I will try to reproduce. In the meantime can you test with the fix https://github.com/dmachard/dnstap-receiver/commit/1ffccbc4f0a5d3df139b911eec92bfec1970df5d ?

[KVInventoR]

looks like issue with metrics fixed also issue with timestamp

[dmachard]

fix in release 3.0.0