Continuous error messages on syslog

    • OMV 2.x
    • Resolved

    This site uses cookies. By continuing to browse this site, you are agreeing to our Cookie Policy.

    • Continuous error messages on syslog

      After a week of so of running the server as a backup to my main NAS, I had a quick look at the logs and found the syslog being swamped with these messages, here are some samples off the top of the syslog:

      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/interface-eth0/if_packets.rrd, [1464679368:7210783:1749906], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/interface-eth0/if_errors.rrd, [1464679368:0:0], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/df-media-fa36508a-b3c4-4499-b30a-711dd5994225/df_complex-reserved.rrd, [1464679368:211551232.000000], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/df-media-457474be-d970-4f9d-9c0b-84a235546ae0/df_complex-reserved.rrd, [1464679368:16777216.000000], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/rrdcached/queue_length.rrd, [1464679368:0.000000], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/rrdcached/operations-receive-update.rrd, [1464679368:2340607], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/rrdcached/operations-receive-flush.rrd, [1464679368:47300], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/rrdcached/operations-write-updates.rrd, [1464679368:18], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/rrdcached/operations-write-data_sets.rrd, [1464679368:18], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/rrdcached/gauge-tree_nodes.rrd, [1464679368:55.000000], 1) failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
      May 31 08:22:48 raspberrypi collectd[19041]: rrdcached plugin: rrdc_update (/var/lib/rrdcached/db/localhost/rrdcached/gauge-tree_depth.rrd, [1464679368:7.000000], 1) failed with status -1.

      My NAS consists of an RPi Model 2 with 2 x 1TB hard disks running as a RAID 1 (mirror) and everything appears to be working correctly, with my Synology NAS backing up everything to the RPi absolutely fine. Clearly there is a configuration error somewhere. Research of some really old threads suggests that it is a problem with connectd and to look at collectd.conf, but I don't know what I am looking for but these are current contents:

      Hostname "localhost"
      FQDNLookup true

      LoadPlugin syslog
      <Plugin syslog>
      LogLevel info
      </Plugin>

      LoadPlugin rrdcached
      <Plugin rrdcached>
      DaemonAddress "unix:/var/run/rrdcached.sock"
      DataDir "/var/lib/rrdcached/db/"
      CreateFiles true
      CollectStatistics true
      </Plugin>

      LoadPlugin unixsock
      <Plugin unixsock>
      SocketFile "/var/run/collectd.socket"
      SocketGroup "root"
      SocketPerms "0660"
      </Plugin>

      LoadPlugin cpu

      LoadPlugin df
      <Plugin df>
      # MountPoint "/"
      MountPoint "/media/fa36508a-b3c4-4499-b30a-711dd5994225"
      MountPoint "/media/457474be-d970-4f9d-9c0b-84a235546ae0"
      IgnoreSelected false
      </Plugin>

      LoadPlugin interface
      <Plugin interface>
      Interface "eth0"
      IgnoreSelected false
      </Plugin>

      LoadPlugin load

      LoadPlugin memory

      Can anyone point me in the right directon?
    • Hi tekkb

      Thanks for the link and I tried the commands you suggested in there to get logging working and - hey presto! :) The error messages have stopped and performance graphs are now appearing - which I didn't realise was all part of the same problem.

      For anyone else who is looking for a solution, the commands needed are:
      rm -r /var/lib/rrdcached/db/localhost
      rm /var/lib/rrdcached/journal/*
      service collectd restart
      service rrdcached restart

      Many thanks.
    • You may also give omv-firstaid a try.
      Absolutely no support through PM!

      I must not fear.
      Fear is the mind-killer.
      Fear is the little-death that brings total obliteration.
      I will face my fear.
      I will permit it to pass over me and through me.
      And when it has gone past I will turn the inner eye to see its path.
      Where the fear has gone there will be nothing.
      Only I will remain.

      Litany against fear by Bene Gesserit
    • I continue to have an issue with the RTC and system time changing and the rrdcached service having errors

      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. 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))