Some syslog entries being logged GMT

[bengalih]

I've been seeing this issue for a long time, but just decided to go about trying to fix as I'm trying to parse through a bunch of logs and would rather not deal with the discrepancies.
I wasn't sure exactly what was going on at first, but I noticed that some apps (seemingly third party ones installed in Entware) was logging with the hours off, like this:

Apr  3 17:04:48 dnsmasq-dhcp[369]: no address range available for DHCP request via br0
Apr  3 22:04:49 dhcp6_client: bound address 2001:506:7ae0:13ca::1/128, prefix 2600:1700:ae01:cea1::/64
Apr  3 22:04:49 rc_service: dhcp6c 1749:notify_rc restart_ddns
Apr  3 22:04:49 rc_service: waitting "start_vpnserver1" via udhcpc ...
Apr  3 17:04:52 kernel: D977E6B0000000001030307)
Apr  3 17:04:54 ovpn-server1[2116]: --cipher is not set. Previous OpenVPN version defaulted to BF-CBC as fallback when cipher negotiation failed in this case. If you need this fallback please add '--data-ciphers-fallback BF-CBC' to your configuration and/or add BF-CBC to --data-ciphers.

I realized that it was always 5 hours off, and that equated to GMT time. Once I realized that I was able to find the following:

Using time zones

Ultimate repo for embedded devices. Contribute to Entware/Entware development by creating an account on GitHub.

github.com

and

Entware Timezone Issue

I have an RT-AC88U on Merlin 3.84.7_2 with: /etc/locatime -> /opt/share/zoneinfo/US/Pacific AND export TZ=:/opt/share/zoneinfo/US/Pacific in /opt/etc/profile and yet my Entware applications are putting GMT times in the system log. I have rebooted the router several times and the above changes...

www.snbforums.com

Using the information from the second thread I did the following:

1. "opkg install zoneinfo-northamerica"
2. "ln -sf /opt/share/zoneinfo/US/Central /etc/localtime"
3. added "export TZ=:/opt/share/zoneinfo/US/Central" into /opt/etc/init.d/rc.func

I'm not sure if both 2 & 3 were necessary, but 2 did not seem to fix the issue on its own. After that I did a reboot. However the following entries still show in GMT in syslog:

Apr  3 22:04:20 keymaster: Started odhcp6c from /jffs/scripts/post-mount.
Apr  3 22:04:20 keymaster: Started wpa_supplicant from /jffs/scripts/post-mount.
Apr  3 22:04:21 keymaster: Started apcupsd from /jffs/scripts/post-mount.
Apr  3 22:04:21 keymaster: Started atd from /jffs/scripts/post-mount.
Apr  3 22:04:21 keymaster: Started lighttpd from /jffs/scripts/post-mount.
Apr  3 22:04:49 dhcp6_client: bound address 2001:506:7ae0:13ca::1/128, prefix 2600:1700:ae01:cea1::/64
Apr  3 22:04:49 rc_service: dhcp6c 1749:notify_rc restart_ddns
Apr  3 22:04:49 rc_service: waitting "start_vpnserver1" via udhcpc ...

Here is another example which is strance becuse it shows the start_vpnserver1 log first the right time, then nearer the bottom the same apparent rc_service logs time in GMT:

