krahabb / meross_lan

Home Assistant integration for Meross devices
MIT License
387 stars 46 forks source link

MSS315 Last daily value introduced during daily reset since Daylight Saving Time change at Sun, Mar 31, 2024 #420

Open Fyr42 opened 2 months ago

Fyr42 commented 2 months ago

Version of the custom_component

v5.0.3 Firmware: 9.5.31 Hardware: 9.0.0

Configuration

Sensor_protocol http

Describe the bug

I use 2 MSS315 to measure my solar and/or battery production. One of them, at the daily reset at midnight, sends the daily value to HA. And have 2 daily reset : midnight and 1:00 AM.

I'm in Europe/Paris Timezone. Now in CEST / UTC+2 https://www.zeitverschiebung.net/en/timezone/europe--paris

Screenshot 2024-04-11 at 01 42 52 Screenshot 2024-04-11 at 01 43 32

The other, draining battery at this time don't show this behavior :

Screenshot 2024-04-11 at 01 59 43

I have others MSS310 only one is active. You will see them in the logs

Debug log

2024-04-10 23:59:58.139 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] Polling begin
2024-04-10 23:59:58.140 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] TX(http) SET Appliance.Control.Multiple (messageId:98d92492cec643329af1fcdf21527a49)
2024-04-10 23:59:58.334 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] RX(http) SETACK Appliance.Control.Multiple (messageId:98d92492cec643329af1fcdf21527a49)
2024-04-10 23:59:58.335 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] Appliance.Control.Multiple requests=3 (responses=3) expected size=3033 (actual=3171)
2024-04-10 23:59:58.337 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] TX(http) GET Appliance.System.DNDMode (messageId:2d7ddbcd9c0648fbbe090ec3fc90241a)
2024-04-10 23:59:58.432 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] RX(http) GETACK Appliance.System.DNDMode (messageId:2d7ddbcd9c0648fbbe090ec3fc90241a)
2024-04-10 23:59:58.432 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] Polling end
2024-04-11 00:00:00.006 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] EnergyEstimateSensor(energy_estimate): _reset at 2024-04-11T00:00:00+02:00
2024-04-11 00:00:00.006 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] EnergyEstimateSensor(energy_estimate): _schedule_reset at 2024-04-12T00:00:00+02:00
2024-04-11 00:00:00.014 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################4] EnergyEstimateSensor(energy_estimate): _reset at 2024-04-11T00:00:00+02:00
2024-04-11 00:00:00.015 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################4] EnergyEstimateSensor(energy_estimate): _schedule_reset at 2024-04-12T00:00:00+02:00
2024-04-11 00:00:00.015 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################1] EnergyEstimateSensor(energy_estimate): _reset at 2024-04-11T00:00:00+02:00
2024-04-11 00:00:00.015 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################1] EnergyEstimateSensor(energy_estimate): _schedule_reset at 2024-04-12T00:00:00+02:00
2024-04-11 00:00:00.015 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################2] EnergyEstimateSensor(energy_estimate): _reset at 2024-04-11T00:00:00+02:00
2024-04-11 00:00:00.018 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################2] EnergyEstimateSensor(energy_estimate): _schedule_reset at 2024-04-12T00:00:00+02:00
2024-04-11 00:00:00.018 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################3] EnergyEstimateSensor(energy_estimate): _reset at 2024-04-11T00:00:00+02:00
2024-04-11 00:00:00.018 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################3] EnergyEstimateSensor(energy_estimate): _schedule_reset at 2024-04-12T00:00:00+02:00
2024-04-11 00:00:00.020 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################5] EnergyEstimateSensor(energy_estimate): _reset at 2024-04-11T00:00:00+02:00
2024-04-11 00:00:00.021 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################5] EnergyEstimateSensor(energy_estimate): _schedule_reset at 2024-04-12T00:00:00+02:00
2024-04-11 00:00:00.021 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] EnergyEstimateSensor(energy_estimate): _reset at 2024-04-11T00:00:00+02:00
2024-04-11 00:00:00.021 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] EnergyEstimateSensor(energy_estimate): _schedule_reset at 2024-04-12T00:00:00+02:00
2024-04-11 00:00:00.021 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################6] EnergyEstimateSensor(energy_estimate): _reset at 2024-04-11T00:00:00+02:00
2024-04-11 00:00:00.022 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################6] EnergyEstimateSensor(energy_estimate): _schedule_reset at 2024-04-12T00:00:00+02:00
2024-04-11 00:00:03.433 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] Polling begin
2024-04-11 00:00:03.435 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] TX(http) SET Appliance.Control.Multiple (messageId:0ae0354bf4c9428799275b6a813910cc)
2024-04-11 00:00:03.533 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] RX(http) SETACK Appliance.Control.Multiple (messageId:0ae0354bf4c9428799275b6a813910cc)
2024-04-11 00:00:03.534 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] Appliance.Control.Multiple requests=3 (responses=3) expected size=1390 (actual=1580)
2024-04-11 00:00:03.535 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] Polling end

