Zero power readings in EmonCMS during the morning?

Vster · 23 October 2017 23:31

I’ve noticed some odd data in my EmonCMS data that’s been going on for a couple of months.
The power data from midnight until solar PV production starts is stored as zero on Emoncms,org.

Looking at the Emonhub console that data is correctly showing 170W, and this is correctly being fed to the MQTT server.
But the inputs on the emoncms.org website is showing zero, and all the other values calculated from it are therefore also zero. The other data in that packet is solar (currently 0), EV charge (also 0) and mains voltage 249V, oddly the mains voltage is being logged correctly. When the solar PV kicked in at 8:22am the power usage was then logged correctly.

I’ve not altered the Emoncms logging set up in a long while, but this started on the 17th August, sadly I’ve only just spotted it while tinkering with something else.

I’d have said this was an error on my part, but the EmonHub feed going out and the zero power logged on Emoncms would suggest it’s an issue at the emoncms end maybe?

pb66 · 24 October 2017 11:34

Where is this data coming from? is it an emonPi? I’m guessing not if you have 3 power readings.

The MQTT feeds data to the local emoncms not to emoncms.org so can you confirm if the data is correct on the local emoncms (if you’re using it) and whether the same packets are being sent to emoncms.org via HTTP(S) from emonhub?

You could attach an emonhub.log excerpt here.

Vster · 24 October 2017 17:35

Hi Paul,

It’s coming from a RasPi2 fitted with a RFM69Pi, feed from an EmonTX2, which monitors the power usage, solar generation and the EV charging. I’m not using a local emoncms (still on my list of things to do), the packets as you say are sent to emoncms.org. Dump dump from the Emonhub console below. Obviously this bit is working, but when I posted the original message after midnight, the first value in node 10 (the power from the EmonTX) still had valid data, despite the feed value on emoncms.org being zero. I can post another dump later if it’ll help?

Lee

2017-10-24 18:30:54,969 INFO     RFM12Pi    Publishing: emon/emontx/power1 273
2017-10-24 18:30:54,971 INFO     RFM12Pi    Publishing: emon/emontx/power2 0
2017-10-24 18:30:54,973 INFO     RFM12Pi    Publishing: emon/emontx/power3 0
2017-10-24 18:30:54,975 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24266
2017-10-24 18:30:54,977 INFO     RFM12Pi    Publishing: emon/emontx/rssi -74
2017-10-24 18:30:54,979 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 273,0,0,24266
2017-10-24 18:30:54,981 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -74
2017-10-24 18:30:54,983 DEBUG    RFM12Pi    55860 adding frame to buffer => [1508866254.96212, 10, 273, 0, 0, 24266, -74]
2017-10-24 18:30:54,984 DEBUG    RFM12Pi    55860 adding frame to buffer => [1508866254.96212, 10, 273, 0, 0, 24266, -74]
2017-10-24 18:30:54,985 DEBUG    RFM12Pi    55860 Sent to channel(end)' : ToEmonCMS
2017-10-24 18:31:00,652 DEBUG    RFM12Pi    55861 NEW FRAME : OK 10 15 1 0 0 0 0 238 94 (-75)
2017-10-24 18:31:00,655 DEBUG    RFM12Pi    55861 Timestamp : 1508866260.65
2017-10-24 18:31:00,656 DEBUG    RFM12Pi    55861 From Node : 10
2017-10-24 18:31:00,657 DEBUG    RFM12Pi    55861    Values : [271, 0, 0, 24302]
2017-10-24 18:31:00,657 DEBUG    RFM12Pi    55861      RSSI : -75
2017-10-24 18:31:00,658 DEBUG    RFM12Pi    55861 Sent to channel(start)' : ToEmonCMS
2017-10-24 18:31:00,660 INFO     RFM12Pi    Publishing: emon/emontx/power1 271
2017-10-24 18:31:00,661 INFO     RFM12Pi    Publishing: emon/emontx/power2 0
2017-10-24 18:31:00,663 INFO     RFM12Pi    Publishing: emon/emontx/power3 0
2017-10-24 18:31:00,665 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24302
2017-10-24 18:31:00,667 INFO     RFM12Pi    Publishing: emon/emontx/rssi -75
2017-10-24 18:31:00,669 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 271,0,0,24302
2017-10-24 18:31:00,671 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -75
2017-10-24 18:31:00,673 DEBUG    RFM12Pi    55861 adding frame to buffer => [1508866260.652418, 10, 271, 0, 0, 24302, -75]
2017-10-24 18:31:00,674 DEBUG    RFM12Pi    55861 adding frame to buffer => [1508866260.652418, 10, 271, 0, 0, 24302, -75]
2017-10-24 18:31:00,675 DEBUG    RFM12Pi    55861 Sent to channel(end)' : ToEmonCMS
2017-10-24 18:31:01,467 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1508866254.026672,16,1718,3729,-67],[1508866254.96212,10,273,0,0,24266,-74],[1508866260.652418,10,271,0,0,24302,-75]]&sentat=1508866261
2017-10-24 18:31:01,601 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2017-10-24 18:31:01,602 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y

