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

OpenDTU-OnBattery stalls on DPL update via MQTT until power is switched off and back on #1494

Closed
4 tasks done
ali-baba-de opened this issue Jan 1, 2025 · 10 comments
Closed
4 tasks done
Labels
bug Something isn't working stale

Comments

@ali-baba-de
Copy link

What happened?

On Dec 1st, 2024 I modified a HomeAssistant automation to not only update the Voltage "Start and Stop Threshold for Battery Discharging" (before I had the "Use Voltage Threshols Only" switch active) but also the two corresponding values for the SOC. The updates are performed via MQTT. Since then it has happened 3-4 times that the system stalled (e.g. no more log entries are produced) and did not recover until I switched off the power. Before Dec 1st, when only updating the two voltage values, the stall has not happened (in at least 6 months).

Thanks to the team for having a look and I appreciate your work tremendously!

To Reproduce Bug

I have tried to reproduce it by manually executing the HA automation in short sequence but was not successful so far (tried at least 50 executions). It happens seldomly (3-4 stalls in Dec. vs 3-4 automation executions per day), I did not find any pattern yet how to reliably trigger the problem.

Expected Behavior

  • All updates sent via MQTT are executed and applied
  • the system continues with "normal" operation and does not stall

Install Method

Pre-Compiled binary from GitHub releases

What git-hash/version of OpenDTU-OnBattery?

2024.11.20

What firmware variant (PIO Environment)?

generic_esp32_4mb_no_ota

Relevant log/trace output

