Is it possible that system log entries and corrupt rrdcached data are included in the OMV boot image

    • OMV 2.x
    • Is it possible that system log entries and corrupt rrdcached data are included in the OMV boot image

      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))
    • Just reporting the same issue here

      I just wanted to add that I am having exactly the same issue with Raspberry Pi 3 OMV 2.2.1 (upgraded or not upgraded to 2.2.4) - exactly the same dates are the in system log with exactly the same errors - first 26 Jul, then changing to 16 Mar and then to 6 Dec, until finally changing to current date/time after ntpd exiting on signal 15.
      hwclock -r gives me correct date/time
      date gives me correct date/time

      Just to be on the safe side I have taken a different microSD - made it NOOBs, installed Raspbian Jessie - after enabling i2c and modules, hwclock works perfectly and the log is all correct dates
      ...
      Jun 17 23:14:19 raspberrypi rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="518" x-info="http://www.rsyslog.com"] startJun 17 23:14:19 raspberrypi systemd-modules-load[111]: Inserted module 'fuse'
      Jun 17 23:14:19 raspberrypi systemd-modules-load[111]: Inserted module 'i2c_dev'
      Jun 17 23:14:19 raspberrypi systemd-modules-load[111]: Inserted module 'i2c_bcm2708'
      Jun 17 23:14:19 raspberrypi systemd-modules-load[111]: Inserted module 'rtc_ds1307'
      Jun 17 23:14:19 raspberrypi systemd[1]: Mounted FUSE Control File System.
      ...

      So I think we can safely conclude that this is not a hardware problem, but rather something happening in OMV 2.2

      Any help/suggestions will be greatly appreciated.
    • Thanks.

      As you have the exact same entries, i think it is safe to assume that these log entries are included in the boot image and can be ignored.

      Are you getting the rrdcached errors at boot? This is what i wanted to fix but it will require making changes to the boot image/drive.

      I think the another solution is to start with a normal jessie/wheezy install and then add OMV using apt-get...
    • Yes, I am getting rrdcached errors as well - exactly like in your log - spent the whole week trying to get rid of them, so yes, it looks like both rrdcached corruption and the log entries are built into the image.
      Do we need to report it somewhere?

      As for correcting this issue I had the same idea as you, so I used the microsd with raspbian (jessie) on it to intsall omv erasmus (3.0.24 as of now) and it works, but I guess omv erasmus is still pretty much work in progress, so I'd rather stay with omv stoneburner. For that I need a debian wheezy image with rpi3 firmware or a raspbian wheezy for rpi3, and I'm not sure where to get that.

      Perhaps you'd have some ideas about that?

      Thanks

      The post was edited 1 time, last by genekh ().

    • You have reported (I create the RPi/odroid images). The log entries are definitely leftover from when I created the image. I never thought it would be that big of a deal to clear them. As for rrdcached corruption, not sure what that means but I will reset the files before creating the next image.

      OMV 3.x has not been released yet. So, it is work in progress. No real need to use it on an RPi yet anyway. I don't know why you can't use the OMV 2.x image and just remove the rrdcached files from it?? You will run into more issues trying to install OMV on Wheezy. Hence the reason I started creating the image in the first place.
      omv 4.1.19 arrakis | 64 bit | 4.15 proxmox kernel | omvextrasorg 4.1.15
      omv-extras.org plugins source code and issue tracker - github

      Please read this before posting a question and this and this for docker questions.
      Please don't PM for support... Too many PMs!
    • First of all - thank you for the pre-built images - for a linux-inexperienced person like me they are great.

      As for the syslog and rrdcached, it is not just that - every time I connect via ssh after every reboot I get "Last login 6 Dec 2016", subsequent connections are dated correctly. Many files are timestamped in the future as well (again 6 Dec 2016)- again as a linux-inexperienced person I am not sure if it is a problem. So basically this date 6 Dec 2016 appears everywhere.

      So I guess whilst not a problem as such, it is quite confusing for people who'd be using these images - looking at the log which always starts in the future and thinking that they can't get the time to set correctly.

      It would be great if the image could be corrected.

      Thank you
    • tekkb wrote:

      I don't understand why you guys get any time stamps that are not the current date if you RTC module is working. At the very beginning of of the logs on boot my RPi 2 has the correct time and date.


      My understanding is that log hasn't been cleared in the image (as well as rrdcached data) and it gets restored after every reboot. So these are not actually our logs, but logs from the image.

      As per my original response to the OP, the same hardware works flawlessly on raspbian after enabling i2c and ds3231

      The OP and I are both using rpi3 with the pre-built omv 2.2.1 image (if I am not mistaken about the OP)

      The post was edited 1 time, last by genekh ().

    • I found the issue with the original poster. He did not do this:

      apt-get purge ntpdate

      You cannot have ntpdate installed if you are using the ntp server. Are you still seeing ntp date stamps in your logs too????

      See these entries from his logs. It tells me he did not uninstall the ntpdate package:

      Source Code

      1. Mar 16 20:37:28 raspberrypi ntpdate[1829]: step time server 129.250.35.251 offset 22857051.581750 sec
      2. Mar 16 20:37:29 raspberrypi ntpdate[1752]: no server suitable for synchronization found
      3. Dec 6 08:48:21 raspberrypi ntpdate[1660]: step time server 129.250.35.251 offset 22857051.582358 sec
    • I don't see how he could have those stamps if he did. Something is wrong with his removal of that package.

      BTW, I have been running my RPi 2 with the RTC module over one year now and it has been flawless.

      The OP should check for the ntpdate package on his system:
      dpkg -l | grep ntpdate

      He may have entered this command wrong:
      apt-get --purge remove ntpdate (there are 2 "--" minus signs in that command)

      As an alternative you can run this:
      apt-get purge ntpdate (I changed my post above to this command)

      The post was edited 2 times, last by tekkb ().

    • tekkb wrote:

      I don't see how he could have those stamps if he did. Something is wrong with his removal of that package.


      I don't think it has anything to do with ntpdate, but has to do with the syslog being RESTORED on each boot from the image. These are not OUR logs, but the SAVED logs.

      Steps to reproduce behaviour:

      root@raspberrypi:~# apt-get install ntpdate
      Reading package lists... Done
      Building dependency tree
      Reading state information... Done
      ntpdate is already the newest version.
      0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
      root@raspberrypi:~# update-rc.d -f ntpdate remove
      update-rc.d: using dependency based boot sequencing
      root@raspberrypi:~# apt-get --purge remove ntpdate
      Reading package lists... Done
      Building dependency tree
      Reading state information... Done
      The following packages will be REMOVED:
      ntpdate*
      0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded.
      After this operation, 135 kB disk space will be freed.
      Do you want to continue [Y/n]? y
      (Reading database ... 44031 files and directories currently installed.)
      Removing ntpdate ...
      Purging configuration files for ntpdate ...
      Processing triggers for man-db ...
      Creating index of upgradeable packages ...
      Creating index of openmediavault plugins ...
      root@raspberrypi:~# dpkg -l | grep ntpdate
      root@raspberrypi:~# > /var/log/syslog
      root@raspberrypi:~# reboot


      Now after reboot looking at the syslog:
      ...
      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))
      ...

      See - these are not our entries, but entries saved with the image. They are the same every single time

      So my understanding is that the image needs to be corrected so that there are no logs, no rrdcached entries and the date is not in the future. ryecoaaron kindly responded acknowledging the issue and will hopefully produce a solution soon.

      Thanks
    • ryecoaaron wrote:

      You have reported (I create the RPi/odroid images). The log entries are definitely leftover from when I created the image. I never thought it would be that big of a deal to clear them. As for rrdcached corruption, not sure what that means but I will reset the files before creating the next image.


      The problem is not with clearing them, but that they are reproduced at each reboot (see my post above). Also the file timestamp and the date in the future 6 Dec 2016 seems to be causing a lot of confusion and problems with rrdcached, so it would be great to resolve this for future omv 2 releases.

      Thank you
    • The date issue happens because the RPi doesn't have a real time clock. In the next release (probably upload today or tomorrow), I added the command to /etc/rc.local which runs on every boot fixing the issue: ntpdate-debian -b pool.ntp.org
      omv 4.1.19 arrakis | 64 bit | 4.15 proxmox kernel | omvextrasorg 4.1.15
      omv-extras.org plugins source code and issue tracker - github

      Please read this before posting a question and this and this for docker questions.
      Please don't PM for support... Too many PMs!
    • ryecoaaron wrote:

      The date issue happens because the RPi doesn't have a real time clock. In the next release (probably upload today or tomorrow), I added the command to /etc/rc.local which runs on every boot fixing the issue: ntpdate-debian -b pool.ntp.org


      Thanks a lot.

      Again, from inexperience, I am going to ask if this is also going to fix the issue with "Last login 6 Dec 2016" in ssh sessions after reboot?

      Also, as the OP and I are both installing RTC - I understand we need to follow the guide for wheezy, not jessie to enable that, as for jessie the installation is as simple as adding dtoverlay to /boot/config.txt and enabling i2c via raspi-config - at least on raspbian it is.
      I understand that for wheezy we need to follow the guide by tekkb, right?

      Thanks again

      P.S. Is the new image going to be uploaded to sourceforge here?
      sourceforge.net/projects/openmediavault/files/Raspberry Pi images/

      The post was edited 1 time, last by genekh ().