Vster · 27 October 2017 00:25

And this is from the early morning…

2017-10-27 01:20:26,990 INFO     RFM12Pi    Publishing: emon/emontx/power1 171
2017-10-27 01:20:26,993 INFO     RFM12Pi    Publishing: emon/emontx/power2 0
2017-10-27 01:20:26,995 INFO     RFM12Pi    Publishing: emon/emontx/power3 2173
2017-10-27 01:20:26,997 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24566
2017-10-27 01:20:27,000 INFO     RFM12Pi    Publishing: emon/emontx/rssi -78
2017-10-27 01:20:27,003 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 171,0,2173,24566
2017-10-27 01:20:27,006 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -78
2017-10-27 01:20:27,009 DEBUG    RFM12Pi    105798 adding frame to buffer => [1509063626.98134, 10, 171, 0, 2173, 24566, -78]
2017-10-27 01:20:27,010 DEBUG    RFM12Pi    105798 adding frame to buffer => [1509063626.98134, 10, 171, 0, 2173, 24566, -78]
2017-10-27 01:20:27,012 DEBUG    RFM12Pi    105798 Sent to channel(end)' : ToEmonCMS
2017-10-27 01:20:29,583 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1509063621.281056,10,168,0,2177,24530,-77],[1509063626.98134,10,171,0,2173,24566,-78]]&sentat=1509063629
2017-10-27 01:20:29,723 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2017-10-27 01:20:29,724 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2017-10-27 01:20:32,763 DEBUG    RFM12Pi    105799 NEW FRAME : OK 10 167 0 0 0 133 8 4 96 (-76)
2017-10-27 01:20:32,765 DEBUG    RFM12Pi    105799 Timestamp : 1509063632.76
2017-10-27 01:20:32,766 DEBUG    RFM12Pi    105799 From Node : 10
2017-10-27 01:20:32,767 DEBUG    RFM12Pi    105799    Values : [167, 0, 2181, 24580]
2017-10-27 01:20:32,768 DEBUG    RFM12Pi    105799      RSSI : -76
2017-10-27 01:20:32,769 DEBUG    RFM12Pi    105799 Sent to channel(start)' : ToEmonCMS
2017-10-27 01:20:32,770 INFO     RFM12Pi    Publishing: emon/emontx/power1 167
2017-10-27 01:20:32,772 INFO     RFM12Pi    Publishing: emon/emontx/power2 0
2017-10-27 01:20:32,774 INFO     RFM12Pi    Publishing: emon/emontx/power3 2181
2017-10-27 01:20:32,776 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24580
2017-10-27 01:20:32,778 INFO     RFM12Pi    Publishing: emon/emontx/rssi -76
2017-10-27 01:20:32,779 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 167,0,2181,24580
2017-10-27 01:20:32,781 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -76
2017-10-27 01:20:32,784 DEBUG    RFM12Pi    105799 adding frame to buffer => [1509063632.763044, 10, 167, 0, 2181, 24580, -76]
2017-10-27 01:20:32,785 DEBUG    RFM12Pi    105799 adding frame to buffer => [1509063632.763044, 10, 167, 0, 2181, 24580, -76]
2017-10-27 01:20:32,786 DEBUG    RFM12Pi    105799 Sent to channel(end)' : ToEmonCMS

Vster · 27 October 2017 00:28

So in 90 mins I’ve used zero electricity (ignoring the car charging), that’s wrong, should be 220W-ish…

pb66 · 27 October 2017 01:11

Yeah the log looks right, around 167watts for 90mins should be almost 0.25 kWh.

What processing to you have set up? Can we see screenshots of the feeds and input pages?

When you say the inputs show zero on the inputs page, are the update times green and updating?

I assume the kWh values on your dash are based on power to kWh processes and feeds, correct?

What timezone are you in?

Vster · 28 October 2017 21:31

Hi Paul,
I’m in the UK, the processing to get to power is minimal, screenshot below. Everything looks like it’s working OK, then the inputs come in from EmonHub (as seen above), the updates happen as they should on Emoncms.org, but the power values are zero until (it looks like) some solar generation takes place.

This feed screen is before midnight, I can capture it again later if you want.

pb66 · 29 October 2017 13:05

Yep all looks fine as far as i can see. Maybe posting screen grabs whilst the fault is occurring with the matching emonhub.log might show something?

From what you say we are looking to see the input values (and subsequent processing) at zero whilst at the same time the emonhub.log showing the non-zero values being sent to emoncms and receipt acknowledged so please include the times of your screen dumps too.

