Stops running after an hour or so

toml · 1 December 2017 10:48

Hi, my emonTX stops running after an hour, I followed the troubleshooting guide and have linked the output below.

Any ideas?

pi@emonpi(ro):~$ sudo service emonhub status
● emonhub.service - LSB: Start/stop emonHub
   Loaded: loaded (/etc/init.d/emonhub)
   Active: active (exited) since Fri 2017-12-01 09:17:19 UTC; 1h 25min ago
  Process: 505 ExecStart=/etc/init.d/emonhub start (code=exited, status=0/SUCCESS)

Dec 01 09:17:19 emonpi sudo[545]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 01 09:17:19 emonpi sudo[545]: pam_unix(sudo:session): session opened fo...0)
Dec 01 09:17:19 emonpi sudo[545]: pam_unix(sudo:session): session closed fo...ot
Dec 01 09:17:19 emonpi sudo[637]: root : TTY=unknown ; PWD=/ ; USER=root ; ...og
Dec 01 09:17:19 emonpi sudo[637]: pam_unix(sudo:session): session opened fo...0)
Dec 01 09:17:19 emonpi sudo[637]: pam_unix(sudo:session): session closed fo...ot
Dec 01 09:17:19 emonpi sudo[648]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 01 09:17:19 emonpi sudo[648]: pam_unix(sudo:session): session opened fo...0)
Dec 01 09:17:19 emonpi sudo[648]: pam_unix(sudo:session): session closed fo...ot
Dec 01 09:17:19 emonpi sudo[675]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 01 09:17:19 emonpi sudo[675]: pam_unix(sudo:session): session opened fo...0)
Dec 01 09:17:19 emonpi sudo[675]: pam_unix(sudo:session): session closed fo...ot
Dec 01 09:17:19 emonpi emonhub[505]: Starting OpenEnergyMonitor emonHub: em...k.
Dec 01 09:17:19 emonpi systemd[1]: Started LSB: Start/stop emonHub.
Hint: Some lines were ellipsized, use -l to show in full.
pi@emonpi(ro):~$ sudo service emonhub status -l
● emonhub.service - LSB: Start/stop emonHub
   Loaded: loaded (/etc/init.d/emonhub)
   Active: active (exited) since Fri 2017-12-01 09:17:19 UTC; 1h 25min ago
  Process: 505 ExecStart=/etc/init.d/emonhub start (code=exited, status=0/SUCCESS)

Dec 01 09:17:19 emonpi sudo[545]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 01 09:17:19 emonpi sudo[545]: pam_unix(sudo:session): session opened fo...0)
Dec 01 09:17:19 emonpi sudo[545]: pam_unix(sudo:session): session closed fo...ot
Dec 01 09:17:19 emonpi sudo[637]: root : TTY=unknown ; PWD=/ ; USER=root ; ...og
Dec 01 09:17:19 emonpi sudo[637]: pam_unix(sudo:session): session opened fo...0)
Dec 01 09:17:19 emonpi sudo[637]: pam_unix(sudo:session): session closed fo...ot
Dec 01 09:17:19 emonpi sudo[648]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 01 09:17:19 emonpi sudo[648]: pam_unix(sudo:session): session opened fo...0)
Dec 01 09:17:19 emonpi sudo[648]: pam_unix(sudo:session): session closed fo...ot
Dec 01 09:17:19 emonpi sudo[675]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 01 09:17:19 emonpi sudo[675]: pam_unix(sudo:session): session opened fo...0)
Dec 01 09:17:19 emonpi sudo[675]: pam_unix(sudo:session): session closed fo...ot
Dec 01 09:17:19 emonpi emonhub[505]: Starting OpenEnergyMonitor emonHub: em...k.
Dec 01 09:17:19 emonpi systemd[1]: Started LSB: Start/stop emonHub.
Hint: Some lines were ellipsized, use -l to show in full.
pi@emonpi(ro):~$ tail /var/log/emonhub/emonhub.log
2017-12-01 10:31:16,062 DEBUG    MQTT       Publishing: emon/gasNode-0-10/tempBoiler 300
2017-12-01 10:31:16,063 DEBUG    MQTT       Publishing: emon/gasNode-0-10/tempHotWater 300
2017-12-01 10:31:16,064 DEBUG    MQTT       Publishing: emon/gasNode-0-10/temp3 300
2017-12-01 10:31:16,066 DEBUG    MQTT       Publishing: emon/gasNode-0-10/temp4 300
2017-12-01 10:31:16,067 DEBUG    MQTT       Publishing: emon/gasNode-0-10/temp5 300
2017-12-01 10:31:16,068 DEBUG    MQTT       Publishing: emon/gasNode-0-10/temp6 300
2017-12-01 10:31:16,070 DEBUG    MQTT       Publishing: emon/gasNode-0-10/gasPulse 0
2017-12-01 10:31:16,071 INFO     MQTT       Publishing: emon/gasNode-0-10/rssi -39
2017-12-01 10:31:16,072 INFO     MQTT       Publishing: emonhub/rx/24/values 0,0,0,0,4.8,300,300,300,300,300,300,0
2017-12-01 10:31:16,073 INFO     MQTT       Publishing: emonhub/rx/24/rssi -39
pi@emonpi(ro):~$ sudo service mqtt_input status
● mqtt_input.service - Emoncms MQTT Input Script
   Loaded: loaded (/etc/systemd/system/mqtt_input.service; enabled)
   Active: active (running) since Fri 2017-12-01 10:08:19 UTC; 35min ago
 Docs: https://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
 Main PID: 1996 (php)
   CGroup: /system.slice/mqtt_input.service
       └─1996 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Dec 01 10:08:19 emonpi systemd[1]: Started Emoncms MQTT Input Script.
pi@emonpi(ro):~$ tail /var/log/emoncms.log
2017-12-01 10:08:11.999|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' in /var/www/emoncms/scripts/phpmqtt_input.php:112
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(112): Mosquitto\Client->loop()
#1 {main}
2017-12-01 10:08:12.001|WARN|phpmqtt_input.php|Not connected, retrying connection
2017-12-01 10:08:21.271|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' with message 'The client is not currently connected.' in /var/www/emoncms/scripts/phpmqtt_input.php:112
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(112): Mosquitto\Client->loop()
#1 {main}
2017-12-01 10:08:21.291|WARN|phpmqtt_input.php|Not connected, retrying connection
pi

TrystanLea · 1 December 2017 11:05

Thanks for the debug output Tom.

Does:

sudo service mqtt_input restart

