Time confusion

[Anders Bruun Olsen]

I have just installed FreeNAS 9.3 and being new to FreeNAS and FreeBSD (but have 15 years experience with Linux) have a question. When I check with the date command, the time is correct, but in /var/log/messages, the timestamps seem to jump back and forward several hours. Most have the correct timestamp, but kernel log messages seem to be behind by 9 hours (I am in UTC+1). Is this normal behaviour, or is there something I need to change in the config? Or is it actually a bug I should report?

 

[cyberjock]

It is not normal behavior, but this definitely seems odd as it is not happening on any of my systems that are running the latest 9.3 build. Are you sure you set the timezone properly? Are you using the NTP service to keep the server time correct?

You failed to list any hardware at all which the forum rules does ask for when creating a thread.

 

[Anders Bruun Olsen]

I have the timezone set as Europe/Copenhagen and am using three NTP servers from the dk.pool.ntp.org pool.

Sorry about not listing my hardware. Here it is:

• AsRock C2550D4I with Atom Avaton CPU
  
• 32Gb ADATA 1600MHz DDR3 RAM (non-ECC because of a mixup. ECC-versions have been ordered)
• SanDisk Cruzer Fit 32gb USB as root
• 9*2Tb WD RE4 in a raidz2

Actually, for the last couple of hours, entries in /var/log/messages from the kernel seem to have the correct timestamps, so it might just have been a temporary problem? The server had been installed and running for about 8 hours when I noticed the problem. Currently it has been about 15 hours since install.

 

[Tywin]

Did you check the system time immediately after installation? I don't know when FreeNAS first hits NTP, but it's not necessarily right away on first startup (i.e. it may not have clock synced until after you noticed the problem).

Edit: Nevermind, see @SweetAndLow's post below.

 

[SweetAndLow]

Clock sync happens at initial startup.

 

[Anders Bruun Olsen]

The weird thing wasn't that the time was wrong, the weird thing was that most entries were correct, while the kernel entries were wrong. The minutes and seconds were correct, it was off by precisely 9 hours, which seems to indicate a timezone mixup. But why would some processes on the system use different timezones than the rest of the processes?

Here are some log messages showing the problem (note that these logentries were made over the period of about an hour and a half):

Apr 2 11:10:47 freenas notifier: Performing sanity check on nginx configuration:
Apr 2 11:10:47 freenas notifier: nginx: the configuration file /usr/local/etc/nginx/nginx.conf syntax is ok
Apr 2 11:10:47 freenas notifier: nginx: configuration file /usr/local/etc/nginx/nginx.conf test is successful
Apr 2 11:10:52 freenas manage.py: [freeadmin.navtree:614] An error occurred while unserializing from http://192.168.0.2/plugins/btsync/1/_s/treemenu: No JSON object could be decoded
Apr 2 02:22:31 freenas kernel: <6>arp: 192.168.0.2 moved from 02:97:1b:00:07:0a to d0:50:99:51:79:1c on epair0b
Apr 2 03:22:29 freenas kernel: <5>epair0a: link state changed to DOWN
Apr 2 03:22:29 freenas kernel: <5>epair0b: link state changed to DOWN
Apr 2 03:22:29 freenas kernel: <5>igb0: link state changed to DOWN
Apr 2 03:22:29 freenas kernel: <6>igb0: promiscuous mode disabled
Apr 2 03:22:29 freenas kernel: <5>bridge0: link state changed to DOWN
Apr 2 03:22:29 freenas kernel: <118>Apr 2 12:22:29 btsync_1 dhclient[70522]: connection closed
Apr 2 03:22:29 freenas kernel: <118>Apr 2 12:22:29 btsync_1 dhclient[70522]: exiting.
Apr 2 03:22:29 freenas kernel: <118>Apr 2 12:22:29 btsync_1 syslogd: exiting on signal 15
Apr 2 03:22:32 freenas kernel: <6>ifa_del_loopback_route: deletion failed
Apr 2 03:22:32 freenas kernel: Freed UMA keg (udp_inpcb) was not empty (40 items). Lost 4 pages of memory.
Apr 2 03:22:32 freenas kernel: Freed UMA keg (udpcb) was not empty (504 items). Lost 3 pages of memory.
Apr 2 03:22:32 freenas kernel: Freed UMA keg (tcptw) was not empty (100 items). Lost 2 pages of memory.
Apr 2 03:22:32 freenas kernel: Freed UMA keg (tcp_inpcb) was not empty (20 items). Lost 2 pages of memory.
Apr 2 03:22:32 freenas kernel: Freed UMA keg (tcpcb) was not empty (8 items). Lost 2 pages of memory.
Apr 2 03:22:32 freenas kernel: Freed UMA keg (ripcb) was not empty (10 items). Lost 1 pages of memory.
Apr 2 03:22:32 freenas kernel: hhook_vnet_uninit: hhook_head type=1, id=1 cleanup required
Apr 2 03:22:32 freenas kernel: hhook_vnet_uninit: hhook_head type=1, id=0 cleanup required
Apr 2 03:22:33 freenas kernel: <5>igb0: link state changed to UP
Apr 2 12:22:34 freenas notifier: Performing sanity check on nginx configuration:
Apr 2 12:22:34 freenas notifier: nginx: the configuration file /usr/local/etc/nginx/nginx.conf syntax is ok
Apr 2 12:22:34 freenas notifier: nginx: configuration file /usr/local/etc/nginx/nginx.conf test is successful
Apr 2 12:22:52 freenas notifier: Stopping collectd.
Apr 2 12:22:55 freenas notifier: Waiting for PIDS: 44468.
Apr 2 12:22:55 freenas notifier: Starting collectd.
Apr 2 03:25:39 freenas kernel: ugen0.4: <Chicony> at usbus0 (disconnected)
Apr 2 03:25:39 freenas kernel: ukbd0: at uhub1, port 3, addr 4 (disconnected)
Apr 2 03:25:39 freenas kernel: uhid0: at uhub1, port 3, addr 4 (disconnected)
Apr 2 12:26:18 freenas notifier: shutdown: [pid 86057]
Apr 2 12:26:18 freenas notifier: Shutdown NOW!