Vster · 31 October 2017 07:33

Hi Paul,

Right, all screen shots taken a few minutes ago at 7:25am-ish…

2017-10-31 07:26:47,655 DEBUG    RFM12Pi    27571 Sent to channel(start)' : ToEmonCMS
2017-10-31 07:26:47,657 INFO     RFM12Pi    Publishing: emon/emontx/power1 656
2017-10-31 07:26:47,661 INFO     RFM12Pi    Publishing: emon/emontx/power2 0
2017-10-31 07:26:47,665 INFO     RFM12Pi    Publishing: emon/emontx/power3 0
2017-10-31 07:26:47,668 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24801
2017-10-31 07:26:47,670 INFO     RFM12Pi    Publishing: emon/emontx/rssi -85
2017-10-31 07:26:47,673 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 656,0,0,24801
2017-10-31 07:26:47,676 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -85
2017-10-31 07:26:47,679 DEBUG    RFM12Pi    27571 adding frame to buffer => [1509434807.644426, 10, 656, 0, 0, 24801, -85]
2017-10-31 07:26:47,680 DEBUG    RFM12Pi    27571 adding frame to buffer => [1509434807.644426, 10, 656, 0, 0, 24801, -85]
2017-10-31 07:26:47,682 DEBUG    RFM12Pi    27571 Sent to channel(end)' : ToEmonCMS
2017-10-31 07:26:48,233 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1509434801.155815,21,4412,2312,3693,-71],[1509434801.796248,10,663,0,0,24821,-83],[1509434807.644426,10,656,0,0,24801,-85]]&sentat=1509434808
2017-10-31 07:26:48,356 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2017-10-31 07:26:48,357 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2017-10-31 07:26:53,332 DEBUG    RFM12Pi    27572 NEW FRAME : OK 10 142 2 0 0 0 0 215 96 (-84)
2017-10-31 07:26:53,335 DEBUG    RFM12Pi    27572 Timestamp : 1509434813.33
2017-10-31 07:26:53,336 DEBUG    RFM12Pi    27572 From Node : 10
2017-10-31 07:26:53,337 DEBUG    RFM12Pi    27572    Values : [654, 0, 0, 24791]
2017-10-31 07:26:53,338 DEBUG    RFM12Pi    27572      RSSI : -84
2017-10-31 07:26:53,339 DEBUG    RFM12Pi    27572 Sent to channel(start)' : ToEmonCMS
2017-10-31 07:26:53,341 INFO     RFM12Pi    Publishing: emon/emontx/power1 654
2017-10-31 07:26:53,343 INFO     RFM12Pi    Publishing: emon/emontx/power2 0
2017-10-31 07:26:53,346 INFO     RFM12Pi    Publishing: emon/emontx/power3 0
2017-10-31 07:26:53,349 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24791
2017-10-31 07:26:53,352 INFO     RFM12Pi    Publishing: emon/emontx/rssi -84
2017-10-31 07:26:53,355 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 654,0,0,24791
2017-10-31 07:26:53,357 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -84
2017-10-31 07:26:53,360 DEBUG    RFM12Pi    27572 adding frame to buffer => [1509434813.332069, 10, 654, 0, 0, 24791, -84]
2017-10-31 07:26:53,362 DEBUG    RFM12Pi    27572 adding frame to buffer => [1509434813.332069, 10, 654, 0, 0, 24791, -84]
2017-10-31 07:26:53,363 DEBUG    RFM12Pi    27572 Sent to channel(end)' : ToEmonCMS

Not 100% sure where the odd glitches over are from, but I suspect they are spikes from the fridge.

pb66 · 31 October 2017 09:37

Can you post the rest of the emonhub.log or at least a larger piece of it?

Looking at the far right of the graph, we can see values of around zero and what could be about 650w are both recorded at times around 7.25’ish. That graph shows a short peak that has come to rest again and the time in the screenshot is 7:28.

The 2 input/feed screens showing zero’s are at 7:25/7:26 and the emonhub.log shows the power to be 654w for a period lasting 6secs at almost 7:27.

In this instance it doesn’t help that the approximate times are staggered across a transitional period, remember there are 6 packets per minute. Plus the graphing applies some cherry-picking and averaging to get 8640 datapoints across one ~900 point graph.

Can you provide the emonhub.log for the same period as the graph so we can see what values where being sent for the period leading up to the time of the screenshots? If the values in emonhub.log tie up with the graph it would suggest the problem is pre-emontx, IF the values do not obviously marry up with the graph, can you try again for some fresh screen grabs and logs whilst the system is CLEARLY at fault rather than at the cusp of correcting itself, that can be anytime between late at night(early am) when the fault starts and just before dawn (7:00/7:15)?