solve the problem briefly for you?

toml · 1 December 2017 11:09

hello,

No, i ran all the restart commands in troubleshooting, and also did a sudo restart, neither did anything.

I unplugged and re plugged it into power and got the following warning:

2017-12-01 11:05:46,657 INFO     MainThread Opening hub...
2017-12-01 11:05:46,657 INFO     MainThread Logging level set to DEBUG
2017-12-01 11:05:46,658 INFO     MainThread Creating EmonHubJeeInterfacer 'RFM2Pi' 
2017-12-01 11:05:46,662 DEBUG    MainThread Opening serial port: /dev/ttyAMA0 @ 38400 bits/s
2017-12-01 11:05:48,665 WARNING  MainThread Device communication error - check settings
2017-12-01 11:05:48,666 INFO     MainThread Setting RFM2Pi frequency: 433 (4b)
2017-12-01 11:05:49,668 INFO     MainThread Setting RFM2Pi group: 210 (210g)
2017-12-01 11:05:50,670 INFO     MainThread Setting RFM2Pi quiet: 0 (0q)
2017-12-01 11:05:51,672 INFO     MainThread Setting RFM2Pi baseid: 2 (2i)
2017-12-01 11:05:52,675 INFO     MainThread Setting RFM2Pi calibration: 230V (1p)
2017-12-01 11:05:53,677 DEBUG    MainThread Setting RFM2Pi subchannels: ['ToRFM12']
2017-12-01 11:05:53,678 DEBUG    MainThread Setting RFM2Pi pubchannels: ['ToEmonCMS']
2017-12-01 11:05:53,679 INFO     MainThread Creating EmonHubMqttInterfacer 'MQTT'

but it then started posting fine, but i expect it will stop in an hour

TrystanLea · 1 December 2017 11:26

Ok thanks, good to know ‘emonhub restart’ and ‘mqtt_input restart’ did not solve it for you.

What are you monitoring on the emontx? I notice your naming is different from standard ‘gasNode-0-10’
Have you made any firmware modifications?

toml · 1 December 2017 11:56

Nothing at the moment, they are just at my home for some testing before I deploy them.

Yes the names are different, I updated the config file in the emonBase. Firmware wise, all 20 emonTX’s are standard with the exception of two which I created updated sketches to test removing some data points I didn’t need. These had been running for most of the week fine.

No changes have been made within a past few days, the issue started yesterday.

Here is my config file (the lack of remote logging section is because im using node red)

#######################################################################
#######################      emonhub.conf     #########################
#######################################################################
### emonHub configuration file, for info see documentation:
### http://github.com/openenergymonitor/emonhub/blob/emon-pi/configuration.md
#######################################################################
#######################    emonHub  settings    #######################
#######################################################################

[hub]
### loglevel must be one of DEBUG, INFO, WARNING, ERROR, and CRITICAL
loglevel = DEBUG
### Uncomment this to also send to syslog
# use_syslog = yes
#######################################################################
#######################       Interfacers       #######################
#######################################################################

[interfacers]
### This interfacer manages the RFM12Pi/RFM69Pi/emonPi module
[[RFM2Pi]]
    Type = EmonHubJeeInterfacer
    [[[init_settings]]]
        com_port = /dev/ttyAMA0
        com_baud = 38400                        # 9600 for old RFM12Pi
    [[[runtimesettings]]]
        pubchannels = ToEmonCMS,
        subchannels = ToRFM12,

        group = 210
        frequency = 433
        baseid = 2                             # emonPi / emonBase nodeID
        quiet = true                            # Report incomplete RF packets (no implemented on emonPi)
        calibration = 230V                      # (UK/EU: 230V, US: 110V)
        # interval =  0                         # Interval to transmit time to emonGLCD (seconds)

[[MQTT]]

    Type = EmonHubMqttInterfacer
    [[[init_settings]]]
        mqtt_host = 127.0.0.1
        mqtt_port = 1883
        mqtt_user = emonpi
        mqtt_passwd = emonpimqtt2016

    [[[runtimesettings]]]
        pubchannels = ToRFM12,
        subchannels = ToEmonCMS,

        # emonhub/rx/10/values format
        # Use with emoncms Nodes module
        node_format_enable = 1
        node_format_basetopic = emonhub/

        # emon/emontx/power1 format - use with Emoncms MQTT input
        # http://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
        nodevar_format_enable = 1
        nodevar_format_basetopic = emon/



#######################################################################
#######################          Nodes          #######################
#######################################################################

[nodes]

## See config user guide: http://github.com/openenergymonitor/emonhub/blob/master/configuration.md

#######################          Base Node        #######################
[[2]]
    nodename = emonpi
    [[[rx]]]
        names = power1,power2,power1pluspower2,vrms,t1,t2,t3,t4,t5,t6,pulsecount
        datacodes = h, h, h, h, h, h, h, h, h, h, L
        scales = 1,1,1,0.01,0.1,0.1,0.1,0.1,0.1,0.1,1
        units = W,W,W,V,C,C,C,C,C,C,p

#######################          Power Node 5-9       #######################

[[5]]
   nodename = powerNode-0-1
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[6]]
   nodename = powerNode-0-2
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[7]]
   nodename = powerNode-0-3
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[8]]
   nodename = powerNode-0-4
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[9]]
   nodename = powerNode-0-5
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p


#######################          Boiler Node 10-14       #######################
[[10]]
   nodename = boilerNode-0-1
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[11]]
   nodename = boilerNode-0-2
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[12]]
   nodename = boilerNode-0-3
   [[[rx]]]
      names = powerOverall, powerCooker , power3, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[13]]
   nodename = boilerNode-0-4
   [[[rx]]]
      names = powerOverall, powerCooker , power3, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[14]]
   nodename = boilerNode-0-5
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

#######################          Gas Node 15-24      #######################

[[15]]
   nodename = gasNode-0-1
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[16]]
   nodename = gasNode-0-2
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[17]]
   nodename = gasNode-0-3
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[18]]
   nodename = gasNode-0-4
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[19]]
   nodename = gasNode-0-5
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[20]]
   nodename = gasNode-0-6
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[21]]
   nodename = gasNode-0-7
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[22]]
   nodename = gasNode-0-8
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[23]]
   nodename = gasNode-0-9
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[24]]
   nodename = gasNode-0-10
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

#######################          TEST SKETCH NODES     #######################

[[26]]
   nodename = TestGasNode
   [[[rx]]]
      names = vrms, gasPulse
      datacodes = h,L
      scales = 0.01,1
      units =V,p