Fetch inverter: xxx
19:47:13.102 > TX RealTimeRunData Channel: 3 --> 15 xx xx xx xx 80 15 92 80 80 0B 00 67 71 99 31 00 00 00 00 00 00 00 00 7F F5 BD 
19:47:13.138 > Interrupt received
19:47:13.148 > RX Channel: 75 --> 95 xx xx xx xx xx xx xx xx 01 00 01 01 F1 00 02 00 0B 01 F2 00 03 00 10 00 05 89 | -80 dBm
19:47:13.189 > Interrupt received
19:47:13.196 > RX Channel: 75 --> 95 xx xx xx xx xx xx xx xx 02 61 02 00 05 83 C1 00 1A 00 21 09 26 13 88 00 1A 26 | -80 dBm
19:47:13.237 > Interrupt received
19:47:13.245 > RX Channel: 75 --> 95 xx xx xx xx xx xx xx xx 83 00 00 00 01 03 E8 00 E8 00 05 F3 4F AD | -80 dBm
19:47:13.709 > [PowerMeterSerialSml] TotalPower: 1740.86
19:47:13.728 > RX Period End
19:47:13.745 > Success
19:47:13.899 > [DPL::loop] ******************* ENTER **********************
19:47:13.906 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 0 s, ignore: no
19:47:13.912 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.64 V, inverter zzz: 49.70 V, returning: 49.62V
19:47:13.918 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 50.50 V, StopTH: 50.00 V
19:47:13.934 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:13.940 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:13.948 > [DPL::calcHouseholdConsumption] power meter value: 1740.9 W, power meter valid: yes
19:47:13.953 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:13.959 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 2 W
19:47:13.966 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 2 W
19:47:13.972 > [DPL::updateInverterLimits] requested: 1722 W, producing: 0 W using 0 solar-powered inverters, diff: 1722 W, hysteresis: 20 W
19:47:13.978 > [DPL::calcBatteryAllowance] power requested: 1722 W
19:47:13.983 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:13.993 > [DPL::updateInverterLimits] requested: 0 W, producing: 6 W using 3 battery-powered inverters, diff: -6 W, hysteresis: 20 W
19:47:13.999 > [DPL::loop] consumption: 1722 W, target output: 1722 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 6 W
19:47:14.077 > Fetch inverter: yyy
19:47:14.091 > TX RealTimeRunData Channel: 23 --> 15 yy yy yy yy 80 15 92 80 80 0B 00 67 71 99 32 00 00 00 00 00 00 00 00 8F E1 FC 
19:47:14.648 > RX Period End
19:47:14.665 > All missing
19:47:14.674 > Nothing received, resend whole request
19:47:14.679 > TX RealTimeRunData Channel: 40 --> 15 yy yy yy yy 80 15 92 80 80 0B 00 67 71 99 32 00 00 00 00 00 00 00 00 8F E1 FC 
19:47:14.685 > [PowerMeterSerialSml] TotalPower: 1730.74
19:47:14.691 > Interrupt received
19:47:14.697 > RX Channel: 23 --> 95 yy yy yy yy yy yy yy yy 01 00 01 01 F1 00 03 00 10 01 F1 00 01 00 07 00 02 82 | -80 dBm
19:47:14.702 > Interrupt received
19:47:14.713 > RX Channel: 23 --> 95 yy yy yy yy yy yy yy yy 02 76 DC 00 02 50 CF 00 23 00 12 09 26 13 88 00 16 33 | -80 dBm
19:47:14.738 > Interrupt received
19:47:14.748 > RX Channel: 3 --> 95 yy yy yy yy yy yy yy yy 83 00 00 00 01 03 EC 00 F2 00 01 8D 88 0E | -80 dBm
19:47:15.043 > [DPL::loop] ******************* ENTER **********************
19:47:15.050 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 1 s, ignore: no
19:47:15.058 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.64 V, inverter zzz: 49.70 V, returning: 49.62V
19:47:15.064 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 50.50 V, StopTH: 50.00 V
19:47:15.069 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:15.074 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:15.080 > [DPL::calcHouseholdConsumption] power meter value: 1730.7 W, power meter valid: yes
19:47:15.086 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:15.092 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 2 W
19:47:15.098 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 2 W
19:47:15.106 > [DPL::updateInverterLimits] requested: 1712 W, producing: 0 W using 0 solar-powered inverters, diff: 1712 W, hysteresis: 20 W
19:47:15.119 > [DPL::calcBatteryAllowance] power requested: 1712 W
19:47:15.124 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:15.129 > [DPL::updateInverterLimits] requested: 0 W, producing: 6 W using 3 battery-powered inverters, diff: -6 W, hysteresis: 20 W
19:47:15.135 > [DPL::loop] consumption: 1712 W, target output: 1712 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 6 W
19:47:15.145 > RX Period End
19:47:15.153 > Success
19:47:15.159 > Fetch inverter: zzz
19:47:15.167 > TX RealTimeRunData Channel: 61 --> 15 zz zz zz zz 80 15 92 80 80 0B 00 67 71 99 33 00 00 00 00 00 00 00 00 1F EC C5 
19:47:15.197 > Interrupt received
19:47:15.207 > RX Channel: 23 --> 95 zz zz zz zz zz zz zz zz 01 00 01 01 F0 00 03 00 0F 01 F1 00 02 00 0C 00 09 9F | -80 dBm
19:47:15.246 > Interrupt received
19:47:15.255 > RX Channel: 23 --> 95 zz zz zz zz zz zz zz zz 02 FA 48 00 09 C3 EB 00 21 00 1B 09 27 13 88 00 0D 86 | -80 dBm
19:47:15.294 > Interrupt received
19:47:15.305 > RX Channel: 3 --> 95 zz zz zz zz zz zz zz zz 83 00 00 00 01 03 F9 00 E0 00 01 04 D6 DE | -80 dBm
19:47:15.668 > RX Period End
19:47:15.685 > Success
19:47:16.538 > Fetch inverter: xxx
19:47:16.548 > [DPL::loop] ******************* ENTER **********************
19:47:16.557 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 1 s, ignore: no
19:47:16.565 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.63 V, inverter zzz: 49.60 V, returning: 49.62V
19:47:16.571 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 50.50 V, StopTH: 50.00 V
19:47:16.577 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:16.584 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:16.599 > [DPL::calcHouseholdConsumption] power meter value: 1730.7 W, power meter valid: yes
19:47:16.606 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:16.613 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 1 W
19:47:16.619 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 2 W
19:47:16.625 > [DPL::updateInverterLimits] requested: 1711 W, producing: 0 W using 0 solar-powered inverters, diff: 1711 W, hysteresis: 20 W
19:47:16.633 > [DPL::calcBatteryAllowance] power requested: 1711 W
19:47:16.640 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:16.646 > [DPL::updateInverterLimits] requested: 0 W, producing: 5 W using 3 battery-powered inverters, diff: -5 W, hysteresis: 20 W
19:47:16.655 > [DPL::loop] consumption: 1711 W, target output: 1711 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 5 W
19:47:16.662 > TX RealTimeRunData Channel: 75 --> 15 xx xx xx xx 80 15 92 80 80 0B 00 67 71 99 34 00 00 00 00 00 00 00 00 2F CA D7 
19:47:16.668 > Interrupt received
19:47:16.681 > RX Channel: 75 --> 95 xx xx xx xx xx xx xx xx 01 00 01 01 F1 00 03 00 0D 01 F2 00 03 00 11 00 05 8F | -80 dBm
19:47:16.687 > Interrupt received
19:47:16.699 > RX Channel: 75 --> 95 xx xx xx xx xx xx xx xx 02 61 02 00 05 83 C1 00 1A 00 21 09 26 13 88 00 1D 21 | -30 dBm
19:47:16.705 > Interrupt received
19:47:16.711 > RX Channel: 61 --> 95 xx xx xx xx xx xx xx xx 83 00 00 00 01 03 EA 00 E7 00 05 D5 2E E7 | -80 dBm
19:47:17.069 > RX Period End
19:47:17.084 > Success
19:47:17.304 > Fetch inverter: yyy
19:47:17.331 > TX RealTimeRunData Channel: 3 --> 15 yy yy yy yy 80 15 92 80 80 0B 00 67 71 99 35 00 00 00 00 00 00 00 00 BF C7 ED 
19:47:17.364 > Interrupt received
19:47:17.375 > RX Channel: 3 --> 95 yy yy yy yy yy yy yy yy 01 00 01 01 F1 00 04 00 12 01 F1 00 02 00 08 00 02 8B | -80 dBm
19:47:17.398 > Interrupt received
19:47:17.409 > RX Channel: 23 --> 95 yy yy yy yy yy yy yy yy 02 76 DC 00 02 50 CF 00 23 00 12 09 26 13 88 00 19 3C | -80 dBm
19:47:17.576 > [DPL::loop] ******************* ENTER **********************
19:47:17.584 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 0 s, ignore: no
19:47:17.590 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.64 V, inverter zzz: 49.60 V, returning: 49.62V
19:47:17.599 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 50.50 V, StopTH: 50.00 V
19:47:17.605 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:17.612 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:17.621 > [DPL::calcHouseholdConsumption] power meter value: 1730.7 W, power meter valid: yes
19:47:17.627 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:17.633 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 1 W
19:47:17.639 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 2 W
19:47:17.646 > [DPL::updateInverterLimits] requested: 1711 W, producing: 0 W using 0 solar-powered inverters, diff: 1711 W, hysteresis: 20 W
19:47:17.652 > [DPL::calcBatteryAllowance] power requested: 1711 W
19:47:17.664 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:17.672 > [DPL::updateInverterLimits] requested: 0 W, producing: 5 W using 3 battery-powered inverters, diff: -5 W, hysteresis: 20 W
19:47:17.680 > [DPL::loop] consumption: 1711 W, target output: 1711 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 5 W
19:47:17.690 > [PowerMeterSerialSml] checksum verification failed
19:47:17.854 > RX Period End
19:47:17.861 > Last missing
19:47:17.866 > Request retransmit: 3
19:47:17.873 > TX RequestFrame Channel: 23 --> 15 yy yy yy yy 80 15 92 80 83 27 
19:47:17.879 > Interrupt received
19:47:17.887 > RX Channel: 23 --> 95 yy yy yy yy yy yy yy yy 83 00 00 00 01 03 ED 00 F2 00 01 A3 7F D6 | -80 dBm
19:47:17.954 > RX Period End
19:47:17.961 > Success
19:47:18.316 > Fetch inverter: zzz
19:47:18.340 > TX RealTimeRunData Channel: 40 --> 15 zz zz zz zz 80 15 92 80 80 0B 00 67 71 99 36 00 00 00 00 00 00 00 00 4F D3 AF 
19:47:18.371 > Interrupt received
19:47:18.385 > RX Channel: 23 --> 95 zz zz zz zz zz zz zz zz 01 00 01 01 F1 00 03 00 0F 01 F1 00 02 00 0C 00 09 9E | -80 dBm
19:47:18.421 > Interrupt received
19:47:18.430 > RX Channel: 23 --> 95 zz zz zz zz zz zz zz zz 02 FA 48 00 09 C3 EB 00 21 00 1B 09 27 13 88 00 1A 91 | -80 dBm
19:47:18.468 > Interrupt received
19:47:18.476 > RX Channel: 3 --> 95 zz zz zz zz zz zz zz zz 83 00 00 00 01 03 EB 00 DF 00 01 13 18 2A | -80 dBm
19:47:18.722 > [DPL::loop] ******************* ENTER **********************
19:47:18.729 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 1 s, ignore: no
19:47:18.736 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.64 V, inverter zzz: 49.60 V, returning: 49.62V
19:47:18.757 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 50.50 V, StopTH: 50.00 V
19:47:18.772 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:18.777 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:18.783 > [DPL::calcHouseholdConsumption] power meter value: 1730.7 W, power meter valid: yes
19:47:18.790 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:18.796 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 1 W
19:47:18.802 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 2 W
19:47:18.809 > [DPL::updateInverterLimits] requested: 1711 W, producing: 0 W using 0 solar-powered inverters, diff: 1711 W, hysteresis: 20 W
19:47:18.815 > [DPL::calcBatteryAllowance] power requested: 1711 W
19:47:18.821 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:18.827 > [DPL::updateInverterLimits] requested: 0 W, producing: 5 W using 3 battery-powered inverters, diff: -5 W, hysteresis: 20 W
19:47:18.833 > [DPL::loop] consumption: 1711 W, target output: 1711 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 5 W
19:47:18.845 > RX Period End
19:47:18.855 > Success
19:47:19.314 > Fetch inverter: xxx
19:47:19.363 > TX RealTimeRunData Channel: 61 --> 15 xx xx xx xx 80 15 92 80 80 0B 00 67 71 99 37 00 00 00 00 00 00 00 00 DF DE 30 
19:47:19.386 > Interrupt received
19:47:19.396 > RX Channel: 3 --> 95 xx xx xx xx xx xx xx xx 01 00 01 01 F1 00 02 00 0B 01 F2 00 03 00 10 00 05 89 | -80 dBm
19:47:19.450 > Interrupt received
19:47:19.465 > RX Channel: 61 --> 95 xx xx xx xx xx xx xx xx 83 00 00 00 01 03 EA 00 E7 00 05 79 0F 6A | -80 dBm
19:47:19.870 > [DPL::loop] ******************* ENTER **********************
19:47:19.878 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 0 s, ignore: no
19:47:19.886 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.64 V, inverter zzz: 49.70 V, returning: 49.62V
19:47:19.895 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 50.50 V, StopTH: 50.00 V
19:47:19.903 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:19.914 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:19.930 > [DPL::calcHouseholdConsumption] power meter value: 1730.7 W, power meter valid: yes
19:47:19.942 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:19.953 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 2 W
19:47:19.964 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 2 W
19:47:19.975 > [DPL::updateInverterLimits] requested: 1712 W, producing: 0 W using 0 solar-powered inverters, diff: 1712 W, hysteresis: 20 W
19:47:19.981 > [DPL::calcBatteryAllowance] power requested: 1712 W
19:47:19.987 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:19.995 > [DPL::updateInverterLimits] requested: 0 W, producing: 6 W using 3 battery-powered inverters, diff: -6 W, hysteresis: 20 W
19:47:20.003 > [DPL::loop] consumption: 1712 W, target output: 1712 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 6 W
19:47:20.007 > RX Period End
19:47:20.015 > Middle missing
19:47:20.033 > Request retransmit: 2
19:47:20.043 > TX RequestFrame Channel: 75 --> 15 xx xx xx xx 80 15 92 80 82 80 
19:47:20.059 > RX Period End
19:47:20.066 > Middle missing
19:47:20.082 > Request retransmit: 2
19:47:20.089 > TX RequestFrame Channel: 3 --> 15 xx xx xx xx 80 15 92 80 82 80 
19:47:20.098 > Interrupt received
19:47:20.106 > RX Channel: 61 --> 95 xx xx xx xx xx xx xx xx 02 61 02 00 05 83 C1 00 1A 00 21 09 25 13 88 00 0C 33 | -80 dBm
19:47:20.113 > RX Period End
19:47:20.134 > Success
19:47:20.317 > Fetch inverter: yyy
19:47:20.341 > TX RealTimeRunData Channel: 23 --> 15 yy yy yy yy 80 15 92 80 80 0B 00 67 71 99 38 00 00 00 00 00 00 00 00 2F 9F 28 
19:47:20.394 > Interrupt received
19:47:20.402 > RX Channel: 23 --> 95 yy yy yy yy yy yy yy yy 01 00 01 01 F1 00 03 00 10 01 F1 00 01 00 07 00 02 82 | -80 dBm
19:47:20.468 > Interrupt received
19:47:20.476 > RX Channel: 40 --> 95 yy yy yy yy yy yy yy yy 83 00 00 00 01 03 EE 00 F2 00 01 09 FE FE | -80 dBm
19:47:20.640 > [PowerMeterSerialSml] TotalPower: 1720.08
19:47:20.860 > RX Period End
19:47:20.867 > Middle missing
19:47:20.873 > Request retransmit: 2
19:47:20.880 > TX RequestFrame Channel: 40 --> 15 yy yy yy yy 80 15 92 80 82 26 
19:47:21.018 > [DPL::loop] ******************* ENTER **********************
19:47:21.025 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 1 s, ignore: no
19:47:21.033 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.64 V, inverter zzz: 49.70 V, returning: 49.62V
19:47:21.043 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 50.50 V, StopTH: 50.00 V
19:47:21.046 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:21.053 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:21.059 > [DPL::calcHouseholdConsumption] power meter value: 1720.1 W, power meter valid: yes
19:47:21.069 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:21.082 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 2 W
19:47:21.089 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 1 W
19:47:21.098 > [DPL::updateInverterLimits] requested: 1700 W, producing: 0 W using 0 solar-powered inverters, diff: 1700 W, hysteresis: 20 W
19:47:21.108 > [DPL::calcBatteryAllowance] power requested: 1700 W
19:47:21.114 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:21.120 > [DPL::updateInverterLimits] requested: 0 W, producing: 5 W using 3 battery-powered inverters, diff: -5 W, hysteresis: 20 W
19:47:21.127 > [DPL::loop] consumption: 1700 W, target output: 1700 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 5 W
19:47:21.136 > RX Period End
19:47:21.143 > Middle missing
19:47:21.149 > Request retransmit: 2
19:47:21.155 > TX RequestFrame Channel: 61 --> 15 yy yy yy yy 80 15 92 80 82 26 
19:47:21.162 > [DPL::announceStatus] the system is stable, the last power limit is still valid
19:47:21.172 > RX Period End
19:47:21.186 > Middle missing
19:47:21.190 > Request retransmit: 2
19:47:21.197 > TX RequestFrame Channel: 75 --> 15 yy yy yy yy 80 15 92 80 82 26 
19:47:21.205 > Interrupt received
19:47:21.212 > RX Channel: 61 --> 95 yy yy yy yy yy yy yy yy 02 76 DC 00 02 50 CF 00 23 00 12 09 26 13 88 00 15 30 | -80 dBm
19:47:21.307 > RX Period End
19:47:21.315 > Success
19:47:22.036 > Fetch inverter: zzz
19:47:22.175 > TX RealTimeRunData Channel: 3 --> 15 zz zz zz zz 80 15 92 80 80 0B 00 67 71 99 39 00 00 00 00 00 00 00 00 BF 92 11 
19:47:22.182 > [DPL::loop] ******************* ENTER **********************
19:47:22.190 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 0 s, ignore: no
19:47:22.197 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.64 V, inverter zzz: 49.70 V, returning: 49.62V
19:47:22.207 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 50.50 V, StopTH: 50.00 V
19:47:22.213 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:22.220 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:22.231 > [DPL::calcHouseholdConsumption] power meter value: 1720.1 W, power meter valid: yes
19:47:22.237 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:22.246 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 2 W
19:47:22.260 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 1 W
19:47:22.275 > [DPL::updateInverterLimits] requested: 1700 W, producing: 0 W using 0 solar-powered inverters, diff: 1700 W, hysteresis: 20 W
19:47:22.290 > [DPL::calcBatteryAllowance] power requested: 1700 W
19:47:22.303 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:22.308 > [DPL::updateInverterLimits] requested: 0 W, producing: 5 W using 3 battery-powered inverters, diff: -5 W, hysteresis: 20 W
19:47:22.312 > [DPL::loop] consumption: 1700 W, target output: 1700 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 5 W
19:47:22.359 > Received MQTT message on topic: solar/powerlimiter/cmd/threshold/voltage/start
19:47:22.846 > Setting voltage start threshold to: 48.50 V
19:47:22.855 > Received MQTT message on topic: solar/powerlimiter/cmd/threshold/voltage/stop
19:47:22.862 > RX Period End
19:47:22.869 > All missing
19:47:22.875 > Nothing received, resend whole request
19:47:22.882 > TX RealTimeRunData Channel: 23 --> 15 zz zz zz zz 80 15 92 80 80 0B 00 67 71 99 39 00 00 00 00 00 00 00 00 BF 92 11 
19:47:23.457 > Setting voltage stop threshold to: 47.60 V
19:47:23.468 > Received MQTT message on topic: solar/powerlimiter/cmd/threshold/soc/start
19:47:23.476 > Interrupt received
19:47:23.481 > [DPL::loop] ******************* ENTER **********************
19:47:23.490 > [DPL::loop] battery interface enabled, SoC: 68.0 %, StartTH: 85 %, StopTH: 75 %, SoC age: 1 s, ignore: no
19:47:23.497 > [DPL::getBatteryVoltage] BMS: 49.62 V, MPPT: 49.64 V, inverter zzz: 49.70 V, returning: 49.62V
19:47:23.503 > [DPL::loop] dcVoltage: 49.62 V, loadCorrectedVoltage: 49.62 V, StartTH: 48.50 V, StopTH: 47.60 V
19:47:23.508 > [DPL::loop] StartTH reached: no, StopTH reached: yes, SolarPT enabled, use at night: yes
19:47:23.517 > [DPL::calcHouseholdConsumption] target consumption: 25 W, base load: 120 W
19:47:23.521 > [DPL::calcHouseholdConsumption] power meter value: 1720.1 W, power meter valid: yes
19:47:23.526 > [DPL::calcHouseholdConsumption] inverter yyy is behind power meter producing 2 W
19:47:23.533 > [DPL::calcHouseholdConsumption] inverter zzz is behind power meter producing 2 W
19:47:23.536 > [DPL::calcHouseholdConsumption] inverter xxx is behind power meter producing 1 W
19:47:23.600 > [DPL::updateInverterLimits] requested: 1700 W, producing: 0 W using 0 solar-powered inverters, diff: 1700 W, hysteresis: 20 W
19:47:23.605 > [DPL::calcBatteryAllowance] power requested: 1700 W
19:47:23.610 > [DPL::calcBatteryAllowance] limited by battery (0 W) and/or solar power (0 W): 0 W
19:47:23.617 > [DPL::updateInverterLimits] requested: 0 W, producing: 5 W using 3 battery-powered inverters, diff: -5 W, hysteresis: 20 W
19:47:23.620 > [DPL::loop] consumption: 1700 W, target output: 1700 W (limited to 2400 W), solar inverters output: 0 W, battery allowance: 0 W, battery inverters output: 5 W

