Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Power update via MQTT is not working as expected #17751

Closed
12 of 14 tasks
Civlo85 opened this issue Jan 20, 2023 · 33 comments
Closed
12 of 14 tasks

Power update via MQTT is not working as expected #17751

Civlo85 opened this issue Jan 20, 2023 · 33 comments
Labels
question Type - Asking for Information stale Action - Issue left behind - Used by the BOT to call for attention

Comments

@Civlo85
Copy link

Civlo85 commented Jan 20, 2023

PROBLEM DESCRIPTION

I want to send the actual Power consumption measured by my tasmota device via MQTT to my local broker. But it does not work as expected. I set up my "powerdelta" to 10 in order to get updates whenever my power consumption changes by 10%. That was the idea. When I look to the console output, I can see, that the trigger seems to work, but the value in the MQTT publish is wrong! It seems to be a little bit behind. How to solve this problem?

Please have a look at this console output:

I have attached my coffee machine to this device and want to measure the energy consumption of the boiler within the machine. Now the machine is pre-heated and just turns the boiler on and off to hold the temperature. We are in idle mode with an power soncumption of 6 Watts. Now lets look at the logs:

09:38:32.459 MQT: tele/MSD05/MARGINS = {"MARGINS":{"PowerDelta":1164}}
09:38:32.468 MQT: tele/MSD05/SENSOR = {"Time":"2023-01-20T09:38:32","ENERGY":{"TotalStartTime":"2022-12-21T21:21:11","Total":2.002,"Yesterday":1.097,"Today":0.302,"Power":42,"ApparentPower":42,"ReactivePower":0,"Factor":1.00,"Voltage":230,"Current":0.184}}

We see, that the "PowerDelta" seems to trigger. It detects an increase of 1164 Watts. So in total we should habe 1170 Watts. But when we look to the MQTT message, we see that a power consumption of only 42 Watts is transmitted! Why?

Ok, now lets wait until the boiler turns off again.

09:38:45.430 MQT: tele/MSD05/MARGINS = {"MARGINS":{"PowerDelta":-435}}
09:38:45.439 MQT: tele/MSD05/SENSOR = {"Time":"2023-01-20T09:38:45","ENERGY":{"TotalStartTime":"2022-12-21T21:21:11","Total":2.006,"Yesterday":1.097,"Today":0.307,"Power":727,"ApparentPower":1165,"ReactivePower":910,"Factor":0.62,"Voltage":228,"Current":5.104}}

09:38:46.418 MQT: tele/MSD05/MARGINS = {"MARGINS":{"PowerDelta":-721}}
09:38:46.425 MQT: tele/MSD05/SENSOR = {"Time":"2023-01-20T09:38:46","ENERGY":{"TotalStartTime":"2022-12-21T21:21:11","Total":2.006,"Yesterday":1.097,"Today":0.307,"Power":6,"ApparentPower":1178,"ReactivePower":1178,"Factor":0.01,"Voltage":231,"Current":5.104}}

Here we see two messages. First, a PowerDelta of -435 Watts was detected. So we should have something like 735 Watts. Via MQTT the transmitted message has 727 Watts. So thats somehow in the range. OK, for me.
Then a delta of -721 Watts was detected. So we should be at 6 Watts again when we take the power value from the MQTT message. And that is exactly what we see in the message output. So fine with that.

Lets wait untile the boiler turns on again.

09:40:00.458 MQT: tele/MSD05/MARGINS = {"MARGINS":{"PowerDelta":1165}}
09:40:00.468 MQT: tele/MSD05/SENSOR = {"Time":"2023-01-20T09:40:00","ENERGY":{"TotalStartTime":"2022-12-21T21:21:11","Total":2.007,"Yesterday":1.097,"Today":0.307,"Power":16,"ApparentPower":16,"ReactivePower":0,"Factor":1.00,"Voltage":230,"Current":0.071}}
09:40:14.451 MQT: tele/MSD05/MARGINS = {"MARGINS":{"PowerDelta":-1166}}
09:40:14.461 MQT: tele/MSD05/SENSOR = {"Time":"2023-01-20T09:40:14","ENERGY":{"TotalStartTime":"2022-12-21T21:21:11","Total":2.011,"Yesterday":1.097,"Today":0.311,"Power":6,"ApparentPower":1184,"ReactivePower":1184,"Factor":0.01,"Voltage":231,"Current":5.121}}

No we are looking at two triggers again. First one detects a delta of 1165 Watts. So we should be at 1171 Watts. But the message in MQTT transmitts only 16 Watts.
The second trigger detects -1166 Watts. So we should be at around 5 Watts. The message sends 6 Watts, so fine with that.

The error seems to be at the rising edge. The trigger detects that increase of power, but the value is not available in the MQTT message. Why that?

And that is what is being logged out of that. It does not reflect the truth and makes monitoring impossible.
screeny

REQUESTED INFORMATION