[[27]]
   nodename = TestPowerNode
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms
      datacodes = h,h,h,h,h
      scales = 1,1,1,1,0.01
      units =W,W,W,W,V

[[28]]
   nodename = TestBoilerNode
   [[[rx]]]
      names = vrms, tempBoiler, tempHotWater
      datacodes = h,h,h
      scales = 0.01,0.1,0.1
      units =V,C,C

[[25]]
    nodename = emonTH_7
   [[[rx]]]
      names = powerOverall, powerCooker , powerLight1, powerLight2, vrms, tempBoiler, tempHotWater, temp3, temp4, temp5, temp6, gasPulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

toml · 1 December 2017 11:58

The longterm plan was to replace the default decoders with something like the ones under test, to match the updated firmware.

pb66 · 1 December 2017 12:58

When you say the “emonTx stops running after an hour” where are you seeing that? are you looking at emoncms? inputs page, feeds page or graphing? Have you checked emonhub.log?

The “Device communication error - check settings” fault you point out is actually normal operation on the emonPi, the ability to check the firmware version and current status was working in the original emonhub but has never functioned in the emonPi variant.

Can you set quiet=false in the [[RFM2Pi]] section of emonhub.conf and if/when it occurs again post your emonhub.log? Can you also confirm the led on the emonTx is flashing whilst it’s working ok and whether than flashing stops or continues if the emonTx stops.

toml · 1 December 2017 14:50

I looked in CMS and also in log, the log file was no longer logging anything, the CMS was no longer receiving anything.

I have checked the logs, the outputs are in my original post but ill change to quiet=false when I am home and post the logfile when I have the issue again.

toml · 1 December 2017 17:28

Went down again, here is the entire log file I have. Now I am back ill change config to quiet = false and wait till it goes down again

2017-12-01 17:17:21,547 INFO     MainThread EmonHub emonHub emon-pi variant v2.0.0
2017-12-01 17:17:21,549 INFO     MainThread Opening hub...
2017-12-01 17:17:21,550 INFO     MainThread Logging level set to DEBUG
2017-12-01 17:17:21,552 INFO     MainThread Creating EmonHubJeeInterfacer 'RFM2Pi' 
2017-12-01 17:17:21,556 DEBUG    MainThread Opening serial port: /dev/ttyAMA0 @ 38400 bits/s
2017-12-01 17:17:23,559 WARNING  MainThread Device communication error - check settings
2017-12-01 17:17:23,561 INFO     MainThread Setting RFM2Pi frequency: 433 (4b)
2017-12-01 17:17:24,563 INFO     MainThread Setting RFM2Pi group: 210 (210g)
2017-12-01 17:17:25,565 INFO     MainThread Setting RFM2Pi quiet: 0 (0q)
2017-12-01 17:17:26,567 INFO     MainThread Setting RFM2Pi baseid: 2 (2i)
2017-12-01 17:17:27,569 INFO     MainThread Setting RFM2Pi calibration: 230V (1p)
2017-12-01 17:17:28,571 DEBUG    MainThread Setting RFM2Pi subchannels: ['ToRFM12']
2017-12-01 17:17:28,572 DEBUG    MainThread Setting RFM2Pi pubchannels: ['ToEmonCMS']
2017-12-01 17:17:28,573 INFO     MainThread Creating EmonHubMqttInterfacer 'MQTT' 
2017-12-01 17:17:28,576 INFO     MainThread MQTT Init mqtt_host=127.0.0.1 mqtt_port=1883 mqtt_user=emonpi
2017-12-01 17:17:28,680 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:17:28,684 INFO     MQTT       Could not connect...
2017-12-01 17:17:29,786 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:17:29,788 INFO     MQTT       Could not connect...
2017-12-01 17:17:30,891 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:17:30,893 INFO     MQTT       Could not connect...
2017-12-01 17:17:31,995 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:17:31,997 INFO     MQTT       Could not connect...
2017-12-01 17:17:33,101 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:17:33,103 INFO     MQTT       Could not connect...
2017-12-01 17:17:34,206 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:17:34,208 INFO     MQTT       Could not connect...
2017-12-01 17:17:35,311 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:17:35,313 INFO     MQTT       Could not connect...
2017-12-01 17:25:45,059 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:45,061 INFO     MQTT       Could not connect...
2017-12-01 17:25:46,163 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:46,165 INFO     MQTT       Could not connect...
2017-12-01 17:25:47,269 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:47,270 INFO     MQTT       Could not connect...
2017-12-01 17:25:48,373 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:48,375 INFO     MQTT       Could not connect...
2017-12-01 17:25:49,496 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:49,511 INFO     MQTT       Could not connect...
2017-12-01 17:25:50,661 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:50,663 INFO     MQTT       Could not connect...
2017-12-01 17:25:51,766 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:51,871 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:51,975 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:25:51,980 INFO     MQTT       connection status: Connection successful
2017-12-01 17:25:51,982 DEBUG    MQTT       CONACK => Return code: 0
2017-12-01 17:25:52,084 INFO     MQTT       on_subscribe

toml · 1 December 2017 18:13

it just froze then restarted, i this was the last thing in the log:

    2017-12-01 18:04:44,254 DEBUG    MQTT       Publishing: emon/powerNode-0-1/tempBoiler 300
    2017-12-01 18:04:44,255 DEBUG    MQTT       Publishing: emon/powerNode-0-1/tempHotWater 300
    2017-12-01 18:04:44,257 DEBUG    MQTT       Publishing: emon/powerNode-0-1/temp3 300
    2017-12-01 18:04:44,259 DEBUG    MQTT       Publishing: emon/powerNode-0-1/temp4 300
    2017-12-01 18:04:44,261 DEBUG    MQTT       Publishing: emon/powerNode-0-1/temp5 300
    2017-12-01 18:04:44,263 DEBUG    MQTT       Publishing: emon/powerNode-0-1/temp6 300
    2017-12-01 18:04:44,265 DEBUG    MQTT       Publishing: emon/powerNode-0-1/gasPulse 0
    2017-12-01 18:04:44,267 INFO     MQTT       Publishing: emon/powerNode-0-1/rssi -52
    2017-12-01 18:04:44,268 INFO     MQTT       Publishing: emonhub/rx/5/values 0,0,0,0,4.59,300,300,300,300,300,300,0
    2017-12-01 18:04:44,270 INFO     MQTT       Publishing: emonhub/rx/5/rssi -52
    2017-12-01 18:04:45,023 DEBUG    RFM2Pi     device settings updated: [RF12demo.14] B i2 g210 @ 433 MHz
    2017-12-01 18:04:45,328 DEBUG    RFM2Pi     device settings updated: [RF12demo.14] B i2 g210 @ 433 MHz
    2017-12-01 18:04:45,833 DEBUG    RFM2Pi     device settings updated: [RF12demo.14] B i2 g210 @ 433 MHz
    2017-12-01 18:04:46,339 DEBUG    RFM2Pi     device settings updated: [RF12demo.14] B i2 g210 @ 433 MHz