Anything else?

The provided log shows three MQTT updates which are also visible in the screenshot of the DPL settings. The fourth value is not updated, it remained at the previous value "75". There was no further log output than the one provided until I restarted the system via power off/on.

  • My complete system consists of four HM800 inverters, one connected directly to solar panels (HM-800@roof) and three connected to a Pylontech US5000 battery
  • the powermeter was set to SML/OBIS when the described incidence occurred but the problem also happened when the powermeter was set to MQTT
  • the DTU pollinterval was set at "1" second when the described incidence occurred but the problem also happened when the interval was at "3"
  • when searching for similar issues I stumbled over DTU web interface hängt sich auf  #893 but did not really see any relationship and it was closed without resolution

image
Screenshot From 2024-12-29 19-50-19
Screenshot From 2024-12-29 19-50-35

Please confirm the following

  • I believe this issue is a bug that affects all users of OpenDTU-OnBattery, not something specific to my installation.
  • I have already searched for relevant existing issues and discussions before opening this report.
  • I have updated the title field above with a concise description.
  • I have double checked that my inverter does not contain a W in the model name (like HMS-xxxW) as they are not supported.
@ali-baba-de ali-baba-de added the bug Something isn't working label Jan 1, 2025
@schlimmchen
Copy link
Member

I am far behind on my notifications, sorry about that. Good issue description, thanks!

