EmonHUB Crashing

Afternoon all
Did anybody get to the bottom of the emonHUB crashing every 4 or so days?
Within the emonHUB log you get the following…

The only way to fix the issue to to restart the service emonHUB or restart.

Regards
Dave

Where else have you seen an issue?

Can you tell us more about your set up? Can you provide some emonhub.log for around the time of the crash? in particular the time preceding the first “thread is dead” entry? Do you have loglevel = DEBUG set in the emonhub.conf?

Hi Paul
I have a EmonPi with 3x EmonTx’s on 433Mhz
A gentlemen private message me on the old forums, I think there was a problem with the RF chip crashing?
I have just had a look at the logs but it is full of not very helpful information. As the logs only go back an hour or so, I will need to try and catch it quicker.
Is there an easy way of extending the log period?

Regards
Dave

Ok, there is a known issue with the emonPi and the RFM2Pi locking out the RFM modules which is what you are referring to. When that fault occurs it will just cease to pass RF packets from the emonPi/RFM2Pi firmware to emonHub via serial. It will not cause emonhub to crash as it simply isn’t passing data in exactly the same way as if you powered down all your emonTx’s. When this occurs on an emonPi the node 5 will continue to pass data as it is not received via the RFM module and if you are up to date with the latest emonPi firmware there is a temporary “hack” been included that masks this issue by constantly resetting the rfm module every 60s.

The fact your RFM2Pi thread and your MQTT thread are crashing means this is probally something very different but we won’t know for sure until we see some logs.

Although the current log will be a max of 1 hour due to the logrotation there should be some other logs in the same folder. If you can SSH in to the Pi and use " ls -la /var/log/emonhub/ " to see what logs are there, you can then view the logs with a text editor like nano.

Have you checked the loglevel in emonhub.conf? if it was already set to “DEBUG” great, but if it wasn’t there is very little point searching out the existing log as the info we need won’t be there, in which case just set the loglevel and wait til the next occurrence.

What version emonhub are you running? Are you using a pre built sd card? If so what’s the date of the build. See emonSD-xxx file in /boot partition

It looks like an error, that also happens with my EmonBase with 433 Mhz with the latest EmonCMS of 3 May. After some days, it crashes with the same “Thread is dead”. It happens with 5 EmonTX and also with only 1 EmonTX sending. I haven’t spend time on it, because I continued with my other EmonBases.

It is the same as in the bottom of my post a while ago: Thread is dead. There I used an older version of EmonCMS 9.x beta version of 20feb2016.

emonHub should not crash like this, emonHub itself has been tested to be stable.

The 20feb2016 was an early beta release I would highly recommend upgrading to the latest RELEASE image emonSD-03May16.

The import / export backup module can be used to easily migrate your data. See backup section of user guide.

I emphasize only that I determine the same problem, as in the earlier version. And looks the same as the error of @Dave :wink:

An automatic restart of emonHUB is a temporary solution?

The “thread is dead” type errors can only occur with the emonpi variant of emonhub and it is a “last resort” log message from the main thread put in place to avoid threads crashing and vanishing without any log entry for debuging.

Each interfacer thread is responsible for it’s own error handling and logging, the main thread loops through the interfacers and if the thread is missing logs that fault.

The probability is that some erroneous data is not being filtered and/or an error is not caught and reported. Thi is why it is important to see the log preceeding the first “thread is dead” entry.

@bart the thread you link to suggests the “main thread is dead”, this isn’t possible as if it was dead it couldn’t report the error. The log entries are formatted date, time, originating thread name and then error message so for example “Main Thread MQTT thread is dead” is the MQTT interfacer thread reported dead by the Main Thread.

I was definitely having issues with emonhub crashing regularly (about once an hour) with quite a recent git update. My suspicions were there was some race condition somewhere.in the code.

My setup was that it received data over the network socket, posted it immediately to MQTT, and then once per 10 seconds to emoncms locally.

I stopped using it in the way that I was because I didn’t think it was particularly fair, and was something I was going to look at at a later stage. I was posting about 35 variables to it from a single source with a post every 250ms. Reducing the frequency, reduced the frequency of any hangs significantly, maybe once this month?

I can probably quite easily re-generate such an error and log over the weekend, if the amount of data isn’t going to overwhelm any analysis effort. I have the log level set to DEBUG usually

Morning All
I managed to catch the crash within time to capture the logs…