What we are trying to see here is whether the emontx (as seen in emonub.log) is or isn’t providing zero values when emoncms is clearly receiving/processing zero’s. Currently we only have the fact “it’s a bit odd” to substantiate anything is a miss, there is no actual evidence of any errors or contradicting data. I do believe it’s not right as I do not believe exactly 0w consumption is likely for that long and the timing from midnight’ish to sun up is significant too, but I cannot rule out that the data seen is being correctly sent and processed (ie an issue in the CT placement etc). The snippets of emonhub.log you have supplied showing snapshots of consumption at around 167w could just be one of those glitches you suspect is the fridge.

If you had your last cuppa at just after 11pm last night and then turned the TV and lights of at midnight as you went to bed, the graph is actually quite believable if your vampire drain was actually near zero, although unlikely the trace isn’t impossible to believe. Under 5a the CT’s are not overly accurate, a very small load could be lost, especially with the possibility of “phantom production” from a reactive inverter at rest to cancel out some consumption and/or no CT calibration. Not suggesting any of these are the case here (yet) just explaining why we need to be sure of what we are seeing.

Vster · 31 October 2017 14:04

Hi Paul,

I’ve just remoted into the Pi, but of course the logs have rotated out and disappeared.
I’ll have another crack at it tomorrow morning, with the full log attached.
Thanks for continued help and patience!

Lee

Vster · 2 November 2017 08:06

Hi Paul,

Right how about this then…

I was a little late, so breakfast has got underway and solar production has just kicked in…

But here are the last three hours of logs, which seem to show a small amount of usage is being radioed in OK, published to MQTT and sent off to Emoncms.org…

emonhub.log.txt (944.7 KB)
emonhub.log.1.txt (1.3 MB)
emonhub.log.2.txt (1.3 MB)

pb66 · 2 November 2017 10:47

This doesn’t really show us anything new nor does it confirm that the input was zero at the same time there was valid data being passed from emonhub.

I can see no evidence of a significant change in the power value around 6:15 in emonhub to explain the spike seen in the graph. This would suggest the data is getting fudged within emoncms as the power data in emonhub is consistent throughout the transition from evening through night to dawn and the generation starting.

However I can also clearly see that the first believable data of the day starts around the time of the first “power2” non-zero value in emonhub.log (difficult to tell the exact time and values on the graph at that resolution, plus the graphing can skew datapoints slightly with averaging, rounding and fixed intervals).

This switch in power values that occurs when generation starts raises a question about the spike recorded at 6:15 because if power data is only recorded whilst there is generation, why was it perceived there was generation at 6:15? The emonhub.logs show no change in the power2 (solar) values at that time. Plus why does the power reading appear ok right up until midnight? Sun goes down a good 6hrs before that.

Whilst I have no real reason to dispute your findings that the inputs are at zero whilst good data is flowing from emonhub for power1, there is no real evidence here to that effect yet, even the zero input screen grabs from a couple of days ago could be explained away so they are inconclusive.

So far I have not been able to think of any way the inputs could be zeroed by emoncms if it is getting good data from emonhub, which leaves us with a possible processing issuewhich could be supported or disproved by catching the screen grabs whilst it is clearly faulting and data is good in emonhub.logs.

Another good debug tool would be to add a phptimeseries logtofeed right at the top (position 1) of the power1 inputs processing ahead of the current phpfina feed. Clearly label this as “power1_debugging” and do not reference it anywhere else in any processing, it can be deleted again once this is resolved.

Can you post copies of all your processinglists? Or check them all very thoroughly for any errors where you could be posting other data to that same feed (it is possible for multiple input processes to post to the same feed) and overruling the power1 values, something like this could explain why a generation affected value is recorded if the solar1 value is being replaced by a generation adjusted power1 value. which then, depending on the timing of the receipts and the fixed interval persistence could effect the value in 99% of cases, whilst allowing on or two unadjusted values to slip through, hence the spikes in the night.

A good test for he above, if we can not prove another way would be to switch off the emonTx node 10 for a couple of minutes sometime between midnight and sun up (whilst the system is faulting) and check the feeds page to ensure the power feed does not get updated by checking the “updated” value remains orange until the emonTx is back online. The time offline would need to be at least 2 or 3 times the update interval of your slowest updating device (emonTh at 60s? 2 to 3 mins) to be reasonably conclusive.

It might be a long shot but right now it’s all I have…

Vster · 2 November 2017 13:49

Hi Paul,

I’ve added the phptimeseries debug to the processing, a very good idea I’d not thought of! I’ll get some more screen grabs early tomorrow morning.

I’ve gone over all the processing (there is rather a lot of it) and the only place writing to the Node10:Power is the second from top line here, the rest is the bulk of the processing from the EmonTX.

This is the solar processing…