[...]

2024-04-11 00:00:21.881 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################3] ConsumptionXSensor(energy): updated midnight epochs: yesterday=1712700000.0 - today=1712786400.0 - tomorrow=1712872800.0
2024-04-11 00:00:21.882 DEBUG (MainThread) [custom_components.meross_lan.mss310_###############################3] ConsumptionXSensor(energy): no readings available for new day - resetting

[...]

2024-04-11 00:00:54.680 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] ConsumptionXSensor(energy): updated midnight epochs: yesterday=1712700000.0 - today=1712786400.0 - tomorrow=1712872800.0
2024-04-11 00:00:54.681 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################0] ConsumptionXSensor(energy): no readings available for new day - resetting

[...]

2024-04-11 00:01:06.707 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] ConsumptionXSensor(energy): updated midnight epochs: yesterday=1712700000.0 - today=1712786400.0 - tomorrow=1712872800.0
2024-04-11 00:01:06.709 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] ConsumptionXSensor(energy): no readings available for new day - resetting

[...]

2024-04-11 00:10:11.272 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] Polling begin
2024-04-11 00:10:11.273 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] TX(http) SET Appliance.Control.Multiple (messageId:3ae483c6834b4a55b66c5bcdb9e9d9a7)
2024-04-11 00:10:11.485 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] RX(http) SETACK Appliance.Control.Multiple (messageId:3ae483c6834b4a55b66c5bcdb9e9d9a7)
2024-04-11 00:10:11.486 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] Appliance.Control.Multiple requests=3 (responses=3) expected size=3033 (actual=3217)
2024-04-11 00:10:11.486 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] ConsumptionXSensor(energy): first consumption reading for new day, offset=0
2024-04-11 00:10:11.487 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] ConsumptionXSensor(energy): updating consumption=3769
2024-04-11 00:10:11.487 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] TX(http) GET Appliance.System.DNDMode (messageId:0f0cd3f393b749f28255c00cc835dc98)
2024-04-11 00:10:11.567 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] RX(http) GETACK Appliance.System.DNDMode (messageId:0f0cd3f393b749f28255c00cc835dc98)
2024-04-11 00:10:11.568 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] Polling end

The last part shows the value of 3769 re-injected at 00:10:11.487 with mention of "first consumption reading for new day" and again at 01:04:33 AM "first consumption reading for new day" with 0 value

2024-04-11 01:04:33.715 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] Polling begin
2024-04-11 01:04:33.718 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] TX(http) SET Appliance.Control.Multiple (messageId:5947a661e2a241629e075a66f1ee2c17)
2024-04-11 01:04:33.926 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] RX(http) SETACK Appliance.Control.Multiple (messageId:5947a661e2a241629e075a66f1ee2c17)
2024-04-11 01:04:33.926 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] Appliance.Control.Multiple requests=3 (responses=3) expected size=2980 (actual=3214)
2024-04-11 01:04:33.927 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] ConsumptionXSensor(energy): first consumption reading for new day, offset=0
2024-04-11 01:04:33.928 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] ConsumptionXSensor(energy): updating consumption=0
2024-04-11 01:04:33.935 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] TX(http) SET Appliance.Control.Multiple (messageId:4fc5dcfffed84c06a9ae8c7f71a7aa70)
2024-04-11 01:04:34.031 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] RX(http) SETACK Appliance.Control.Multiple (messageId:4fc5dcfffed84c06a9ae8c7f71a7aa70)
2024-04-11 01:04:34.032 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] Appliance.Control.Multiple requests=2 (responses=2) expected size=950 (actual=1061)
2024-04-11 01:04:34.032 DEBUG (MainThread) [custom_components.meross_lan.mss315_###############################7] Polling end

config_entry-meross_lan-92466c48ad9ba657b5c0b99b268e56c3.json

Kind Regards,

krahabb commented 2 months ago

Hello @Fyr42 , This is always tricky ;) I'll try check the issue in the coming days but I'm very busy at the moment. Putting in the backlog...