Make sure your have performed every step and checked the applicable boxes before submitting your issue. Thank you!

  • Read the Contributing Guide and Policy and the Code of Conduct
  • Searched the problem in issues
  • Searched the problem in discussions
  • Searched the problem in the docs
  • Searched the problem in the chat
  • Device used (e.g., Sonoff Basic): NOUS A1T, flashed with Tasmota 12.3.1
  • Tasmota binary firmware version number used: 12.3.1
    • Pre-compiled
    • Self-compiled
  • Flashing tools used: It came preflashed with Tasmota, so I used the tasmota OTA method
  • Provide the output of command: Backlog Template; Module; GPIO 255:
  Configuration output here:
  09:31:59.123 MQT: stat/MSD05/RESULT = {"NAME":"MSD05","GPIO":[32,0,0,0,2720,2656,0,0,2624,320,224,0,0,0],"FLAG":0,"BASE":49}
  09:31:59.350 MQT: stat/MSD05/RESULT = {"Module":{"0":"MSD05"}}
  09:31:59.603 MQT: stat/MSD05/RESULT = {"GPIO0":{"32":"Button1"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"2720":"BL0937 CF"},"GPIO5":{"2656":"HLWBL CF1"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"2624":"HLWBL SEL_i"},"GPIO13":{"320":"Led_i1"},"GPIO14":{"224":"Relay1"},"GPIO15":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"}}

  • If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:
  Rules output here:

  • Provide the output of this command: Status 0:
  STATUS 0 output here:
  09:33:06.613 MQT: stat/MSD05/STATUS = {"Status":{"Module":0,"DeviceName":"MSD05","FriendlyName":["MSD05"],"Topic":"MSD05","ButtonTopic":"0","Power":1,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0,"InfoRetain":0,"StateRetain":0,"StatusRetain":0}}
09:33:06.621 MQT: stat/MSD05/STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota/release/tasmota.bin.gz","RestartReason":"Software/System restart","Uptime":"0T20:55:42","StartupUTC":"2023-01-19T11:37:24","Sleep":50,"CfgHolder":4617,"BootCount":16,"BCResetTime":"2022-12-21T21:21:11","SaveCount":68,"SaveAddress":"FB000"}}
09:33:06.628 MQT: stat/MSD05/STATUS2 = {"StatusFWR":{"Version":"12.3.1(tasmota)","BuildDateTime":"2022-12-16T10:28:17","Boot":31,"Core":"2_7_4_9","SDK":"2.2.2-dev(38a443e)","CpuFrequency":80,"Hardware":"ESP8266EX","CR":"366/699"}}
09:33:06.635 MQT: stat/MSD05/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["Experimentelles Atomlabor",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["00008009","2805C80001000600003C5A0A192800000000","00000080","00006000","00004000","00000000"]}}
09:33:06.649 MQT: stat/MSD05/STATUS4 = {"StatusMEM":{"ProgramSize":629,"Free":372,"Heap":22,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"146085","FlashFrequency":40,"FlashMode":"DOUT","Features":["00000809","8F9AC787","04368001","000000CF","010013C0","C000F981","00004004","00001000","54000020","00000080"],"Drivers":"1,2,3,4,5,6,7,8,9,10,12,16,18,19,20,21,22,24,26,27,29,30,35,37,45,62","Sensors":"1,2,3,4,5,6"}}
09:33:06.657 MQT: stat/MSD05/STATUS5 = {"StatusNET":{"Hostname":"MSD05-1089","IPAddress":"192.168.178.82","Gateway":"192.168.178.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.178.2","DNSServer2":"0.0.0.0","Mac":"48:55:19:17:C4:41","Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":17.0}}
09:33:06.664 MQT: stat/MSD05/STATUS6 = {"StatusMQT":{"MqttHost":"mqtt.home.tounsi.de","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_17C441","MqttUser":"DVES_USER","MqttCount":1,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4}}
09:33:06.673 MQT: stat/MSD05/STATUS7 = {"StatusTIM":{"UTC":"2023-01-20T08:33:06","Local":"2023-01-20T09:33:06","StartDST":"2023-03-26T02:00:00","EndDST":"2023-10-29T03:00:00","Timezone":"+01:00","Sunrise":"08:34","Sunset":"17:27"}}
09:33:06.680 MQT: stat/MSD05/STATUS9 = {"StatusPTH":{"PowerDelta":[10,0,0],"PowerLow":0,"PowerHigh":0,"VoltageLow":0,"VoltageHigh":0,"CurrentLow":0,"CurrentHigh":0}}
09:33:06.691 MQT: stat/MSD05/STATUS10 = {"StatusSNS":{"Time":"2023-01-20T09:33:06","ENERGY":{"TotalStartTime":"2022-12-21T21:21:11","Total":1.987,"Yesterday":1.097,"Today":0.287,"Power":1167,"ApparentPower":1173,"ReactivePower":116,"Factor":1.00,"Voltage":229,"Current":5.130}}}
09:33:06.700 MQT: stat/MSD05/STATUS11 = {"StatusSTS":{"Time":"2023-01-20T09:33:06","Uptime":"0T20:55:42","UptimeSec":75342,"Heap":22,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"Experimentelles Atomlabor","BSSId":"2C:91:AB:5F:D5:1C","Channel":13,"Mode":"11n","RSSI":48,"Signal":-76,"LinkCount":1,"Downtime":"0T00:00:03"}}}

  • Set weblog to 4 and then, when you experience your issue, provide the output of the Console log:
  Console output here:

TO REPRODUCE

Nothing special here. It is not working the whole time.