2016-05-28 06:57:01,504 INFO     RFM2Pi     Publishing: emon/emonpi/RearPV 2149
2016-05-28 06:57:01,506 INFO     RFM2Pi     Publishing: emon/emonpi/FrontPV 290
2016-05-28 06:57:01,508 INFO     RFM2Pi     Publishing: emon/emonpi/TotalGeneration 2439
2016-05-28 06:57:01,510 INFO     RFM2Pi     Publishing: emon/emonpi/vrms 243.53
2016-05-28 06:57:01,512 INFO     RFM2Pi     Publishing: emon/emonpi/t1 18.6
2016-05-28 06:57:01,514 INFO     RFM2Pi     Publishing: emon/emonpi/t2 13.8
2016-05-28 06:57:01,515 INFO     RFM2Pi     Publishing: emon/emonpi/t3 0
2016-05-28 06:57:01,517 INFO     RFM2Pi     Publishing: emon/emonpi/t4 0
2016-05-28 06:57:01,519 INFO     RFM2Pi     Publishing: emon/emonpi/t5 0
2016-05-28 06:57:01,521 INFO     RFM2Pi     Publishing: emon/emonpi/t6 0
2016-05-28 06:57:01,523 INFO     RFM2Pi     Publishing: emon/emonpi/pulsecount 1186671
2016-05-28 06:57:01,524 INFO     RFM2Pi     Publishing: emon/emonpi/Irms1 8.7
2016-05-28 06:57:01,526 INFO     RFM2Pi     Publishing: emon/emonpi/Irms2 1.4
2016-05-28 06:57:01,528 INFO     RFM2Pi     Publishing: emon/emonpi/Irms1_plus_2 10.1
2016-05-28 06:57:01,530 INFO     RFM2Pi     Publishing: emon/emonpi/powerFactor1 1
2016-05-28 06:57:01,531 INFO     RFM2Pi     Publishing: emon/emonpi/powerFactor2 0.82
2016-05-28 06:57:01,533 INFO     RFM2Pi     Publishing: emon/emonpi/rssi 0
2016-05-28 06:57:01,535 INFO     RFM2Pi     Publishing: emonhub/rx/5/values 2149,290,2439,243.53,18.6,13.8,0,0,0,0,1186671,8.7,1.4,10.1,1,0.82
2016-05-28 06:57:01,537 INFO     RFM2Pi     Publishing: emonhub/rx/5/rssi 0
2016-05-28 06:57:01,539 DEBUG    RFM2Pi     231124 adding frame to buffer => [1464418621, 5, 2149, 290, 2439, 243.53, 18.6, 13.8, 0, 0, 0, 0, 1186671, 8.700000000000001, 1.4000000000000001, 10.100000000000001, 1, 0.8200000000000001]
2016-05-28 06:57:01,540 DEBUG    RFM2Pi     231124 Sent to channel' : ToEmonCMS
2016-05-28 06:57:03,253 DEBUG    RFM2Pi     231125 NEW FRAME : OK 9 1 249 64 0 44 0 0 0 242 94 184 11 184 11 184 11 184 11 184 11 184 11 2 0 0 0 76 0 4 0 3 0 0 0 160 255 61 0 55 0 0 0 (-54)
2016-05-28 06:57:03,257 DEBUG    RFM2Pi     231125 Timestamp : 1464418623.25
2016-05-28 06:57:03,258 DEBUG    RFM2Pi     231125 From Node : 9
2016-05-28 06:57:03,258 DEBUG    RFM2Pi     231125    Values : [-1791, 64, 44, 0, 243.06, 300, 300, 300, 300, 300, 300, 2, 7.6000000000000005, 0.4, 0.30000000000000004, 0, -0.96, 0.61, 0.55, 0]
2016-05-28 06:57:03,259 DEBUG    RFM2Pi     231125      RSSI : -54
2016-05-28 06:57:03,260 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Supply -1791
2016-05-28 06:57:03,261 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Kitchen_Sockets 64
2016-05-28 06:57:03,262 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Downstairs_Sockets 44
2016-05-28 06:57:03,263 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Downstairs_Lights 0
2016-05-28 06:57:03,265 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/vrms 243.06
2016-05-28 06:57:03,266 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp1 300
2016-05-28 06:57:03,267 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp2 300
2016-05-28 06:57:03,268 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp3 300
2016-05-28 06:57:03,269 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp4 300
2016-05-28 06:57:03,270 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp5 300
2016-05-28 06:57:03,271 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp6 300
2016-05-28 06:57:03,272 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/pulse 2
2016-05-28 06:57:03,273 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Irms1 7.6
2016-05-28 06:57:03,275 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Irms2 0.4
2016-05-28 06:57:03,276 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Irms3 0.3
2016-05-28 06:57:03,277 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Irms4 0
2016-05-28 06:57:03,278 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/powerFactor1 -0.96
2016-05-28 06:57:03,279 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/powerFactor2 0.61
2016-05-28 06:57:03,280 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/powerFactor3 0.55
2016-05-28 06:57:03,281 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/powerFactor4 0
2016-05-28 06:57:03,282 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/rssi -54
2016-05-28 06:57:03,283 INFO     RFM2Pi     Publishing: emonhub/rx/9/values -1791,64,44,0,243.06,300,300,300,300,300,300,2,7.6,0.4,0.3,0,-0.96,0.61,0.55,0
2016-05-28 06:57:03,284 INFO     RFM2Pi     Publishing: emonhub/rx/9/rssi -54
2016-05-28 06:57:03,284 DEBUG    RFM2Pi     231125 adding frame to buffer => [1464418623, 9, -1791, 64, 44, 0, 243.06, 300, 300, 300, 300, 300, 300, 2, 7.6000000000000005, 0.4, 0.30000000000000004, 0, -0.96, 0.61, 0.55, 0, -54]
2016-05-28 06:57:03,285 DEBUG    RFM2Pi     231125 Sent to channel' : ToEmonCMS
2016-05-28 06:57:05,137 DEBUG    RFM2Pi     231126 NEW FRAME : OK 8 24 0 134 0 9 1 27 0 7 95 184 11 184 11 184 11 184 11 184 11 184 11 2 0 0 0 2 0 6 0 14 0 1 0 35 0 86 0 77 0 66 0 (-51)
2016-05-28 06:57:05,141 DEBUG    RFM2Pi     231126 Timestamp : 1464418625.14
2016-05-28 06:57:05,141 DEBUG    RFM2Pi     231126 From Node : 8
2016-05-28 06:57:05,142 DEBUG    RFM2Pi     231126    Values : [24, 134, 265, 27, 243.27, 300, 300, 300, 300, 300, 300, 2, 0.2, 0.6000000000000001, 1.4000000000000001, 0.1, 0.35000000000000003, 0.86, 0.77, 0.66]
2016-05-28 06:57:05,143 DEBUG    RFM2Pi     231126      RSSI : -51
2016-05-28 06:57:05,143 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Upstairs_Sockets 24
2016-05-28 06:57:05,145 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Shed_Submain 134
2016-05-28 06:57:05,147 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Loft_Sockets 265
2016-05-28 06:57:05,148 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Upstairs_Lights 27
2016-05-28 06:57:05,149 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/vrms 243.27
2016-05-28 06:57:05,150 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp1 300
2016-05-28 06:57:05,152 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp2 300
2016-05-28 06:57:05,153 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp3 300
2016-05-28 06:57:05,154 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp4 300
2016-05-28 06:57:05,155 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp5 300
2016-05-28 06:57:05,157 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp6 300
2016-05-28 06:57:05,158 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/pulse 2
2016-05-28 06:57:05,159 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Irms1 0.2
2016-05-28 06:57:05,160 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Irms2 0.6
2016-05-28 06:57:05,162 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Irms3 1.4
2016-05-28 06:57:05,163 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Irms4 0.1
2016-05-28 06:57:05,164 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/powerFactor1 0.35
2016-05-28 06:57:05,166 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/powerFactor2 0.86
2016-05-28 06:57:05,167 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/powerFactor3 0.77
2016-05-28 06:57:05,168 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/powerFactor4 0.66
2016-05-28 06:57:05,169 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/rssi -51
2016-05-28 06:57:05,170 INFO     RFM2Pi     Publishing: emonhub/rx/8/values 24,134,265,27,243.27,300,300,300,300,300,300,2,0.2,0.6,1.4,0.1,0.35,0.86,0.77,0.66
2016-05-28 06:57:05,171 INFO     RFM2Pi     Publishing: emonhub/rx/8/rssi -51
2016-05-28 06:57:05,172 DEBUG    RFM2Pi     231126 adding frame to buffer => [1464418625, 8, 24, 134, 265, 27, 243.27, 300, 300, 300, 300, 300, 300, 2, 0.2, 0.6000000000000001, 1.4000000000000001, 0.1, 0.35000000000000003, 0.86, 0.77, 0.66, -51]
2016-05-28 06:57:05,172 DEBUG    RFM2Pi     231126 Sent to channel' : ToEmonCMS
2016-05-28 06:57:05,276 DEBUG    RFM2Pi     231127 NEW FRAME : OK 10 185 248 233 255 2 0 3 0 0 0 235 94 184 11 (-56)
2016-05-28 06:57:05,278 DEBUG    RFM2Pi     231127 Timestamp : 1464418625.28
2016-05-28 06:57:05,279 DEBUG    RFM2Pi     231127 From Node : 10
2016-05-28 06:57:05,280 DEBUG    RFM2Pi     231127    Values : [-1863, -23, 2, 3, 0, 242.99, 300]
2016-05-28 06:57:05,280 DEBUG    RFM2Pi     231127      RSSI : -56
2016-05-28 06:57:05,281 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Grid_Watts -1863
2016-05-28 06:57:05,284 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Diverted_Watts -23
2016-05-28 06:57:05,285 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Cooker 2
2016-05-28 06:57:05,286 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Shower 3
2016-05-28 06:57:05,288 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Diverted_Energy_WattHours 0
2016-05-28 06:57:05,289 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/vrms 242.99
2016-05-28 06:57:05,290 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/temp 300
2016-05-28 06:57:05,292 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/rssi -56
2016-05-28 06:57:05,293 INFO     RFM2Pi     Publishing: emonhub/rx/10/values -1863,-23,2,3,0,242.99,300
2016-05-28 06:57:05,294 INFO     RFM2Pi     Publishing: emonhub/rx/10/rssi -56
2016-05-28 06:57:05,296 DEBUG    RFM2Pi     231127 adding frame to buffer => [1464418625, 10, -1863, -23, 2, 3, 0, 242.99, 300, -56]
2016-05-28 06:57:05,297 DEBUG    RFM2Pi     231127 Sent to channel' : ToEmonCMS
2016-05-28 06:57:05,734 INFO     emoncmsorg sending: http://192.168.10.90/emoncms//input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1464418621,5,2149,290,2439,243.53,18.6,13.8,0,0,0,0,1186671,8.700000000000001,1.4000000000000001,10.100000000000001,1,0.8200000000000001],[1464418623,9,-1791,64,44,0,243.06,300,300,300,300,300,300,2,7.6000000000000005,0.4,0.30000000000000004,0,-0.96,0.61,0.55,0,-54],[1464418625,8,24,134,265,27,243.27,300,300,300,300,300,300,2,0.2,0.6000000000000001,1.4000000000000001,0.1,0.35000000000000003,0.86,0.77,0.66,-51],[1464418625,10,-1863,-23,2,3,0,242.99,300,-56]]&sentat=1464418625
2016-05-28 06:57:05,774 WARNING  emoncmsorg send failure: wanted 'ok' but got '<br />
<b>Warning</b>:  Division by zero in <b>/var/www/emoncms/Modules/process/process_processlist.php</b> on line <b>661</b><br />
ok'
2016-05-28 06:57:05,775 INFO     emoncmsorg sending: http://192.168.10.90/emoncms//myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 06:57:05,783 WARNING  emoncmsorg emoncmsorg couldn't send to server, HTTPError: 406
2016-05-28 06:57:06,508 DEBUG    RFM2Pi     231128 NEW FRAME : OK 5 117 8 33 1 150 9 10 95 186 0 138 0 0 0 0 0 0 0 0 0 114 27 18 0 88 0 14 0 102 0 100 0 83 0 (-0)
2016-05-28 06:57:06,512 DEBUG    RFM2Pi     231128 Timestamp : 1464418626.51
2016-05-28 06:57:06,513 DEBUG    RFM2Pi     231128 From Node : 5
2016-05-28 06:57:06,513 DEBUG    RFM2Pi     231128    Values : [2165, 289, 2454, 243.3, 18.6, 13.8, 0, 0, 0, 0, 1186674, 8.8, 1.4000000000000001, 10.200000000000001, 1, 0.8300000000000001]
2016-05-28 06:57:06,514 INFO     RFM2Pi     Publishing: emon/emonpi/RearPV 2165
2016-05-28 06:57:06,516 INFO     RFM2Pi     Publishing: emon/emonpi/FrontPV 289
2016-05-28 06:57:06,517 INFO     RFM2Pi     Publishing: emon/emonpi/TotalGeneration 2454
2016-05-28 06:57:06,518 INFO     RFM2Pi     Publishing: emon/emonpi/vrms 243.3
2016-05-28 06:57:06,519 INFO     RFM2Pi     Publishing: emon/emonpi/t1 18.6
2016-05-28 06:57:06,520 INFO     RFM2Pi     Publishing: emon/emonpi/t2 13.8
2016-05-28 06:57:06,521 INFO     RFM2Pi     Publishing: emon/emonpi/t3 0
2016-05-28 06:57:06,523 INFO     RFM2Pi     Publishing: emon/emonpi/t4 0
2016-05-28 06:57:06,524 INFO     RFM2Pi     Publishing: emon/emonpi/t5 0
2016-05-28 06:57:06,525 INFO     RFM2Pi     Publishing: emon/emonpi/t6 0
2016-05-28 06:57:06,526 INFO     RFM2Pi     Publishing: emon/emonpi/pulsecount 1186674
2016-05-28 06:57:06,527 INFO     RFM2Pi     Publishing: emon/emonpi/Irms1 8.8
2016-05-28 06:57:06,528 INFO     RFM2Pi     Publishing: emon/emonpi/Irms2 1.4
2016-05-28 06:57:06,529 INFO     RFM2Pi     Publishing: emon/emonpi/Irms1_plus_2 10.2
2016-05-28 06:57:06,530 INFO     RFM2Pi     Publishing: emon/emonpi/powerFactor1 1
2016-05-28 06:57:06,552 INFO     RFM2Pi     Publishing: emon/emonpi/powerFactor2 0.83
2016-05-28 06:57:06,553 INFO     RFM2Pi     Publishing: emon/emonpi/rssi 0
2016-05-28 06:57:06,555 INFO     RFM2Pi     Publishing: emonhub/rx/5/values 2165,289,2454,243.3,18.6,13.8,0,0,0,0,1186674,8.8,1.4,10.2,1,0.83
2016-05-28 06:57:06,556 INFO     RFM2Pi     Publishing: emonhub/rx/5/rssi 0
2016-05-28 06:57:06,557 DEBUG    RFM2Pi     231128 adding frame to buffer => [1464418626, 5, 2165, 289, 2454, 243.3, 18.6, 13.8, 0, 0, 0, 0, 1186674, 8.8, 1.4000000000000001, 10.200000000000001, 1, 0.8300000000000001]
2016-05-28 06:57:06,558 DEBUG    RFM2Pi     231128 Sent to channel' : ToEmonCMS
2016-05-28 06:57:08,170 DEBUG    RFM2Pi     231129 NEW FRAME : OK 9 240 248 64 0 43 0 0 0 233 94 184 11 184 11 184 11 184 11 184 11 184 11 2 0 0 0 76 0 4 0 3 0 0 0 160 255 60 0 53 0 0 0 (-54)
2016-05-28 06:57:08,174 DEBUG    RFM2Pi     231129 Timestamp : 1464418628.17
2016-05-28 06:57:08,175 DEBUG    RFM2Pi     231129 From Node : 9
2016-05-28 06:57:08,176 DEBUG    RFM2Pi     231129    Values : [-1808, 64, 43, 0, 242.97, 300, 300, 300, 300, 300, 300, 2, 7.6000000000000005, 0.4, 0.30000000000000004, 0, -0.96, 0.6, 0.53, 0]
2016-05-28 06:57:08,176 DEBUG    RFM2Pi     231129      RSSI : -54
2016-05-28 06:57:08,177 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Supply -1808
2016-05-28 06:57:08,179 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Kitchen_Sockets 64
2016-05-28 06:57:08,180 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Downstairs_Sockets 43
2016-05-28 06:57:08,181 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Downstairs_Lights 0
2016-05-28 06:57:08,183 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/vrms 242.97
2016-05-28 06:57:08,184 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp1 300
2016-05-28 06:57:08,185 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp2 300
2016-05-28 06:57:08,187 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp3 300
2016-05-28 06:57:08,188 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp4 300
2016-05-28 06:57:08,190 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp5 300
2016-05-28 06:57:08,191 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/temp6 300
2016-05-28 06:57:08,192 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/pulse 2
2016-05-28 06:57:08,194 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Irms1 7.6
2016-05-28 06:57:08,195 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Irms2 0.4
2016-05-28 06:57:08,196 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Irms3 0.3
2016-05-28 06:57:08,197 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Irms4 0
2016-05-28 06:57:08,199 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/powerFactor1 -0.96
2016-05-28 06:57:08,200 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/powerFactor2 0.6
2016-05-28 06:57:08,201 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/powerFactor3 0.53
2016-05-28 06:57:08,203 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/powerFactor4 0
2016-05-28 06:57:08,204 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/rssi -54
2016-05-28 06:57:08,205 INFO     RFM2Pi     Publishing: emonhub/rx/9/values -1808,64,43,0,242.97,300,300,300,300,300,300,2,7.6,0.4,0.3,0,-0.96,0.6,0.53,0
2016-05-28 06:57:08,205 INFO     RFM2Pi     Publishing: emonhub/rx/9/rssi -54
2016-05-28 06:57:08,206 DEBUG    RFM2Pi     231129 adding frame to buffer => [1464418628, 9, -1808, 64, 43, 0, 242.97, 300, 300, 300, 300, 300, 300, 2, 7.6000000000000005, 0.4, 0.30000000000000004, 0, -0.96, 0.6, 0.53, 0, -54]
2016-05-28 06:57:08,207 DEBUG    RFM2Pi     231129 Sent to channel' : ToEmonCMS
2016-05-28 06:57:10,051 DEBUG    RFM2Pi     231130 NEW FRAME : OK 8 24 0 132 0 9 1 27 0 226 94 184 11 184 11 184 11 184 11 184 11 184 11 2 0 0 0 2 0 6 0 14 0 1 0 35 0 85 0 77 0 67 0 (-50)
2016-05-28 06:57:10,055 DEBUG    RFM2Pi     231130 Timestamp : 1464418630.05
2016-05-28 06:57:10,056 DEBUG    RFM2Pi     231130 From Node : 8
2016-05-28 06:57:10,056 DEBUG    RFM2Pi     231130    Values : [24, 132, 265, 27, 242.9, 300, 300, 300, 300, 300, 300, 2, 0.2, 0.6000000000000001, 1.4000000000000001, 0.1, 0.35000000000000003, 0.85, 0.77, 0.67]
2016-05-28 06:57:10,057 DEBUG    RFM2Pi     231130      RSSI : -50
2016-05-28 06:57:10,058 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Upstairs_Sockets 24
2016-05-28 06:57:10,059 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Shed_Submain 132
2016-05-28 06:57:10,060 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Loft_Sockets 265
2016-05-28 06:57:10,061 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Upstairs_Lights 27
2016-05-28 06:57:10,063 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/vrms 242.9
2016-05-28 06:57:10,064 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp1 300
2016-05-28 06:57:10,065 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp2 300
2016-05-28 06:57:10,066 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp3 300
2016-05-28 06:57:10,067 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp4 300
2016-05-28 06:57:10,068 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp5 300
2016-05-28 06:57:10,069 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/temp6 300
2016-05-28 06:57:10,070 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/pulse 2
2016-05-28 06:57:10,071 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Irms1 0.2
2016-05-28 06:57:10,072 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Irms2 0.6
2016-05-28 06:57:10,074 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Irms3 1.4
2016-05-28 06:57:10,075 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Irms4 0.1
2016-05-28 06:57:10,076 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/powerFactor1 0.35
2016-05-28 06:57:10,077 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/powerFactor2 0.85
2016-05-28 06:57:10,078 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/powerFactor3 0.77
2016-05-28 06:57:10,079 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/powerFactor4 0.67
2016-05-28 06:57:10,080 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/rssi -50
2016-05-28 06:57:10,081 INFO     RFM2Pi     Publishing: emonhub/rx/8/values 24,132,265,27,242.9,300,300,300,300,300,300,2,0.2,0.6,1.4,0.1,0.35,0.85,0.77,0.67
2016-05-28 06:57:10,082 INFO     RFM2Pi     Publishing: emonhub/rx/8/rssi -50
2016-05-28 06:57:10,083 DEBUG    RFM2Pi     231130 adding frame to buffer => [1464418630, 8, 24, 132, 265, 27, 242.9, 300, 300, 300, 300, 300, 300, 2, 0.2, 0.6000000000000001, 1.4000000000000001, 0.1, 0.35000000000000003, 0.85, 0.77, 0.67, -50]
2016-05-28 06:57:10,083 DEBUG    RFM2Pi     231130 Sent to channel' : ToEmonCMS
2016-05-28 06:57:10,287 DEBUG    RFM2Pi     231131 NEW FRAME : OK 10 173 248 233 255 1 0 3 0 0 0 223 94 184 11 (-57)
2016-05-28 06:57:10,290 DEBUG    RFM2Pi     231131 Timestamp : 1464418630.29
2016-05-28 06:57:10,291 DEBUG    RFM2Pi     231131 From Node : 10
2016-05-28 06:57:10,292 DEBUG    RFM2Pi     231131    Values : [-1875, -23, 1, 3, 0, 242.87, 300]
2016-05-28 06:57:10,292 DEBUG    RFM2Pi     231131      RSSI : -57
2016-05-28 06:57:10,294 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Grid_Watts -1875
2016-05-28 06:57:10,295 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Diverted_Watts -23
2016-05-28 06:57:10,297 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Cooker 1
2016-05-28 06:57:10,299 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Shower 3
2016-05-28 06:57:10,300 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/Diverted_Energy_WattHours 0
2016-05-28 06:57:10,302 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/vrms 242.87
2016-05-28 06:57:10,304 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/temp 300
2016-05-28 06:57:10,305 INFO     RFM2Pi     Publishing: emon/emonTx_Diverter/rssi -57
2016-05-28 06:57:10,307 INFO     RFM2Pi     Publishing: emonhub/rx/10/values -1875,-23,1,3,0,242.87,300
2016-05-28 06:57:10,308 INFO     RFM2Pi     Publishing: emonhub/rx/10/rssi -57
2016-05-28 06:57:10,310 DEBUG    RFM2Pi     231131 adding frame to buffer => [1464418630, 10, -1875, -23, 1, 3, 0, 242.87, 300, -57]
2016-05-28 06:57:10,311 DEBUG    RFM2Pi     231131 Sent to channel' : ToEmonCMS
2016-05-28 06:57:10,740 INFO     emoncmsorg sending: http://192.168.10.90/emoncms//input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1464418626,5,2165,289,2454,243.3,18.6,13.8,0,0,0,0,1186674,8.8,1.4000000000000001,10.200000000000001,1,0.8300000000000001],[1464418628,9,-1808,64,43,0,242.97,300,300,300,300,300,300,2,7.6000000000000005,0.4,0.30000000000000004,0,-0.96,0.6,0.53,0,-54],[1464418630,8,24,132,265,27,242.9,300,300,300,300,300,300,2,0.2,0.6000000000000001,1.4000000000000001,0.1,0.35000000000000003,0.85,0.77,0.67,-50],[1464418630,10,-1875,-23,1,3,0,242.87,300,-57]]&sentat=1464418630
2016-05-28 06:57:10,784 WARNING  emoncmsorg send failure: wanted 'ok' but got '<br />
<b>Warning</b>:  Division by zero in <b>/var/www/emoncms/Modules/process/process_processlist.php</b> on line <b>661</b><br />
ok'
2016-05-28 06:57:10,785 INFO     emoncmsorg sending: http://192.168.10.90/emoncms//myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 06:57:10,795 WARNING  emoncmsorg emoncmsorg couldn't send to server, HTTPError: 406
2016-05-28 06:57:11,524 DEBUG    RFM2Pi     231132 NEW FRAME : OK 5 97 8 32 1 129 9 25 95 186 0 138 0 0 0 0 0 0 0 0 0 118 27 18 0 88 0 14 0 102 0 100 0 82 0 (-0)
2016-05-28 06:57:11,529 DEBUG    RFM2Pi     231132 Timestamp : 1464418631.52
2016-05-28 06:57:11,530 DEBUG    RFM2Pi     231132 From Node : 5
2016-05-28 06:57:11,531 DEBUG    RFM2Pi     231132    Values : [2145, 288, 2433, 243.45000000000002, 18.6, 13.8, 0, 0, 0, 0, 1186678, 8.8, 1.4000000000000001, 10.200000000000001, 1, 0.8200000000000001]
2016-05-28 06:57:11,532 INFO     RFM2Pi     Publishing: emon/emonpi/RearPV 2145
2016-05-28 06:57:11,534 INFO     RFM2Pi     Publishing: emon/emonpi/FrontPV 288
2016-05-28 06:57:11,535 INFO     RFM2Pi     Publishing: emon/emonpi/TotalGeneration 2433
2016-05-28 06:57:11,537 INFO     RFM2Pi     Publishing: emon/emonpi/vrms 243.45
2016-05-28 06:57:11,538 INFO     RFM2Pi     Publishing: emon/emonpi/t1 18.6
2016-05-28 06:57:11,540 INFO     RFM2Pi     Publishing: emon/emonpi/t2 13.8
2016-05-28 06:57:11,542 INFO     RFM2Pi     Publishing: emon/emonpi/t3 0
2016-05-28 06:57:11,543 INFO     RFM2Pi     Publishing: emon/emonpi/t4 0
2016-05-28 06:57:11,545 INFO     RFM2Pi     Publishing: emon/emonpi/t5 0
2016-05-28 06:57:11,546 INFO     RFM2Pi     Publishing: emon/emonpi/t6 0
2016-05-28 06:57:11,548 INFO     RFM2Pi     Publishing: emon/emonpi/pulsecount 1186678
2016-05-28 06:57:11,549 INFO     RFM2Pi     Publishing: emon/emonpi/Irms1 8.8
2016-05-28 06:57:11,551 INFO     RFM2Pi     Publishing: emon/emonpi/Irms2 1.4
2016-05-28 06:57:11,552 INFO     RFM2Pi     Publishing: emon/emonpi/Irms1_plus_2 10.2
2016-05-28 06:57:11,554 INFO     RFM2Pi     Publishing: emon/emonpi/powerFactor1 1
2016-05-28 06:57:11,555 INFO     RFM2Pi     Publishing: emon/emonpi/powerFactor2 0.82
2016-05-28 06:57:11,557 INFO     RFM2Pi     Publishing: emon/emonpi/rssi 0
2016-05-28 06:57:11,558 INFO     RFM2Pi     Publishing: emonhub/rx/5/values 2145,288,2433,243.45,18.6,13.8,0,0,0,0,1186678,8.8,1.4,10.2,1,0.82
2016-05-28 06:57:11,560 INFO     RFM2Pi     Publishing: emonhub/rx/5/rssi 0
2016-05-28 06:57:11,562 DEBUG    RFM2Pi     231132 adding frame to buffer => [1464418631, 5, 2145, 288, 2433, 243.45000000000002, 18.6, 13.8, 0, 0, 0, 0, 1186678, 8.8, 1.4000000000000001, 10.200000000000001, 1, 0.8200000000000001]
2016-05-28 06:57:11,563 DEBUG    RFM2Pi     231132 Sent to channel' : ToEmonCMS
2016-05-28 06:57:13,076 DEBUG    RFM2Pi     231133 NEW FRAME : OK 9 235 248 65 0 42 0 0 0 204 94 184 11 184 11 184 11 184 11 184 11 184 11 2 0 0 0 76 0 4 0 3 0 0 0 160 255 60 0 52 0 0 0 (-54)
2016-05-28 06:57:13,080 DEBUG    RFM2Pi     231133 Timestamp : 1464418633.08
2016-05-28 06:57:13,081 DEBUG    RFM2Pi     231133 From Node : 9
2016-05-28 06:57:13,082 DEBUG    RFM2Pi     231133    Values : [-1813, 65, 42, 0, 242.68, 300, 300, 300, 300, 300, 300, 2, 7.6000000000000005, 0.4, 0.30000000000000004, 0, -0.96, 0.6, 0.52, 0]
2016-05-28 06:57:13,083 DEBUG    RFM2Pi     231133      RSSI : -54
2016-05-28 06:57:13,084 INFO     RFM2Pi     Publishing: emon/emonTx_Node9/Supply -1813
2016-05-28 06:57:13,264 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:13,266 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:13,492 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:13,493 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:13,728 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:13,729 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:13,953 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:13,954 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:14,180 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:14,181 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:14,407 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:14,408 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:14,634 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:14,635 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:14,860 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:14,861 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:15,086 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:15,087 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:15,313 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:15,314 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:15,540 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:15,541 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:15,773 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:15,774 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:15,809 INFO     emoncmsorg sending: http://192.168.10.90/emoncms//input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1464418631,5,2145,288,2433,243.45000000000002,18.6,13.8,0,0,0,0,1186678,8.8,1.4000000000000001,10.200000000000001,1,0.8200000000000001]]&sentat=1464418635
2016-05-28 06:57:15,845 WARNING  emoncmsorg send failure: wanted 'ok' but got '<br />
<b>Warning</b>:  Division by zero in <b>/var/www/emoncms/Modules/process/process_processlist.php</b> on line <b>661</b><br />
ok'
2016-05-28 06:57:15,846 INFO     emoncmsorg sending: http://192.168.10.90/emoncms//myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 06:57:15,853 WARNING  emoncmsorg emoncmsorg couldn't send to server, HTTPError: 406
2016-05-28 06:57:16,019 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:16,020 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:16,257 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:16,258 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:16,496 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:16,497 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:16,736 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:16,738 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:16,976 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:16,977 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:17,215 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:17,216 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:17,453 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:17,454 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:17,692 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:17,693 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:17,932 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:17,934 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:18,176 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:18,177 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:18,415 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:18,417 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:18,653 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:18,655 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:18,899 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:18,901 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:19,127 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:19,128 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:19,353 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:19,354 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:19,594 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:19,595 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:19,821 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:19,822 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:20,048 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:20,049 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:20,275 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:20,276 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:20,501 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:20,502 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:20,728 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:20,729 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:20,867 INFO     emoncmsorg sending: http://192.168.10.90/emoncms//input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1464418640
2016-05-28 06:57:20,876 WARNING  emoncmsorg send failure: wanted 'ok' but got 'Error: Format error, json string supplied is not valid
'
2016-05-28 06:57:20,877 INFO     emoncmsorg sending: http://192.168.10.90/emoncms//myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 06:57:20,883 WARNING  emoncmsorg emoncmsorg couldn't send to server, HTTPError: 406
2016-05-28 06:57:20,958 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:20,959 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:21,199 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:21,201 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:21,426 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:21,427 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:21,653 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:21,654 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:21,879 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:21,880 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:22,106 WARNING  MainThread RFM2Pi thread is dead
2016-05-28 06:57:22,107 WARNING  MainThread MQTT thread is dead
2016-05-28 06:57:22,332 WARNING  MainThread RFM2Pi thread is dead

