Home emoncms graphs again not updating

jasonnet · 1 February 2018 19:35

Hello Community.

I’m again noticing that the emoncms graphs are not updating. Upon first blush, the problem looked to be the same as Home emoncms graphs not updating, but it doesn’t look like a disk space issue this time. The feeds page seems to show updated feeds, but the phpfina directory stopped updating at “Jan 31 21:31” (or a few minutes before, depending on the file):

-rw-r--r-- 1 www-data www-data 6465152 Jan 31 21:09 19.dat
-rw-r--r-- 1 www-data www-data 6465144 Jan 31 21:09 20.dat
-rw-r--r-- 1 www-data www-data 6465144 Jan 31 21:09 21.dat
-rw-r--r-- 1 www-data www-data 6465132 Jan 31 21:09 23.dat
-rw-r--r-- 1 www-data www-data 6463988 Jan 31 21:09 30.dat
-rw-r--r-- 1 www-data www-data 6463980 Jan 31 21:09 31.dat
-rw-r--r-- 1 www-data www-data 6463424 Jan 31 21:09 32.dat
-rw-r--r-- 1 www-data www-data 6425816 Jan 31 21:09 38.dat
-rw-r--r-- 1 www-data www-data 1411632 Jan 31 21:09 63.dat
-rw-r--r-- 1 www-data www-data 1411644 Jan 31 21:09 62.dat
-rw-r--r-- 1 www-data www-data 1411400 Jan 31 21:09 67.dat
-rw-r--r-- 1 www-data www-data 1411448 Jan 31 21:09 66.dat
-rw-r--r-- 1 www-data www-data 1411460 Jan 31 21:09 65.dat
-rw-r--r-- 1 www-data www-data 1411368 Jan 31 21:09 70.dat
-rw-r--r-- 1 www-data www-data 1411380 Jan 31 21:09 69.dat
-rw-r--r-- 1 www-data www-data 1411392 Jan 31 21:09 68.dat
-rw-r--r-- 1 www-data www-data 6463028 Jan 31 21:10 33.dat
-rw-r--r-- 1 www-data www-data 6426104 Jan 31 21:10 37.dat
-rw-r--r-- 1 www-data www-data 6429308 Jan 31 21:10 36.dat
-rw-r--r-- 1 www-data www-data 6463028 Jan 31 21:10 34.dat
-rw-r--r-- 1 www-data www-data 6425548 Jan 31 21:10 41.dat
-rw-r--r-- 1 www-data www-data 6425684 Jan 31 21:10 40.dat
-rw-r--r-- 1 www-data www-data 6425772 Jan 31 21:10 39.dat
-rw-r--r-- 1 www-data www-data  470580 Jan 31 21:10 60.dat
-rw-r--r-- 1 www-data www-data 8703696 Jan 31 21:10 49.dat
-rw-r--r-- 1 www-data www-data 8778956 Jan 31 21:10 48.dat
-rw-r--r-- 1 www-data www-data 6425548 Jan 31 21:10 42.dat
-rw-r--r-- 1 www-data www-data 1411496 Jan 31 21:10 64.dat
-rw-r--r-- 1 www-data www-data  926488 Jan 31 21:10 73.dat
-rw-r--r-- 1 www-data www-data 6465224 Jan 31 21:11 14.dat
-rw-r--r-- 1 www-data www-data 6465228 Jan 31 21:12 15.dat
-rw-r--r-- 1 www-data www-data 6465184 Jan 31 21:12 16.dat
-rw-r--r-- 1 www-data www-data 6465184 Jan 31 21:12 17.dat
-rw-r--r-- 1 www-data www-data 6465180 Jan 31 21:31 18.dat

The SSD/disk is not full:

pi@emonpi(ro):log$ df -m  ~/data/phpfina/       
Filesystem     1M-blocks  Used Available Use% Mounted on
/dev/sda1         112547   517    106291   1% /mnt/usb/sda1
pi@emonpi(ro):log$

I have no reason to believe it ever was close to being full. And I’ve confirm that that directory is still writable.

/var/log/emonhub/emonhub.log is still updating. I do see every few seconds a Discarding RX frame ‘unrelaiable content’? message though:

