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
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
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
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.
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:
pb66PaulMay 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
coldpenguinGarethMay 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.