And this is the EV charger…

I can’t explain the 7:26.05 blip (below) either, but there is a clear correlation at 7:26.55 with the start of PV generation, on the graph and the new frame coming in at 7:27.01 on the log (more below).

 >    2017-11-02 07:26:50,113 DEBUG    RFM12Pi    71804 NEW FRAME : OK 10 165 0 0 0 0 0 61 97 (-75)
>     2017-11-02 07:26:50,116 DEBUG    RFM12Pi    71804 Timestamp : 1509607610.11
>     2017-11-02 07:26:50,117 DEBUG    RFM12Pi    71804 From Node : 10
>     2017-11-02 07:26:50,118 DEBUG    RFM12Pi    71804    Values : [165, 0, 0, 24893]
>     2017-11-02 07:26:50,119 DEBUG    RFM12Pi    71804      RSSI : -75
>     2017-11-02 07:26:50,120 DEBUG    RFM12Pi    71804 Sent to channel(start)' : ToEmonCMS
>     2017-11-02 07:26:50,121 INFO     RFM12Pi    Publishing: emon/emontx/power1 165
>     2017-11-02 07:26:50,124 INFO     RFM12Pi    Publishing: emon/emontx/power2 0
>     2017-11-02 07:26:50,127 INFO     RFM12Pi    Publishing: emon/emontx/power3 0
>     2017-11-02 07:26:50,129 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24893
>     2017-11-02 07:26:50,132 INFO     RFM12Pi    Publishing: emon/emontx/rssi -75
>     2017-11-02 07:26:50,134 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 165,0,0,24893
>     2017-11-02 07:26:50,137 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -75
>     2017-11-02 07:26:50,140 DEBUG    RFM12Pi    71804 adding frame to buffer => [1509607610.112931, 10, 165, 0, 0, 24893, -75]
>     2017-11-02 07:26:50,141 DEBUG    RFM12Pi    71804 adding frame to buffer => [1509607610.112931, 10, 165, 0, 0, 24893, -75]
>     2017-11-02 07:26:50,142 DEBUG    RFM12Pi    71804 Sent to channel(end)' : ToEmonCMS
>     2017-11-02 07:26:55,823 DEBUG    RFM12Pi    71805 NEW FRAME : OK 10 112 0 0 0 0 0 74 97 (-77)
>     2017-11-02 07:26:55,826 DEBUG    RFM12Pi    71805 Timestamp : 1509607615.82
>     2017-11-02 07:26:55,828 DEBUG    RFM12Pi    71805 From Node : 10
>     2017-11-02 07:26:55,830 DEBUG    RFM12Pi    71805    Values : [112, 0, 0, 24906]
>     2017-11-02 07:26:55,832 DEBUG    RFM12Pi    71805      RSSI : -77
>     2017-11-02 07:26:55,834 DEBUG    RFM12Pi    71805 Sent to channel(start)' : ToEmonCMS
>     2017-11-02 07:26:55,836 INFO     RFM12Pi    Publishing: emon/emontx/power1 112
>     2017-11-02 07:26:55,839 INFO     RFM12Pi    Publishing: emon/emontx/power2 0
>     2017-11-02 07:26:55,842 INFO     RFM12Pi    Publishing: emon/emontx/power3 0
>     2017-11-02 07:26:55,845 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24906
>     2017-11-02 07:26:55,847 INFO     RFM12Pi    Publishing: emon/emontx/rssi -77
>     2017-11-02 07:26:55,849 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 112,0,0,24906
>     2017-11-02 07:26:55,851 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -77
>     2017-11-02 07:26:55,854 DEBUG    RFM12Pi    71805 adding frame to buffer => [1509607615.823166, 10, 112, 0, 0, 24906, -77]
>     2017-11-02 07:26:55,855 DEBUG    RFM12Pi    71805 adding frame to buffer => [1509607615.823166, 10, 112, 0, 0, 24906, -77]
>     2017-11-02 07:26:55,856 DEBUG    RFM12Pi    71805 Sent to channel(end)' : ToEmonCMS
>     <snip>
>     2017-11-02 07:26:57,362 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1509607610.112931,10,165,0,0,24893,-75],[1509607615.823166,10,112,0,0,24906,-77],[1509607616.163777,22,1860,1880,6790,7500,3717,7144,-73]]&sentat=1509607617
>     2017-11-02 07:26:57,493 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
>     2017-11-02 07:26:57,494 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
>     <snip>
>     2017-11-02 07:27:01,600 DEBUG    RFM12Pi    71807 NEW FRAME : OK 10 115 0 16 0 0 0 74 97 (-77)
>     2017-11-02 07:27:01,603 DEBUG    RFM12Pi    71807 Timestamp : 1509607621.6
>     2017-11-02 07:27:01,604 DEBUG    RFM12Pi    71807 From Node : 10
>     2017-11-02 07:27:01,605 DEBUG    RFM12Pi    71807    Values : [115, 16, 0, 24906]
>     2017-11-02 07:27:01,606 DEBUG    RFM12Pi    71807      RSSI : -77
>     2017-11-02 07:27:01,607 DEBUG    RFM12Pi    71807 Sent to channel(start)' : ToEmonCMS
>     2017-11-02 07:27:01,608 INFO     RFM12Pi    Publishing: emon/emontx/power1 115
>     2017-11-02 07:27:01,610 INFO     RFM12Pi    Publishing: emon/emontx/power2 16
>     2017-11-02 07:27:01,613 INFO     RFM12Pi    Publishing: emon/emontx/power3 0
>     2017-11-02 07:27:01,615 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24906
>     2017-11-02 07:27:01,617 INFO     RFM12Pi    Publishing: emon/emontx/rssi -77
>     2017-11-02 07:27:01,619 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 115,16,0,24906
>     2017-11-02 07:27:01,621 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -77
>     2017-11-02 07:27:01,624 DEBUG    RFM12Pi    71807 adding frame to buffer => [1509607621.599975, 10, 115, 16, 0, 24906, -77]
>     2017-11-02 07:27:01,626 DEBUG    RFM12Pi    71807 adding frame to buffer => [1509607621.599975, 10, 115, 16, 0, 24906, -77]
>     2017-11-02 07:27:01,627 DEBUG    RFM12Pi    71807 Sent to channel(end)' : ToEmonCMS
>     2017-11-02 07:27:04,320 DEBUG    RFM12Pi    71808 NEW FRAME : OK 16 95 6 145 14 (-66)
>     2017-11-02 07:27:04,323 DEBUG    RFM12Pi    71808 Timestamp : 1509607624.32
>     2017-11-02 07:27:04,324 DEBUG    RFM12Pi    71808 From Node : 16
>     2017-11-02 07:27:04,325 DEBUG    RFM12Pi    71808    Values : [1631, 3729]
>     2017-11-02 07:27:04,326 DEBUG    RFM12Pi    71808      RSSI : -66
>     2017-11-02 07:27:04,327 DEBUG    RFM12Pi    71808 Sent to channel(start)' : ToEmonCMS
>     <snip>
>     2017-11-02 07:27:07,310 DEBUG    RFM12Pi    71809 NEW FRAME : OK 10 111 0 15 0 0 0 90 97 (-77)
>     2017-11-02 07:27:07,313 DEBUG    RFM12Pi    71809 Timestamp : 1509607627.31
>     2017-11-02 07:27:07,314 DEBUG    RFM12Pi    71809 From Node : 10
>     2017-11-02 07:27:07,315 DEBUG    RFM12Pi    71809    Values : [111, 15, 0, 24922]
>     2017-11-02 07:27:07,316 DEBUG    RFM12Pi    71809      RSSI : -77
>     2017-11-02 07:27:07,317 DEBUG    RFM12Pi    71809 Sent to channel(start)' : ToEmonCMS
>     2017-11-02 07:27:07,319 INFO     RFM12Pi    Publishing: emon/emontx/power1 111
>     2017-11-02 07:27:07,321 INFO     RFM12Pi    Publishing: emon/emontx/power2 15
>     2017-11-02 07:27:07,323 INFO     RFM12Pi    Publishing: emon/emontx/power3 0
>     2017-11-02 07:27:07,325 INFO     RFM12Pi    Publishing: emon/emontx/vrms 24922
>     2017-11-02 07:27:07,327 INFO     RFM12Pi    Publishing: emon/emontx/rssi -77
>     2017-11-02 07:27:07,330 INFO     RFM12Pi    Publishing: emonhub/rx/10/values 111,15,0,24922
>     2017-11-02 07:27:07,332 INFO     RFM12Pi    Publishing: emonhub/rx/10/rssi -77
>     2017-11-02 07:27:07,334 DEBUG    RFM12Pi    71809 adding frame to buffer => [1509607627.310431, 10, 111, 15, 0, 24922, -77]
>     2017-11-02 07:27:07,336 DEBUG    RFM12Pi    71809 adding frame to buffer => [1509607627.310431, 10, 111, 15, 0, 24922, -77]
>     2017-11-02 07:27:07,336 DEBUG    RFM12Pi    71809 Sent to channel(end)' : ToEmonCMS
>     2017-11-02 07:27:07,407 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1509607621.599975,10,115,16,0,24906,-77],[1509607624.320342,16,1631,3729,-66],[1509607627.310431,10,111,15,0,24922,-77]]&sentat=1509607627
>     2017-11-02 07:27:07,573 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
>     2017-11-02 07:27:07,575 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y