EXPECTED BEHAVIOUR

I expect that the right values are being send via MQTT

SCREENSHOTS

See my error description.

ADDITIONAL CONTEXT

I want to track the power consumption of my coffee machine ;-)

(Please, remember to close the issue when the problem has been addressed)

@arendst arendst added the question Type - Asking for Information label Jan 29, 2023
@sfromis
Copy link
Contributor

sfromis commented Jan 29, 2023

What I'm doing is to issue an extra Status 10 shortly after significant jumps up/down to get a stable reading, instead of what could look like a transitory value across the short interval which the change occurred within, or something like that. This way, it works out nicely for me, and I did not look further into what happens with first SENSOR messages after the MARGINS.

@github-actions
Copy link

This issue has been automatically marked as stale because it hasn't any activity in last few weeks. It will be closed if no further activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the stale Action - Issue left behind - Used by the BOT to call for attention label Feb 23, 2023
@Civlo85
Copy link
Author

Civlo85 commented Feb 23, 2023

What I'm doing is to issue an extra Status 10 shortly after significant jumps up/down to get a stable reading, instead of what could look like a transitory value across the short interval which the change occurred within, or something like that. This way, it works out nicely for me, and I did not look further into what happens with first SENSOR messages after the MARGINS.

Could you take it a bit further? I am not sure if I understood correctly. You mean you type status 10 into the console? I don't get the effect.

@sfromis
Copy link
Contributor

sfromis commented Feb 23, 2023

While I could type it into the console, doing it manually is very impractical. I created a small bot publishing the command after a short delay (3 seconds, I think). That causes Tasmota to generate a payload with the same data as found in the telemetry SENSOR payload. Note that this depends on my automation taking this extra payload into account.

@github-actions github-actions bot removed the stale Action - Issue left behind - Used by the BOT to call for attention label Feb 23, 2023
@AleXSR700
Copy link
Contributor

Out of curiosity @Civlo85 :
When the boiler turns on, do you see the correct value on the Tasmota main web ui page?
And if you set weblog 4, do you see it in console as non broadcasted value?

@Civlo85
Copy link
Author

Civlo85 commented Mar 2, 2023 via email

@barbudor
Copy link
Contributor

barbudor commented Mar 2, 2023

If you see values that makes sense in the console as in the SENSOR message then that is exactly what is published on mqtt.
Is MQTT working for other things like STATE message or sending commands to Tasmota.
What do you see at the start of the SENSOR message in the console after the timestamp?
Is that MQT or RSL?
Are you using ACL on your broker that would prevent Tasmota from publishing on some topics?

@github-actions github-actions bot added the stale Action - Issue left behind - Used by the BOT to call for attention label Mar 27, 2023
@github-actions
Copy link

github-actions bot commented Apr 1, 2023

This issue was automatically closed because of being stale. Feel free to open a new one if you still experience this problem.

@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Apr 1, 2023
@Boerny41
Copy link

Boerny41 commented Apr 28, 2023

Hi @Civlo85,

have you found a solution? I have the same problem and I'm not a fan of creating a bot that forces more mqtt messages just to get around a bug.

In the last message you can see that it sent "Power: 15" when it should have sent "Power: 37". The web interface also showed 37.

`16:55:50.462 MQT: tele/tasmota_A1T_1/SENSOR = {"Time":"2023-04-28T16:55:50","ENERGY":{"TotalStartTime":"2023-04-28T15:46:08","Total":0.017,"Yesterday":0.000,"Today":0.017,"Power":0,"ApparentPower":0,"ReactivePower":0,"Factor":0.00,"Voltage":0,"Current":0.039}}

16:55:52.436 MQT: tele/tasmota_A1T_1/MARGINS = {"MARGINS":{"PowerDelta":-1}}

16:55:52.446 MQT: tele/tasmota_A1T_1/SENSOR = {"Time":"2023-04-28T16:55:52","ENERGY":{"TotalStartTime":"2023-04-28T15:46:08","Total":0.017,"Yesterday":0.000,"Today":0.017,"Power":1,"ApparentPower":7,"ReactivePower":7,"Factor":0.12,"Voltage":230,"Current":0.030}}

16:55:53.464 MQT: tele/tasmota_A1T_1/MARGINS = {"MARGINS":{"PowerDelta":7}}

16:55:53.474 MQT: tele/tasmota_A1T_1/SENSOR = {"Time":"2023-04-28T16:55:53","ENERGY":{"TotalStartTime":"2023-04-28T15:46:08","Total":0.017,"Yesterday":0.000,"Today":0.017,"Power":7,"ApparentPower":7,"ReactivePower":0,"Factor":1.00,"Voltage":230,"Current":0.030}}

16:55:55.466 MQT: tele/tasmota_A1T_1/MARGINS = {"MARGINS":{"PowerDelta":30}}

16:55:55.475 MQT: tele/tasmota_A1T_1/SENSOR = {"Time":"2023-04-28T16:55:55","ENERGY":{"TotalStartTime":"2023-04-28T15:46:08","Total":0.017,"Yesterday":0.000,"Today":0.017,"Power":15,"ApparentPower":15,"ReactivePower":0,"Factor":1.00,"Voltage":230,"Current":0.064}}`

@Civlo85
Copy link
Author

