Emonpi low-write 9.8.25 - inputs stopped working

Pukka · 3 March 2018 18:36

@Bernie_Carter @TrystanLea @glyn.hudson @pb66

Are you any further along or have you found anything else out? mine has crashed again and I am almost at the point of a full reinstall and restore of the database or even just create a job to reboot the pi every 2 days.

When it loses connection it dumps about 2 days worth of data. even if you start the feed writer after it crashed, the number in cache counts down but the data is still lost.

Anyone else have any ideas how to fix or even better do we need a watchdog service.

If anyone wants access to it when its crashed let me know and i will setup an ssh session to the pi

Paul

Bernie_Carter · 4 March 2018 02:43

@Pukka

I ruled out NodeRed, as mine was completely down after a failed upgrade,
and MQTT still crashed.

I will look into the situation further this weekend and see if anything
else pops up.

It sounds odd that you are losing data pre-crash. Mine just doesn’t log
any new data.

If you want to set me up with an SSH, ill certainly take a look at it and
compare, just PM me the details.

Bernie

borpin · 4 March 2018 13:02

@Pukka As I suggested above, the best way to monitor this is to install MONIT and use the ‘Timestamp test’ to look for when the feed directories are accessed / written to.

You could get it to run a small script to output the status of the services to a file.

You can also monitor the feedwriter service and try a restart.

Looking a bit deeper at the log you posted, it looks to me like a MQTT mosquitto feed that is causing the problem. Which feeds are MQTT feeds? Have you tried disabling any of these feeds?

@glyn.hudson - Paul says he is using the ‘low-write’ version. The phpmqtt_input.php file in the low-write branch does not have 220 lines! I’m not really sure how this all hangs together but could this be an issue?

These things can be a real pain to work out…

Bernie_Carter · 4 March 2018 14:27

@borpin

I’m running the exact same version of low-write and my phpmqtt_input has 297 lines.
Line 220 is exactly as shown in the error log
$dbinputs = $input->get_inputs($userid);

Is there a different version?

pb66 · 4 March 2018 20:40

@borpin - The low-write btanch is a bit of a relic, last updated in Apr '16, “low-write” in now a “mode” rather than a separate branch or version.

The line cited in the log is still current in the “stable” branch,

github.com