emonhub.zip (777.8 KB)

Dave can you simply add your logfile to the post as a text file instead of pasting the entire log in your post!

Paul

I’ve edited your post to us use the code quote block formatting which somewhat limits the length of the log to a scrollable box.

E.g

Code

```

Sorry Paul, I put a snippet from the logs in and attached at the bottom, thou I had to put into a zip as the file extension .log wasn’t allowed.

Thanks Glyn, I didn’t know if CODE would work on this forum

Regards
Dave

No worries Dave, you can always attach such files as log.txt instead of log.log

Paul

Well this is interesting!

Can you post your emonhub.conf and also 2 more log excerpts (or one combined)? What I would like to see are

  • A) The start up phase to see each of the interfacers being created
  • B) A short period of logging sometime after the setup is complete but well before the first occurrence of any issue, ie normal pre-fault running

This is what I can see so far

2016-05-28 06:57:03,253 DEBUG    RFM2Pi     231125 NEW FRAME : OK 9 1 249 64 0 44 0 0 0 242 94 184 11 184 11 184 11 184 11 184 11 184 11 2 0 0 0 76 0 4 0 3 0 0 0 160 255 61 0 55 0 0 0 (-54)
2016-05-28 06:57:03,257 DEBUG    RFM2Pi     231125 Timestamp : 1464418623.25
2016-05-28 06:57:03,258 DEBUG    RFM2Pi     231125 From Node : 9
2016-05-28 06:57:03,258 DEBUG    RFM2Pi     231125    Values : [-1791, 64, 44, 0, 243.06, 300, 300, 300, 300, 300, 300, 2, 7.6000000000000005, 0.4, 0.30000000000000004, 0, -0.96, 0.61, 0.55, 0]
2016-05-28 06:57:03,259 DEBUG    RFM2Pi     231125      RSSI : -54

is normal running, we have a date&time, loglevel of DEBUG, a thread named RFM2Pi, a packet id of 231125 and the correct parsing of a frame from node 9 all looks good. But immediately after that

2016-05-28 06:57:05,143 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Upstairs_Sockets 24
2016-05-28 06:57:05,145 INFO     RFM2Pi     Publishing: emon/emonTx_Node8/Shed_Submain 134

The “RFM2Pi” thread has no ability to “Publish” this is supposed to be the “MQTT” thread, pretty much all the logging seems to be from the RFM2Pi thread. Whether that is reported accurately or not I have no idea, is the “MQTT” code running within the “RFM2Pi” thread or is the “MQTT” thread presenting itself as the “RFM2Pi” thread ?

I guess probably the former as I believe there are measures in the threading lib to prevent threads having the same name, or is that what is eventually causing the crash? This is definitely a threading issue. That is why I originally said this can only be seen in the emonpi variant as the interfacers are not threaded in the original version.

My “experimental” version that the “emonpi” version was based on used a self contained routing system rather than an external pub/sub lib and the interfacer code was all in a single module not split out into individual modules so I have not done any testing on this version and cannot be sure what to expect.

Are you using a stock version? or have you made any changes to the code?

Not intending to hijack, this is supplied in case it is useful to compare what might be a similar crash. Although the config file below is quite complete, in reality for this emonhub I only have node 33 configured, and the only items it should be communicating with are the emoncms server and MQTT (the other nodes are currently dealt with a different emonhub)
As an interest, I re-enabled my system and received a crash almost immediately. I am on HEAD apparently.
I did make some changes whilst trying to debug things, looks like I didn’t quite back all of them out:

diff --git a/src/interfacers/EmonHubMqttInterfacer.py b/src/interfacers/EmonHubMqttInterfacer.py
index d25958c..325fb5d 100644
--- a/src/interfacers/EmonHubMqttInterfacer.py
+++ b/src/interfacers/EmonHubMqttInterfacer.py
@@ -9,6 +9,14 @@ import Cargo

 class EmonHubMqttInterfacer(EmonHubInterfacer):

+# The callback for when the client receives a CONNACK response from the server.
+    def aon_connect(self, client,usedata, rc):
+       print("Connected with result code "+str(rc))
+
+    # Subscribing in on_connect() means that if we lose the connection and
+    # reconnect then subscriptions will be renewed.
+       client.subscribe("$SYS/#")
+
     def __init__(self, name, mqtt_user=" ", mqtt_passwd=" ", mqtt_host="127.0.0.1", mqtt_port=1883):
         # Initialization
         super(EmonHubMqttInterfacer, self).__init__(name)
@@ -33,8 +41,9 @@ class EmonHubMqttInterfacer(EmonHubInterfacer):
             'nodevar_format_enable': 0,
             'nodevar_format_basetopic': "nodes/"
         };
-
         self._mqttc = mqtt.Client()
+        self._log.debug("After client")
+
         self._mqttc.on_connect = self.on_connect
         self._mqttc.on_disconnect = self.on_disconnect
         self._mqttc.on_message = self.on_message
@@ -45,14 +54,17 @@ class EmonHubMqttInterfacer(EmonHubInterfacer):
         if not self._connected:
             self._log.info("Connecting to MQTT Server")
             try:
-                self._mqttc.username_pw_set(self._user, self._passwd)
-                self._mqttc.connect(self._host, self._port, 60)
+             self._mqttc.username_pw_set(self._user, self._passwd)
+             self._log.debug("Details:"+self._host+" :"+self._port)
+             self._mqttc.connect(host=self._host, port=self._port, keepalive=6, bind_address="10.1.0.53")
+            self._mqttc.tls_insecure_set(true)
             except:
                 self._log.info("Could not connect...")
                 time.sleep(1.0)
         self._mqttc.loop(0)

     def on_connect(self, client, userdata, flags, rc):
+        self._log.debug("Connection made")

         connack_string = {0:'Connection successful',
                           1:'Connection refused - incorrect protocol version',
@@ -72,6 +84,7 @@ class EmonHubMqttInterfacer(EmonHubInterfacer):
         self._log.debug("CONACK => Return code: "+str(rc))

     def on_disconnect(self, client, userdata, rc):
+        self._log.debug("Connection disconnected!!!")
         if rc != 0:
             self._log.info("Unexpected disconnection")
             self._connected = False
@@ -80,6 +93,7 @@ class EmonHubMqttInterfacer(EmonHubInterfacer):
         self._log.info("on_subscribe")

     def on_message(self, client, userdata, msg):
+        self._log.info("message")
         topic_parts = msg.topic.split("/")

         if topic_parts[0] == self._settings["node_format_basetopic"][:-1]:
diff --git a/src/interfacers/emonhub_interfacer.py b/src/interfacers/emonhub_interfacer.py
index 2c9a1e1..e68c40a 100644
--- a/src/interfacers/emonhub_interfacer.py
+++ b/src/interfacers/emonhub_interfacer.py
@@ -168,7 +168,8 @@ class EmonHubInterfacer(threading.Thread):
             # Discard the frame & return 'False' if it doesn't match the summed datasizes
             if len(rxc.realdata) != sum(datasizes):
                 self._log.warning(str(rxc.uri) + " RX data length: " + str(len(rxc.realdata)) +
-                                  " is not valid for datacodes " + str(datacodes))
+                                  " is not valid for datacodes " + str(datacodes) + "datasize:" +str(len((datasizes)))+":"+str(rxc.realdata))
+                self._log.warning(str(rxc.uri) + " RX data length: " + str(len(rxc.realdata)) +":"+ str(sum(datasizes)))
                 return False
             else:
                 # Determine the expected number of values to be decoded

Anyways, the error occurred quite quickly this time (the first couple of 406 errors are semi-expected, there was no data to send, perhaps this is why it hits some people and not others?). Times between packets reduced to 1s:

2016-05-28 13:15:39,420 INFO     MainThread EmonHub emonHub 'emon-pi' variant v1.1
2016-05-28 13:15:39,420 INFO     MainThread Opening hub...
2016-05-28 13:15:39,420 INFO     MainThread Logging level set to DEBUG
2016-05-28 13:15:39,420 INFO     MainThread Creating EmonHubSocketInterfacer 'socketb'
2016-05-28 13:15:39,420 DEBUG    MainThread Opening socket on port 51014
2016-05-28 13:15:39,421 INFO     MainThread Creating EmonHubMqttInterfacer 'MQTT'
2016-05-28 13:15:39,421 INFO     MainThread MQTT Init mqtt_host=10.1.0.53 mqtt_port=1883 mqtt_user=
2016-05-28 13:15:39,423 DEBUG    MainThread After client
2016-05-28 13:15:39,423 DEBUG    MainThread MQTT Subscribed to channel' : ToEmonCMS
2016-05-28 13:15:39,423 DEBUG    MainThread MQTT Subscribed to channel' : espmon01
2016-05-28 13:15:39,423 DEBUG    MainThread MQTT Subscribed to channel' : ch1
2016-05-28 13:15:39,423 INFO     MainThread Creating EmonHubEmoncmsHTTPInterfacer 'emoncms'
2016-05-28 13:15:39,424 DEBUG    MainThread emoncms Subscribed to channel' : ToEmonCMS
2016-05-28 13:15:39,424 DEBUG    MainThread emoncms Subscribed to channel' : ch1
2016-05-28 13:15:39,424 DEBUG    MainThread emoncms Subscribed to channel' : espmon01
2016-05-28 13:15:39,524 INFO     MQTT       Connecting to MQTT Server
2016-05-28 13:15:39,524 DEBUG    MQTT       Details:10.1.0.53 :1883
2016-05-28 13:15:39,525 INFO     MQTT       Could not connect...
2016-05-28 13:15:40,527 DEBUG    MQTT       Connection made
2016-05-28 13:15:40,528 INFO     MQTT       connection status: Connection successful
2016-05-28 13:15:40,528 DEBUG    MQTT       CONACK => Return code: 0
2016-05-28 13:15:40,629 INFO     MQTT       on_subscribe
2016-05-28 13:16:09,443 INFO     emoncms    sending: http://10.1.0.53/emoncms/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1464437769
2016-05-28 13:16:09,484 WARNING  emoncms    send failure: wanted 'ok' but got 'Error: Format error, json string supplied is not valid
'
2016-05-28 13:16:09,484 INFO     emoncms    sending: http://10.1.0.53/emoncms/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 13:16:09,498 WARNING  emoncms    emoncms couldn't send to server, HTTPError: 406
2016-05-28 13:16:39,513 INFO     emoncms    sending: http://10.1.0.53/emoncms/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1464437799
2016-05-28 13:16:39,548 WARNING  emoncms    send failure: wanted 'ok' but got 'Error: Format error, json string supplied is not valid
'
2016-05-28 13:16:39,548 INFO     emoncms    sending: http://10.1.0.53/emoncms/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 13:16:39,562 WARNING  emoncms    emoncms couldn't send to server, HTTPError: 406
2016-05-28 13:17:09,564 INFO     emoncms    sending: http://10.1.0.53/emoncms/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1464437829
2016-05-28 13:17:09,606 WARNING  emoncms    send failure: wanted 'ok' but got 'Error: Format error, json string supplied is not valid
'
2016-05-28 13:17:09,606 INFO     emoncms    sending: http://10.1.0.53/emoncms/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 13:17:09,621 WARNING  emoncms    emoncms couldn't send to server, HTTPError: 406
2016-05-28 13:17:39,642 INFO     emoncms    sending: http://10.1.0.53/emoncms/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1464437859
2016-05-28 13:17:39,682 WARNING  emoncms    send failure: wanted 'ok' but got 'Error: Format error, json string supplied is not valid
'
2016-05-28 13:17:39,682 INFO     emoncms    sending: http://10.1.0.53/emoncms/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 13:17:39,697 WARNING  emoncms    emoncms couldn't send to server, HTTPError: 406
2016-05-28 13:18:09,718 INFO     emoncms    sending: http://10.1.0.53/emoncms/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1464437889
2016-05-28 13:18:09,759 WARNING  emoncms    send failure: wanted 'ok' but got 'Error: Format error, json string supplied is not valid
'
2016-05-28 13:18:09,760 INFO     emoncms    sending: http://10.1.0.53/emoncms/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 13:18:09,774 WARNING  emoncms    emoncms couldn't send to server, HTTPError: 406
2016-05-28 13:18:39,733 INFO     emoncms    sending: http://10.1.0.53/emoncms/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1464437919
2016-05-28 13:18:39,772 WARNING  emoncms    send failure: wanted 'ok' but got 'Error: Format error, json string supplied is not valid
'
2016-05-28 13:18:39,772 INFO     emoncms    sending: http://10.1.0.53/emoncms/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 13:18:39,787 WARNING  emoncms    emoncms couldn't send to server, HTTPError: 406
2016-05-28 13:18:57,504 DEBUG    socketb    1 NEW FRAME : 33 50 101 40 63 109 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 24000 0 33 477 896 466 543 1997 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 24000 10 531 2
2016-05-28 13:18:57,505 DEBUG    socketb    1 Timestamp : 1464437937.5
2016-05-28 13:18:57,505 DEBUG    socketb    1 From Node : 33
2016-05-28 13:18:57,505 DEBUG    socketb    1    Values : [50, 101, 40, 63, 109, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 240, 0, 33, 477, 896, 466, 543, 1997, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 24000, 10, 531, 2]
2016-05-28 13:18:57,506 INFO     socketb    Publishing: emon/espmon01/ct01 50
2016-05-28 13:18:57,507 INFO     socketb    Publishing: emon/espmon01/ct02 101
2016-05-28 13:18:57,507 INFO     socketb    Publishing: emon/espmon01/ct03 40
2016-05-28 13:18:57,508 INFO     socketb    Publishing: emon/espmon01/ct04 63
2016-05-28 13:18:57,509 INFO     socketb    Publishing: emon/espmon01/ct05 109
2016-05-28 13:18:57,510 INFO     socketb    Publishing: emon/espmon01/ct06 0
2016-05-28 13:18:57,510 INFO     socketb    Publishing: emon/espmon01/ct07 0
2016-05-28 13:18:57,511 INFO     socketb    Publishing: emon/espmon01/ct08 0
2016-05-28 13:18:57,512 INFO     socketb    Publishing: emon/espmon01/ct09 0
2016-05-28 13:18:57,513 INFO     socketb    Publishing: emon/espmon01/ct10 0
2016-05-28 13:18:57,513 INFO     socketb    Publishing: emon/espmon01/ct11 0
2016-05-28 13:18:57,514 INFO     socketb    Publishing: emon/espmon01/ct12 0
2016-05-28 13:18:57,515 INFO     socketb    Publishing: emon/espmon01/ct13 0
2016-05-28 13:18:57,515 INFO     socketb    Publishing: emon/espmon01/ct14 0
2016-05-28 13:18:57,516 INFO     socketb    Publishing: emon/espmon01/ct15 0
2016-05-28 13:18:57,516 INFO     socketb    Publishing: emon/espmon01/ct16 0
2016-05-28 13:18:57,517 INFO     socketb    Publishing: emon/espmon01/vrms 240
2016-05-28 13:18:57,517 INFO     socketb    Publishing: emon/espmon01/time1 0
2016-05-28 13:18:57,518 INFO     socketb    Publishing: emon/espmon01/time2 33
2016-05-28 13:18:57,518 INFO     socketb    Publishing: emon/espmon01/counter 477
2016-05-28 13:18:57,519 INFO     socketb    Publishing: emon/espmon01/21 896
2016-05-28 13:18:57,519 INFO     socketb    Publishing: emon/espmon01/22 466
2016-05-28 13:18:57,520 INFO     socketb    Publishing: emon/espmon01/23 543
2016-05-28 13:18:57,520 INFO     socketb    Publishing: emon/espmon01/24 1997
2016-05-28 13:18:57,520 INFO     socketb    Publishing: emon/espmon01/25 0
2016-05-28 13:18:57,520 INFO     socketb    Publishing: emon/espmon01/26 0
2016-05-28 13:18:57,521 INFO     socketb    Publishing: emon/espmon01/27 0
2016-05-28 13:18:57,521 INFO     socketb    Publishing: emon/espmon01/28 0
2016-05-28 13:18:57,521 INFO     socketb    Publishing: emon/espmon01/29 0
2016-05-28 13:18:57,522 INFO     socketb    Publishing: emon/espmon01/30 0
2016-05-28 13:18:57,522 INFO     socketb    Publishing: emon/espmon01/31 0
2016-05-28 13:18:57,524 INFO     socketb    Publishing: emon/espmon01/32 0
2016-05-28 13:18:57,525 INFO     socketb    Publishing: emon/espmon01/33 0
2016-05-28 13:18:57,525 INFO     socketb    Publishing: emon/espmon01/34 0
2016-05-28 13:18:57,525 INFO     socketb    Publishing: emon/espmon01/35 0
2016-05-28 13:18:57,526 INFO     socketb    Publishing: emon/espmon01/36 24000
2016-05-28 13:18:57,526 INFO     socketb    Publishing: emon/espmon01/37 10
2016-05-28 13:18:57,527 INFO     socketb    Publishing: emon/espmon01/38 531
2016-05-28 13:18:57,533 INFO     socketb    Publishing: emon/espmon01/39 2
2016-05-28 13:18:57,533 INFO     socketb    Publishing: emon/espmon01/rssi 0
2016-05-28 13:18:57,534 INFO     socketb    Publishing: emonhub/rx/33/values 50,101,40,63,109,0,0,0,0,0,0,0,0,0,0,0,240,0,33,477,896,466,543,1997,0,0,0,0,0,0,0,0,0,0,0,24000,10,531,2
2016-05-28 13:18:57,534 INFO     socketb    Publishing: emonhub/rx/33/rssi 0
2016-05-28 13:18:57,534 DEBUG    socketb    1 adding frame to buffer => [1464437937, 33, 50, 101, 40, 63, 109, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 240, 0, 33, 477, 896, 466, 543, 1997, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 24000, 10, 531, 2]
2016-05-28 13:18:57,534 DEBUG    socketb    1 Sent to channel' : ch1
2016-05-28 13:18:58,649 DEBUG    socketb    2 NEW FRAME : 33 128 237 120 157 408 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 24000 5 609 333 248 439 240 293 861 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 24000 4 539 4
2016-05-28 13:18:58,650 DEBUG    socketb    2 Timestamp : 1464437938.65
2016-05-28 13:18:58,650 DEBUG    socketb    2 From Node : 33
2016-05-28 13:18:58,650 DEBUG    socketb    2    Values : [128, 237, 120, 157, 408, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 240, 5, 609, 333, 248, 439, 240, 293, 861, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 24000, 4, 539, 4]
2016-05-28 13:18:58,650 INFO     socketb    Publishing: emon/espmon01/ct01 128
2016-05-28 13:18:58,651 INFO     socketb    Publishing: emon/espmon01/ct02 237
2016-05-28 13:18:58,651 INFO     socketb    Publishing: emon/espmon01/ct03 120
2016-05-28 13:18:58,651 INFO     socketb    Publishing: emon/espmon01/ct04 157
2016-05-28 13:18:58,651 INFO     socketb    Publishing: emon/espmon01/ct05 408
2016-05-28 13:18:58,652 INFO     socketb    Publishing: emon/espmon01/ct06 0
2016-05-28 13:18:58,652 INFO     socketb    Publishing: emon/espmon01/ct07 0
2016-05-28 13:18:58,652 INFO     socketb    Publishing: emon/espmon01/ct08 0
2016-05-28 13:18:58,653 INFO     socketb    Publishing: emon/espmon01/ct09 0
2016-05-28 13:18:58,653 INFO     socketb    Publishing: emon/espmon01/ct10 0
2016-05-28 13:18:58,653 INFO     socketb    Publishing: emon/espmon01/ct11 0
2016-05-28 13:18:58,653 INFO     socketb    Publishing: emon/espmon01/ct12 0
2016-05-28 13:18:58,653 INFO     socketb    Publishing: emon/espmon01/ct13 0
2016-05-28 13:18:58,653 INFO     socketb    Publishing: emon/espmon01/ct14 0
2016-05-28 13:18:58,654 INFO     socketb    Publishing: emon/espmon01/ct15 0
2016-05-28 13:18:58,654 INFO     socketb    Publishing: emon/espmon01/ct16 0
2016-05-28 13:18:58,654 INFO     socketb    Publishing: emon/espmon01/vrms 240
2016-05-28 13:18:58,655 INFO     socketb    Publishing: emon/espmon01/time1 5
2016-05-28 13:18:58,655 INFO     socketb    Publishing: emon/espmon01/time2 609
2016-05-28 13:18:58,655 INFO     socketb    Publishing: emon/espmon01/counter 333
2016-05-28 13:18:58,655 INFO     socketb    Publishing: emon/espmon01/21 248
2016-05-28 13:18:58,655 INFO     socketb    Publishing: emon/espmon01/22 439
2016-05-28 13:18:58,656 INFO     socketb    Publishing: emon/espmon01/23 240
2016-05-28 13:18:58,656 INFO     socketb    Publishing: emon/espmon01/24 293
2016-05-28 13:18:58,656 INFO     socketb    Publishing: emon/espmon01/25 861
2016-05-28 13:18:58,656 INFO     socketb    Publishing: emon/espmon01/26 0
2016-05-28 13:18:58,656 INFO     socketb    Publishing: emon/espmon01/27 0
2016-05-28 13:18:58,656 INFO     socketb    Publishing: emon/espmon01/28 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/29 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/30 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/31 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/32 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/33 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/34 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/35 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/36 0
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/37 24000
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/38 4
2016-05-28 13:18:58,657 INFO     socketb    Publishing: emon/espmon01/39 539
2016-05-28 13:18:58,658 INFO     socketb    Publishing: emon/espmon01/40 4
2016-05-28 13:18:58,658 INFO     socketb    Publishing: emon/espmon01/rssi 0
2016-05-28 13:18:58,658 INFO     socketb    Publishing: emonhub/rx/33/values 128,237,120,157,408,0,0,0,0,0,0,0,0,0,0,0,240,5,609,333,248,439,240,293,861,0,0,0,0,0,0,0,0,0,0,0,24000,4,539,4
2016-05-28 13:18:58,658 INFO     socketb    Publishing: emonhub/rx/33/rssi 0
2016-05-28 13:18:58,658 DEBUG    socketb    2 adding frame to buffer => [1464437938, 33, 128, 237, 120, 157, 408, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 240, 5, 609, 333, 248, 439, 240, 293, 861, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 24000, 4, 539, 4]
2016-05-28 13:18:58,658 DEBUG    socketb    2 Sent to channel' : ch1
2016-05-28 13:18:59,765 DEBUG    socketb    3 NEW FRAME : 33 0 0 0 033 509 887 501 578 1855 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 24000 0 512 6
2016-05-28 13:18:59,766 DEBUG    socketb    3 Timestamp : 1464437939.77
2016-05-28 13:18:59,766 DEBUG    socketb    3 From Node : 33
2016-05-28 13:18:59,766 DEBUG    socketb    3    Values : [0, 0, 0, 33, 509, 887, 501, 578, 1855, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 24000, 0, 512, 6]
2016-05-28 13:18:59,767 INFO     socketb    Publishing: emon/espmon01/ct01 0
2016-05-28 13:18:59,768 INFO     socketb    Publishing: emon/espmon01/ct02 0
2016-05-28 13:18:59,768 INFO     socketb    Publishing: emon/espmon01/ct03 0
2016-05-28 13:18:59,769 INFO     socketb    Publishing: emon/espmon01/ct04 33
2016-05-28 13:18:59,770 INFO     socketb    Publishing: emon/espmon01/ct05 509
2016-05-28 13:18:59,770 INFO     socketb    Publishing: emon/espmon01/ct06 887
2016-05-28 13:18:59,770 INFO     socketb    Publishing: emon/espmon01/ct07 501
2016-05-28 13:18:59,771 INFO     socketb    Publishing: emon/espmon01/ct08 578
2016-05-28 13:18:59,772 INFO     socketb    Publishing: emon/espmon01/ct09 1855
2016-05-28 13:18:59,772 INFO     socketb    Publishing: emon/espmon01/ct10 0
2016-05-28 13:18:59,772 INFO     socketb    Publishing: emon/espmon01/ct11 0
2016-05-28 13:18:59,773 INFO     socketb    Publishing: emon/espmon01/ct12 0
2016-05-28 13:18:59,774 INFO     socketb    Publishing: emon/espmon01/ct13 0
2016-05-28 13:18:59,774 INFO     socketb    Publishing: emon/espmon01/ct14 0
2016-05-28 13:18:59,774 INFO     socketb    Publishing: emon/espmon01/ct15 0
2016-05-28 13:18:59,775 INFO     socketb    Publishing: emon/espmon01/ct16 0
2016-05-28 13:18:59,776 INFO     socketb    Publishing: emon/espmon01/vrms 0
2016-05-28 13:18:59,776 INFO     socketb    Publishing: emon/espmon01/time1 0
2016-05-28 13:18:59,776 INFO     socketb    Publishing: emon/espmon01/time2 0
2016-05-28 13:18:59,777 INFO     socketb    Publishing: emon/espmon01/counter 0
2016-05-28 13:18:59,778 INFO     socketb    Publishing: emon/espmon01/21 24000
2016-05-28 13:18:59,778 INFO     socketb    Publishing: emon/espmon01/22 0
2016-05-28 13:18:59,778 INFO     socketb    Publishing: emon/espmon01/23 512
2016-05-28 13:18:59,778 INFO     socketb    Publishing: emon/espmon01/24 6
2016-05-28 13:18:59,778 INFO     socketb    Publishing: emon/espmon01/rssi 0
2016-05-28 13:18:59,779 INFO     socketb    Publishing: emonhub/rx/33/values 0,0,0,33,509,887,501,578,1855,0,0,0,0,0,0,0,0,0,0,0,24000,0,512,6
2016-05-28 13:18:59,779 INFO     socketb    Publishing: emonhub/rx/33/rssi 0
2016-05-28 13:18:59,780 DEBUG    socketb    3 adding frame to buffer => [1464437939, 33, 0, 0, 0, 33, 509, 887, 501, 578, 1855, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 24000, 0, 512, 6]
2016-05-28 13:18:59,780 DEBUG    socketb    3 Sent to channel' : ch1
2016-05-28 13:19:00,980 DEBUG    socketb    4 NEW FRAME : 33 128 237 120 15733 440 746 432 503 1549 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 24000 4 517 8
2016-05-28 13:19:00,980 DEBUG    socketb    4 Timestamp : 1464437940.98
2016-05-28 13:19:00,980 DEBUG    socketb    4 From Node : 33
2016-05-28 13:19:00,980 DEBUG    socketb    4    Values : [128, 237, 120, 15733, 440, 746, 432, 503, 1549, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 24000, 4, 517, 8]
2016-05-28 13:19:00,980 INFO     socketb    Publishing: emon/espmon01/ct01 128
2016-05-28 13:19:00,980 INFO     socketb    Publishing: emon/espmon01/ct02 237
2016-05-28 13:19:00,981 INFO     socketb    Publishing: emon/espmon01/ct03 120
2016-05-28 13:19:00,981 INFO     socketb    Publishing: emon/espmon01/ct04 15733
2016-05-28 13:19:00,981 INFO     socketb    Publishing: emon/espmon01/ct05 440
2016-05-28 13:19:00,981 INFO     socketb    Publishing: emon/espmon01/ct06 746
2016-05-28 13:19:00,981 INFO     socketb    Publishing: emon/espmon01/ct07 432
2016-05-28 13:19:00,981 INFO     socketb    Publishing: emon/espmon01/ct08 503
2016-05-28 13:19:01,036 INFO     socketb    Publishing: emon/espmon01/ct09 1549
2016-05-28 13:19:01,036 INFO     socketb    Publishing: emon/espmon01/ct10 0
2016-05-28 13:19:01,036 INFO     socketb    Publishing: emon/espmon01/ct11 0
2016-05-28 13:19:01,036 INFO     socketb    Publishing: emon/espmon01/ct12 0
2016-05-28 13:19:01,036 INFO     socketb    Publishing: emon/espmon01/ct13 0
2016-05-28 13:19:01,036 INFO     socketb    Publishing: emon/espmon01/ct14 0
2016-05-28 13:19:01,036 INFO     socketb    Publishing: emon/espmon01/ct15 0
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/ct16 0
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/vrms 0
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/time1 0
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/time2 0
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/counter 0
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/21 24000
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/22 4
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/23 517
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/24 8
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emon/espmon01/rssi 0
2016-05-28 13:19:01,037 INFO     socketb    Publishing: emonhub/rx/33/values 128,237,120,15733,440,746,432,503,1549,0,0,0,0,0,0,0,0,0,0,0,24000,4,517,8
2016-05-28 13:19:01,079 INFO     socketb    Publishing: emonhub/rx/33/rssi 0
2016-05-28 13:19:01,079 DEBUG    socketb    4 adding frame to buffer => [1464437940, 33, 128, 237, 120, 15733, 440, 746, 432, 503, 1549, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 24000, 4, 517, 8]
2016-05-28 13:19:01,079 DEBUG    socketb    4 Sent to channel' : ch1
2016-05-28 13:19:01,385 WARNING  MainThread socketb thread is dead
...
2016-05-28 13:19:09,678 WARNING  MainThread socketb thread is dead
2016-05-28 13:19:09,780 INFO     emoncms    sending: http://10.1.0.53/emoncms/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1464437937,33,50,101,40,63,109,0,0,0,0,0,0,0,0,0,0,0,240,0,33,477,896,466,543,1997,0,0,0,0,0,0,0,0,0,0,0,24000,10,531,2],[1464437938,33,128,237,120,157,408,0,0,0,0,0,0,0,0,0,0,0,240,5,609,333,248,439,240,293,861,0,0,0,0,0,0,0,0,0,0,0,24000,4,539,4],[1464437939,33,0,0,0,33,509,887,501,578,1855,0,0,0,0,0,0,0,0,0,0,0,24000,0,512,6],[1464437940,33,128,237,120,15733,440,746,432,503,1549,0,0,0,0,0,0,0,0,0,0,0,24000,4,517,8]]&sentat=1464437949
2016-05-28 13:19:09,901 WARNING  MainThread socketb thread is dead
2016-05-28 13:19:09,902 DEBUG    emoncms    acknowledged receipt with 'ok' from http://10.1.0.53/emoncms
2016-05-28 13:19:09,902 INFO     emoncms    sending: http://10.1.0.53/emoncms/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-05-28 13:19:09,910 WARNING  emoncms    emoncms couldn't send to server, HTTPError: 406
2016-05-28 13:19:10,108 WARNING  MainThread socketb thread is dead
... the above line repeats frequently

2016-05-28 13:19:23,006 DEBUG    MainThread SIGINT received.
2016-05-28 13:19:23,007 INFO     MainThread Exiting hub...
2016-05-28 13:19:23,157 INFO     MainThread Exit completed

#######################################################################
#######################      emonhub.conf     #########################
#######################################################################

## **LEGACY CONFIG: For use with 17thJune2015 emonPi/emonBase image and older **
## (check image version by looking for file in /boot)
## Uses old CSV MQTT topic structure compatible with Emoncms Nodes
## Does not use MQTT server authentication

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

[hub]
### loglevel must be one of DEBUG, INFO, WARNING, ERROR, and CRITICAL
loglevel = DEBUG #(default:WARNING)
### 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 modules
#    [[[runtimesettings]]]
#        pubchannels = ToEmonCMS,
#        subchannels = ToRFM12,
#
#        group = 210
#        frequency = 433
#        baseid = 5                              # 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)



[[socketb]]
    Type = EmonHubSocketInterfacer
    [[[init_settings]]]
        port_nb = 51014
    [[[runtimesettings]]]
#        timestamped = false


[[MQTT]]

    Type = EmonHubMqttInterfacer
    [[[init_settings]]]
        mqtt_host = 10.1.0.53
        mqtt_port = 1883
        mqtt_user = ''
        mqtt_passwd = ''

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

        # 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/

[[emoncms]]
    Type = EmonHubEmoncmsHTTPInterfacer
    [[[init_settings]]]
    [[[runtimesettings]]]
        pubchannels = ToRFM12,ch1,espmon01
        subchannels = ToEmonCMS,ch1,espmon01
        url = http://10.1.0.53/emoncms
        apikey = 
        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

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

[[33]]
    nodename = espmon01
    [[[rx]]]
       names = ct01,ct02,ct03,ct04,ct05,ct06,ct07,ct08,ct09,ct10,ct11,ct12,ct13,ct14,ct15,ct16,vrms,time1,time2,counter
       scales = 1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,0.01,1,1,1
       units = W,W,W,W,W,W,W,W,W,W,W,W,W,W,W,W,V,ms,ms,p

Thanks for sharing your logs too, it would look like the same thing is happening here, looking at the “thread name” column it starts off on the “MainThread” creating all the other interfacers which should each be on thier own thread.

It moves on to the “MQTT” thread and connects to the MQTT server etc. Moves on to the “emoncms” thread and reports some send errors.

When a packet arrives via a socket the “socketb” thread parses it ok and then tries to publish it, that is not right, it should be the MQTT thread that publishes it. It then apparently remains on that thread till the “MainThread” detects the “socketb” thread has disappeared.

Another odd observation is that nothing appears to be logged from the "emoncms" thread after it locks into the "socketb" thread and then once the "socketb" thread is dead the "emoncms" thread kicks in again and has a multi packet payload the first off which is 12 secs old and originates from when the "socketb" entries started. Just noticed there is also a 18sec gap immediately prior to the first "socketb" frame too. I think the only conclusion I can draw from this 1st brief look is that is is not likely to be the RFM2Pi interfacer since the socket interfacer does it to, at first glance It seems to be the MQTT interfacer at fault but I cannot rule out the emoncmshttp interfacer playing a part in it as I cannot tell if the pause of the "emoncms" thread is cause or effect of the odd MQTT interfacer behavior. Actually now I think about it the emoncmshttp interfacer only sends every 30secs so it may just be coincidence, In Dave's log it appears there is a log entry from the "emoncmsorg" thread in the middle of the run of "RFM2Pi" messages.

EDIT - Ignore all I said about the emoncms thread, it does actually make some sense there is an 18 sec gap after the http errors at startup before the first data frame lands at “socketb” the 12 secs later, coincidently after the “socketb” thread has died it sends the data to emoncms, 18sec gap + 12secs of data = 30sec intervals !! so that was a red herring.

Hi Paul

I have to admit that your level of understanding is above me bit I think I get what your saying.

<QUOTE>

Actually now I think about it the emoncmshttp interfacer only sends every 30secs so it may just be coincidence, In Dave’s log it appears there is a log entry from the “emoncmsorg” thread in the middle of the run of “RFM2Pi” messages.

</QUOTE>

I have increased the posting rate as I has played about with emoncms installed on my Ubuntu server and I wanted the dashboard to update as quick as the emonpi.

Regards

Dave

PS Paul

If you feel it would be a benifit, please share the credentials between trusted members of the team.

via CloudMagic EmailOn Sat, May 28, 2016 at 2:56 PM, Paul <[email protected]> wrote:

pb66Paul

May 28

Thanks for sharing your logs too, it would look like the same thing is happening here, looking at the "thread name" column it starts off on the "MainThread" creating all the other interfacers which should each be on thier own thread.

It moves on to the "MQTT" thread and connects to the MQTT server etc. Moves on to the "emoncms" thread and reports some send errors.

When a packet arrives via a socket the "socketb" thread parses it ok and then tries to publish it, that is not right, it should be the MQTT thread that publishes it. It then apparently remains on that thread till the "MainThread" detects the "socketb" thread has disappeared.

Another odd observation is that nothing appears to be logged from the "emoncms" thread after it locks into the "socketb" thread and then once the "socketb" thread is dead the "emoncms" thread kicks in again and has a multi packet payload the first off which is 12 secs old and originates from when the "socketb" entries started.

Just noticed there is also a 18sec gap immediately prior to the first "socketb" frame too.

I think the only conclusion I can draw from this 1st brief look is that is is not likely to be the RFM2Pi interfacer since the socket interfacer does it to, at first glance It seems to be the MQTT interfacer at fault but I cannot rule out the emoncmshttp interfacer playing a part in it as I cannot tell if the pause of the "emoncms" thread is cause or effect of the odd MQTT interfacer behavior. Actually now I think about it the emoncmshttp interfacer only sends every 30secs so it may just be coincidence, In Dave's log it appears there is a log entry from the "emoncmsorg" thread in the middle of the run of "RFM2Pi" messages.


Visit Topic or reply to this email to respond


In Reply To

coldpenguinGareth

May 28Not intending to hijack, this is supplied in case it is useful to compare what might be a similar crash. Although the config file below is quite complete, in reality for this emonhub I only have node 33 configured, and the only items it should be communicating with are the emoncms server and MQTT (t…


Visit Topic or reply to this email to respond

To stop receiving notifications for this particular topic, click here. To unsubscribe from these emails, change your user preferences

I can feel myself being sucked into this in this and not being able to return to what I should be doing!! much like leaving a unfinished suduku or crossword.

I have just noticed some very peculiar stuff in Gareth’s emonhub.conf. In the [[emoncms]] settings you have

Which means the “emoncms” interfacer aka thread is pushing all it’s data out to 3 channels (internal to emonhub) named “ToEmonCMS”,“ch1” and “espmon01” two of which it is also pulling data from “ch1” and “espmon01” surely that cannot end well?

AND !!!

it seems the [[MQTT]] is doing exactly the same and to/from the same channels (listed in a v.slightly different order)

AND thats not even the weirdest bit!
It appears the “socketb” interfacer does none of this as there are no channels defined at all, I haven’t checked the code for defaults yet. The original"experimental" branch did have defaults so the channels didn’t need defining on a default setup but my “channels code” was all chopped away for the pub/sub library by Trystan…

EDIT - Ahh, ok! there are some defaults https://github.com/openenergymonitor/emonhub/blob/emon-pi/src/interfacers/emonhub_interfacer.py#L50 shows by default all interfacers will pub to “ch1” and sub to “ch2”.

The way the channels were originally intended to work was each channel had a “purpose” eg delivering data to emoncms or delivering data to the rfm2pi, lets call them “CMS” and “RFM” for the moment. any interfacers can send data to emoncms by pushing data onto “CMS” and any emoncms interfacers OR interfacers wanting a carbon copy of the data going to emoncms can pull data from “CMS”.

ditto for “RFM” and data going to the rfm2pi

So if you wanted to you could have a socket with pub RFM and any sockets arriving on that port would be transmitted out to the rfm network or alternatively (or additionally) you could have a second socket interfacer with pub CMS and any packets arriving on that port would get routed to emoncms. There is no point having any sub’s on a socket interfacer as it cannot send out of a socket.

You can sub or pub to multiple channels (or at least you could in the original code I haven’t tested this) so for example if the aim was to send the data recieved on a socket to both emoncms and the rfm2pi then just pub to RFM and CMS. this was intended to avoid throwing all data into one pot and then sending a copy of all out to all parties.

I think you should try and tidy up the channels and test again, where is what data supposed to be going and I will help you with the settings?

On reflection this maybe something completely different to Dave’s issue as what we may be seeing is a common end result for a multitude of sins, any bad data, poor config or genuine errors will cause the threads to crash as there is very little sanitation, filtering and fault handling.