Civlo85 commented Apr 28, 2023

Hi @Boerny41

unfortunately I have no solution for my Tasmota devices. I tried to figure out what section of the source code is responsible for that, but I had no luck. To be honest, I thought there would be more help or at least good hints.

My solution for now is to use completely different devices without Tasmota.

@Boerny41
Copy link

I thought about returning mine because they make a high-pitched noise when turned off, but I couldn't find a non-Tasmota one that didn't require a cloud connection.

Which one did you choose?

@aliasnameless
Copy link

I have encountered the same issue. I am joining the search for a solution. The actual power value is very important in my automation.

@arendst
Copy link
Owner

arendst commented Apr 29, 2023

The issue is as designed. What @sfromis already tried to explain is that the powerdelta signals a user configurable change. The reported values are measured in the process of the change. They are not the end result of the change.

You need to know how energy measurements work. They are time based! Energy usage is calculated over a known amount of time. PowerDelta measures energy change every second. If the change is larger then the user configured threshold it reports the change. The final energy value is most probably different from the reported PowerDelta value.

If you want to know the final energy level you will need to read the value once the transistion is complete. That's where a (rule) call to status 10 is useful as it reports the latest state.

@Boerny41
Copy link

Okay, if it's a feature that sometimes the wrong number, a different number to the one shown in the UI, is send out, then I'd say it's a pretty bad feature because it only "works" 30% of the time.

We could spend all day discussing whether sending the correct power value is a good thing for a power meter to do, but the fact is that sometimes it does and sometimes it doesn't. No matter how you look at it, there is an error.

Since I believe that a power meter should report the correct amount, and since you don't seem interested in fixing it or even acknowledging it, I'm returning my units.

Thank you for absolutely nothing.

@sfromis
Copy link
Contributor

sfromis commented Apr 29, 2023

The number is not "wrong" or "incorrect", it is already sending the correct value. However, you must realize that what you see in the JSON is only relevant to the specific time stamp included in the JSON, and does not represent what the value would be a few seconds later, if the difference does not trigger another reporting. You could either use a lower PowerDelta value, or use my method of polling for an extra reporting.

@Boerny41
Copy link

@sfromis
My switch is set to PowerDelta 101, so it should send out a message with the current power consumption every time it detects a 1% change in power, right?

The output I posted above essentially shows this:

Power: 7 at 16:55:53.474
PowerDelta 30 detected at 16:55:55.466
Power: 15 at 15:46:08 at 16:55:55.475

and there it stopped updating because a stable power consumption was reached. So far so good, the only problem is that the actual power consumption was ~37 watts, but the last message it sent out said 15 watts.

You guys keep saying that this is how it's supposed to be (which I personally disagree with, but that's another topic), but then explain to me why it only behaves like this sometimes? Like 20 or 30% of the time. If it is intended, it should behave this way all the time.

@sfromis
Copy link
Contributor

sfromis commented Apr 29, 2023

The last message you posted should not have been 37, but you cut the log so tightly, that it does not show what came next, and you gave no info about whether the consumption level change was gradual, or it was a step change. PowerDelta is from one measurement to the next, meaning that it will not react to a difference to 5 seconds ago, only to previous second.

(101 means 1 watt, not 1%)

@Boerny41
Copy link

The thing is, I didn't cut it tight, that's all. It stopped right there. No more messages.

I'll do it again and now write down step by step what I did and also copy everything form the consol:
My laptop charges at ~40 watts. I plugged it in and switched it on. After a few moments the UI said it was charging at 40 watts, but the last mqtt message sent out said 12 watts (see below). I do not mean the last message before I copied the text, just the last one that was send out (at the time of sending the laptop was charging with 40W not 12W).

I understand that it shouldn't update if the PowerDelta doesn't change, so it was right that there weren't any more messages after the last one, but as the last message said Power:12, which straight up wasn't true. That's also what Home Assistant will now show until the charge rate changes from 40 to something else that triggers an update.

19:06:19.438 MQT: stat/tasmota_A1T_3/POWER = ON
19:06:22.406 MQT: tele/tasmota_A1T_3/MARGINS = {"MARGINS":{"PowerDelta":32}}
19:06:22.413 MQT: tele/tasmota_A1T_3/SENSOR = {"Time":"2023-04-29T19:06:22","ENERGY":{"TotalStartTime":"2023-04-28T15:49:57","Total":0.020,"Yesterday":0.000,"Today":0.020,"Power":5,"ApparentPower":5,"ReactivePower":0,"Factor":1.00,"Voltage":230,"Current":0.020}}
19:06:23.407 MQT: tele/tasmota_A1T_3/MARGINS = {"MARGINS":{"PowerDelta":-32}}
19:06:23.416 MQT: tele/tasmota_A1T_3/SENSOR = {"Time":"2023-04-29T19:06:23","ENERGY":{"TotalStartTime":"2023-04-28T15:49:57","Total":0.020,"Yesterday":0.000,"Today":0.020,"Power":0,"ApparentPower":5,"ReactivePower":5,"Factor":0.09,"Voltage":230,"Current":0.020}}
19:06:24.449 MQT: tele/tasmota_A1T_3/MARGINS = {"MARGINS":{"PowerDelta":5}}
19:06:24.458 MQT: tele/tasmota_A1T_3/SENSOR = {"Time":"2023-04-29T19:06:24","ENERGY":{"TotalStartTime":"2023-04-28T15:49:57","Total":0.020,"Yesterday":0.000,"Today":0.020,"Power":5,"ApparentPower":12,"ReactivePower":10,"Factor":0.47,"Voltage":230,"Current":0.050}}
19:06:27.410 MQT: tele/tasmota_A1T_3/MARGINS = {"MARGINS":{"PowerDelta":28}}
19:06:27.419 MQT: tele/tasmota_A1T_3/SENSOR = {"Time":"2023-04-29T19:06:27","ENERGY":{"TotalStartTime":"2023-04-28T15:49:57","Total":0.020,"Yesterday":0.000,"Today":0.020,"Power":12,"ApparentPower":12,"ReactivePower":0,"Factor":1.00,"Voltage":230,"Current":0.052}}