I cant post the entire log file as its to big but here is the part around this timeframe (the log has a 30min gap for some reason)

    300, 300, 300, 0]
2017-12-01 17:33:00,282 DEBUG    RFM2Pi     25      RSSI : -43
2017-12-01 17:33:00,283 DEBUG    RFM2Pi     25 Sent to channel(start)' : ToEmonCMS
2017-12-01 17:33:00,283 DEBUG    RFM2Pi     25 Sent to channel(end)' : ToEmonCMS
2017-12-01 17:33:00,691 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 21 0 0 0 0 0 0 0 196 1 184 11 184 11 184 11 184 11 184 11 184 (-58)
2017-12-01 17:33:00,794 INFO     MQTT       Connecting to MQTT Server
2017-12-01 17:33:00,795 INFO     MQTT       Could not connect...
2017-12-01 18:06:17,888 DEBUG    RFM2Pi     26 NEW FRAME : OK 20 0 0 0 0 0 0 0 0 196 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-42)
2017-12-01 18:06:17,892 DEBUG    RFM2Pi     26 Timestamp : 1512151577.89
2017-12-01 18:06:17,892 DEBUG    RFM2Pi     26 From Node : 20
2017-12-01 18:06:17,893 DEBUG    RFM2Pi     26    Values : [0, 0, 0, 0, 4.5200000000000005, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:17,894 DEBUG    RFM2Pi     26      RSSI : -42
2017-12-01 18:06:17,894 DEBUG    RFM2Pi     26 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:17,895 DEBUG    RFM2Pi     26 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:18,486 INFO     MQTT       Connecting to MQTT Server
2017-12-01 18:06:18,489 INFO     MQTT       Could not connect...
2017-12-01 18:06:18,729 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 26 192 128 159 203 82 148 96 28 211 (-87)
2017-12-01 18:06:19,378 DEBUG    RFM2Pi     27 NEW FRAME : OK 5 0 0 0 0 0 0 0 0 222 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-51)
2017-12-01 18:06:19,382 DEBUG    RFM2Pi     27 Timestamp : 1512151579.38
2017-12-01 18:06:19,383 DEBUG    RFM2Pi     27 From Node : 5
2017-12-01 18:06:19,384 DEBUG    RFM2Pi     27    Values : [0, 0, 0, 0, 4.78, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:19,384 DEBUG    RFM2Pi     27      RSSI : -51
2017-12-01 18:06:19,385 DEBUG    RFM2Pi     27 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:19,385 DEBUG    RFM2Pi     27 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:19,591 INFO     MQTT       Connecting to MQTT Server
2017-12-01 18:06:19,593 INFO     MQTT       Could not connect...
2017-12-01 18:06:20,095 DEBUG    RFM2Pi     28 NEW FRAME : OK 22 0 0 0 0 0 0 0 0 198 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-48)
2017-12-01 18:06:20,099 DEBUG    RFM2Pi     28 Timestamp : 1512151580.1
2017-12-01 18:06:20,100 DEBUG    RFM2Pi     28 From Node : 22
2017-12-01 18:06:20,101 DEBUG    RFM2Pi     28    Values : [0, 0, 0, 0, 4.54, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:20,101 DEBUG    RFM2Pi     28      RSSI : -48
2017-12-01 18:06:20,102 DEBUG    RFM2Pi     28 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:20,103 DEBUG    RFM2Pi     28 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:20,327 DEBUG    RFM2Pi     29 NEW FRAME : OK 16 0 0 0 0 0 0 0 0 225 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-60)
2017-12-01 18:06:20,331 DEBUG    RFM2Pi     29 Timestamp : 1512151580.33
2017-12-01 18:06:20,332 DEBUG    RFM2Pi     29 From Node : 16
2017-12-01 18:06:20,333 DEBUG    RFM2Pi     29    Values : [0, 0, 0, 0, 4.8100000000000005, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:20,334 DEBUG    RFM2Pi     29      RSSI : -60
2017-12-01 18:06:20,335 DEBUG    RFM2Pi     29 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:20,335 DEBUG    RFM2Pi     29 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:20,441 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 24 0 0 0 0 0 0 0 223 1 184 11 184 11 184 11 184 11 184 11 184 (-55)
2017-12-01 18:06:20,696 INFO     MQTT       Connecting to MQTT Server
2017-12-01 18:06:20,698 INFO     MQTT       Could not connect...
2017-12-01 18:06:20,746 DEBUG    RFM2Pi     30 NEW FRAME : OK 26 1 2 0 0 0 0 (-40)
2017-12-01 18:06:20,748 DEBUG    RFM2Pi     30 Timestamp : 1512151580.75
2017-12-01 18:06:20,749 DEBUG    RFM2Pi     30 From Node : 26
2017-12-01 18:06:20,749 DEBUG    RFM2Pi     30    Values : [5.13, 0]
2017-12-01 18:06:20,750 DEBUG    RFM2Pi     30      RSSI : -40
2017-12-01 18:06:20,751 DEBUG    RFM2Pi     30 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:20,751 DEBUG    RFM2Pi     30 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:20,859 DEBUG    RFM2Pi     31 NEW FRAME : OK 8 0 0 0 0 0 0 0 0 199 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-58)
2017-12-01 18:06:20,862 DEBUG    RFM2Pi     31 Timestamp : 1512151580.86
2017-12-01 18:06:20,863 DEBUG    RFM2Pi     31 From Node : 8
2017-12-01 18:06:20,864 DEBUG    RFM2Pi     31    Values : [0, 0, 0, 0, 4.55, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:20,864 DEBUG    RFM2Pi     31      RSSI : -58
2017-12-01 18:06:20,865 DEBUG    RFM2Pi     31 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:20,866 DEBUG    RFM2Pi     31 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:21,072 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 10 0 0 0 0 0 0 0 224 1 184 11 184 11 184 11 184 11 184 11 184 (-45)
2017-12-01 18:06:21,589 DEBUG    RFM2Pi     32 NEW FRAME : OK 19 0 0 0 0 0 0 0 0 223 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-60)
2017-12-01 18:06:21,593 DEBUG    RFM2Pi     32 Timestamp : 1512151581.59
2017-12-01 18:06:21,594 DEBUG    RFM2Pi     32 From Node : 19
2017-12-01 18:06:21,594 DEBUG    RFM2Pi     32    Values : [0, 0, 0, 0, 4.79, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:21,595 DEBUG    RFM2Pi     32      RSSI : -60
2017-12-01 18:06:21,596 DEBUG    RFM2Pi     32 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:21,596 DEBUG    RFM2Pi     32 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:21,704 DEBUG    RFM2Pi     33 NEW FRAME : OK 6 0 0 0 0 0 0 0 0 223 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-50)
2017-12-01 18:06:21,708 DEBUG    RFM2Pi     33 Timestamp : 1512151581.7
2017-12-01 18:06:21,708 DEBUG    RFM2Pi     33 From Node : 6
2017-12-01 18:06:21,709 DEBUG    RFM2Pi     33    Values : [0, 0, 0, 0, 4.79, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:21,710 DEBUG    RFM2Pi     33      RSSI : -50
2017-12-01 18:06:21,710 DEBUG    RFM2Pi     33 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:21,711 DEBUG    RFM2Pi     33 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:21,800 INFO     MQTT       Connecting to MQTT Server
2017-12-01 18:06:21,802 INFO     MQTT       Could not connect...
2017-12-01 18:06:22,536 DEBUG    RFM2Pi     34 NEW FRAME : OK 7 0 0 0 0 0 0 0 0 214 93 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-39)
2017-12-01 18:06:22,541 DEBUG    RFM2Pi     34 Timestamp : 1512151582.54
2017-12-01 18:06:22,543 DEBUG    RFM2Pi     34 From Node : 7
2017-12-01 18:06:22,546 DEBUG    RFM2Pi     34    Values : [0, 0, 0, 0, 240.22, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:22,547 DEBUG    RFM2Pi     34      RSSI : -39
2017-12-01 18:06:22,548 DEBUG    RFM2Pi     34 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:22,548 DEBUG    RFM2Pi     34 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:22,655 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 11 0 0 0 0 0 0 0 199 1 184 11 184 11 184 11 184 11 184 11 184 (-56)
2017-12-01 18:06:22,905 INFO     MQTT       Connecting to MQTT Server
2017-12-01 18:06:22,907 INFO     MQTT       Could not connect...
2017-12-01 18:06:23,494 DEBUG    RFM2Pi     35 NEW FRAME : OK 12 0 0 0 0 0 0 0 0 228 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-67)
2017-12-01 18:06:23,498 DEBUG    RFM2Pi     35 Timestamp : 1512151583.49
2017-12-01 18:06:23,499 DEBUG    RFM2Pi     35 From Node : 12
2017-12-01 18:06:23,500 DEBUG    RFM2Pi     35    Values : [0, 0, 0, 0, 4.84, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:06:23,500 DEBUG    RFM2Pi     35      RSSI : -67
2017-12-01 18:06:23,508 DEBUG    RFM2Pi     35 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:06:23,508 DEBUG    RFM2Pi     35 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:06:24,010 INFO     MQTT       Connecting to MQTT Server
2017-12-01 18:06:24,013 INFO     MQTT       Could not connect...
2017-12-01 18:06:24,016 DEBUG    RFM2Pi     36 NEW FRAME : OK 27 0 0 0 0 0 0 0 0 225 1 (-41)

It carried on posting after it restarted but its not happy about something…

toml · 1 December 2017 18:26

restarted again, here is the last log enteries so hopefully that’s enough logs now but if you need more let me know

log before self reboot:

2017-12-01 18:23:55,776 DEBUG    RFM2Pi     1434 From Node : 24
2017-12-01 18:23:55,776 DEBUG    RFM2Pi     1434    Values : [0, 0, 0, 0, 4.79, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:23:55,777 DEBUG    RFM2Pi     1434      RSSI : -57
2017-12-01 18:23:55,778 DEBUG    RFM2Pi     1434 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:23:55,778 DEBUG    RFM2Pi     1434 Sent to channel(end)' : ToEmonCMS
2017-12-01 18:23:55,881 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 26 1 2 0 0 0 17 (-44)
2017-12-01 18:23:56,079 DEBUG    MQTT       Publishing: emon/gasNode-0-10/powerOverall 0
2017-12-01 18:23:56,081 DEBUG    MQTT       Publishing: emon/gasNode-0-10/powerCooker 0
2017-12-01 18:23:56,082 DEBUG    MQTT       Publishing: emon/gasNode-0-10/powerLight1 0
2017-12-01 18:23:56,084 DEBUG    MQTT       Publishing: emon/gasNode-0-10/powerLight2 0
2017-12-01 18:23:56,085 DEBUG    MQTT       Publishing: emon/gasNode-0-10/vrms 4.79
2017-12-01 18:23:56,087 DEBUG    MQTT       Publishing: emon/gasNode-0-10/tempBoiler 300
2017-12-01 18:23:56,088 DEBUG    MQTT       Publishing: emon/gasNode-0-10/tempHotWater 300
2017-12-01 18:23:56,090 DEBUG    MQTT       Publishing: emon/gasNode-0-10/temp3 300
2017-12-01 18:23:56,091 DEBUG    MQTT       Publishing: emon/gasNode-0-10/temp4 300
2017-12-01 18:23:56,092 DEBUG    MQTT       Publishing: emon/gasNode-0-10/temp5 300
2017-12-01 18:23:56,094 DEBUG    MQTT       Publishing: emon/gasNode-0-10/temp6 300
2017-12-01 18:23:56,095 DEBUG    MQTT       Publishing: emon/gasNode-0-10/gasPulse 0
2017-12-01 18:23:56,096 INFO     MQTT       Publishing: emon/gasNode-0-10/rssi -57
2017-12-01 18:23:56,098 INFO     MQTT       Publishing: emonhub/rx/24/values 0,0,0,0,4.79,300,300,300,300,300,300,0
2017-12-01 18:23:56,100 INFO     MQTT       Publishing: emonhub/rx/24/rssi -57
2017-12-01 18:23:58,099 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 20 0 0 0 0 0 0 0 196 1 184 11 184 11 184 11 184 11 184 11 184 (-39)
2017-12-01 18:23:58,206 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 5 0 0 0 0 0 0 0 203 1 184 11 184 11 184 11 184 11 184 11 184 (-54)
2017-12-01 18:23:58,313 DEBUG    RFM2Pi     1435 NEW FRAME : OK 18 0 0 0 0 0 0 0 0 200 1 184 11 184 11 184 11 184 11 184 11 184 11 0 0 0 0 (-51)
2017-12-01 18:23:58,316 DEBUG    RFM2Pi     1435 Timestamp : 1512152638.31
2017-12-01 18:23:58,317 DEBUG    RFM2Pi     1435 From Node : 18
2017-12-01 18:23:58,317 DEBUG    RFM2Pi     1435    Values : [0, 0, 0, 0, 4.5600000000000005, 300, 300, 300, 300, 300, 300, 0]
2017-12-01 18:23:58,318 DEBUG    RFM2Pi     1435      RSSI : -51
2017-12-01 18:23:58,318 DEBUG    RFM2Pi     1435 Sent to channel(start)' : ToEmonCMS
2017-12-01 18:23:58,319 DEBUG    RFM2Pi     1435 Sent to channel(end)' : ToEmonCMS

pi@emonpi(ro):~$ tail /var/log/emoncms.log

2017-12-01 18:25:14.999|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' in /var/www/emoncms/scripts/phpmqtt_input.php:112
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(112): Mosquitto\Client->loop()
#1 {main}
2017-12-01 18:25:15.002|WARN|phpmqtt_input.php|Not connected, retrying connection
2017-12-01 18:25:24.398|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' with message 'The client is not currently connected.' in /var/www/emoncms/scripts/phpmqtt_input.php:112
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(112): Mosquitto\Client->loop()
#1 {main}
2017-12-01 18:25:24.430|WARN|phpmqtt_input.php|Not connected, retrying connection

pi@emonpi(ro):~$ sudo service emonhub status -l

 emonhub.service - LSB: Start/stop emonHub
   Loaded: loaded (/etc/init.d/emonhub)
   Active: active (running) since Fri 2017-12-01 18:17:19 UTC; 19min ago
  Process: 501 ExecStart=/etc/init.d/emonhub start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/emonhub.service
           └─726 python /usr/share/emonhub/emonhub.py --config-file /home/pi/...

Dec 01 18:17:19 emonpi sudo[640]: pam_unix(sudo:session): session opened fo...0)
Dec 01 18:17:19 emonpi sudo[640]: pam_unix(sudo:session): session closed fo...ot
Dec 01 18:17:19 emonpi sudo[649]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 01 18:17:19 emonpi sudo[649]: pam_unix(sudo:session): session opened fo...0)
Dec 01 18:17:19 emonpi sudo[649]: pam_unix(sudo:session): session closed fo...ot
Dec 01 18:17:19 emonpi sudo[658]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 01 18:17:19 emonpi sudo[658]: pam_unix(sudo:session): session opened fo...0)
Dec 01 18:17:19 emonpi sudo[658]: pam_unix(sudo:session): session closed fo...ot
Dec 01 18:17:19 emonpi emonhub[501]: Starting OpenEnergyMonitor emonHub: em...k.
Dec 01 18:17:19 emonpi systemd[1]: Started LSB: Start/stop emonHub.