pb66 · 2 November 2017 16:33

I hear what you’re saying but the “blip” contradicts that “correlation”, that one graph both supports and questions the theory that power1 is dependent on there being generation, plus the issue doesn’t appear until midnight, perhaps you could look closer at the time it start faulting just in case the “sun up” is a red herring. What is the data doing each side of midnight? I doubt there will be any evidence of any generation and yet will power1 “just stop”? Is there any significance in that time of day? Does your inverter go into a deep sleep 6 hours after sun down? What are the inputs doing at midnight? do they just stop updating and go from green to orange?

Vster · 3 November 2017 00:47

Hi Paul,

All fair points. Pictures below. The data drops out at 23:57, the only significance of this is that I reset the consumption & generation totals, in NodeRed, which is not connected to the Power1 reading. Odd.
The phptimeseries drops out just like the Power1, inferring it’s not being overwritten by something else?
While there should not be any generation, there were odd blips in the output from the EmonTX, so it has code in the AVR to ignore anything less than 15W production which got rid of most of the over night blips.
The inverter is nearly 7 years old and this behaviour is only two months old, the inference is that it’s in the code at my end or maybe at emoncms.org. Nothing seems to change in the input around midnight, and they all stay green.

pb66 · 3 November 2017 07:40

Looks like the screen grabs were taken about 00:22’ish (perhaps it would be a good idea to keep the PC clock in the screenshot) , did you keep the emonhub.logs for that period?

