Time date in logs not correct.

Understudy

Issue:
Time and date stamps in Status/System/ Logs/Firewall/Normal View do not reflect the current time and date. Screenshot 2022-11-01 234948.png

You can view the current time here.
Screenshot 2022-11-01 235127.png

You can see the time settings here:
Screenshot 2022-11-01 235331.png

You can see the results of ntpq -pn here:
Screenshot 2022-11-01 235705.png
It has been restarted when I first discovered this about a week ago. I am just perplexed as to where to go next.

rcoleman-netgate

If your system clock is correct now then it's correct - the logs show up in the GUI in time order

I would go to the Command Prompt page (Diagnostics->Command Prompt) and run this command to verify:

tail -n 25 /var/log/system.log

and

tail -n 25 /var/log/filter.log

They should show current times instead of the Nov 2 times.

You might need to reboot but I don't believe so.

JKnott

@understudy

I suspect the logs may be in UTC, which is currently 4 hours ahead of Eastern Daylight time and next week will be 5 hours ahead of Eastern Standard time.

Understudy

Thank you both, I will check them as soon as I can get off the road and into the system.

Understudy

@rcoleman-netgate said in Time date in logs not correct.:

tail -n 25 /var/log/system.log

[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root: tail -n 25 /var/log/system.log
Nov  2 19:00:30 Ignis php[13294]: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload
Nov  2 19:00:30 Ignis php[13294]:
Nov  2 19:11:00 Ignis sshguard[89538]: Exiting on signal.
Nov  2 19:11:00 Ignis sshguard[39961]: Now monitoring attacks.
Nov  2 20:00:00 Ignis php[38550]: [pfBlockerNG] Starting cron process.
Nov  2 20:00:26 Ignis php[38550]: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload
Nov  2 20:00:26 Ignis php[38550]:
Nov  3 05:04:19 Ignis nginx: 2022/11/03 05:04:19 [error] 79510#100201: *617130 open() "/usr/local/www/Security/users" failed (2: No such file or directory), client: 70.80.211.151, server: , request: "GET /Security/users?auth=YWRtaW46MTEK HTTP/1.1", host: "xxx.xxx.xxx.94"
Nov  2 20:22:00 Ignis sshguard[39961]: Exiting on signal.
Nov  2 20:22:00 Ignis sshguard[43591]: Now monitoring attacks.
Nov  2 21:00:00 Ignis php[83757]: [pfBlockerNG] Starting cron process.
Nov  2 21:00:34 Ignis php[83757]: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload
Nov  2 21:00:34 Ignis php[83757]:
Nov  2 21:31:00 Ignis sshguard[43591]: Exiting on signal.
Nov  2 21:31:00 Ignis sshguard[95664]: Now monitoring attacks.
Nov  3 06:31:43 Ignis nginx: 2022/11/03 06:31:43 [error] 79510#100201: *617142 open() "/usr/local/www/robots.txt" failed (2: No such file or directory), client: 185.165.190.17, server: , request: "GET /robots.txt HTTP/1.1", host: "xxx.xxx.xxx.94"
Nov  3 06:31:43 Ignis nginx: 2022/11/03 06:31:43 [error] 79510#100201: *617143 open() "/usr/local/www/sitemap.xml" failed (2: No such file or directory), client: 185.165.190.17, server: , request: "GET /sitemap.xml HTTP/1.1", host: "xxx.xxx.xxx.94"
Nov  3 06:31:43 Ignis nginx: 2022/11/03 06:31:43 [error] 79510#100201: *617144 open() "/usr/local/www/.well-known/security.txt" failed (2: No such file or directory), client: 185.165.190.17, server: , request: "GET /.well-known/security.txt HTTP/1.1", host: "xxx.xxx.xxx.94"
Nov  3 06:57:23 Ignis nginx: 2022/11/03 06:57:23 [error] 79510#100201: *617147 open() "/usr/local/www/boaform/admin/formLogin" failed (2: No such file or directory), client: 45.61.187.101, server: , request: "POST /boaform/admin/formLogin HTTP/1.1", host: "xxx.xxx.xxx.94:80", referrer: "http://xxx.xxx.xxx.94:80/admin/login.asp"
Nov  2 22:00:00 Ignis php[38665]: [pfBlockerNG] Starting cron process.
Nov  2 22:00:26 Ignis php[38665]: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload
Nov  2 22:00:26 Ignis php[38665]:
Nov  3 07:20:39 Ignis nginx: 2022/11/03 07:20:39 [error] 79194#100241: *617148 open() "/usr/local/www/home.asp" failed (2: No such file or directory), client: 107.182.129.219, server: , request: "GET /home.asp HTTP/1.1", host: "xxx.xxx.xxx.94:80"
Nov  2 22:29:12 Ignis php-fpm[98064]: /index.php: Successful login for user 'admin' from: 192.168.1.91 (Local Database)
Nov  2 22:31:13 Ignis sshd[78290]: Accepted keyboard-interactive/pam for admin from 99.178.151.122 port 63979 ssh2
[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root: date
Wed Nov  2 22:35:33 EDT 2022

and

[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root: tail -n 25 /var/log/filter.log
Nov  3 07:36:37 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,232,28188,0,DF,1,icmp,36,15.188.65.218,xxx.xxx.xxx.89,request,27,1376816
Nov  3 07:36:39 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,236,46206,0,none,6,tcp,40,185.156.73.107,xxx.xxx.xxx.94,47206,36912,0,S,1068734224,,1024,,
Nov  3 07:36:40 Ignis filterlog[16230]: 4,,,1000000103,ix5,match,block,in,4,0x0,,239,54321,0,none,6,tcp,44,206.189.146.175,xxx.xxx.xxx.90,45855,3389,0,S,3012520328,,65535,,mss
Nov  3 07:36:42 Ignis filterlog[16230]: 4,,,1000000103,ix5,match,block,in,4,0x28,,237,11043,0,none,6,tcp,40,198.144.159.104,xxx.xxx.xxx.92,45200,31986,0,S,2623530125,,1024,,
Nov  3 07:36:43 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,236,40875,0,none,6,tcp,40,5.188.206.134,xxx.xxx.xxx.94,42503,34698,0,S,3468798847,,1024,,
Nov  3 07:36:46 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,236,46735,0,none,6,tcp,40,89.248.165.104,xxx.xxx.xxx.89,50390,50689,0,S,314754007,,1024,,
Nov  3 07:36:46 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,234,18876,0,DF,6,tcp,40,61.1.25.228,xxx.xxx.xxx.94,55207,80,0,S,4053637015,,14600,,
Nov  3 07:36:46 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,236,50800,0,none,6,tcp,40,5.188.206.134,xxx.xxx.xxx.88,42503,34698,0,S,455275170,,1024,,
Nov  3 07:36:46 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,236,24370,0,none,6,tcp,40,5.188.206.134,xxx.xxx.xxx.89,42503,34698,0,S,495872993,,1024,,
Nov  3 07:36:46 Ignis filterlog[16230]: 4,,,1000000103,ix5,match,block,in,4,0x0,,255,58626,0,none,17,udp,100,172.16.1.11,255.255.255.255,5678,5678,80
Nov  3 07:36:46 Ignis filterlog[16230]: 69,,,12003,bridge0,match,block,in,4,0x0,,255,58626,0,none,17,udp,100,172.16.1.11,255.255.255.255,5678,5678,80
Nov  3 07:36:46 Ignis filterlog[16230]: 4,,,1000000103,ix5,match,block,in,4,0x0,,255,58626,0,none,17,udp,100,172.16.1.11,255.255.255.255,5678,5678,80
Nov  3 07:36:48 Ignis filterlog[16230]: 4,,,1000000103,ix5,match,block,in,4,0x0,,242,54321,0,none,6,tcp,40,64.62.197.103,xxx.xxx.xxx.90,55271,6379,0,S,1259739034,,65535,,
Nov  3 07:36:51 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,41,12454,0,DF,6,tcp,52,218.74.148.31,xxx.xxx.xxx.92,63308,445,0,S,3587255221,,8192,,mss;nop;wscale;nop;nop;sackOK
Nov  3 07:36:51 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,228,16754,0,DF,1,icmp,36,13.208.238.234,xxx.xxx.xxx.89,request,5,1022016
Nov  3 07:36:53 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,229,19207,0,DF,1,icmp,36,3.127.220.127,xxx.xxx.xxx.89,request,26,1308816
Nov  3 07:36:53 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,237,15418,0,none,6,tcp,40,46.161.27.96,xxx.xxx.xxx.89,49973,1111,0,S,2701232948,,1024,,
Nov  3 07:36:53 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,41,12687,0,DF,6,tcp,52,218.74.148.31,xxx.xxx.xxx.92,63308,445,0,S,3587255221,,8192,,mss;nop;wscale;nop;nop;sackOK
Nov  3 07:36:55 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,102,32223,0,none,6,tcp,44,183.136.225.42,xxx.xxx.xxx.88,8088,8161,0,S,3842244096,,29200,,mss
Nov  3 07:36:56 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,236,41153,0,none,6,tcp,40,5.188.206.38,xxx.xxx.xxx.94,42016,43768,0,S,8173927,,1024,,
Nov  3 07:36:56 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,218,46635,0,DF,1,icmp,36,18.183.137.44,xxx.xxx.xxx.89,request,5,2422116
Nov  3 07:36:57 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,232,54321,0,none,6,tcp,44,139.59.26.21,xxx.xxx.xxx.89,37789,8888,0,S,3476618278,,65535,,mss
Nov  3 07:36:59 Ignis filterlog[16230]: 4,,,1000000103,ix5,match,block,in,4,0x0,,236,43350,0,none,6,tcp,40,78.128.112.2,xxx.xxx.xxx.94,41519,38504,0,S,582454368,,1024,,
Nov  3 07:37:02 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,50,65415,0,none,6,tcp,40,45.143.200.114,xxx.xxx.xxx.89,8080,31530,0,S,3329374196,,1024,,
Nov  3 07:37:03 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x0,,236,58790,0,none,6,tcp,40,89.248.165.14,xxx.xxx.xxx.88,55931,30550,0,S,513745320,,1024,,
[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root:date
Wed Nov  2 22:41:02 EDT 2022

Understudy

So the time in the logs is off. It appears to be off by like 9 hours.

Still trying to figure this one out.

Sincerely,
Brendhan

stephenw10

Is it exactly 9hrs?

Understudy

@stephenw10

I believe it is.

Nov  3 22:36:45 Ignis filterlog[16230]: 82,,,1770008940,ix5,match,block,in,4,0x28,,12,39,0,DF,1,icmp,44,1.71.141.102,104.219.179.88,request,62198,3824
Nov  3 22:36:46 Ignis filterlog[16230]: 4,,,1000000103,ix5,match,block,in,4,0x0,,235,8021,0,none,6,tcp,40,91.191.209.14,104.219.179.88,55893,40656,0,S,871183069,,1024,,
[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root: date
Thu Nov  3 13:36:52 EDT 2022

stephenw10

Hmm, curious. The timezone you have set is not 9hrs from UTC.

Have you tried setting different TZ and then switching back? Or setting GMT+5 directly?

serbus

Hello!

Have you restarted all of the relevant services since making any system timezone changes?

John

Understudy

@serbus Yes

Understudy

@stephenw10

[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root: date
Thu Nov  3 13:38:02 -05 2022

Screenshot 2022-11-03 144042.png

I have done that as suggested. I will let it run for a bit and see what the logs say. I thank you again for your help. It will be interesting because I am technically gmt -5 and I may have to do another restart. Which I will do later tonight.

Sincerely,
Brendhan

stephenw10

@understudy said in Time date in logs not correct.:

I am technically gmt -5

Not if you use the POSIX time format, which FreeBSD/pfSense does.
https://docs.netgate.com/pfsense/en/latest/troubleshooting/time-zone.html#clock-does-not-use-the-expected-zone-offset

Understudy

I am going to do a reboot also just to be sure.

Brendhan

Understudy

Okay, I did a reboot and checked the bios time. The bios time was off by two hours. It wasn't before so I am probably going to have to replace the cmos battery. As it stands right now it looks like the times for everything are correct. I am leaving it with posix time and making sure the ntpq -pn is good. I will check again in the morning to be sure and report back but initial reports look good.

[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root: date
Thu Nov  3 17:15:46 -05 2022
[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root: ntpq -pn
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 2.pfsense.pool. .POOL.          16 p    -   64    0    0.000   +0.000   0.000
 0.north-america .POOL.          16 p    -   64    0    0.000   +0.000   0.000
 1.north-america .POOL.          16 p    -   64    0    0.000   +0.000   0.000
 2.north-america .POOL.          16 p    -   64    0    0.000   +0.000   0.000
 216.197.156.83  .PPS.            1 u   24   64  377   87.111  -358288   1.279
 198.211.103.209 206.108.0.131    2 u   19   64  377   36.503  -358289   0.932
 159.203.158.197 128.59.0.245     2 u   19   64  377   37.168  -358289   0.977
 157.245.141.244 129.6.15.29      2 u   23   64  377   38.057  -358289   2.271
 12.167.151.1    158.51.134.123   3 u   17   64  377   36.220  -358291   0.514
+209.115.181.110 206.108.0.131    2 u   37   64    7   88.227  -358289   0.135
*167.99.186.165  129.6.15.28      2 u   30   64    7   48.159  -358289   0.748
[2.6.0-RELEASE][admin@Ignis.brendhanhorne.com]/root:

SteveITS

@understudy The BIOS being off by exactly a multiple of an hour is frustrating to figure out. Much more obvious if it is 27 minutes. :)

re: some services using other times, I actually posted a log of that in a completely unrelated redmine, https://redmine.pfsense.org/issues/13593. That log entry was:

system log (14:07 is UTC, 9:07 is US CDT):

Oct 25 14:07:44 check_reload_status 353 Syncing firewall
Oct 25 14:07:44 php-fpm 69691 /pkg_mgr_install.php: Configuration Change: admin@ip (Local Database): Saved firmware branch setting.
Oct 25 09:07:13 pkg-static 50845 pfSense-repo upgraded: 2.6.0_8 -> 2.7.0.a.20221025.0600
Oct 25 09:07:11 pkg-static 47503 pkg upgraded: 1.17.5_2 -> 1.18.4_1
Oct 25 14:07:02 check_reload_status 353 Syncing firewall
Oct 25 14:07:01 php-fpm 69213 /pkg_mgr_install.php: Configuration Change: admin@ip (Local Database): Saved firmware branch setting.

In that case it was the 5 hour time zone.

Not on pfSense, AFAIK, but I have set up Linux servers where if you change time zones some services don't pick it up until they restart.