Reliability of Emon Pi and purchaser expectations

pb66 · 2017-05-05T19:23:17.035Z

Duchess:

Portion of log where it crashed, for what it is worth:

It’s worth a great deal, thank you. what we normally get to see here on the forums is just a long

2017-05-02 15:56:37,030 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:37,031 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:37,232 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:37,232 WARNING  MainThread MQTT thread is dead

so thank you for taking the time to hunt out the point it crashed.

I have been looking at your log and not yet found any specific reason for the crash such as a malformed packet etc.

Can you tell us a bit more about your system?
What is node 8?
Is it really sending packets over the RFM network at a rate of 1 or more per second?
What else is on the network?
What is the “pulsecount” at the end of node 8? is it just a coincidence it increments by 1 per payload or is it a transmission counter?

I am heading out now for the evening so I will post some inconclusive notes I’ve made on here for now and hopefully comeback to it over the weekend.

2017-05-02 15:56:33,715 DEBUG    RFM2Pi     287873 adding frame to buffer => [1493740593.691949, 5, 0, 0, 0, 233.86, 0, 0, 0, 0, 0, 0, 0]
2017-05-02 15:56:33,716 DEBUG    RFM2Pi     287873 Sent to channel(end)' : ToEmonCMS


# FRAME 287874 gets passed succesfully
2017-05-02 15:56:33,829 DEBUG    RFM2Pi     287874 NEW FRAME : OK 8 245 24 41 12 0 0 0 0 142 1 184 11 184 11 184 11 184 11 184 11 184 11 232 101 36 0 (-46)
2017-05-02 15:56:33,833 DEBUG    RFM2Pi     287874 Timestamp : 1493740593.83
2017-05-02 15:56:33,839 DEBUG    RFM2Pi     287874 From Node : 8
2017-05-02 15:56:33,842 DEBUG    RFM2Pi     287874    Values : [6389, 3113, 0, 0, 3.98, 300, 300, 300, 300, 300, 300, 2385384]
2017-05-02 15:56:33,843 DEBUG    RFM2Pi     287874      RSSI : -46
2017-05-02 15:56:33,846 DEBUG    RFM2Pi     287874 Sent to channel(start)' : ToEmonCMS
2017-05-02 15:56:33,848 INFO     RFM2Pi     Publishing: emon/emontx3/power1 6389

# this is the relative point at which the next frame processed trips up.

2017-05-02 15:56:33,850 INFO     RFM2Pi     Publishing: emon/emontx3/power2 3113
2017-05-02 15:56:33,851 INFO     RFM2Pi     Publishing: emon/emontx3/power3 0
2017-05-02 15:56:33,853 INFO     RFM2Pi     Publishing: emon/emontx3/power4 0
2017-05-02 15:56:33,854 INFO     RFM2Pi     Publishing: emon/emontx3/vrms 3.98
2017-05-02 15:56:33,856 INFO     RFM2Pi     Publishing: emon/emontx3/temp1 300
2017-05-02 15:56:33,858 INFO     RFM2Pi     Publishing: emon/emontx3/temp2 300
2017-05-02 15:56:33,859 INFO     RFM2Pi     Publishing: emon/emontx3/temp3 300
2017-05-02 15:56:33,860 INFO     RFM2Pi     Publishing: emon/emontx3/temp4 300
2017-05-02 15:56:33,862 INFO     RFM2Pi     Publishing: emon/emontx3/temp5 300
2017-05-02 15:56:33,863 INFO     RFM2Pi     Publishing: emon/emontx3/temp6 300
2017-05-02 15:56:33,865 INFO     RFM2Pi     Publishing: emon/emontx3/pulse 2385384
2017-05-02 15:56:33,866 INFO     RFM2Pi     Publishing: emon/emontx3/rssi -46
2017-05-02 15:56:33,868 INFO     RFM2Pi     Publishing: emonhub/rx/8/values 6389,3113,0,0,3.98,300,300,300,300,300,300,2385384
2017-05-02 15:56:33,869 INFO     RFM2Pi     Publishing: emonhub/rx/8/rssi -46
2017-05-02 15:56:33,871 DEBUG    RFM2Pi     287874 adding frame to buffer => [1493740593.82888, 8, 6389, 3113, 0, 0, 3.98, 300, 300, 300, 300, 300, 300, 2385384, -46]
2017-05-02 15:56:33,872 DEBUG    RFM2Pi     287874 Sent to channel(end)' : ToEmonCMS


