logging and timestamp

[proxymoxy]

Hi
I have configured Localization to be in my timezone (UTC+1, I selected Europe/Copenhagen) and most logs show up in the correct time, but some logs show up one our early.
For example, in the Status -> System Logs -> OpenVPN view then I can see several lines

Dec 6 08:46:10 firewall-production openvpn[74858]: xxxxxxx peer info: IV_TCPNL=1
Dec 6 08:46:10 firewall-production openvpn[74858]: xxxxxxx [username] Peer Connection Initiated with [AF_INET]xxxxxxxx
Dec 6 09:46:10 firewall-production openvpn[35584]: user 'username' authenticated
Dec 6 08:46:10 firewall-production openvpn[74858]: username/xxxxxxxx MULTI_sva: pool returned IPv4=yyyyyyyy, IPv6=(Not enabled)

As you can see then the timestamp jumps from 08:46:10 to 09:46:10 and then back to 08:46:10. the 09:46:10 is the correct time.
Why is this happening? What can be done to fix this?

[stephenw10]

There are some logs that use UTC by default unless you choose otherwise. The DHCP log is where I usually see it.
That example is odd seeing it in OpenVPN. I note it's a different process ID though. Do you have more that one OpenVPN server? Could it have been started before you set the timezone?

Steve

[proxymoxy]

Thanks for your answer @stephenw10

No, there are no other OpenVPN processes running. The system or the OpenVPN process has not been restarted since the lines above. I also see this with nginx for example. Is there some checkbox in the GUI that can force all services/programs to use the local timezone or do we have to do some fix in the shell that then needs to be done each time the system restarts?

[stephenw10]

The only setting I'm aware of is in the dhcp server settings: Change DHCP display lease time from UTC to local time
That should have no effect here though.

Steve

[proxymoxy]

After digging a bit further into this then I see this on several servers but not all.
I see this specially when php-fpm is writing logs.
For example then I can see the following in one systems /var/log/system.log file

<6>1 2022-01-20T10:00:49.477865+01:00 $our_hostname syslogd - - - kernel boot file is /boot/kernel/kernel
<27>1 2022-01-20T09:03:18.922177+00:00 $our_hostname php-fpm 344 - - /index.php: User logged out for user 'admin' from: x.x.x.x (Local Database)
<13>1 2022-01-20T09:06:09.953692+00:00 $our_hostname check_reload_status 382 - - Syncing firewall

As can be seen there then the timezone does not get picked up. I also had a look at the source of check_reload_status and it seems that this messages (and others that had wrong timestamps) were sent through php-fpm, see source of check_reload_status.
So looks like whatever mechanism that php-fpm uses to send to syslog is not picking up the timezone.
As to the openvpn example, could that also be initiated by a process in pfSense and from there call php-fpm?

[proxymoxy]

Restarting PHP-FPM fixes the timestamps on those at least.
Could it be some kind of issue of the timezone not being seen at bootup by some processes?

[proxymoxy]

After some testing then restarting those services that had wrong timestamps fixed the issue for me.
For OpenVPN I did a minor change (like allowing one more to connect concurrently) and saved the change, that restarts the service. Other services should behave similarly.
To restart PHP-FPM you can either ssh into pfSense and choose the option there to restart PHP-FPM or run /etc/rc.php-fpm_restart in the Command Prompt window inside pfSense.

I can't reproduce the issue when I restart some of my firewalls, but it seems like there is some bootup issue with timezones.

[pete35]

@proxymoxy

thank you, i had the same situation here, restarting php-fpm solved it. Don´t know what happens after next reboot ....