Is it possible, that the MQTT payload for solar/powerlimiter/cmd/threshold/soc/start was the same as the current setting?

There should be only one other reason for why there is no message like "Setting battery SoC start threshold to: 75 %": The config write guard could not be acquired... And that should shortly cause a panic by the watchdog.

Strange.

Is the frequency of this issue increasing? Is your flash ruined by too many writes? If that was the case, we should still see the aforementioned message...

@ali-baba-de
Copy link
Author

thx for your investigation and no worries, the issue is a bit annoying but not too urgent as it does not happen very often :)
The frequency does not seem to increase; and how would I find out whether my flash is ruined? Everything else seems to be working fine...
The payload was definitely differently, my use case is too switch between two levels of voltage and soc (50.5/50.0-85/75 vs. 48.5/47.6-15/8) to optimize the usage of the battery at times when power is most expensive (we have a Tibber hourly price contract).
I have not found the time yet to try to reproduce the issue better but will hopefully be able to do that on the next weekend. Actually I was wondering whether the usage of a QoS of "1" instead of "0" might also prevent it?

@schlimmchen
Copy link
Member

I was wondering whether the usage of a QoS of "1" instead of "0" might also prevent it?

Afraid not, as the log tells us that the value was received, but processing it trips something up.

and how would I find out whether my flash is ruined?