2017-05-02 15:56:34,278 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 16 0 0 0 0 0 0 32 0 0 0 0 32 4 144 102 0 128 0 0 0 (-104)

# only 0.656 seconds later than FRAME 287874, this frame appears to have nothing wrong with it but JeeLib says it failed the CRC check
2017-05-02 15:56:34,485 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 8 255 24 12 0 0 0 0 135 1 184 11 184 11 184 11 184 11 184 11 184 (-44)

# FRAME 287875 1.111 seconds after dropped packet
2017-05-02 15:56:35,596 DEBUG    RFM2Pi     287875 NEW FRAME : OK 8 252 24 30 12 0 0 0 0 141 1 184 11 184 11 184 11 184 11 184 11 184 11 234 101 36 0 (-45)
2017-05-02 15:56:35,599 DEBUG    RFM2Pi     287875 Timestamp : 1493740595.6
2017-05-02 15:56:35,599 DEBUG    RFM2Pi     287875 From Node : 8
2017-05-02 15:56:35,600 DEBUG    RFM2Pi     287875    Values : [6396, 3102, 0, 0, 3.97, 300, 300, 300, 300, 300, 300, 2385386]
2017-05-02 15:56:35,600 DEBUG    RFM2Pi     287875      RSSI : -45
2017-05-02 15:56:35,601 DEBUG    RFM2Pi     287875 Sent to channel(start)' : ToEmonCMS
2017-05-02 15:56:35,602 INFO     RFM2Pi     Publishing: emon/emontx3/power1 6396

# 0.166 seconds later it crashes, the next iteration of the publish loop is usually only 0.002 Seconds later so should have happened comfortably in this time 
2017-05-02 15:56:35,768 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:35,994 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:35,995 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:36,196 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:36,197 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:36,397 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:36,398 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:36,599 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:36,600 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:36,801 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:36,802 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:37,030 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:37,031 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:37,232 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:37,232 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:37,433 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:37,434 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:37,635 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:37,636 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:37,837 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:37,838 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:38,064 WARNING  MainThread RFM2Pi thread is dead
2017-05-02 15:56:38,064 WARNING  MainThread MQTT thread is dead
2017-05-02 15:56:38,265 WARNING  MainThread RFM2Pi thread is dead

It is in this loop when it stops

github.com

openenergymonitor/emonhub/blob/emon-pi/src/interfacers/EmonHubMqttInterfacer.py#L115-L131


      
              value = frame['data'][i]
          
              # Construct topic
              topic = self._settings["nodevar_format_basetopic"]+nodename+"/"+inputname
              payload = str(value)
              
              self._log.debug("Publishing: "+topic+" "+payload)
              result =self._mqttc.publish(topic, payload=payload, qos=2, retain=False)
              
              if result[0]==4:
                  self._log.info("Publishing error? returned 4")
                  return False
          
          # send rssi
          if 'rssi' in frame:
              topic = self._settings["nodevar_format_basetopic"]+nodename+"/rssi"
              payload = str(frame['rssi'])

It prints the log for the first value of the payload (on line 125) and fails to reach the same point for the second value.


				varid = 1
                for value in cargo.realdata:
                    # Variable id or variable name if given
                    varstr = str(varid)
                    if (varid-1)<len(cargo.names):
                        varstr = str(cargo.names[varid-1])
                    # Construct topic
                    topic = self._settings["nodevar_format_basetopic"]+nodestr+"/"+varstr
                    payload = str(value)
                    		
                    # SUCCESSFULLY GETS HERE FOR FIRST VALUE IN FRAME 287875 - BUT FAILS TO REACH HERE FORE THE SECOND VALUE.
                    self._log.info("Publishing: "+topic+" "+payload)	
                    result =self._mqttc.publish(topic, payload=payload, qos=2, retain=False)
                    
                    if result[0]==4:
                        self._log.info("Publishing error? returned 4")
                    
                    varid += 1

Duchess · 2017-05-06T01:36:02.167Z