sudo service mqtt_input status

● mqtt_input.service - Emoncms MQTT Input Script
   Loaded: loaded (/etc/systemd/system/mqtt_input.service; enabled)
   Active: active (running) since Fri 2017-12-01 18:25:22 UTC; 12min ago
     Docs: https://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
 Main PID: 1985 (php)
   CGroup: /system.slice/mqtt_input.service
           └─1985 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Dec 01 18:25:22 emonpi systemd[1]: Started Emoncms MQTT Input Script.

daemon.log had this exception

Dec  1 18:25:22 emonpi systemd[1]: Received SIGRTMIN+21 from PID 217 (plymouthd).
Dec  1 18:25:22 emonpi systemd[1]: Started Terminate Plymouth Boot Screen.
Dec  1 18:25:22 emonpi systemd[1]: Started Hold until boot process finishes up.
Dec  1 18:25:23 emonpi systemd[1]: Starting Getty on tty1...
Dec  1 18:25:23 emonpi systemd[1]: Started Getty on tty1.
Dec  1 18:25:23 emonpi systemd[1]: Starting Login Prompts.
Dec  1 18:25:23 emonpi systemd[1]: Reached target Login Prompts.
Dec  1 18:25:23 emonpi systemd[1]: Starting Multi-User System.
Dec  1 18:25:23 emonpi systemd[1]: Reached target Multi-User System.
Dec  1 18:25:23 emonpi systemd[1]: Starting Graphical Interface.
Dec  1 18:25:23 emonpi systemd[1]: Reached target Graphical Interface.
Dec  1 18:25:23 emonpi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Dec  1 18:25:23 emonpi systemd[1]: Started Update UTMP about System Runlevel Changes.
Dec  1 18:25:23 emonpi systemd[1]: Startup finished in 2.244s (kernel) + 55.057s (userspace) = 57.301s.
Dec  1 18:25:24 emonpi openhab.sh[1063]: 2017-12-01 18:25:23.998 [ERROR] [.o.core.internal.CoreActivator] - Couldn't create file 'webapps/static/version'.
Dec  1 18:25:24 emonpi openhab.sh[1063]: java.io.FileNotFoundException: webapps/static/version (Read-only file system)
Dec  1 18:25:24 emonpi openhab.sh[1063]: at java.io.FileOutputStream.open0(Native Method) ~[na:1.8.0_111]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at java.io.FileOutputStream.open(FileOutputStream.java:270) ~[na:1.8.0_111]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at java.io.FileOutputStream.<init>(FileOutputStream.java:213) ~[na:1.8.0_111]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at java.io.FileOutputStream.<init>(FileOutputStream.java:162) ~[na:1.8.0_111]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.openhab.core.internal.CoreActivator.writeFile(CoreActivator.java:114) [org.openhab.core_1.8.3.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.openhab.core.internal.CoreActivator.createVersionFile(CoreActivator.java:107) [org.openhab.core_1.8.3.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.openhab.core.internal.CoreActivator.start(CoreActivator.java:59) [org.openhab.core_1.8.3.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:711) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at java.security.AccessController.doPrivileged(Native Method) [na:1.8.0_111]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:702) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:683) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:381) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:390) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1176) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:559) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:544) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:457) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:438) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:1) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [org.eclipse.osgi_3.8.2.v20130124-134944.jar:na]
Dec  1 18:25:24 emonpi openhab.sh[1063]: 2017-12-01 18:25:24.018 [INFO ] [.o.core.internal.CoreActivator] - openHAB runtime has been started (v1.8.3).