2018-02-01 19:02:47,925 DEBUG    MQTT       Publishing: emon/TX08Main/temp3 300
2018-02-01 19:02:47,925 DEBUG    MQTT       Publishing: emon/TX08Main/temp4 300
2018-02-01 19:02:47,925 DEBUG    MQTT       Publishing: emon/TX08Main/temp5 300
2018-02-01 19:02:47,926 DEBUG    MQTT       Publishing: emon/TX08Main/temp6 300
2018-02-01 19:02:47,926 DEBUG    MQTT       Publishing: emon/TX08Main/pulse 1
2018-02-01 19:02:47,926 INFO     MQTT       Publishing: emon/TX08Main/rssi -40
2018-02-01 19:02:47,927 INFO     MQTT       Publishing: emonhub/rx/8/values 452,441,28,13,120.47,300,300,300,300,300,300,1
2018-02-01 19:02:47,927 INFO     MQTT       Publishing: emonhub/rx/8/rssi -40
2018-02-01 19:02:48,295 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 10 49 207 124 96 16 245 177 20 26 36 64 160 230 102 221 107 247 253 242 201 (-93)
2018-02-01 19:02:49,903 DEBUG    RFM2Pi     1198814 NEW FRAME : OK 19 93 0 0 0 127 1 25 0 (-62)
2018-02-01 19:02:49,905 DEBUG    RFM2Pi     1198814 Timestamp : 1517511769.9
2018-02-01 19:02:49,905 DEBUG    RFM2Pi     1198814 From Node : 19
2018-02-01 19:02:49,906 DEBUG    RFM2Pi     1198814    Values : [9.3, 0, 38.300000000000004, 2.5]
2018-02-01 19:02:49,907 DEBUG    RFM2Pi     1198814      RSSI : -62
2018-02-01 19:02:49,907 DEBUG    RFM2Pi     1198814 Sent to channel(start)' : ToEmonCMS
2018-02-01 19:02:49,908 DEBUG    RFM2Pi     1198814 Sent to channel(end)' : ToEmonCMS
2018-02-01 19:02:50,015 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 13 249 10 182 94 144 223 70 212 105 111 243 252 229 219 244 56 162 127 66 114 (-90)
2018-02-01 19:02:50,146 DEBUG    RFM2Pi     1198815 NEW FRAME : OK 9 0 0 3 0 8 0 0 0 172 47 184 11 184 11 184 11 184 11 184 11 184 11 1 0 0 0 (-39)
2018-02-01 19:02:50,149 DEBUG    RFM2Pi     1198815 Timestamp : 1517511770.15
2018-02-01 19:02:50,150 DEBUG    MQTT       Publishing: emon/TH19_Laundry/temperature 9.3
2018-02-01 19:02:50,150 DEBUG    RFM2Pi     1198815 From Node : 9
2018-02-01 19:02:50,152 DEBUG    RFM2Pi     1198815    Values : [0, 3, 8, 0, 122.04, 300, 300, 300, 300, 300, 300, 1, 0]
2018-02-01 19:02:50,153 DEBUG    MQTT       Publishing: emon/TH19_Laundry/external temperature 0
2018-02-01 19:02:50,153 DEBUG    RFM2Pi     1198815      RSSI : -39
2018-02-01 19:02:50,155 DEBUG    MQTT       Publishing: emon/TH19_Laundry/humidity 38.3
2018-02-01 19:02:50,155 DEBUG    RFM2Pi     1198815 Sent to channel(start)' : ToEmonCMS
2018-02-01 19:02:50,157 DEBUG    RFM2Pi     1198815 Sent to channel(end)' : ToEmonCMS
2018-02-01 19:02:50,158 DEBUG    MQTT       Publishing: emon/TH19_Laundry/battery 2.5
2018-02-01 19:02:50,159 INFO     MQTT       Publishing: emon/TH19_Laundry/rssi -62
2018-02-01 19:02:50,161 INFO     MQTT       Publishing: emonhub/rx/19/values 9.3,0,38.3,2.5
2018-02-01 19:02:50,162 INFO     MQTT       Publishing: emonhub/rx/19/rssi -62
2018-02-01 19:02:50,264 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 17 244 20 72 223 22 212 134 29 180 153 176 56 56 97 218 33 241 219 215 123 (-86)
2018-02-01 19:02:50,369 DEBUG    MQTT       Publishing: emon/TX09SubP/D03_dryer 0
2018-02-01 19:02:50,371 DEBUG    MQTT       Publishing: emon/TX09SubP/D04_dryer 3

I don’t know if that is really a problem though. The history of that log does not go back to before the graph phpfina directory stopped updating.

Looking at /var/log/ I see that certain files and directories were updating until just before the problem:

-rw-r----- 1 root      adm           940 Jan 25 01:36 ufw.log
-rw-r----- 1 root      adm       1063571 Jan 29 02:17 auth.log.2
-rw-r----- 1 root      adm       1063455 Jan 31 10:17 auth.log.1
-rw-r----- 1 root      adm       1085594 Jan 31 15:17 daemon.log.2
-rw-r----- 1 root      adm       1086584 Jan 31 18:17 syslog.2
drwxr-xr-x 2 openhab   openhab       100 Jan 31 21:37 openhab
-rw-rw-rw- 1 root      root         3210 Jan 31 21:38 emoncms.log
-rw-r----- 1 root      adm       1086143 Feb  1 15:17 syslog.1
-rw-r----- 1 root      adm       1069402 Feb  1 17:17 daemon.log.1
drwxr-xr-x 2 pi        pi             80 Feb  1 18:17 logrotate
-rw-rw-r-- 1 root      utmp         2688 Feb  1 18:36 wtmp
drwxr-xr-x 2 emonhub   root          100 Feb  1 18:57 emonhub
-rw-r----- 1 root      adm        793669 Feb  1 19:15 messages
-rw-r----- 1 root      adm        798276 Feb  1 19:15 kern.log
-rw-rw-rw- 1 root      root       487084 Feb  1 19:16 service-runner.log
-rw-r----- 1 root      adm        521015 Feb  1 19:16 auth.log
-rw-r----- 1 root      adm        183531 Feb  1 19:16 syslog
-rw-r----- 1 root      adm         68300 Feb  1 19:16 daemon.log

As you can see, emoncms.log was one of those. It ends with…

2018-01-31 21:11:17.025|WARN|phpmqtt_input.php|Disconnected cleanly
2018-01-31 21:11:23.603|WARN|phpmqtt_input.php|Subscribing to: emon/#
2018-01-31 21:11:27.270|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-01-31 21:11:30.863|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0
2018-01-31 21:11:33.888|WARN|phpmqtt_input.php|Subscribed to topic: emon/#
2018-01-31 21:11:41.036|WARN|phpmqtt_input.php|Disconnected cleanly
2018-01-31 21:11:51.989|WARN|phpmqtt_input.php|Subscribing to: emon/#
2018-01-31 21:11:57.194|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-01-31 21:12:02.529|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0
2018-01-31 21:12:07.588|WARN|phpmqtt_input.php|Subscribed to topic: emon/#
2018-01-31 21:12:14.906|WARN|phpmqtt_input.php|Disconnected cleanly
2018-01-31 21:12:26.231|WARN|phpmqtt_input.php|Subscribing to: emon/#
2018-01-31 21:12:31.680|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-01-31 21:12:32.142|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0
2018-01-31 21:12:32.142|WARN|phpmqtt_input.php|Subscribed to topic: emon/#
2018-01-31 21:38:09.134|WARN|phpmqtt_input.php|Starting MQTT Input script
2018-01-31 21:38:10.571|WARN|phpmqtt_input.php|Subscribing to: emon/#
2018-01-31 21:38:10.571|WARN|phpmqtt_input.php|Not connected, retrying connection
2018-01-31 21:38:10.572|WARN|phpmqtt_input.php|Connecting to MQTT server: Connection Accepted.: code: 0
2018-01-31 21:38:10.572|WARN|phpmqtt_input.php|Subscribed to topic: emon/#emoncms

That “not connected” looks a bit odd to me, but it seemed to be there before the problem.

As you can also see above, the /var/log/openhab/ directory was also modified just before the problem. The content of that is:

-rw-r--r-- 1 openhab openhab    0 Jan 19 19:02 events.log
-rw-r--r-- 1 openhab openhab 1127 Jan 31 21:37 openhab-2018-03.log.zip
-rw-r--r-- 1 openhab openhab 1346 Jan 31 21:37 openhab.log

So it does look like the zipping up of the old log file happened just as the problem occurred.

Looking at what the new openhab.log file shows also suggests a problem:

2018-01-31 21:37:09.885 [ERROR] [.c.mqttv3.internal.ClientState] - openhab.1516388564568: Timed out as no activity, keepAlive=60,000 lastOutboundActivity=1,517,434,136,899 lastInboundActivity=1,517,433,161,121
2018-01-31 21:37:10.381 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to broker was lost
org.eclipse.paho.client.mqttv3.MqttException: Connection lost
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:138) [mqtt-client-0.4.0.jar:na]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_151]
Caused by: java.io.EOFException: null
        at java.io.DataInputStream.readByte(DataInputStream.java:267) ~[na:1.8.0_151]
        at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:56) ~[na:na]
        at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:100) [mqtt-client-0.4.0.jar:na]
        ... 1 common frames omitted
2018-01-31 21:37:10.383 [ERROR] [o.i.t.m.i.MqttBrokerConnection] - MQTT connection to 'mosquitto' was lost: Connection lost : ReasonCode 32109 : Cause : null
2018-01-31 21:37:10.384 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'mosquitto'
2018-01-31 21:37:20.387 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto'