[quote]What is node 8?
Is it really sending packets over the RFM network at a rate of 1 or more per second?
What else is on the network?
What is the “pulsecount” at the end of node 8? is it just a coincidence it increments by 1 per payload or is it a transmission counter?[/quote]

I am monitoring power in two different places in the house. I have two emontx linked to the emon pi, one is set to address 7, one to 8.

Node 8 is on the meter and measures incoming and the split out from the meter to two different distribution boards. Node 8 also has a meter pulse optical sensor attached to it.

Node 7 is measuring one of the distribution boards (one of which has a solar feed).

Thank you for taking the time to answer.

Penny

Duchess · 2017-05-06T01:39:02.557Z

Full log :
emonhublog.txt (2.8 MB)

pb66 · 2017-05-06T11:13:01.738Z

I’m inclined to suspect the reason it’s failing might be the update interval of node 8.

Spanning the 13.6 seconds of log up to the fail, there are 14 packets from node 8, ranging from 0.656 to 1.378 seconds. That one every 1.046 secs, 10x the recommended update interval. Of those 14 packets only 8 (57%) make it though, the other 6 (43%) fail CRC checks despite looking perfectly ok.

Have you altered the firmware(s)?
What version of firmware is running on node 8?
What changes have you made to it?

Running an RFM device at that speed is not likely to go well, even if it was 100% successful, the chances are it would block anything else working on the RFM network most if not all the time. The fact the packets are failing CRC checks almost half the time probably means something along the lines of the values are changing in between the emonTx creating the CRC and sending the packet or the receiver is struggling to keep up perhaps?

This is an issue and it is causing problems, I cannot say it is definitely the cause behind emonhub’s problem, but I would not be at all surprised as the “emonpi” variant doesn’t run multi-threaded (hence the whole centre column of the log file is all “RFM2Pi” until it crashes and the “mainthread” logs the threads are missing). Maybe blocking the serial port being read has a greater consequence purely because of the amount of traffic flowing to the serial port.

Regardless, backing off that update interval to 10 secs will almost definitely eliminate those node 8 packets getting corrupted and might just fix the main issue too so can we start there?

Duchess · 2017-05-06T11:34:33.912Z

pb66:

Have you altered the firmware(s)?
What version of firmware is running on node 8?
What changes have you made to it?

The emontx boxes are unchanged from when I received them from the shop, I have not updated or altered the firmware and I have no idea how to find out their firmware versions.

How would I go about altering the update interval please?

pb66 · 2017-05-06T11:47:01.607Z

Duchess:

The emontx boxes are unchanged from when I received them from the shop,

Oh, that’s odd.

Did you purchase or do you have a USB-to-serial programmer?

Can you give us some idea of your skill level in this area? Are you familiar with Arduino or have any programming or hobbyist micro-computer knowledge?

pb66 · 2017-05-06T12:21:27.891Z

As a quick experiment could you disconnect the pulse counter from node 8, let it run a minuite or two and post the emonhub.log?

I have now noticed there are significant differences between the successful and the discarded node 8 packets and will look deeper into that too, but in the interim it would also be useful to know if the absence of a pulsecount has any effect.

And… when did you buy the emonTx approximately?

pb66 · 2017-05-06T13:08:57.429Z

Somemore notes and observations

image.png1413×322 19.3 KB

All the packets that fail CRC (in red) have the LSB of “Power2” missing (except one which has an abnormally low rssi so can be ignored). (note - only the first 20 bytes of failed packets are displayed so the missing “T6” MSB and “pulsecount” are not significant)

Pulsecount is almost incrementing with each transmission, is the pulsecount (or interrupt) causing a premature send? Last time we saw something along these lines the emonTH was sending packets with the wrong CRC due to the send being too soon after the RFM being awoken from sleep. So is the increased send frequency preventing a full sleep-awaken cycle perhaps?

@Duchess, how are these powered? Is node 8 powered via a shop purchased Ideal 9vAC adapter?

Duchess · 2017-05-07T09:03:21.280Z

pb66:

Did you purchase or do you have a USB-to-serial programmer?

I did.

pb66:

Can you give us some idea of your skill level in this area? Are you familiar with Arduino or have any programming or hobbyist micro-computer knowledge?

I have a little familiarity with this (not a huge amount). I am a software developer by trade but my skills are PC based using C++.