@aliasnameless
Copy link

aliasnameless commented May 1, 2023

I'll add my logs. The difference between the actual Power value and the value in the SENSOR topic is 1775 - 75 = 1700. The correct value in the SENSOR topic will be received on schedule. All this time my automation will run with the wrong value of 75, although the actual value is 1700.

11:15:41.396 MQT: stat/tasmota_AC87B2/RESULT = {"PowerDelta1":200}
11:15:58.219 MQT: tele/tasmota_AC87B2/SENSOR = {"Time":"2023-04-29T11:15:58","ENERGY":{"TotalStartTime":"2023-04-21T00:00:00","Total":17.421,"TotalTariff":[1.264,16.156],"Yesterday":3.178,"Today":2.778,"Power":71,"ApparentPower":1731,"ReactivePower":1730,"Factor":0.04,"Voltage":215,"Current":8.062}}
11:16:02.182 MQT: tele/tasmota_AC87B2/MARGINS = {"MARGINS":{"PowerDelta":1681}}
11:16:02.191 MQT: tele/tasmota_AC87B2/SENSOR = {"Time":"2023-04-29T11:16:02","ENERGY":{"TotalStartTime":"2023-04-21T00:00:00","Total":17.421,"TotalTariff":[1.264,16.157],"Yesterday":3.178,"Today":2.778,"Power":75,"ApparentPower":75,"ReactivePower":0,"Factor":1.00,"Voltage":212,"Current":0.354}}
11:16:32.309 CMD: status 8
11:16:32.321 MQT: stat/tasmota_AC87B2/STATUS8 = {"StatusSNS":{"Time":"2023-04-29T11:16:32","ENERGY":{"TotalStartTime":"2023-04-21T00:00:00","Total":17.436,"TotalTariff":[1.264,16.171],"Yesterday":3.178,"Today":2.793,"Power":1775,"ApparentPower":1775,"ReactivePower":0,"Factor":1.00,"Voltage":216,"Current":8.231}}}

@aliasnameless
Copy link

aliasnameless commented May 2, 2023

So, I think I found a solution by using rules without STATUS 8.
"TelePeriod - See current value and force publish STATE and SENSOR message."
Wait for MARGINS to change, then delay a second and send the TelePeriod command. To be sure power update, repeat again after 4 seconds.
Rule1 ON MARGINS DO Backlog Delay 10; TelePeriod; Delay 40; TelePeriod ENDON
Rule1 on
Thus, all the necessary data remain in the SENSOR topic.
You can try adjusting the delays.
I think this is a hotfix. But it's enough for me to use.

@AleXSR700
Copy link
Contributor

Problem is that these kinds of workaround only work for stable power consumption. A lot of devices, especially electronics, fluctuate quite a lot. So the use case is very limited.

@vthoang
Copy link

vthoang commented May 10, 2023

Adding my logs.

Running a keurig through a Sonoff S31.
Wattage sustained for around 2 minutes at about 1385W.
UI is correct, MARGINS is detecting but SENSOR didn't picked up and published the value over MQTT.