That's a good question. Let's not focus on it for now, as it seems far-fetched. 4 updates per day should still get you 6 years of flash usage at the very least... Well, except that you send four new values each time, causing four writes per "HA cycle". So we are down to ~1.25 years. Is this anywhere close to the age of your ESP32?

Are you able to connect some sort of PC to log the output of the hardware serial console? There might be more info in there than in the web console.

Have you had the web console running for extensive amount of times? Try to observe the amount of free heap while you are doing so. Good point: Can you monitor the system stats published to the MQTT broker to see if the temperature gets excessive, or the heap is getting low right before the issue presents itself?

@ali-baba-de
Copy link
Author

So, jetzt komm ich endlich dazu, die gesammelten Daten zu sortieren und zu schicken :)
Und zwar hat es tatsächlich geklappt, den Fehler letztes Wochenende zu reproduzieren. Dazu habe ich statt der vorherigen vier geänderten Werte alle sieben in HA änderbaren Werte verändert, und zwar alle 20 Sekunden zwischen zwei jeweils verschiedenen Zuständen hin- und hergeschaltet. Nach 30-50 Umschaltungen trat das Problem dann auf.

  • beim ersten Mal (15:37:35) gab es nur einen kurzen Hänger von 35 Sekunden
    • was mir hier auffällt, ist dass die letzte Receive-Message noch ausgegeben wird, die zugehörige Setting-Message jedoch nicht mehr
  • beim zweiten Mal (15:49:30) hing das System wieder vollständig; leider hatte ich noch keine serielle Konsole angeschlossen, denn hier gab es dann einen ganz krassen Effekt. Das Board ging in den AP-Modus (mit einer neuen ID) und es waren alle Einstellungen gelöscht, d.h. vermutlich wurde so was ähnliches wie ein Factory Reset ausgelöst. Das hatte ich bis jetzt auch noch nicht... Die Stromversorgung für die DTU schafft 2,4A, das war noch nie ein Problem, aber ich bin jetzt nicht sicher, ob das auch eine Rolle gespielt haben kann. Die Wiederherstellung war kein Problem, habe Backups der Konfiguration, so gesehen in der Hinsicht ein erfolgreicher Test :D
  • beim dritten Mal (16:55:47, diesmal mit tty-log) hing das System wieder, wobei (nur) der PowerMeterSerialSml-Log weiterlief. Nach kurzer Zeit bootete das Board von selbst, war danach aber immer noch nicht per Web-Konsole erreichtbar (das lag aber vielleicht auch an mir, hab vermutlich nur F5 gedrückt und nicht CTRL-F5). Nach einem Strom aus/an war es wieder "normal". Ich hab dann die 2025.01.10-Firmware drauf gespielt, seit dem ist das Problem nicht wieder aufgetreten.