So what we are actually looking at is not a power1 that replies upon generation, since power1 continues to log correctly past sun down and up to the time the feeds are reset.

What are actually looking for is the reason behind power1 dropping to zero for a period that starts with the feeds being reset by nodered and ends at the first sign of any generation being recorded. That is indeed very odd!

Can you also include screen grabs of the reset inputs and processing. I can’t help you check nodered as I do not use it, but we can check what is actually arriving and happening at emoncms.

Personally I wouldn’t use nodered for this purpose, I would simply enable a socketinterfacer in emonhub and have a single line cron entry to send the zeroing payload to that socket. The obvious benefit in this instance would be that the reset payload would also be logged in emonhub so you could see the datapoints timeline.

Correct. But having the phptimeseries feed is also about being able to compare the time and values of each received datapoint for that input to compare against the emonhub.log to see if anything funky is happening with the timestamps or values missing etc. It looks like your emonTX sends about every 5.75 secs, which will result in null datapoints in a 5s phpfina or dropped values in a 10s phpfina. What sizes are you using?

The search continues…

Vster · 3 November 2017 08:25

Paul,
Oops, yes I downloaded the emonhublog, but forgot to attach it.

emonhub.log.1.txt (1.3 MB)

As for the code, you can see Contot & Gentot also being logged under Node10. They are the cumulative Consumpution Total and Generated Total of the the electricity for the given day, hence being zeroed at midnight. Apart from the values of both being stored in Node10, there’s no interaction between them, the value for Power1/Power2 come into NodeRed from MQTT and they’re totalled up during the day. The reset code is below.

Can you point me to a example of using the socket interfacer reset? I’m OK with crontab/bash, it’s the the mechanics I’ve not seen before.

As for the processing of Contot & Gentot -

Which is basically this -

// Just for reference all the calcs are done here due to timing issues with data turning up on two difference MQTT queues
// the power1/power2 values get out of step and produce odd results.

// initialise power2 to 0 if it doesn’t exist already
var power2 = msg.payload;
var gentot = flow.get(‘gentot’)||0; // generation total (for the day so far)
var gen_ts = flow.get(‘gen_ts’)||0; // generation timestamp of last reading
var contot = flow.get(‘contot’)||0; // consumption total (for the day so far) or 0 if not set
var con_ts = flow.get(‘con_ts’)||0; // consumption timestamp of last read or 0 if not set
var now_ts = Math.round(+new Date()); // now timestamp

var power1 = flow.get(‘power1’)||0; // get power1
if (power1 === 0) {power1 = 1; } // match the old system

if (gen_ts === 0) { // no previous gen timestamp
flow.set(‘gentot’,0);
flow.set(‘gen_ts’,now_ts);
flow.set(‘power2’,power2);
} else {
var diff = (now_ts - gen_ts) / 1000; // time since last reading in seconds
gentot = gentot + (power2 / 3600 * diff); // increase the consumption total by the watts * seconds
gentot = (Math.round(gentot*100))/100; // trim to 2dp
flow.set(‘gentot’,gentot);
flow.set(‘gen_ts’,now_ts);
flow.set(‘power2’,power2);
}