10:20:26.903 CMD: Backlog Template; Module; GPIO 255
10:20:26.963 MQT: stat/tasmota_E2B04E/RESULT = {"NAME":"Generic","GPIO":[1,1,1,1,1,1,1,1,1,1,1,1,1,1],"FLAG":0,"BASE":18}
10:20:27.161 MQT: stat/tasmota_E2B04E/RESULT = {"Module":{"41":"Sonoff S31"}}
10:20:27.371 MQT: stat/tasmota_E2B04E/RESULT = {"GPIO0":{"32":"Button1"},"GPIO1":{"3072":"CSE7766 Tx"},"GPIO2":{"0":"None"},"GPIO3":{"3104":"CSE7766 Rx"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"224":"Relay1"},"GPIO13":{"320":"Led_i1"},"GPIO14":{"0":"None"},"GPIO15":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"}}
09:50:26.432 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":-2}}
09:50:26.440 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-10T09:50:26","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.213,"Yesterday":0.075,"Today":0.036,"Power":6,"ApparentPower":12,"ReactivePower":10,"Factor":0.48,"Voltage":122,"Current":0.096}}
09:50:39.387 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":1384}}
09:50:39.394 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-10T09:50:39","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.213,"Yesterday":0.075,"Today":0.036,"Power":9,"ApparentPower":9,"ReactivePower":0,"Factor":1.00,"Voltage":122,"Current":0.072}}
09:52:12.402 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":-1385}}
09:52:12.411 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-10T09:52:12","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.247,"Yesterday":0.075,"Today":0.070,"Power":2,"ApparentPower":4,"ReactivePower":4,"Factor":0.39,"Voltage":122,"Current":0.037}}
09:52:58.389 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":1}}
09:52:58.397 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-10T09:52:58","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.247,"Yesterday":0.075,"Today":0.070,"Power":2,"ApparentPower":4,"ReactivePower":4,"Factor":0.50,"Voltage":122,"Current":0.035}}
09:53:03.419 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":-1}}
09:53:03.426 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-10T09:53:03","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.247,"Yesterday":0.075,"Today":0.070,"Power":2,"ApparentPower":4,"ReactivePower":4,"Factor":0.44,"Voltage":122,"Current":0.036}}
09:53:06.420 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":2}}
09:53:06.428 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-10T09:53:06","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.247,"Yesterday":0.075,"Today":0.070,"Power":4,"ApparentPower":7,"ReactivePower":6,"Factor":0.56,"Voltage":122,"Current":0.055}}
09:53:12.407 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":-2}}
09:53:12.415 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-10T09:53:12","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.247,"Yesterday":0.075,"Today":0.070,"Power":1,"ApparentPower":4,"ReactivePower":4,"Factor":0.26,"Voltage":122,"Current":0.034}}
09:53:27.388 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":-1}}

@vthoang
Copy link

vthoang commented May 10, 2023

The issue isn't consistent.
Possible race condition where SENSORS is reporting a stale value even though it appears to run after MARGIN.
If there is a lot of MARGINS triggering, then you won't be able to notice the issue since the issue gets masked by new updates.

Using the workaround by @aliasnameless;
Forcing a publish 1 second past MARGIN seems to be noisy but it's a feasible work around for the stable energy readings that gets lost.

@arendst
Copy link
Owner

arendst commented May 11, 2023

Gents, you might want to dig in deeper and enable weblog 4. Depending on the energy monitoring hardware you'll see what communication goes on between the monitoring chip and Tasmota.

For CSE7766 you might see a serial datagram every 100mS. See the driver how to decode it.

                  Hd Id VCal---- Voltage- ICal---- Current- PCal---- Power--- Ad CF--- Ck
16:01:58.035 DMP: F2 5A 02 E1 80 00 05 E1 00 3E BC 03 65 8F 4E 66 50 77 3F 27 61 09 DE 63
16:01:58.140 DMP: F2 5A 02 E1 80 00 05 E1 00 3E BC 03 65 8F 4E 66 50 77 3F 27 61 09 DE 63
16:01:58.244 DMP: F2 5A 02 E1 80 00 05 E1 00 3E BC 03 65 8F 4E 66 50 77 3F 27 61 09 DF 64 - Margin chk history
16:01:58.349 DMP: F2 5A 02 E1 80 00 05 E1 00 3E BC 03 65 8F 4E 66 50 77 3F 27 61 09 E0 65
16:01:58.452 DMP: F2 5A 02 E1 80 00 05 E1 00 3E BC 03 65 8F 4E 66 50 77 3F 27 61 09 E1 66
16:01:58.558 DMP: F2 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 77 3F 27 61 09 E1 67
16:01:58.662 DMP: F2 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 77 3F 27 61 09 E2 68
Start detecting change in power (turn 60W bulb on):
16:01:58.767 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E3 D5
16:01:58.871 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E3 D5
16:01:58.976 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E4 D6
16:01:59.081 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E5 D7
16:01:59.185 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E5 D7
16:01:59.290 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E6 D8  - Margin chk history
16:01:59.415 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E7 D9
16:01:59.499 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E8 DA
16:01:59.604 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 4F E8 71 09 E8 DA
16:01:59.709 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 49 7B 71 09 E9 68
16:01:59.813 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 49 7B 71 09 EA 69
16:01:59.917 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 49 7B 71 09 EA 69
16:02:00.022 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 49 7B 71 09 EB 6A
16:02:00.126 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 49 7B 71 09 EC 6B
16:02:00.231 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 49 7B 71 09 EC 6B
16:02:00.336 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 49 7B 71 09 ED 6C - Margin chk current
Report powerdelta after three seconds of power change (as designed to fix stability)
16:02:00.428 MQT: tele/refossp11a/MARGINS = {"MARGINS":{"PowerDelta":62}}
Before reporting some calculation needs to be done as this monitoring device does not provide ApparentPower
and ReactivePower.
As active power can never be larger than ApparentPower (= U*I), active power is adjusted to measured U * I.
At this time the correct current has not been reported by the monitoring device.
16:02:00.436 MQT: tele/refossp11a/SENSOR = {"Time":"2023-05-11T16:02:00","ENERGY":{"TotalStartTime":"2023-05-05T17:13:32","Total":0.007,"Yesterday":0.000,"Today":0.007,"Power":16.83,"ApparentPower":16.83,"ReactivePower":0.00,"Factor":1.00,"Voltage":233.93,"Current":0.072}}
16:02:00.439 NRG: APower 62, 62.76, 16.83 - Debug info showing 
16:02:00.444 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 03 65 8F 4E 66 50 02 49 7B 71 09 EE 6D
Start detecting change in current (turn 60W bulb on):
16:02:00.544 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 00 E3 E8 4E 66 50 02 46 97 71 09 EF 5B - Starting here,
the correct current (I) is reported by the monitoring device
16:02:00.650 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 00 E3 E8 4E 66 50 02 46 97 71 09 EF 5B
16:02:00.753 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 00 E3 E8 4E 66 50 02 46 97 71 09 F0 5C
16:02:00.858 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 00 E3 E8 4E 66 50 02 46 97 71 09 F1 5D
16:02:00.962 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 00 E3 E8 4E 66 50 02 46 97 71 09 F1 5D
16:02:01.067 DMP: 55 5A 02 E1 80 00 05 E2 00 3E BC 00 E3 E8 4E 66 50 02 46 97 71 09 F2 5E