Zu deinen Fragen:

  • freien Heap-Space habe ich in HA geprüft, der war meiner Ansicht nach i.O.
  • die Temperatur ist während des Testens tatsächlich angestiegen, sieht aber auch nicht kritisch aus. Ich häng die Charts mit dran...
  • und das Board ist jetzt ein gutes Jahr alt (es ist eine OpenDTU von BlinkyParts, 4MB Flash), der Update der Settings via MQTT läuft mit zwei Werten seit ca. 6 Monaten (da gab es das Problem ja nie, zumindest keine vollständigen Hänger), mit vier Werten seit 01.12.24. D.h. dürfte noch nicht kritisch sein?

Freier Heap-Space:
Image

Temperatur:
Image

Console-Log Hänger Nr. 1:
https://pastebin.com/dRZXknEm

Console-Log Hänger Nr. 2:
https://pastebin.com/HCi8wM3f

Console-Log Hänger Nr. 3:
https://pastebin.com/EkqbmVgS

tty-Log Hänger Nr. 3 (ab Zeile 3041):
https://pastebin.com/BTFuBJGk

Happy Hunting, wenn du mal Zeit und Lust drauf hast :) - die Prio ist wirklich nicht sehr hoch, ich bin auch so total glücklich mit dem Projekt, kann gar nicht oft genug danke sagen dafür!