pb66 · 2 December 2017 12:14

I think you’ve attached the wrong log here, this is essentially 21s seconds of log starting late in the day and after “quiet=false” was set. There is a 7min jump 14s in, but the log messages are the same, I wonder if this is a time correction? Did you reboot or did you restart emonhub? Was the network connected if/when you rebooted?

Are you saying a service has actually been confirmed as failed or are you saying emoncms is no longer getting data? or there is no movement in the log(s), if so which one(s)?

What froze and restarted? Are you saying something (eg logging or the emoncms inputs) paused and then resumed or that a service stopped and was restarted?

Those last 4 items are interesting but without the preceding log they have no meaning, they are a respose to something, maybe legitimate maybe not, there is no clue in the response, but looks to be valid settings.

I had already up’d your user level a few days ago so you shouldn’t have any trouble attaching files if you give them a .txt extension, if they are still too big you can either zip them or just post the most relevant portion, there is a big difference between “too large too post” and posting just a few lines, it is difficult to draw any conclusions from the snippets.

Interestingly, the snippet of log immediately above this bit with the missing 30s is in that “missing” time range. But the frame ids (25,26,27…) show no missing packets and we cannot see any frame ids in the log above.

Is something odd happening with the time settings? Can you check syslog for any time related entries around the time of the “missing” sections?