The above shown report tries to explain where the change in powerdelta power and reported activepower comes from.

It's debateble if instead of changing active power based on measured current the current should be changed on measured active power.....

Anyway, the current solution of using a rule to delay display of final results seems to be a working solution.

arendst added a commit that referenced this issue May 11, 2023
Energy power delta report delayed by two seconds allowing hardware to stabilize (#17751)
@vthoang
Copy link

vthoang commented May 11, 2023

Still trying to capture, but that makes sense if device reported U-I doesn't match device reported Power.
Since activepower (apparentpower) is what is reported for downstream consumption,
Would it make more sense in the long run, if possible, to be able to optionally switch powerdelta to react on apparentpower instead?

@sfromis
Copy link
Contributor

sfromis commented May 11, 2023

What would the use case / value be of having PowerDelta depend on ApparentPower instead?

With ActivePower being what is consumed, and what you're usually also being charged for (assuming normal household usage), this is the "natural" thing to focus on, and what Tasmota reports and summarizes, when calculating Energy Today, Yesterday and Total.

@vthoang
Copy link

vthoang commented May 11, 2023

Using PowerDelta as it is here for a mqtt publish is inappropriate because it's detecting a change to a value that's not even being sent/published.

This causes data of interest to potentially not be captured as in the posts above.

Since the mqtt publish sends ApparentPower, it's natural for us to want to events based on the changes in that value.

ApparentPowerDelta or CurrentDelta.

Confirmed that current update is lagging behind.

                  Hd Id VCal---- Voltage- ICal---- Current- PCal---- Power--- Ad CF--- Ck
12:21:06.591 DMP: 55 5A 02 E6 30 00 06 2E 00 3E 7B 02 10 79 4F AE 70 00 0F 53 F1 57 E6 8D
12:21:06.694 DMP: 55 5A 02 E6 30 00 06 2E 00 3E 7B 02 10 79 4F AE 70 00 0F 20 F1 58 01 76
12:21:06.798 DMP: 55 5A 02 E6 30 00 06 2E 00 3E 7B 02 10 79 4F AE 70 00 0F 16 F1 58 1C 87
12:21:06.902 DMP: 55 5A 02 E6 30 00 06 2E 00 3E 7B 02 10 79 4F AE 70 00 0F 13 F1 58 38 A0
12:21:07.004 DMP: 55 5A 02 E6 30 00 06 2E 00 3E 7B 02 10 79 4F AE 70 00 0F 16 F1 58 53 BE
12:21:07.108 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 02 10 79 4F AE 70 00 0F 15 F1 58 6E 27
12:21:07.212 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 02 10 79 4F AE 70 00 0F 18 F1 58 89 45
12:21:07.316 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 02 10 79 4F AE 70 00 0F 15 F1 58 A4 5D
12:21:07.385 MQT: tele/tasmota_E2B04E/MARGINS = {"MARGINS":{"PowerDelta":1347}}
12:21:07.397 RUL: MARGINS performs "Backlog Delay 1; TelePeriod"
12:21:07.399 SRC: Rule
12:21:07.401 CMD: Grp 0, Cmd 'BACKLOG', Idx 1, Len 19, Pld -99, Data 'Delay 1; TelePeriod'
12:21:07.409 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-11T12:21:07","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.286,"Yesterday":0.070,"Today":0.039,"Power":14,"ApparentPower":14,"ReactivePower":0,"Factor":1.00,"Voltage":114,"Current":0.118}}
12:21:07.415 SRC: Backlog
12:21:07.418 CMD: Grp 0, Cmd 'DELAY', Idx 1, Len 1, Pld 1, Data '1'
12:21:07.421 MQT: stat/tasmota_E2B04E/RESULT = {"Delay":1}
12:21:07.426 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 02 10 79 4F AE 70 00 0F 18 F1 58 BF 7B
12:21:07.522 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 02 10 79 4F AE 70 00 0F 19 F1 58 DA 97
12:21:07.621 SRC: Backlog
12:21:07.624 CMD: Grp 0, Cmd 'TELEPERIOD', Idx 1, Len 0, Pld -99, Data ''
12:21:07.629 MQT: stat/tasmota_E2B04E/RESULT = {"TelePeriod":3600}
12:21:07.633 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 02 10 79 4F AE 70 00 0F 1A F1 58 F5 B3
12:21:07.728 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 02 10 79 4F AE 70 00 0F 1C F1 59 10 D1
12:21:07.831 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 02 10 79 4F AE 70 00 0F 1B F1 59 2C EC
12:21:07.935 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 00 05 5D 4F AE 70 00 0F 1D F1 59 47 E0
12:21:08.039 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 00 05 5D 4F AE 70 00 0F 1D F1 59 62 FB
12:21:08.142 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 00 05 5D 4F AE 70 00 0F 22 F1 59 7D 1B
12:21:08.246 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 00 05 5D 4F AE 70 00 0F 20 F1 59 98 34
12:21:08.350 DMP: 55 5A 02 E6 30 00 06 7D 00 3E 7B 00 05 5D 4F AE 70 00 0F 1F F1 59 B3 4E
12:21:08.411 MQT: tele/tasmota_E2B04E/STATE = {"Time":"2023-05-11T12:21:08","Uptime":"3T16:17:25","UptimeSec":317845,"Heap":24,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"bilby","BSSId":"58:EF:68:5D:63:B7","Channel":5,"Mode":"11n","RSSI":100,"Signal":-40,"LinkCount":1,"Downtime":"0T00:00:03"}}
12:21:08.426 MQT: tele/tasmota_E2B04E/SENSOR = {"Time":"2023-05-11T12:21:08","ENERGY":{"TotalStartTime":"2023-05-08T01:06:59","Total":0.286,"Yesterday":0.070,"Today":0.039,"Period":0,"Power":1333,"ApparentPower":1333,"ReactivePower":0,"Factor":1.00,"Voltage":114,"Current":11.650}}