@ali-baba-de
Copy link
Author

eins noch... falls das Problem bis Ende Januar tatsächlich nicht mehr auftreten sollte, werde ich den Issue zumachen

@schlimmchen
Copy link
Member

ich bin auch so total glücklich mit dem Projekt, kann gar nicht oft genug danke sagen dafür!

❤️

Der Backtrace

abort() was called at PC 0x401ec56f on core 0
 
Backtrace: 0x400840ed:0x3ffef420 0x4008fb61:0x3ffef440 0x40095f31:0x3ffef460 0x401ec56f:0x3ffef4e0 0x401ec5b6:0x3ffef500 0x401ec8fb:0x3ffe0

ELF file SHA256: 38eee8b326b2eef7

ergibt wohl

0x400840ed: panic_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/panic.c:408
0x4008fb61: esp_system_abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/esp_system/esp_system.c:137
0x40095f31: abort at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/newlib/abort.c:46
0x401ec56f: __cxxabiv1::__terminate(void (*)()) at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/gcc/libstdc++-v3/libsupc++/eh_terminate.cc:50
0x401ec5b6: std::get_unexpected() at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/gcc/libstdc++-v3/libsupc++/eh_terminate.cc:119
0x401ec8fb: __cxa_rethrow at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/gcc/libstdc++-v3/libsupc++/unwind-cxx.h:346
 (inlined by) __cxa_rethrow at /builds/idf/crosstool-NG/.build/xtensa-esp32-elf/src/gcc/libstdc++-v3/libsupc++/eh_throw.cc:110

