Incorrect time stamps in syslog for dnscrypt-proxy entries

[Marco-vW]

Hi Frank,

I'm opening another issue on this, by request of @thuantran, as we still have users running dnscrypt-proxy on Asuswrt-Merlin reporting syslog entries with a different time offset:

Jan 31 11:39:12 xxxxxxx: Start dnscrypt-proxy
Jan 31 07:39:13 dnscrypt-proxy[8007]: Source [https://download.dnscrypt.info/resolvers-list/v2/public-resolvers.md] loaded
Jan 31 07:39:13 dnscrypt-proxy[8007]: Starting dnscrypt-proxy 2.0.0beta12
Jan 31 07:39:13 dnscrypt-proxy[8007]: Now listening to 127.0.0.1:65053 [UDP]
Jan 31 07:39:13 dnscrypt-proxy[8007]: Now listening to 127.0.0.1:65053 [TCP]
Jan 31 07:39:13 dnscrypt-proxy[8007]: Refreshing certificates
Jan 31 07:39:13 dnscrypt-proxy[8007]: [d0wn-gr-ns1] OK (crypto v1) - rtt: 195ms
Jan 31 07:39:14 dnscrypt-proxy[8007]: [d0wn-is-ns1] OK (crypto v1) - rtt: 146ms
Jan 31 07:39:14 dnscrypt-proxy[8007]: [scaleway-fr] OK (crypto v2) - rtt: 112ms

Only the dnscrypt-proxy lines have different offset, the rest of syslog complies with the configured timezone.

I don't have any issue myself and I'm in CET/GMT+1, presumably the same TZ where you reside (if I did my homework correctly ;-) ). Could it be that you can't reproduce the issue and I don't have it, because we're in the same timezone? I don't know coding in Go (I basically know pretty little about coding, I just analyze), but I noticed in the Go documentation that Ldate and Ltime etc. in the Log package, should output the locally configured timezone instead of UTC or something else that has been hardcoded? Could you please take a look at that?

[jedisct1]

This is a bit weird since I got the the timestamps in the locale zone, at least on macOS.

I'm not very familiar with Go either. But maybe https://github.com/jedisct1/dnscrypt-proxy/commit/1bbc7e954027ac68c44514e6b5487d2ddcf76ec8 fixes it.

[Marco-vW]

We'll have to see, thanks for taking another look at it!

[thuantran]

So I went and did what dev on open source project usually does, that is reading the damn source code.

The code to read timezone in golang is here https://golang.org/src/time/zoneinfo_unix.go , first let's note down how golang read timezone:

1. it reads TZ env var
2. if it exists then golang will use that in function loadLocation with in turn use loadZoneFile to read timezone, if does not then it will simply read timezone from /etc/localtime with loadZoneFile function (well to be technical correct it's a different function with the same name doing the same thing with different input, OOP polymorphism crap, go is a weird lang yet beautiful but that's another topic)

So what's the problem with asuswrt, it does not set TZ env var, but I did set it in my script so what gives? The problem is asuswrt firmware does not have zoneinfo package which includes various binary files required for loadZoneFile to work, so in the end it falls back with UTC.

In short we're f***ed on embedded system without zoneinfo package. On asuswrt-merlin entware-ng does have this package but it's only available after usb mount, IOW much later than required to run the proxy at boot for things to init.

There might be other way to init the timezone, but that will be quite a challenge for me to look at, first time I look at go code today.

[thuantran]

Fixed, as my script is now able to install /etc/localtime for asuswrt-merlin.

[Marco-vW]

That's awesome @thuantran! Thanks for your efforts.