It is odd that it “carried on posting” since that log is riddled with failed connections to the MQTT server, there is no evidence of a single successful publish so I’m unsure how it can be posting anything.

Just for clarification can you confirm ALL the data stops when this issue occurs? In your opening post you said “my emonRX stops running after an hour” which I took to be a typo and corrected to “emonTX”, I now think you mean “emonBase”, but that doesn’t apparently “stop running” as such, it stops updating emoncms, it that correct?

The logs in your opening post show nothing that peculiar. the emonhub.log shows the last packet as being successfully passed on, yes that was several minuets previous, but that would have been in-keeping with an “emonTx stopping”, emonhub would have nothing to log. Since then I can see lots of snippets for other nodes, so I assume now, that you were not referring to a single emonTx stopping and that there are several devices running and they ALL apparently “stop”.

All logs are lost on a reboot, are you saying you happened to grab this just before it rebooted itself? or you rebooted it after getting the logs or you have created some way of persisting the log files? Or do you not mean “reboot”? As I write this I’m now thinking you mean “restart” and you are refering to a service? emonhub or mqtt_input? Or both? the status of both show an uptime of only 12 and 19mins. But those up times show they were running prior to the “log before self reboot:” so I’m not really sure what were looking at.

There is without doubt something no right with the mqtt side of things, possibly caused by openhab failing to find the file “webapps/static/version” suggesting the reason being “(Read-only file system)” but I have zero openhab experience so that is a guess and I cannot suggest anything other than disabling the openhab service from starting at boot to see if that has an impact.

The only time I have seen logs halt and then resume is when the /var/log partition has filled up because of a runaway log (usually apache or messages), can you check the partition size/use with df -h and the content sizes with du -h /var/log and ls -la /var/log? Obviously these will all be reset on a reboot and probably appear fine until a problem occurs, if you could recheck these at that time before any restarting/rebooting and hopefully before logrotate runs, which maybe why the logs start rolling again.

toml · 2 December 2017 18:42

Hi pb, thanks for the reply

It stopped posting data, so I copied the log file and posted it, I then changed the ‘quiet = false’ setting, followed by a restart.

Sorry I can’t seem to quote properly on my device but anywhere I have said it has frozen or stopped, I mean it is no longer logging data as coming in (in the emonHUB View Log screen), and is no longer logging data as going out (in the emonHUB View Log screen), and emonCMS is also not receiving data, It literally stops/freezes, at which point I try to grab the log files I hoped would help.

When I mentioned ‘it froze then restarted’, I mean the emonHUB stopped reporting data coming in (in the emonHUB View Log screen), and going out (in the emonHUB View Log screen), and I was also not getting any data reported in emonCMS. When I say it restarted, I mean my connection to the emonHUB was lost, followed by a short wait, me needing to log back in and followed by the typical startup log being reported in emonHUB, which I assumed was a system restart. I just happened to grab a copy of that was in the log before this happened.

What ideally you need from me to be able to help in addition to the logs I am posting around when the ‘freezing’ and ‘rebooting’ happens? would you like a dump of all log files from the entire system? (thanks for increasing the limit so I can do this)

Thanks

pb66 · 2 December 2017 20:48

That log excerpt contains this line

2017-12-01 17:17:25,565 INFO     MainThread Setting RFM2Pi quiet: 0 (0q)

which is the result of quiet=false already being set, unless you had already changed it since posting the emonhub.conf. As long as it’s set now that’s fine, it’s just trying to piece all the snippets of info together is difficult. What we need is a decent size emonhub.log that starts way before the issue occurs and extends well beyond that time. That will paint the best picture of what is happening.

We need to determine if the emonhub service is actually stopping, and we need to determine if there is an issue with the clock or if logging is being paused due to disk space, I have suggested some checks in my last post.

In my last post I also suggested disabling openhab for now.

The emonhub config page where you see the logs is limited in it’s ability, it only starts showing the log from when you open the page. This doesn’t mean that’s all there is, it just means that is all that has been logged since you opened the page. You need to use SSH and view/copy the files directly and try not to be tempted by that restart button until you have checked the service is stopped or in trouble. At the moment restarting or rebooting isn’t helping you find the cause, you are better off exploring whilst it isn’t working rather than restarting it.

toml · 2 December 2017 21:30

Then I can only assume that log file data was after it was restarted, and everything before had been cleared out. I was sure I took it before but clearly not.

Right well, what ill do is see if it happens again (not gone down for a while), and if/when it does, ill post every log I can find via SSH, I have seen quite a few log related files in the log folder, ill grab them all and post them all and not restart anything.

Thanks for looking at the what I have so far though, appreciate it.

toml · 3 December 2017 01:45

Ok, so its stopped posting any data again/no, I have not restarted it and just logged in via SSH to get all the log files. Ill start with the things in troubleshooting section.

The last reading I had posted was 4 hours ago (so 9pm 2nd Dec)

pi@emonpi(ro):~$ sudo service emonhub status -l