emoncms/emoncms/blob/stable/scripts/phpmqtt_input.php#L220


      
              if( $r==0 ) {
                  // if CONACK is zero
                  $connected = true;
                  if ($subscribed==0) {
                      $topic = $settings['mqtt']['basetopic']."/#";
                      $subscribed = $mqtt_client->subscribe($topic,2);
                      $log->info("Subscribed to: ".$topic." ID - ".$subscribed);
                  }
              } else {
                  $subscribed = 0;
                  $log->error('unexpected connection problem mqtt server:'.$message);
              }
          }
          
          function subscribe() {
              global $log, $topic;
              //echo "Subscribed to topic: ".$topic."\n";
              $log->info("Callback subscribed to topic: ".$topic);
          }
          
          function unsubscribe() {

For that line to trip up I would expect there is no userid, no user with that userid or no inputs for that user. Since the userid is hard coded to "1! and almost all emoncms instances have a user “1” setup, I doubt it could be either of those so perhaps it couldn’t find any inputs for that user, redis flushed or mysql offline or something along those lines?

It would seem that log file is 6weeks old, can you be sure the problem is the same ? You are now running emoncms v9.8.28 and have updated the emonPi since then, so some fresh logs would be useful.

The best course of action is always to fix the cause rather than hide it behind a watchdog and restart.

By all means set up a watchdog to tell you when it misbehaves, and grab the logfiles and info when it does fail, but if you start setting up auto restarts etc you may never find the issue. You might not of even had this issue if prior issues were properly diagnosed and resolved rather than resorting to workarounds.

Can you provide new logs for the time leading up to and beyond a fail (emonhub and emoncms)?

Also check the status of the mqtt_input, emonhub and feedwriter services and post the info?

Pukka · 4 March 2018 21:10

Hi All

Thanks for your help so far

I have updated the PI with the latest os updates and node-red. if/when it crashes in the next few days i will post the log files here. i will also try and download the log files everyday.

Paul

Bernie_Carter · 6 March 2018 02:51

Exactly, that’s the direction I’m looking as well.

Mine shows up as a broken pipe, Pauls shows up with a connection error. Whether these 2 incidents are related remains to be seen, but it appears to me then there’s an issue with the MQTT Broker while running in this configuration.

I’m now running an update on mine as well so that I’m inline with pauls setup, and I will again see what happens.

pb66 · 6 March 2018 10:42

I cannot really comment on the issue you are seeing as you have not posted any info or logs

I’ve not seen any signs of the Mosquitto broker failing, it does seem the issues are all common to MQTT, but that’s where the most traffic is on an emonPi/SD, plus all the “tricky” stuff, eg bespoke node-red flows and the more exotic emonhub interfacers.

borpin · 7 March 2018 10:07

Just looking at the log again…

exception is raised on 116:

github.com

emoncms/emoncms/blob/86adaec5fff7a5a3327d2968a7cd4870dac92952/scripts/phpmqtt_input.php#L103-L122


      
          $connected = false;
          $last_retry = 0;
          $last_heartbeat = time();
          $count = 0;
          
          $mqtt_client->onConnect('connect');
          $mqtt_client->onDisconnect('disconnect');
          $mqtt_client->onSubscribe('subscribe');
          $mqtt_client->onMessage('message');
          
          // Option 1: extend on this:
           while(true){
              try { 
                  $mqtt_client->loop(); 
              } catch (Exception $e) {
                  if ($connected) $log->error($e);
              }
              
              if (!$connected && (time()-$last_retry)>5.0) {
                  $last_retry = time();

Examining this bit of code (and excuse my lack of PHP knowledge) I’d have expected an exception on 116 to be caught by the try catch. If this is in a namesapce (don’t really understand that) the ‘Exception’ should have a leading \ (apparently).

The systemd service is set to restart when failed. Next time it crashes can you check the status of the mqtt_input.service and the mosquitto.service?

Bernie_Carter · 11 March 2018 14:05

I have been looking into what is causing paul’s issues. I did find one thing of interest:

AND

Node-red changes its PID and PPID:
[GMT Mar 9 13:38:11] error : ‘node-red’ process PID changed from 543 to 29534
[GMT Mar 9 13:38:11] error : ‘node-red’ process PPID changed from 1 to 29521
[GMT Mar 9 13:40:11] error : ‘node-red’ process PID changed from 29534 to 543
[GMT Mar 9 13:40:11] error : ‘node-red’ process PPID changed from 29521 to 1
[GMT Mar 10 13:38:13] error : ‘node-red’ process PID changed from 543 to 18153
[GMT Mar 10 13:38:13] error : ‘node-red’ process PPID changed from 1 to 18139
[GMT Mar 10 13:42:13] error : ‘node-red’ process PID changed from 18153 to 543
[GMT Mar 10 13:42:13] error : ‘node-red’ process PPID changed from 18139 to 1
[GMT Mar 11 01:38:30] error : ‘node-red’ process PID changed from 543 to 28738
[GMT Mar 11 01:38:30] error : ‘node-red’ process PPID changed from 1 to 28724
[GMT Mar 11 01:42:30] error : ‘node-red’ process PID changed from 28738 to 543
[GMT Mar 11 01:42:30] error : ‘node-red’ process PPID changed from 28724 to 1

AND

The Cpu wait time averages 30-71% ever 12 hours (around 1 am and 1 pm daily)

This all corresponds to when Node-Red runs a backup script to Dropbox.
Now I can understand the wait time, but why the PID change and evenmore so why the MQTT error?

The only other issue I saw was:
[GMT Mar 9 23:07:09] error : ‘mqtt_input’ process PID changed from 13989 to 1969
[GMT Mar 9 23:07:09] error : ‘mqtt_input’ process PPID changed from 2267 to 1

Pukka · 11 March 2018 14:57

just logged in and found a random input listed.

pb66 · 11 March 2018 15:00

Yes in a try/catch if the try fails the catch is executed, however that has been somewhat undermined by the content of the catch.

    if ($connected) $log->error($e);

essentially says if there is a working connection log the error, otherwise (if there is no working connection) just carry on as if nothing’s wrong.

Presumably this was done to hide all the “failed to connect” error that used to happen, but along with it has gone any useful info, unless of course it raises and exception with a working connection.

I think it would be marginally better to have something like

    if ($connected) {
        $log->error($e);
    } else {
        $log->info($e);
    }

so that the errors can be seen if the “info” log level is selected. But that still doesn’t seem right to me.

pb66 · 11 March 2018 15:03

This maybe just a coincidence and totally unrelated, BUT, not so long ago I installed a dropbox utility to a Pi3 and I had to remove it again as it regularly brought the Pi to it’s knee’s, I mean to the point I could barely ssh in. I don’t recall off-hand what code I used, but it certainly wasn’t anything node-red as I don’t use it.

pb66 · 11 March 2018 15:09

The emonhub.log’s for the time leading up to and beyond the time of the incident (19hrs previous) would be very useful. As would your emonhub.conf nodes section.

If the “emonth1” node is correctly defined emonhub will not allow anything that doesn’t conform to that definition through. So if it is defined correctly the “rogue node input” has come from elsewhere bypassing emonhub. Otherwise a tighter definition will prevent further occurrences. But the emonhub.log (if you have it) will be more exact, ie we should see if that packet passed via emonhub and how, rather than assuming the node definition is working.

Pukka · 11 March 2018 15:17

emonhub.txt (1.2 MB)

#######################################################################
#######################      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 communication to BMW API for electric car monitoring
[[BMWi3]]
    Type = EmonHubBMWInterfacer
    [[[init_settings]]]
        timeinverval =600
        duringchargetimeinterval=60
        nodeid = 28
        tempcredentialfile = /tmp/bmwcredentials.json
        bmwapiusername = username
        bmwapipassword = password

    [[[runtimesettings]]]
        pubchannels = ToEmonCMS,

### 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 = 5                              # emonPi / emonBase nodeID
        calibration = 230V                      # (UK/EU: 230V, US: 110V)
        quiet = true                            # Disable quite mode (default enabled) to enable RF packet debugging, show packets which fail crc
        # interval =  0                         # Interval to transmit time to emonGLCD (seconds)
        

[[MQTT]]

    Type = EmonHubMqttInterfacer
    [[[init_settings]]]
        mqtt_host = localhost
        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/

## [[emoncmsorg]]
##  Type = EmonHubEmoncmsHTTPInterfacer
##    [[[init_settings]]]
##    [[[runtimesettings]]]
##        pubchannels = ToRFM12,
##        subchannels = ToEmonCMS,
##       url = https://emoncms.org
##        apikey = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
##        senddata = 1                    # Enable sending data to Emoncms.org
##        sendstatus = 1                  # Enable sending WAN IP to Emoncms.org MyIP > https://emoncms.org/myip/list
##        sendinterval= 30                # Bulk send interval to Emoncms.org in seconds

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

[nodes]

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

[[5]]
    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

[[6]]
    nodename = emontxshield
    [[[rx]]]
       names = power1, power2, power3, power4, vrms
       datacode = h
       scales = 1,1,1,1,0.01
       units =W,W,W,W,V

[[7]]
   nodename = emontx4
   [[[rx]]]
      names = power1, power2, power3, power4, vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
      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 = emontx3
    [[[rx]]]
       names = power1, power2, power3, power4, vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
       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 = emontx2
   [[[rx]]]
      names = power1, power2, power3, power4, vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
      datacode = h
      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

[[10]]
    nodename = emontx1
    [[[rx]]]
       names = power1, power2, power3, power4, vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
       datacode = h
       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 = 3phase
    [[[rx]]]
       names = powerL1, powerL2, powerL3, power4, Vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
       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 = 3phase2
    [[[rx]]]
       names = powerL1, powerL2, powerL3, power4, Vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
       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 = 3phase3
    [[[rx]]]
       names = powerL1, powerL2, powerL3, power4, Vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
       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 = 3phase4
    [[[rx]]]
       names = powerL1, powerL2, powerL3, power4, Vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
       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 = emonth1
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacode = h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

[[20]]
   nodename = emonth2
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacode = h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

[[21]]
   nodename = emonth3
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacode = h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

[[22]]
   nodename = emonth4
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacode = h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

[[23]]
    nodename = emonth5
    [[[rx]]]
       names = temperature, external temperature, humidity, battery, pulsecount
       datacodes = h,h,h,h,L
       scales = 0.1,0.1,0.1,0.1,1
       units = C,C,%,V,p

[[24]]
    nodename = emonth6
    [[[rx]]]
       names = temperature, external temperature, humidity, battery, pulsecount
       datacodes = h,h,h,h,L
       scales = 0.1,0.1,0.1,0.1,1
       units = C,C,%,V,p

[[25]]
    nodename = emonth7
    [[[rx]]]
       names = temperature, external temperature, humidity, battery, pulsecount
       datacodes = h,h,h,h,L
       scales = 0.1,0.1,0.1,0.1,1
       units = C,C,%,V,p

[[26]]
    nodename = emonth8
    [[[rx]]]
       names = temperature, external temperature, humidity, battery, pulsecount
       datacodes = h,h,h,h,L
       scales = 0.1,0.1,0.1,0.1,1
       units = C,C,%,V,p

pb66 · 11 March 2018 15:27

[[19]]
   nodename = emonth1
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacode = h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

Allows any data presenting itself as node 19 to be passed to emoncms as long as the payload has an even number of bytes (ie undefined number of ints)

[[19]]
   nodename = emonth1
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacodes = h,h,h,h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

will only allow data packets that are exactly 8 bytes through to emoncms. (notice the use of “datacodes” in place of “datacode” too)

I haven’t checked the emonpi variant of emonhub’s code for this yet but, I do not know what the result is of passing a packet with more than 4 ints and reaching the point where emonhub is applying the names and scales. I do not know if it has been written to handle the error if there is no name or scale available for the 5th (and subsequent) values. Perhaps this is the cause of you loss of data??? (if it’s an unhandled occurrance). have you noticed these extra inputs previously at all?

ps the emonhub.log is too recent to show anything relating to this occurance

Pukka · 11 March 2018 16:32

I have made the change in the emonhub

pb66 · 11 March 2018 16:40

This would be useful too know…

Pukka · 11 March 2018 16:50

Yes I have, cannot remember the names.

pb66 · 11 March 2018 17:01

Can you perhaps at least remember if they overlapped your valid nodes as this one does and/or if you noticed these extra inputs around the same time as any “emonpi stops updating” events?