Might the problem be the log zipping itself is incompatible with something using that log file?

Anyway, I’m posting in part for my benefit, and in part to help us all diagnose and fix/stabilize this. I assume that if I reboot, my phpfina directory will start populating again. Is there any information the community needs before I reboot?

Jason.

jasonnet · 5 February 2018 03:55

Please let me know if there’s any data you need. Otherwise I plan to reboot on Monday night.

Thanks
J.

pb66 · 5 February 2018 12:06

Can we assume this is a “stock” emonSD and you have simply mounted a SSD in place of the 3rd SD partition?

Are there any other significant changes?

When was the system last updated? What version of emoncms are you running?

Is the feedwriter active?

sudo service feedwriter status

or

sudo systemctl status feedwriter

If not try restarting it with

sudo service feedwriter restart

or

sudo systemctl restart feedwriter

What is the response to

df -h

Is the /var/log partition in tempfs full?

jasonnet · 5 February 2018 16:54

Paul,
Thanks for the response. Yes, I haven’t done much to this besides add a SSD and create a symbolic link for the phpfina directory to a SSD directory

It was updated in late October or early November:

pi@emonpi(ro):~$ cd emonpi
pi@emonpi(ro):emonpi$ git log -v
commit 3abbbaca9b6e7ca1126243cd4b0798353ca04496
Author: Glyn Hudson <[email protected]>
Date:   Fri Oct 27 17:00:01 2017 +0100

    Update SD-card-build.md

Here is the status command you suggested:

pi@emonpi(ro):emonpi$ sudo service feedwriter status
â— feedwriter.service - LSB: feedwriter script daemon
   Loaded: loaded (/etc/init.d/feedwriter)
   Active: active (exited) since Fri 2018-01-19 19:02:37 UTC; 2 weeks 2 days ago
  Process: 1587 ExecStart=/etc/init.d/feedwriter start (code=exited, status=0/SUCCESS)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

I believe that means it has stopped. The df -h currently is:

pi@emonpi(ro):emonpi$ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root       3.4G  2.3G  941M  72% /
devtmpfs        481M     0  481M   0% /dev
tmpfs           486M     0  486M   0% /dev/shm
tmpfs           486M   50M  437M  11% /run
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
tmpfs           486M     0  486M   0% /sys/fs/cgroup
/dev/mmcblk0p3  194M   38M  147M  21% /home/pi/data
tmpfs            40M  6.1M   34M  16% /var/lib/openhab
/dev/mmcblk0p1   60M   22M   39M  37% /boot
tmpfs           1.0M     0  1.0M   0% /var/lib/dhcp
/dev/sda1       110G  517M  104G   1% /mnt/usb/sda1
tmpfs           1.0M     0  1.0M   0% /var/lib/dhcpcd5
tmpfs            50M   22M   29M  44% /var/log
tmpfs            30M   36K   30M   1% /tmp
pi@emonpi(ro):emonpi$

Restarting it we see:

pi@emonpi(ro):emonpi$ sudo service feedwriter restart
pi@emonpi(ro):emonpi$ sudo systemctl status feedwriter
â— feedwriter.service - LSB: feedwriter script daemon
   Loaded: loaded (/etc/init.d/feedwriter)
   Active: active (running) since Mon 2018-02-05 16:21:54 UTC; 8s ago
  Process: 22889 ExecStop=/etc/init.d/feedwriter stop (code=exited, status=0/SUCCESS)
  Process: 22897 ExecStart=/etc/init.d/feedwriter start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/feedwriter.service
           â””â”€22914 /usr/bin/php -f /var/www/emoncms/scripts/feedwriter.php

Feb 05 16:21:47 emonpi feedwriter[22897]: Log is turned off
Feb 05 16:21:47 emonpi feedwriter[22897]: Starting RPI
Feb 05 16:21:54 emonpi systemd[1]: Started LSB: feedwriter script daemon.

I see the phpfina directory is now updating. And eventually graphing. In fact, no data is lost at all. I have multi-day gaps in the graphs.

As you can see in the df command above, /var/log is not currently full, but I can keep an eye on it.

FWIW… openhab.log doesn’t seem to be updating. At least not in the 15 minutes since I restarted feedwriter (above). – As you saw above, the openhab.log zip file was pretty short. It contained only about 25 seconds of log data dated back on 1/19, well before the current problem. (I don’t know what is normally seen in this file. Might this indicate the zip failed to zip the full openhab.log file that was in that directory when things went awry on 1/31?)

As I just mentioned, openhab.log is apparently not updating. Is this normal, or should I take further action?

J.