Plausibel, aber leider nichtssagend.

Es bleibt dabei, dass sich das Teil irgendwie beim Schreiben der Konfig verklemmt. Die anderen Tasks, bei dir beispielsweise der SML Power Meter Task, laufen normal weiter.

Ich hab dann die 2025.01.10-Firmware drauf gespielt, seit dem ist das Problem nicht wieder aufgetreten.

Hm... Ich kann mir mögliche Gründe ausdenken, aber keine konkreten. Kann schon sein, dass in einer Bibliothek etwas repariert wurde, dass hier hilft. Dann beobachten wir mal, ob dein Problem wieder auftaucht. 👍

@ali-baba-de
Copy link
Author

jetzt ist es leider doch wieder passiert, zwar kein kpl. Stall, aber es wurde zwei Mal nur der erste MQTT-Wert übernommen. Außerdem ist mir aufgefallen, dass es in der Config einen SaveCount gibt; der steht zur Zeit auf ca. 3000, d.h. (hoffentlich) nicht kritisch.

Copy link

github-actions bot commented Feb 6, 2025

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@github-actions github-actions bot added the stale label Feb 6, 2025
@ali-baba-de
Copy link
Author

Two weeks ago I switched from a HA scene for the limits to a script with a 3 second delay between setting each value. Since then no more problems... maybe a timing issue still? Anyway, I close the issue, thx a lot for your support!

@schlimmchen
Copy link
Member

Interesting... Thanks for coming back to us and sharing that information. I will keep this in mind that frequent MQTT updates can potentially cause issues.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working stale
Projects
None yet
Development

No branches or pull requests

2 participants