Paul - I was able to get everything working a few weeks ago. I started with a new SD and the current image. And then moved all data files over (via the emonpi backup). Everything has been running perfect since then.
The only thing I haven’t done is apt-get update && apt-get upgrade. I think running those commands with the MQTT update caused the issues. The MQTT update to 1.4.10 / mosquitto version 1.4.10 bit me (pun intended).
It may appear to be working correctly but it is not right. This is what your log should have looked like, note all the “MQTT” labels down the centre.
2016-10-19 22:45:55,465 DEBUG RFM2Pi 21751 NEW FRAME : OK 5 184 1 231 0 159 2 30 48 0 0 0 0 0 0 0 0 0 0 0 0 221 65 0 0 (-0)
2016-10-19 22:45:55,468 DEBUG RFM2Pi 21751 Timestamp : 1476935155.47
2016-10-19 22:45:55,468 DEBUG RFM2Pi 21751 From Node : 5
2016-10-19 22:45:55,469 DEBUG RFM2Pi 21751 Values : [440, 231, 671, 123.18, 0, 0, 0, 0, 0, 0, 16861]
2016-10-19 22:45:55,470 INFO MQTT Publishing: emon/emonpi/power1 440
2016-10-19 22:45:55,471 INFO MQTT Publishing: emon/emonpi/power2 231
2016-10-19 22:45:55,473 INFO MQTT Publishing: emon/emonpi/power1pluspower2 671
2016-10-19 22:45:55,474 INFO MQTT Publishing: emon/emonpi/vrms 123.18
2016-10-19 22:45:55,475 INFO MQTT Publishing: emon/emonpi/t1 0
2016-10-19 22:45:55,476 INFO MQTT Publishing: emon/emonpi/t2 0
2016-10-19 22:45:55,477 INFO MQTT Publishing: emon/emonpi/t3 0
2016-10-19 22:45:55,479 INFO MQTT Publishing: emon/emonpi/t4 0
2016-10-19 22:45:55,480 INFO MQTT Publishing: emon/emonpi/t5 0
2016-10-19 22:45:55,481 INFO MQTT Publishing: emon/emonpi/t6 0
2016-10-19 22:45:55,482 INFO MQTT Publishing: emon/emonpi/pulsecount 16861
2016-10-19 22:45:55,483 INFO MQTT Publishing: emon/emonpi/rssi 0
2016-10-19 22:45:55,485 INFO MQTT Publishing: emonhub/rx/5/values 440,231,671,123.18,0,0,0,0,0,0,16861
2016-10-19 22:45:55,486 INFO MQTT Publishing: emonhub/rx/5/rssi 0
2016-10-19 22:45:55,487 DEBUG RFM2Pi 21751 adding frame to buffer => [1476935155, 5, 440, 231, 671, 123.18, 0, 0, 0, 0, 0, 0, 16861]
2016-10-19 22:45:55,488 DEBUG RFM2Pi 21751 Sent to channel' : ToEmonCMS
There is no code for publishing in the JeeInterafacer, only the MqttInterfacer publishes. Look at Perig’s log after a reboot, the MqttInterfacer makes the connection to the MQTT broker, you can see the “MQTT” thread names in each line and then it switches to “RFM2Pi” when it publishes for some unknown reason, that means the threads are not independent, there are some crossed wires somewhere, it’s an issue in the emonPi variant of emonhub that I have only ever perviously seen in the logs of “thread is dead” cases.
Paul - this is the log from Day 1 (right after starting with a new SD card and the current emonPi image).
It looks like it has always been this way. And I have done many, many reboots. I’ll try
restarting emonhub and reading thru the “thread is dead” posts.
2016-09-12 14:17:21,950 DEBUG RFM2Pi device settings updated: E i5 g210 @ 433 MHz USA 1
2016-09-12 14:17:23,223 DEBUG RFM2Pi 4 NEW FRAME : OK 5 180 0 153 0 77 1 173 46 227 0 0 0 0 0 0 0 0 0 0 0 173 80 1 0 (-0)
2016-09-12 14:17:23,228 DEBUG RFM2Pi 4 Timestamp : 1473707843.22
2016-09-12 14:17:23,230 DEBUG RFM2Pi 4 From Node : 5
2016-09-12 14:17:23,231 DEBUG RFM2Pi 4 Values : [180, 153, 333, 119.49000000000001, 22.700000000000003, 0, 0, 0, 0, 0, 86189]
2016-09-12 14:17:23,233 INFO RFM2Pi Publishing: emon/emonpi/power1 180
2016-09-12 14:17:23,235 INFO RFM2Pi Publishing: emon/emonpi/power2 153
2016-09-12 14:17:23,237 INFO RFM2Pi Publishing: emon/emonpi/power1pluspower2 333
2016-09-12 14:17:23,240 INFO RFM2Pi Publishing: emon/emonpi/vrms 119.49
2016-09-12 14:17:23,242 INFO RFM2Pi Publishing: emon/emonpi/t1 22.7
2016-09-12 14:17:23,244 INFO RFM2Pi Publishing: emon/emonpi/t2 0
2016-09-12 14:17:23,246 INFO RFM2Pi Publishing: emon/emonpi/t3 0
2016-09-12 14:17:23,248 INFO RFM2Pi Publishing: emon/emonpi/t4 0
2016-09-12 14:17:23,250 INFO RFM2Pi Publishing: emon/emonpi/t5 0
2016-09-12 14:17:23,251 INFO RFM2Pi Publishing: emon/emonpi/t6 0
2016-09-12 14:17:23,253 INFO RFM2Pi Publishing: emon/emonpi/pulsecount 86189
2016-09-12 14:17:23,256 INFO RFM2Pi Publishing: emon/emonpi/rssi 0
2016-09-12 14:17:23,258 INFO RFM2Pi Publishing: emonhub/rx/5/values 180,153,333,119.49,22.7,0,0,0,0,0,86189
2016-09-12 14:17:23,260 INFO RFM2Pi Publishing: emonhub/rx/5/rssi 0
2016-09-12 14:17:23,263 DEBUG RFM2Pi 4 adding frame to buffer => [1473707843, 5, 180, 153, 333, 119.49000000000001, 22.700000000000003, 0, 0, 0, 0, 0, 86189]
2016-09-12 14:17:23,264 DEBUG RFM2Pi 4 Sent to channel' : ToEmonCMS
2016-09-12 14:17:36,167 DEBUG RFM2Pi 5 NEW FRAME : OK 5 180 0 160 0 84 1 98 47 227 0 0 0 0 0 0 0 0 0 0 0 173 80 1 0 (-0)
EDIT: here is the log after the emonhub restart
2016-10-25 18:42:51,499 INFO RFM2Pi Publishing: emonhub/rx/5/values 260,179,439,120.67,0,0,0,0,0,0,4745
2016-10-25 18:42:51,501 INFO RFM2Pi Publishing: emonhub/rx/5/rssi 0
2016-10-25 18:42:51,502 DEBUG RFM2Pi 6430 adding frame to buffer => [1477438971, 5, 260, 179, 439, 120.67, 0, 0, 0, 0, 0, 0, 4745]
2016-10-25 18:42:51,504 DEBUG RFM2Pi 6430 Sent to channel' : ToEmonCMS
2016-10-25 18:42:52,997 DEBUG MainThread SIGINT received.
2016-10-25 18:42:52,998 INFO MainThread Exiting hub...
2016-10-25 18:42:53,147 INFO MainThread Exit completed
2016-10-25 18:42:54,056 INFO MainThread EmonHub emonHub 'emon-pi' variant v1.1
2016-10-25 18:42:54,057 INFO MainThread Opening hub...
2016-10-25 18:42:54,058 INFO MainThread Logging level set to DEBUG
2016-10-25 18:42:54,059 INFO MainThread Creating EmonHubJeeInterfacer 'RFM2Pi'
2016-10-25 18:42:54,061 DEBUG MainThread Opening serial port: /dev/ttyAMA0 @ 38400 bits/s
2016-10-25 18:42:56,066 INFO MainThread RFM2Pi device firmware version & configuration: not available
2016-10-25 18:42:56,067 INFO MainThread Setting RFM2Pi frequency: 433 (4b)
2016-10-25 18:42:57,070 INFO MainThread Setting RFM2Pi group: 210 (210g)
2016-10-25 18:42:58,072 INFO MainThread Setting RFM2Pi quiet: 0 (0q)
2016-10-25 18:42:59,075 INFO MainThread Setting RFM2Pi baseid: 5 (5i)
2016-10-25 18:43:00,077 INFO MainThread Setting RFM2Pi calibration: 110V (2p)
2016-10-25 18:43:01,080 DEBUG MainThread Setting RFM2Pi subchannels: ['ToRFM12']
2016-10-25 18:43:01,081 DEBUG MainThread Interfacer: Subscribed to channel' : ToRFM12
2016-10-25 18:43:01,082 DEBUG MainThread Setting RFM2Pi pubchannels: ['ToEmonCMS']
2016-10-25 18:43:01,083 DEBUG MainThread Interfacer: Subscribed to channel' : ToRFM12
2016-10-25 18:43:01,089 INFO MainThread Creating EmonHubMqttInterfacer 'MQTT'
2016-10-25 18:43:01,090 INFO MainThread MQTT Init mqtt_host=127.0.0.1 mqtt_port=1883 mqtt_user=emonpi
2016-10-25 18:43:01,093 DEBUG RFM2Pi 1 NEW FRAME : OK 5 255 0 186 0 185 1 175 47 0 0 0 0 0 0 0 0 0 0 0 0 138 18 0 0 (-0)
2016-10-25 18:43:01,095 DEBUG RFM2Pi 1 Timestamp : 1477438981.09
2016-10-25 18:43:01,097 DEBUG MainThread MQTT Subscribed to channel' : ToEmonCMS
2016-10-25 18:43:01,097 DEBUG RFM2Pi 1 From Node : 5
2016-10-25 18:43:01,099 DEBUG RFM2Pi 1 Values : [255, 186, 441, 12207, 0, 0, 0, 0, 0, 0, 4746, 0]
2016-10-25 18:43:01,100 DEBUG RFM2Pi 1 Sent to channel' : ToEmonCMS
2016-10-25 18:43:01,101 INFO MainThread Creating EmonHubEmoncmsHTTPInterfacer 'emoncmsorg'
2016-10-25 18:43:01,103 DEBUG MainThread emoncmsorg Subscribed to channel' : ToEmonCMS
2016-10-25 18:43:01,202 DEBUG RFM2Pi device settings updated: E i5 g210 @ 433 MHz USA 1
2016-10-25 18:43:01,203 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:01,305 DEBUG RFM2Pi device settings updated: E i5 g210 @ 433 MHz USA 1
2016-10-25 18:43:01,307 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:01,409 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:01,514 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:01,611 DEBUG RFM2Pi acknowledged command: <nn> i - set node IDs (standard node ids are 1..30)
2016-10-25 18:43:01,617 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:01,715 DEBUG RFM2Pi acknowledged command: <n> b - set MHz band (4 = 433, 8 = 868, 9 = 915)
2016-10-25 18:43:01,721 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:01,819 DEBUG RFM2Pi acknowledged command: <nnn> g - set network group (RFM12 only allows 212, 0 = any)
2016-10-25 18:43:01,824 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:01,922 DEBUG RFM2Pi acknowledged command: <n> c - set collect mode (advanced, normally 0)
2016-10-25 18:43:01,928 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:02,026 DEBUG RFM2Pi acknowledged command: ...,<nn> a - send data packet to node <nn>, request ack
2016-10-25 18:43:02,031 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:02,129 DEBUG RFM2Pi acknowledged command: ...,<nn> s - send data packet to node <nn>, no ack
2016-10-25 18:43:02,133 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:02,244 INFO MQTT Connecting to MQTT Server
2016-10-25 18:43:02,250 INFO MQTT connection status: Connection successful
2016-10-25 18:43:02,251 DEBUG MQTT CONACK => Return code: 0
2016-10-25 18:43:02,253 DEBUG RFM2Pi acknowledged command: ...,<n> p - Set AC Adapter Vcal 1p = UK, 2p = USA
2016-10-25 18:43:02,355 INFO MQTT on_subscribe
2016-10-25 18:43:02,469 DEBUG RFM2Pi device settings updated: E i5 g210 @ 433 MHz USA 1
2016-10-25 18:43:02,572 DEBUG RFM2Pi device settings updated: E i5 g210 @ 433 MHz USA 1
2016-10-25 18:43:02,696 DEBUG RFM2Pi device settings updated: E i5 g210 @ 433 MHz USA 1
2016-10-25 18:43:02,802 DEBUG RFM2Pi 4 NEW FRAME : OK 5 0 1 181 0 181 1 142 47 0 0 0 0 0 0 0 0 0 0 0 0 139 18 0 0 (-0)
2016-10-25 18:43:02,807 DEBUG RFM2Pi 4 Timestamp : 1477438982.8
2016-10-25 18:43:02,808 DEBUG RFM2Pi 4 From Node : 5
2016-10-25 18:43:02,808 DEBUG RFM2Pi 4 Values : [256, 181, 437, 121.74000000000001, 0, 0, 0, 0, 0, 0, 4747]
2016-10-25 18:43:02,810 INFO RFM2Pi Publishing: emon/emonpi/power1 256
2016-10-25 18:43:02,812 INFO RFM2Pi Publishing: emon/emonpi/power2 181
2016-10-25 18:43:02,814 INFO RFM2Pi Publishing: emon/emonpi/power1pluspower2 437
2016-10-25 18:43:02,816 INFO RFM2Pi Publishing: emon/emonpi/vrms 121.74
2016-10-25 18:43:02,818 INFO RFM2Pi Publishing: emon/emonpi/t1 0
2016-10-25 18:43:02,820 INFO RFM2Pi Publishing: emon/emonpi/t2 0
2016-10-25 18:43:02,822 INFO RFM2Pi Publishing: emon/emonpi/t3 0
2016-10-25 18:43:02,824 INFO RFM2Pi Publishing: emon/emonpi/t4 0
2016-10-25 18:43:02,826 INFO RFM2Pi Publishing: emon/emonpi/t5 0
2016-10-25 18:43:02,829 INFO RFM2Pi Publishing: emon/emonpi/t6 0
2016-10-25 18:43:02,831 INFO RFM2Pi Publishing: emon/emonpi/pulsecount 4747
2016-10-25 18:43:02,833 INFO RFM2Pi Publishing: emon/emonpi/rssi 0
2016-10-25 18:43:02,835 INFO RFM2Pi Publishing: emonhub/rx/5/values 256,181,437,121.74,0,0,0,0,0,0,4747
2016-10-25 18:43:02,837 INFO RFM2Pi Publishing: emonhub/rx/5/rssi 0
2016-10-25 18:43:02,839 DEBUG RFM2Pi 4 adding frame to buffer => [1477438982, 5, 256, 181, 437, 121.74000000000001, 0, 0, 0, 0, 0, 0, 4747]
2016-10-25 18:43:02,840 DEBUG RFM2Pi 4 Sent to channel' : ToEmonCMS
2016-10-25 18:43:06,477 DEBUG RFM2Pi 5 NEW FRAME : OK 5 0 1 205 0 205 1 167 47 0 0 0 0 0 0 0 0 0 0 0 0 139 18 0 0 (-0)
2016-10-25 18:43:06,479 DEBUG RFM2Pi 5 Timestamp : 1477438986.48
20
@pb66 - I cannot locate a emonhub.log with the MQTT similar to the above emonhub.log. Is the emonPi emonhub coded differently?
I’m not even sure where to begin debugging something like this…
If you’re running the latest emonSD (03May16), this has now been fixed. As long as you run admin > emonpi update to pull in the latest changes it’s fine (and highly recommended to fix Dirty Cow) to update to mosquito 1.4.10 by running sudo apt-get update && upgrade 
.
The issue was Mosquito 1.4.10 now requires a log file to be created. This has now been added to rc.local which runs at boot. The rc.local_jessieminimal in the emonp repo ~/emonpi is symlinked to /etc/rc.local on the emonSD.
Yes.the emonPi variant was adapted by Trystan from my unreleased “experimental” branch of the original emonhub. That branch was only a proof of concept for evaluation of using bi-directional interfacers and selective internal routing, the MQTT interfacer was not fully implemented at that time as the jury was still in deliberation over which topic hierarchy we were going to adopt. Trystan added the MQTT code and made several significant changes to both the code structure and the internal routing before releasing it as the “emonpi variant of emonhub” but since I have never finished or released the experimental branch and most of the characteristic “emonhub” features were removed, it’s differences to the released “original” version of emonhub are significant.
I have noticed something else on the logs too.
This is a complete packet (number 4) passing through the RFM2Pi interfacer, taken from your log immediately above this post, but with the interlaced mqtt stuff removed.
2016-10-25 18:43:02,802 DEBUG RFM2Pi 4 NEW FRAME : OK 5 0 1 181 0 181 1 142 47 0 0 0 0 0 0 0 0 0 0 0 0 139 18 0 0 (-0)
2016-10-25 18:43:02,807 DEBUG RFM2Pi 4 Timestamp : 1477438982.8
2016-10-25 18:43:02,808 DEBUG RFM2Pi 4 From Node : 5
2016-10-25 18:43:02,808 DEBUG RFM2Pi 4 Values : [256, 181, 437, 121.74000000000001, 0, 0, 0, 0, 0, 0, 4747]
....
2016-10-25 18:43:02,839 DEBUG RFM2Pi 4 adding frame to buffer => [1477438982, 5, 256, 181, 437, 121.74000000000001, 0, 0, 0, 0, 0, 0, 4747]
2016-10-25 18:43:02,840 DEBUG RFM2Pi 4 Sent to channel' : ToEmonCMS
you can see it gets added to a “buffer” and sent to the “ToEmonCMS” channel, this is/was core behaviour and the MQTT interfacer should, along with other interested interfacers be listening to the “ToEmonCMS” channel (or another channel if the packet was sent to more than one eg “ToMQTT”) and publish from that channel, but oddly the MQTT is published before the packet is added to the channel it should be retrieving it from. That suggests the RFM2Pi and MQTT interfacers are effectively linked directly and not using the internal routing, (that might be the cause of the cross thread confusion?).
The centre column is reporting the thread making the log entry, it is not part of the log entry itself per se, so it is not a typo or being reported incorrectly, it appears all the MQTT thread does is establishes a connection and handles the MQTT settings. the RFM2Pi thread then does all the publishing, so although I cannot say with any certainty this is the cause of the “thread is dead” issues, it will almost certainly be the reason both the threads crash together.
I suspect the MQTT thread is crashing for some reason and taking the RFM2Pi thread down with it since there is no longer an active MQTT connection for the RFM2Pi thread to publish to, this should never happen, the reason for making emonhub multi-thread was to ensure each interfacer ran independently. If this cross threading issue didn’t exist, the “thread is dead” issue would actually be a MQTTinterfacer issue (either internal or reaction to external) and only effect the local emoncms due to it being fed via MQTT, the RFM2Pi thread would continue and data would still arrive at any remote emoncms’s.
I do not know how to proceed with debugging this whilst the 2 interfacers are entwined and a brief look at the code didn’t reveal any quick fixes either.