Fyr42 commented 2 months ago

Hi

Just for the record the "official" app doesn't show

I don't know why only one of the two mss315 is buggy..

previous day , before daily reset

before-midnight

after daily reset

after-midnight

Kind regards

krahabb commented 2 months ago

The issue where the power readings are all '0' is well-known (#367 and others) but without a really clear solution. I suggest you to try power-cycle the plug (if not done already) and see if it fixes this. Back in time it appeared as if this was related to the device not being able to get its correct system time from NTP servers.

As for the wrong daily energy reset, by inspecting the trace you've uploaded I see the device exposes a bug where it does not correctly reset at midnight (after 31-03-2024 the day of DST change). It looks like, after the DST change, it kept resetting its daily energy at/around 10:58 PM GMT time which was correct during DST but it is no more now that we have +2:00 with respect to GMT. This brings the device energy reset at around 1:00 AM (CET) and then conflicts with a special algorithm in meross_lan which is in place to try correct another bug (#264) appeared on some fw/hw.

When I wrote the patch algorithm for #264 I was scared that patching could have worsened some other misbehaviors and this is an example: without the patch, I guess the plug would just reset at 1:00 AM and the statistics would likely be unaffected (even if the roundtrip time is not correct)

I still have to better check if this is the scenario but I expect that, if this is correct, you should experience again the same kind of glitch unless the plug has now started resetting exactly at midnight (local time) again.

In my reasoning, the glitch would not be seen every day since the energy reading doesn't update between 12:00 AM and 1:00 AM (roughly) because the power consumption is very low. If, by chance, the energy reading changes (increases by at least 1 Wh) during that time then you should see the wrong reset like in your issue reporting.

Fyr42 commented 2 months ago

Hi,

Yes. The last two days, bug not seen, but value was in my good range, not very low. 4.06 (I stopped the panels for ~2 hours, and unplugged the MSS315, so power cycle done, and bug vanished) and 7.08 kWh for yesterday. As it's related to solar production there is no change after 20h30 on the MSS315. I have a local NTP server on my FreeBSD server, published via DHCP server. No ntp broadcast of unicast. I will trace if they use my server or not, if the MSS315 has hardcoded ntp server inside firmware.

The non buggy MSS315 is working by night, draining a battery. So the energy reading is changing, and no wrong reset. The 1 and 2 April (after the DST) this non buggy MSS315 was not working at all, with an inverter failure.

If you need deeper debug trace let me know.

Thanks for the answer : power cycle killed the bug for the last 2 days.

Kind regards,

sushiat commented 2 months ago

Two of my MSS310 plugs still do this, I added NTP server to the network and added it to the DHCP options, reset both devices but they keep on doing it every night. Anything else I can try? image

krahabb commented 2 months ago

Hello @sushiat , could you try setup a 'debug tracing' for either of the mss310 so I could better understand if it's the same issue or something else?

sushiat commented 2 months ago

Tried and failed I think 😢 I let it do it's 10 minute log, started it at like 23:53 thinking that would do fine. Didn't realise the value goes to 0 at midnight, but it's like 3 minutes later it get's restored/reset. And the log ended at 02:21. Will have another go tomorrow.

krahabb commented 2 months ago

Don't worry trying catching the around-midnight failure. A plain trace at whatever time will be enough since I just have to inspect the device overall state and the trace will anyway carry the latest month consumption history and every timestamp/timezone settings useful for analysis

sushiat commented 2 months ago

Ah I forgot last night anyway, but I kept the file from the night before. But if it's still of use to you here it is: 2024-04-29_23-52-45_9f927a68096393144e266d28354f367a.csv