Apr  3 17:04:42 custom_script: Running /jffs/scripts/service-event (args: start vpnserver1)
Apr  3 17:04:42 rc_service: udhcpc 1335:notify_rc start_vpnserver2
Apr  3 17:04:42 rc_service: waitting "start_vpnserver1" via udhcpc ...
Apr  3 17:04:42 syslog: wlceventd_proc_event(527): eth2: Auth B8:C7:5D:DB:2A:FC, status: Successful (0), rssi:0
Apr  3 17:04:42 syslog: wlceventd_proc_event(556): eth2: Assoc B8:C7:5D:DB:2A:FC, status: Successful (0), rssi:0
Apr  3 17:04:42 dnsmasq-dhcp[369]: no address range available for DHCP request via br0
Apr  3 17:04:46 kernel: 02080AED97664B0000000001030307)
Apr  3 17:04:46 dnsmasq-dhcp[369]: no address range available for DHCP request via br0
Apr  3 17:04:48 syslog: wlceventd_proc_event(527): eth2: Auth 24:77:03:2F:F6:E4, status: Successful (0), rssi:0
Apr  3 17:04:48 syslog: wlceventd_proc_event(527): eth2: Auth 24:77:03:2F:F6:E4, status: Successful (0), rssi:0
Apr  3 17:04:48 syslog: wlceventd_proc_event(527): eth2: Auth 24:77:03:2F:F6:E4, status: Successful (0), rssi:0
Apr  3 17:04:48 dnsmasq-dhcp[369]: no address range available for DHCP request via br0
Apr  3 22:04:49 dhcp6_client: bound address 2001:506:7ae0:13ca::1/128, prefix 2600:1700:ae01:cea1::/64
Apr  3 22:04:49 rc_service: dhcp6c 1749:notify_rc restart_ddns
Apr  3 22:04:49 rc_service: waitting "start_vpnserver1" via udhcpc ...
Apr  3 17:04:52 kernel: D977E6B0000000001030307)
Apr  3 17:04:54 ovpn-server1[2116]: --cipher is not set. Previous OpenVPN version defaulted to BF-CBC as fallback when cipher negotiation failed in this case. If you need this fallback please add '--data-ciphers-fallback BF-CBC' to your configuration and/or add BF-CBC to --data-ciphers.

These rc_service entries appear to only log incorrect time at boot. If for instance I issue a "service restart_ddns" after the system is up, the logged time seems correct.

However all "keymaster" entries which are logged when I restart entware services from /opt/etc/init.d are logging the wrong time.
I want to stress that the services themselves are now (after the above fixes) properly logging time, but the "keymaster" entry is not, as in:

Apr  3 17:27:54 apcupsd[1276]: apcupsd exiting, signal 15
Apr  3 17:27:54 apcupsd[1276]: apcupsd shutdown succeeded
Apr  3 22:27:55 keymaster: Started apcupsd from .
Apr  3 17:27:55 apcupsd[8113]: apcupsd 3.14.14 (31 May 2016) unknown startup succeeded
Apr  3 17:27:55 apcupsd[8113]: NIS server startup succeeded

(again, previously al these would have been logged in GMT, but now only keymaster).

I'm not completely sure of the way that rc_service is called (especially at boot) and if that can't be fixed I can live with those incorrect.
Also, the keymaster entries are easy to spot being a single entry in the middle of properly logged service info.

However hoping @RMerlin or another educated user can shed any light.
Can these discrepancies be prevented, or are they inevitable?

thx

 

[ColinTaylor]

As you say, this is an old problem that's been discussed before. In my case all I did was add the following two lines just prior to starting the Entware services (rc.unslung).

if [ -x /opt/etc/init.d/rc.unslung ]; then
  TZ=$(cat /etc/TZ)
  export TZ
  /opt/etc/init.d/rc.unslung start
fi

I don't know what script you have that starts Entware but it'll be different than mine. Putting the TZ changes into rc.func wouldn't work for me because not all Entware startup scripts call that function.

EDIT: The standard (i.e. not through amtm) Entware install already creates a soft link for /etc/localtime so I'm not sure what affect your option 2 would have on that. Check that you have /opt/etc/localtime -> /etc/localtime

Some processes log using the kernel time rather than the local time, therefore they will always show UTC time regardless of how the timezone is set.

 

[bengalih]

As you say, this is an old problem that's been discussed before. In my case all I did was add the following two lines just prior to starting the Entware services (rc.unslung).

if [ -x /opt/etc/init.d/rc.unslung ]; then
  TZ=$(cat /etc/TZ)
  export TZ
  /opt/etc/init.d/rc.unslung start
fi

I don't know what script you have that starts Entware but it'll be different than mine. Putting the TZ changes into rc.func wouldn't work for me because not all Entware startup scripts call that function.

EDIT: The standard (i.e. not through amtm) Entware install already creates a soft link for /etc/localtime so I'm not sure what affect your option 2 would have on that. Check that you have /opt/etc/localtime -> /etc/localtime

Some processes log using the kernel time rather than the local time, therefore they will always show UTC time regardless of how the timezone is set.

I'll try what you stated, but a few things I notice:

1) My rc.unslung is started by a Skynet mount-entware.div script. Because this script might get updated by Skynet, wouldn't it be better to include the lines in rc.unslung directly?
(The changes I made to rc.func must have worked since that is the only thing that survived a reboot (and just the installation of the northamerica zones).

2) Putting these changes into rc.unslung - wouldn't that mean that they would only affect the services via their initial startup from rc.unslung? If you manually stopped and started services later (e..g /'opt/etc/init.d/Sxxx restart') would they still operate under the proper environment?

3) What is the difference between `cat /etc/TZ` and `/opt/share/zoneinfo/US/Central`? It looks like /etc/TZ is simple text file, whereas the file in zoneinfo is not. I used the latter in my rc.func and it seemed to work, but I have seen your method also listed.

4) I just realized that my linking the zoneinfo file to /etc/localtime didn't survive a reboot (obviously). So clearly that had no effect since I tested after a reboot. How does the standard entware install create (and maintain) the link to the zoneinfo file?

5) I don't see anything being logged in UTC. When my device first starts it has the wrong time (May 5th) because there is no time sync. Then about 5 seconds after syslog starts I get my initial ntp sync and everything starts reporting in my local time zone (24 hour time). Before I made any of these fixes, the only discrepancies I saw were some 5 hours ahead, which would be GMT time for me (Central). After I made the rc.func fix, I only see a handful of the keymaster entries and some of the rc_service entries. These latter may be fixed putting the changes in rc.unslung as you suggest.

That leaves the keymaster entries which...DUH! I just realized are just the root (keymaster is my renamed admin account, I wasn't putting 2+2 together thinking 'keyamster' was some service control function). I just tested manually starting services via command line I was able to fix those errors by simply doing the export TZ in my shell session. This means I can probably add these setting to a profile.add config script to handle the keymaster entries during boot?

Will have to try this next time I can reboot.

 

[ColinTaylor]

1) I can't comment on amtm/Diversion/Skynet as I didn't use those to install Entware. I used the standard Entware installer and created my own startup script.

2) The intention is to fix the problem with batch processes. Interactive sessions should already have TZ set with the following line in /jffs/configs/profile.add

export TZ="`nvram get time_zone_x`"

4) It creates the soft link that I mentioned earlier, which ultimately points to the timezone database set in the firmware's GUI. In my case:

/opt/etc/localtime -> /etc/localtime
/etc/localtime -> /rom/usr/share/zoneinfo/Europe/Dublin

 

[bengalih]

1) I can't comment on amtm/Diversion/Skynet as I didn't use those to install Entware. I used the standard Entware installer and created my own startup script.

Thanks...I didn't recall installing entware via amtm, but I had rebuilt the drive more than once and it is possible I did. Do you run Skynet and just installed it after entware was installed?

2) The intention is to fix the problem with batch processes. Interactive sessions should already have TZ set with the following line in /jffs/configs/profile.add

export TZ="`nvram get time_zone_x`"

That was not existent in my profile.add, but I assumed I should add it. I'm not sure if it was placed there automatically in your configuration...if so not sure why it wasn't in mine.

4) It creates the soft link that I mentioned earlier, which ultimately points to the timezone database set in the firmware's GUI. In my case:

/opt/etc/localtime -> /etc/localtime
/etc/localtime -> /rom/usr/share/zoneinfo/Europe/Dublin

My question was unclear. I mean what method does it use to create that link. Since it is in /tmp it would need to be recreated on boot. I was curious what specific entries it used to do that so I could recreate it as close to possible.

 

[ColinTaylor]

Thanks...I didn't recall installing entware via amtm, but I had rebuilt the drive more than once and it is possible I did. Do you run Skynet and just installed it after entware was installed?

As I said, I don't use Skynet, etc. so I don't know what installation stuff they do.

That was not existent in my profile.add, but I assumed I should add it. I'm not sure if it was placed there automatically in your configuration...if so not sure why it wasn't in mine.

I can't remember how that line got there. It's possible I put it there years ago when I migrated from John's firmware to Merlin's. In John's that line exists by default in /etc/profile. That line doesn't exist in Merlin so it's possible that I manually added it to profile.add. The simplest thing to do would be to SSH into the router and type echo $TZ. If it doesn't return anything then add the line to profile.add which will fix your interactive sessions.

My question was unclear. I mean what method does it use to create that link. Since it is in /tmp it would need to be recreated on boot. I was curious what specific entries it used to do that so I could recreate it as close to possible.

The second soft link is created automatically by the firmware each time the router boots up.