● emonhub.service - LSB: Start/stop emonHub
   Loaded: loaded (/etc/init.d/emonhub)
   Active: active (running) since Sat 2017-12-02 17:17:23 UTC; 7h ago
  Process: 502 ExecStart=/etc/init.d/emonhub start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/emonhub.service
           └─708 python /usr/share/emonhub/emonhub.py --config-file /home/pi/...

Dec 02 17:17:23 emonpi sudo[640]: pam_unix(sudo:session): session opened fo...0)
Dec 02 17:17:23 emonpi sudo[640]: pam_unix(sudo:session): session closed fo...ot
Dec 02 17:17:23 emonpi sudo[649]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 02 17:17:23 emonpi sudo[649]: pam_unix(sudo:session): session opened fo...0)
Dec 02 17:17:23 emonpi sudo[649]: pam_unix(sudo:session): session closed fo...ot
Dec 02 17:17:23 emonpi sudo[668]: root : TTY=unknown ; PWD=/ ; USER=root ; ...ub
Dec 02 17:17:23 emonpi sudo[668]: pam_unix(sudo:session): session opened fo...0)
Dec 02 17:17:23 emonpi sudo[668]: pam_unix(sudo:session): session closed fo...ot
Dec 02 17:17:23 emonpi emonhub[502]: Starting OpenEnergyMonitor emonHub: em...k.
Dec 02 17:17:23 emonpi systemd[1]: Started LSB: Start/stop emonHub.
Hint: Some lines were ellipsized, use -l to show in full.

pi@emonpi(ro):~$ tail /var/log/emonhub/emonhub.log

(its empty)

pi@emonpi(ro):~$

pi@emonpi(ro):~$ sudo service mqtt_input status

● mqtt_input.service - Emoncms MQTT Input Script
   Loaded: loaded (/etc/systemd/system/mqtt_input.service; enabled)
   Active: active (running) since Sat 2017-12-02 17:55:31 UTC; 7h ago
     Docs: https://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
 Main PID: 2215 (php)
   CGroup: /system.slice/mqtt_input.service
           └─2215 /usr/bin/php /var/www/emoncms/scripts/phpmqtt_input.php

Dec 02 17:55:31 emonpi systemd[1]: Started Emoncms MQTT Input Script.

pi@emonpi(ro):~$ tail /var/log/emoncms.log

2017-12-02 17:55:24.000|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' with message 'The client is not currently connected.' in /var/www/emoncms/scripts/phpmqtt_input.php:112
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(112): Mosquitto\Client->loop()
#1 {main}
2017-12-02 17:55:24.001|WARN|phpmqtt_input.php|Not connected, retrying connection
2017-12-02 17:55:33.260|ERROR|phpmqtt_input.php|exception 'Mosquitto\Exception' with message 'The client is not currently connected.' in /var/www/emoncms/scripts/phpmqtt_input.php:112
Stack trace:
#0 /var/www/emoncms/scripts/phpmqtt_input.php(112): Mosquitto\Client->loop()
#1 {main}
2017-12-02 17:55:33.282|WARN|phpmqtt_input.php|Not connected, retrying connection

pi@emonpi(ro):~$ date

(correct value)

Sun 3 Dec 00:59:37 UTC 2017

Now for the log files found within \var\log

Archive.zip (1.1 MB)

ill leave the emonHUB unreset so if you need anything I have missed, just let me know

Thanks

toml · 3 December 2017 01:47

it actually started logging again at some point after I was using SSH to gather those files… I just noticed after I finished my post

pb66 · 3 December 2017 12:27

However if you look at the Archive.zip content there is an emonhub.log.1 and an emonhub.log.2 where the log file has been rotated out.

I had a very brief look (as I’m doing other stuff today) and there deosn’t appear to be anything of huge concern towards the end of the file, the last packet received was fully processed, it simply looks like the packets to stopped coming, therefore everything (emonhub, emoncms and the log files) just appears to have stopped because there isn’t anything to process.

Can you confirm the LED on the rfm2pi is flashing (when running ok and when “stopped”)?

Try creating this little script as /home/pi/reset_rfm2pi.py, you will need to use the rpi-rw command first to make the filesytem writable.

#!/usr/bin/env python
"""
"""

__author__ = 'Paul Burnell (pb66)'
__date__ = '14-05-2015'
# http://openenergymonitor.org/emon/node/5549

import RPi.GPIO as GPIO
import time

pin = 7 # P1-7 (BCM pin 4 or WiringPi pin 7)

try:
	GPIO.setmode(GPIO.BOARD)
	GPIO.setup(pin, GPIO.OUT)
	GPIO.output(pin, GPIO.HIGH)
	time.sleep(0.12)
	GPIO.output(pin, GPIO.LOW)
	GPIO.cleanup()
except Exception as e:
	print(e)

make it executable

sudo chmod +x /home/pi/reset_rfm2pi.py

and next time it stops try running it with

sudo /home/pi/reset_rfm2pi.py

It simply pulses the reset line for the rfnm2pi causing the processor to restart.

If this kickstarts everything back off then it is the RFM2Pi that is freezing and restarting emonhub is simply resetting the serial port and the rfm2pi in the process. (See RFM69Pi stops updating/freezes and the many linked threads on the old forum for further info on this)

However! I have never seen a lockout rfm2pi restart of it’s own accord. This makes me think this might be an RF collision issue. Although I have never experienced it, in theory it might be possible the last received packet was the last packet transmitted in “clean air”, the next packet may have started transmitting (or deferred transmitting) before this one had finished and the next before this one finished, effectively getting a rolling blockage. 4hrs seems along time, but with 20 nodes?

You can also check the rfm2pi is seated correctly (square and straight) and it’s not shorting on the unused gpio pins below the antenna wire.

toml · 3 December 2017 13:21

Hello,

Yes now when I log in, I do see .1 versions of log files, would you like me to upload them for you?

The LED on the rfm2pi is not flashing, it is a solid red, the system is again not processing/receiving anything, with it is working as expected, the LED flashes, I assume every time it gets a packet.The RF module seems seated correctly, it is sitting flat and fully down on the pins, the emonHUB is located somewhere it cant be knocked about to upset any connections.

Ill grab the rest of the log files and store them in case you would like to see them, create the script you posted (thanks for that) and let you know how it goes.

Thanks

toml · 3 December 2017 13:26

Here are the .1 and .2 files you mentioned

Archive 2.zip (931.6 KB)

I have run your script by the way, as soon as I did, the RF module started flashing, and data started getting posted. I will have a read about the issue in the link you provided.