@sfromis
Copy link
Contributor

sfromis commented May 11, 2023

What do you mean by stating "because it's detecting a change to a value that's not even being sent/published" ?

The JSON in what you copy/pasted very much contains "Power":1333 along with "ApparentPower":1333. Those two values are the same as "Factor":1.00 looks like a purely resistive load. What you get in Power in the JSON is what you see as "Active Power" in the web UI.

@vthoang
Copy link

vthoang commented May 11, 2023

That was forced with a teleperiod delay rule.

See my message log on 2023-05-10.
Specifically between 09:50:39.387 and 09:53:03.419

There was two minutes where Power / UI was 1300W+ and didn't get published.

@sfromis
Copy link
Contributor

sfromis commented May 11, 2023

You are still not explaining what the point would be of using ApparentPower instead of the real power being used and already what is being reported.

The log you now refer to instead shows "Today" being incremented with 34 watt over a period of 93 seconds, and that increment is based on "Power" (same as "Active Power" in the web UI). That would match a power draw of 1316 W over that interval, a number in the same ballpark as the MARGINS values also published. If you were expecting to see something similar in the "Power" field in the JSON, that is likely be due to this being a momentary value at the time of reporting, instead of something useful for a period of time. And as already discussed, a single momentary value is not really useful when the consumption level jumps up or down.

Anyway, arendst just made a change to delay PowerDelta reporting by two seconds. This will likely improve chances of values coming only after sensor has stabilized after the step up/down of consumption. You might want to see how this works out for you.

@vthoang
Copy link

vthoang commented May 11, 2023

I can already tell it will work out in my case because current lags between 0-1s.

From what @arendst detailed out PowerDelta is reacting to device reported Power, but ApparentPower maxes at device reported (Voltage * Current). Theoretically they are the same data, but practically they are not the same data.

Given a event based option vs a 2 second delay waiting (hoping) for current to catch up, I'm suggesting it makes more sense in the long run to react to the desired value component being sent without such a delay.

@vthoang
Copy link

vthoang commented May 11, 2023

RE: "what the point would be of using ApparentPower instead of the real power being used and already what is being reported."

Review:
#17751 (comment)
And elaborate on how I would track that the Keurig is using 1385W while it's boiling water from the MQTT data seen. It's not possible. You can call it momentary, yet it should be completely possible to capture since the MARGINS is showing 1384W delta detected.

Then examine:
#17751 (comment)
Almost the same log but with WebLog 4 + TelePeriod Rule.
By detecting ApparentPower or Current, the MARGINS/Deltas can be tuned to trigger at 12:21:07.935 where the values of use are first found.

Before this specific time, Power is changing, but ApparentPower is capped due to Current not changing. Thus the reported Power is not the Power value that initiated the event.

With the pending change 12:21:07.409 mqtt publishing event will occur at about 12:21:09.409 which should work since anything after 12:21:07.935 will do.

@robbedenys
Copy link

Anyway, arendst just made a change to delay PowerDelta reporting by two seconds. This will likely improve chances of values coming only after sensor has stabilized after the step up/down of consumption. You might want to see how this works out for you.

Aha, so that's why the Powerdelta configuration started acting weird when I updated from 12.5 to 13.0. I am using the Powerdelta 101 setting to have very fast and detailed power consumtion updates in home assistant and it was indeed not following the values that were seen on the tasmota page of the power meter.

I now downgraded again to 12.5 and the updates are much faster again, but if I understand correctly these values are not always that accurate?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
question Type - Asking for Information stale Action - Issue left behind - Used by the BOT to call for attention
Projects
None yet
Development

No branches or pull requests

9 participants