pb66:

And… when did you buy the emonTx approximately?

Order was placed 10 Apr 2017 and delivered shortly after.

pb66:

@Duchess, how are these powered? Is node 8 powered via a shop purchased Ideal 9vAC adapter?

Both emotx’s are battery powered at the moment (until I can sort out getting a socket fitted at the installation sites)

I shall test the disconnect of the pulse counter this morning.

Thank you once again for the help Paul.

Penny

Duchess · 2017-05-07T09:39:50.535Z

pb66:

As a quick experiment could you disconnect the pulse counter from node 8, let it run a minuite or two and post the emonhub.log?

Log file attached. Search for “Publishing: emon/emontx3/pulse 2967617” for the period of time it was disconnected (about a minute)

Pennyemonhub8log.txt (2.1 MB)

pb66 · 2017-05-07T11:09:36.330Z

Duchess:

I have a little familiarity with this (not a huge amount). I am a software developer by trade but my skills are PC based using C++.

Cool, so you would be ok with installing the Arduino IDE to a PC (or preferably a Laptop if you can so we can check node 8 in-situ ) then we can

Check the firmware revision (I’m sure it will be ok if purchased in April '17 but worth a check)
Power node 8 via the programmer rather than batteries for another test.

I notice that the battery voltage for node 8 has dropped from 3.96v yesterday to 3.5v today, that’s quite a drop overnight, but I cannot tell if the battery level is low because the emonTx is sending 10x as many packets as normal or if the low battery is causing an issue that results in an increased send frequency. So it would be good to see if powering via the USB-programmer helps reduce the send frequency.

Your new log shows that around the point you indicate around 09:32am, the send interval returns to normal for the same period that the pulsecount doesn’t increase. Interestingly this is also seen for a period right at the beginning of the log file at around 09:17am too. Did you try this more than once or was that “correction” due to something different?

The removal of the pulsecounter may have just reduced the current consumption enough to not dip far enough as to trigger a send so the change of power source above would need to be checked with the pulse counter and then if the send interval is still too rapid, without the pulse counter.

It may just be low batteries, I do not know if it’s recommended to use the pulsecounter with batteries, the LED on it adds quite a bit of consumption too. Either way IMO it’s not good that when the batteries get low the result is to send 10x as many packets, that is counter-productive and seals the batteries fate.

Were the batteries new when installed? are the batteries in the node 7 the same age etc? that currently has a battery voltage of 4.56v.

If you are not able to use a laptop for the checks, are you able to run a mains extension lead to the emonTx location from another room just to try powering via the AC adapter?

[edit] Or perhaps you have one of those little usb battery packs used for topping up a mobile phone you could use to power the emontx for a test?

Duchess · 2017-05-07T12:02:44.977Z

pb66:

Cool, so you would be ok with installing the Arduino IDE to a PC (or preferably a Laptop if you can so we can check node 8 in-situ ) then we can

Check the firmware revision (I’m sure it will be ok if purchased in April '17 but worth a check)

Power node 8 via the programmer rather than batteries for another test.

Yes, willing to have a go

pb66:

Your new log shows that around the point you indicate around 09:32am, the send interval returns to normal for the same period that the pulsecount doesn’t increase. Interestingly this is also seen for a period right at the beginning of the log file at around 09:17am too. Did you try this more than once or was that “correction” due to something different?

Yes, I tried it earlier but could not find the data in the log that time, so I repeated the test.

pb66:

Were the batteries new when installed? are the batteries in the node 7 the same age etc? that currently has a battery voltage of 4.56v.

Yes, both had brand new batteries installed at the same time.

pb66:

Or perhaps you have one of those little usb battery packs used for topping up a mobile phone you could use to power the emontx for a test?

Yes, I do have one of those that I could use.

Penny

pb66 · 2017-05-07T12:31:35.549Z

Probably the quickest test is to use the USB battery pack to power the emonTx and see what the logs show (assuming it’s charged that is).

Then if it is simply “low battery” you may choose not to bother with the Arduino IDE and checking the Firmware revision as this will simply no longer be an issue once you have the AC adapter in play.

Otherwise if you want to install the Arduino IDE whilst the emonTx is running on the battery pack, we can check the firmware version afterwards. It maybe of benefit to you to get set up in case you want to do an update at a later date or want to get involved with some development etc. Or just want to see how it works if you’re that way inclined whilst you have your sleeves rolled up and a programmer to hand.

Duchess · 2017-05-07T12:46:49.900Z

Battery pack attached at 12:42

New log:

emonhublog9.txt (3.7 MB)

pb66 · 2017-05-07T13:23:31.251Z

So much for that idea then, there was no noticeable difference to the send interval when the battery pack was added despite seeing a big jump in voltage 3.49v up to 5.03v

2017-05-07 12:42:12,614 DEBUG    RFM2Pi     181071 NEW FRAME : OK 8 50 14 152 10 0 0 0 0 93 1 184 11 184 11 184 11 184 11 184 11 184 11 181 111 45 0 (-42)
2017-05-07 12:42:15,535 DEBUG    RFM2Pi     181074 NEW FRAME : OK 8 98 14 183 10 0 0 0 0 247 1 184 11 184 11 184 11 184 11 184 11 184 11 184 111 45 0 (-42)

So there is an issue with the pulsecounter causing an increase in send frequency that is not caused by low battery.

Did you install the Arduino IDE? can you get the emonTx hooked up to the PC/programmer?

You’ll need to know the com port number Windows assigns to the programmer, you can get that from the Windows Device manager or if you fire up the IDE first and check “tools → port” then plug in the usb-programmer and recheck “tools → port” again, the new arrival is the programmer, select that and go to "tools → serial monitor"and select a baud of 115200 in the bottom right of the window, you should start to get some serial output and the version should be in that initial output.

If you are able to do this where the node 8 is located it would be helpful to know how frequently the new frames are printed to serial, it supposed to be ~10secs but if the issue is still there it will be ~1 sec.

pb66 · 2017-05-07T15:29:11.348Z

Hi Penny (@Duchess)

I have been discussing this with @TrystanLea and @glyn.hudson over PM and it has come to light that the way the firmware works is that if there is no AC signal found at start-up it will assume battery operation and powering via a solid 5v PSU (or USB battery) will not change the fact it is in “battery mode” . When in “Battery mode” the emonTx doesn’t support pulsecounting (yet! I think this will now be looked at in the not so distant future).

I’m fairly confident this issue should resolve itself when powered from an AC adapter. Are you willing to wait or do you have an extension lead you can use to test the emonTx on an AC adapter?

Alternatively there is a way we can trick it. If you can take the emonTx to somewhere you can connect an AC adapter first and then connect the USB battery pack and disconnect the AC adapter it should now be running on the USB battery BUT in “AC power mode”, you can now take it back to it’s proper location and it should (hopefully) work perfectly until the next restart (ie until the batteries and/or battery pack runs out).

Alternatively you can just leave the pulsecounter disconnected until you get the socket fitted.

TrystanLea · 2017-05-08T11:00:52.373Z

Hello Penny (@Duchess), our apologies for this issue with the emontx not supporting pulse counting properly without an ACAC adapter plugged in as Paul described.

I have developed a modification to the firmware this morning that fixes this issue. I have uploaded this new version to the firmware github repository here: GitHub - openenergymonitor/emontx3 at battery_pulsecount - it’s in a different branch at the moment called battery_pulsecount.

You’re very welcome to send the EmonTx back to us if you prefer and we can upload the new firmware. Alternatively, you can upload the firmware yourself using the Arduino IDE or platform IO. There are instructions for platform IO using linux here: emontx3/firmware at battery_pulsecount · openenergymonitor/emontx3 · GitHub

glyn.hudson · 2017-05-08T22:06:43.718Z

Here’s a more thorough step-by-step guide on how to upload using PlatformIO:

Guide | OpenEnergyMonitor

Firmware Modification

Compiling Firmware

Duchess · 2017-05-17T22:22:12.807Z

Hi all. I finally managed to get the firmware updated (bit of a challenge, that)

Anyhow, the firmware from @TrystanLea (thank you very much, by the way) seems to have fixed the issue. The emonPi has been running now for 5 days without data loss.

Thank you for all of you help.

Penny

pb66 · 2017-05-18T00:31:27.294Z

Great to hear you got it sorted, thanks for highlighting the issue and supplying the info to debug and fix it.