if (con_ts === 0) { // no previous consumption timestamp
var diff = 0;
flow.set(‘contot’,0);
flow.set(‘con_ts’,now_ts);
flow.set(‘power1’,power1);
flow.set(‘power1max’,power1);
flow.set(‘powerc’,0);
} else {
var powerc = parseInt(power1, 10) + parseInt(power2, 10); // Consumption power now (need to convert back from string to int in decimal)
flow.set(‘powerc’,powerc); // store for later
var diff = (now_ts - con_ts) / 1000; // time since last reading in seconds
var powinc = (powerc / 3600 * diff);
contot = contot + (powerc / 3600 * diff); // increase the consumption total by the watts * seconds
flow.set(‘contot’,contot);
flow.set(‘con_ts’,now_ts);
flow.set(‘power1’,power1);
}

// this section stores the max power usage - short spikes like kettles/toasters/microwave are missed from PVO graphing
// if you don’t like this remove this section. power1max is reset in the SetUpData function after POSTing
var power1max = flow.get(‘power1max’)||0;
if (powerc > power1max) {power1max = powerc; flow.set(‘power1max’,power1max); }

var timestamp = new Date();

var now = new Date();
var hour = now.getHours();
var minute = now.getMinutes();
var second = now.getSeconds();

//var msg1 = {“ConTot”: contot, “Power1”: power1, “Power2”: power2, " DiffTS": diff, “Power1max”: power1max, “PowerC”: powerc, “PowInc”: powinc, “GenTot”: gentot, “PowerA”: power1, “PowerB”: power2};
var msg1 = {payload: {“ConTot”: contot, “Power1”: power1, “Power2”: power2, “GenTot”: gentot } };
//var msg1 = { payload: {“PowA”:power1, “PowB”: power2, “Power1max”: power1max, “H”: hour, “M”: minute, “S”:second} };
var msg2 = { payload: powerc };

if (contot > 0) {
var msg3 = { payload: {“6”: contot} }; //send to emoncms - key 6 on node 10
} else { var msg3 = “”; }
if (gentot > 1) {
var msg4 = { payload: {“7”: gentot} }; //send to emoncms - key 7 on node 10
} else { var msg4 = “”; }

return [ msg1, msg2, msg3, msg4 ];

Which then get pushed out of the outputs and and sent to emoncms.org in the blue nodes.

pb66 · 3 November 2017 09:36

Well this casts a different light on things.

I’m afraid the nodered screenshots are wasted on me, I do not use nodered so without a crash course in it the screen do not mean anything.

IMO that’s just asking for trouble.

I think that remains to be seen…

Although I do not fully understand the nodered stuff, I can see in that last screenshot that the sending of the resets is attached to power2, so there could be a link between generation and the reseting code. I see there are lines like “if (gen_ts === 0)” which “gen_ts” would probably remain at zero from reset until sun up.

Armed with this new info I looked back at your input screen dumps and noticed that this one of the input at 07:25 shows the Power1 and Emontxcontot updates at 2s and the rest at 6s

https://community.openenergymonitor.org/uploads/default/original/2X/4/48bd2cf1dd64cc6a3ca0cb09713bc5b78173204c.png

to me that suggests the full packet was received 6s ago and the 1st and 6th inputs were received again 4s later, this will override the original values and since this overlap in time will not be fixed that could explain why some “blips” are recorded, that is when the phpfina interval falls between the original and the revised inputs, therefore saving the original value.

If you look at the raw phptimeseries CSV, I suspect you will see power1 will be alternating between the real value and zero Depending on the various update intervals)

I assume all the emoncms screenshots are from emoncms.org and that the data is coming from emonhub directly using http(s) and the resets from nodered via http(s) too, is that right?

Not offhand, I do not even recall if anyone has done this previously, but there are plenty of socketinterfacer threads with examples across the 2 forums (this one and the archived one).

If I get a chance I will try and locate one but if you search out and read a few of those threads it will better arm you to do what you want rather than be just giving you what I think you want.

A good place to start is to look at multi-tarriff support examples using a socket interfacer, that also uses a cronjob to send certain values at certain times. eg

58 23 * * * /bin/bash -c 'echo -e "99 0 \r" > /dev/tcp/localhost/50011'

would send a single zero value to node 99 (on both your local and remote emoncms instances) at 2 minuites to midnight and in that “Node 99” input 1’s process list you could just log2feed that one 0 to each feed that needs resetting.

No matter what method you use I strongly recommend moving your resetting out of node 10, that most likely both the cause of the issue and the reason you cannot see or debug it. If you had a separate “reset” node id/name the original node 10 may have been unaffected, but either way you would have seen the streams separately which is easier to debug.

Vster · 3 November 2017 09:38

Paul,
I missed a bit above, the Power1 is using a 10sec phpfina, and the 5.75 was the default firmware when I built the EmonTX kit. I’m not too fussed with dropped values as long as something gets logged. There’s a lot of data flying around the airwaves from the sensors I have spread around the house, and I have more planned