I have OMV 2.2 installed from the latest OMV release for wheezy.
I continue to have an issue with the RTC and what looks like system time changing during boot and the rrdcached service having errors.
Note that I have followed the instruction for installing the RTC very closely. (many times!)...
If i look at the logs - It looks like the RTC is working fine. see below for the first items in the boot log. This looks ok, right?
However, the syslog entries use a totally different date/time until very late in the startup sequence. I see the same entries each time the system boots. At one point during boot, date changes to 6 dec 2016 (i.e in the future).
I'm new to this stuff but I have a feeling that the following is happening:
1. the RTC clock is setup and working correctly.
2. there are entries at the start of the syslog that are not actually my startup logs but included from the image i used for the original setup of OMV
3. where my actual log files kick in all is well in terms of RTC and time settings
4. when rrdcached starts to write data for the charts, there is a load of bogus data causing an error and flooding the logs
If I clear the data at startup, I resolve the problem.
rm -r /var/lib/rrdcached/db/localhost
rm /var/lib/rrdcached/journal/*
The only issue is that this clears all the statistics data each time i boot the system.
Any thoughts or assistance appreciated.
Boot log following a reboot of the Pi:
Sun Jun 12 13:41:59 2016: Setting parameters of disc: (none).
Sun Jun 12 13:41:59 2016: RTC found on bus 3f804000.i2c.
Sun Jun 12 13:41:59 2016: Setting the system clock.
Sun Jun 12 13:41:59 2016: System Clock set to: Sun Jun 12 12:41:59 UTC 2016.
Sun Jun 12 13:41:59 2016: Setting preliminary keymap...done.
Sun Jun 12 13:41:59 2016: Activating swap...done.
Sun Jun 12 13:41:59 2016: Checking root file system...fsck from util-linux 2.20.1
Sun Jun 12 13:41:59 2016: omv: clean, 62955/217296 files, 436814/863232 blocks
Sun Jun 12 13:41:59 2016: done.
Sun Jun 12 13:41:59 2016: Cleaning up temporary files... /tmp.
Sun Jun 12 13:41:59 2016: Loading kernel module snd-bcm2835.
Sun Jun 12 13:42:00 2016: Loading kernel module i2c-bcm2708.
Sun Jun 12 13:42:00 2016: Loading kernel module i2c-dev.
Sun Jun 12 13:42:00 2016: Loading kernel module rtc-ds1307.
Sun Jun 12 13:42:00 2016: Loading kernel module ipv6.
Below are a few extracts (in order presented in syslog. Note the the pi name raspberrypi is not the name i use for my pi.
first section of syslog - note time is incorrect at 26 June 2016:
Jun 26 07:26:33 raspberrypi kernel: imklog 5.8.11, log source = /proc/kmsg started.
Jun 26 07:26:33 raspberrypi rsyslogd: [origin software="rsyslogd" swVersion="5.8.11" x-pid="2140" x-info="http://www.rsyslog.com"] start
Jun 26 07:26:33 raspberrypi kernel: [ 0.000000] Booting Linux on physical CPU 0xf00
Jun 26 07:26:33 raspberrypi kernel: [ 0.000000] Initializing cgroup subsys cpuset
Jun 26 07:26:33 raspberrypi kernel: [ 0.000000] Initializing cgroup subsys cpu
Jun 26 07:26:33 raspberrypi kernel: [ 0.000000] Initializing cgroup subsys cpuacct
Jun 26 07:26:33 raspberrypi kernel: [ 0.000000] Linux version 4.0.6-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.8.3 20140303 (prerelease) (crosstool-NG linaro-1.13.1+bzr2650 - Linaro GCC 2014.03) ) #798 SMP PREEMPT Tue Jun 23 18:06:01 BST 2015
Jun 26 07:26:33 raspberrypi kernel: [ 0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
Jun 26 07:26:33 raspberrypi kernel: [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Jun 26 07:26:33 raspberrypi kernel: [ 0.000000] Machine model: Raspberry Pi 2 Model B Rev 1.1
---------
then a few seconds later into the log. the following happens. As you can see the date/time changes a couple of times. nptdate is used but i have deleted/removed this using apt-get remove. the date/time is now 6 december 2016 - in the future and this causes major problems with rrdcached.
Jun 26 07:26:35 raspberrypi avahi-daemon[2372]: Service "raspberrypi - Web administration" (/services/website.service) successfully established.
Jun 26 07:26:35 raspberrypi avahi-daemon[2372]: Service "raspberrypi" (/services/udisks.service) successfully established.
Jun 26 07:26:35 raspberrypi avahi-daemon[2372]: Service "raspberrypi - SSH" (/services/ssh.service) successfully established.
Mar 16 20:37:28 raspberrypi ntpdate[1829]: step time server 129.250.35.251 offset 22857051.581750 sec
Mar 16 20:37:29 raspberrypi ntpdate[1752]: no server suitable for synchronization found
Dec 6 08:48:21 raspberrypi ntpdate[1660]: step time server 129.250.35.251 offset 22857051.582358 sec
Dec 6 08:48:27 raspberrypi rrdcached[2118]: queue_thread_main: rrd_update_r (/var/lib/rrdcached/db/localhost/cpu-0/cpu-user.rrd) failed with status -1. (/var/lib/rrdcached/db/localhost/cpu-0/cpu-user.rrd: illegal attempt to update using time 1435321594 when last update time is 1447575165 (minimum one second step))
----------
Then - pages and pages of log files later, i see the following. This marks the end of incorrect time and i can see the correct name of my device pi-omv. It looks like this could be the start of the real syslog and all previous entries are not real. Is this possible?
Dec 6 09:11:01 raspberrypi ifplugd(lo)[1602]: Exiting.
Dec 6 09:11:01 raspberrypi ntpd[2071]: ntpd exiting on signal 15
Jun 12 13:42:18 pi-omv kernel: imklog 5.8.11, log source = /proc/kmsg started.
Jun 12 13:42:18 pi-omv rsyslogd: [origin software="rsyslogd" swVersion="5.8.11" x-pid="2302" x-info="http://www.rsyslog.com"] start
Jun 12 13:42:18 pi-omv kernel: [ 0.000000] Booting Linux on physical CPU 0x0
Jun 12 13:42:18 pi-omv kernel: [ 0.000000] Initializing cgroup subsys cpuset
Jun 12 13:42:18 pi-omv kernel: [ 0.000000] Initializing cgroup subsys cpu
Jun 12 13:42:18 pi-omv kernel: [ 0.000000] Initializing cgroup subsys cpuacct
Jun 12 13:42:18 pi-omv kernel: [ 0.000000] Linux version 4.1.19-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611) ) #858 SMP Tue Mar 15 15:56:00 GMT 2016
Jun 12 13:42:18 pi-omv kernel: [ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
Jun 12 13:42:18 pi-omv kernel: [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Jun 12 13:42:18 pi-omv kernel: [ 0.000000] Machine model: Raspberry Pi 3 Model B Rev 1.2
------
The final part of the syslog is included below but i have left out hundreds of entries where the log flies are flooded with rrdcached errors. The only way to clear the error is to clear the data and restart the services using the commands outlined by tekkb in the RTC clock setup thread.
Jun 12 13:42:25 pi-omv kernel: [ 33.388663] cfg80211: Calling CRDA to update world regulatory domain
Jun 12 13:42:28 pi-omv kernel: [ 36.548690] cfg80211: Calling CRDA to update world regulatory domain
Jun 12 13:42:31 pi-omv kernel: [ 39.708730] cfg80211: Exceeded CRDA call max attempts. Not calling CRDA
Jun 12 13:42:50 pi-omv monit[2647]: Starting monit HTTP server at [localhost:2812]
Jun 12 13:42:50 pi-omv monit[2647]: monit HTTP server started
Jun 12 13:42:50 pi-omv monit[2647]: 'localhost' Monit started
Jun 12 13:45:01 pi-omv /USR/SBIN/CRON[2946]: (root) CMD (/usr/sbin/omv-mkgraph >/dev/null 2>&1)
Jun 12 13:45:01 pi-omv rrdcached[2274]: Received FLUSHALL
Jun 12 13:45:01 pi-omv rrdcached[2274]: queue_thread_main: rrd_update_r (/var/lib/rrdcached/db/localhost/cpu-0/cpu-idle.rrd) failed with status -1. (/var/lib/rrdcached/db/localhost/cpu-0/cpu-idle.rrd: illegal attempt to update using time 1465735340 when last update time is 1481037057 (minimum one second step))
Jun 12 13:45:01 pi-omv rrdcached[2274]: queue_thread_main: rrd_update_r (/var/lib/rrdcached/db/localhost/cpu-0/cpu-softirq.rrd) failed with status -1. (/var/lib/rrdcached/db/localhost/cpu-0/cpu-softirq.rrd: illegal attempt to update using time 1465735340 when last update time is 1481037057 (minimum one second step))