3.4 b10 not reading all entities from Heat Pump anymore (NTP flooding EMS bus?)

[mvjt]

Bug description
Later/Latest version is not consistent in generating entities. One day I have 95/40, another day 75/25 etc. Right now, 5 minutes after reboot, I´m missing a lot of entities. I've touched the HP display to try to make it force send, but this does not help. I'm pretty sure this worked much better in previous versions. I have 100% quality in the EMS connection. The error log has quite a few 2022-04-03 08:58:48.841 E 20: [emsesp] Last Tx write rejected by host which I've never seen before...

Steps to reproduce
Don't know. In general, after reboot, different amount of entities can be detected. This morning, before reboot I had > 95 entities for the boiler and 40 for the thermostat. 5-10 min after reboot I only have 75/25.

Expected behavior
Read same amount of entities every time.

Screenshots

Device information
{ "System": { "version": "3.4.0b10", "uptime": "000+00:05:18.427", "uptime (seconds)": 318, "freemem": 115, "reset reason": "Software reset CPU / Software reset CPU", "temperature sensors": 0 }, "Network": { "connection": "Ethernet", "hostname": "ems-esp", "MAC": "8C:CE:4E:95:50:97", "IPv4 address": "10.10.10.121/255.255.255.0", "IPv4 gateway": "10.10.10.1", "IPv4 nameserver": "10.10.10.1" }, "Status": { "bus status": "connected", "bus protocol": "Buderus", "bus telegrams received (rx)": 2555, "bus reads (tx)": 438, "bus writes (tx)": 409, "bus incomplete telegrams": 0, "bus reads failed": 0, "bus writes failed": 0, "bus rx line quality": 100, "bus tx line quality": 100, "MQTT status": "connected", "MQTT publishes": 842, "MQTT publish fails": 0, "temperature sensors": 0, "temperature sensor reads": 0, "temperature sensor fails": 0, "analog sensors": 0, "API calls": 6, "API fails": 0 }, "Devices": [ { "type": "Boiler", "name": "Enviline/Compress 6000AW/Hybrid 7000iAW/SupraEco/Geo 5xx", "device id": "0x08", "product id": 172, "version": "02.03", "entities": 75, "handlers received": "0xD1 0xE3 0xE4 0xE5 0xE9 0x0494 0x0495 0x048F", "handlers fetched": "0x048D", "handlers pending": "0x10 0x11 0xC2 0x15 0x1C 0x18 0x19 0x1A 0x35 0x34 0x2A" }, { "type": "Thermostat", "name": "Rego 2000/3000", "device id": "0x10", "product id": 172, "version": "02.03", "entities": 21, "handlers received": "0x06", "handlers fetched": "0x02A5 0x02B9 0x02A6 0x02BA", "handlers pending": "0xA3 0xA2 0x12 0x02AF 0x029B 0x02B0 0x029C 0x02A7 0x02BB 0x02B1 0x029D 0x0473 0x02A8 0x02BC 0x02B2 0x029E 0x0474 0x02A9 0x02BD 0x02B3 0x029F 0x0475 0x02AA 0x02BE 0x02B4 0x02A0 0x0476 0x02AB 0x02BF 0x02B5 0x02A1 0x0477 0x02AC 0x02C0 0x02B6 0x02A2 0x0" }, { "type": "Gateway", "name": "KM200/MB LAN 2", "device id": "0x48", "product id": 189, "version": "04.08", "entities": 0 }, { "type": "Controller", "name": "Rego 3000", "device id": "0x09", "product id": 240, "version": "38.03", "entities": 0 } ] }

Additional context

2022-04-03 08:51:21.814 E 10: [emsesp] Last Tx write rejected by host
2022-04-03 08:52:08.827 E 11: [emsesp] Last Tx write rejected by host
2022-04-03 08:52:19.189 E 12: [emsesp] Last Tx write rejected by host
2022-04-03 08:52:46.827 E 13: [emsesp] Last Tx write rejected by host
2022-04-03 08:53:16.827 E 14: [emsesp] Last Tx write rejected by host
2022-04-03 08:56:14.840 E 15: [emsesp] Last Tx write rejected by host
2022-04-03 08:56:30.840 E 16: [emsesp] Last Tx write rejected by host
2022-04-03 08:56:36.840 E 17: [emsesp] Last Tx write rejected by host
2022-04-03 08:57:18.840 E 18: [emsesp] Last Tx write rejected by host
2022-04-03 08:57:38.840 E 19: [emsesp] Last Tx write rejected by host
2022-04-03 08:58:48.841 E 20: [emsesp] Last Tx write rejected by host
2022-04-03 09:01:24.841 E 21: [emsesp] Last Tx write rejected by host

Boiler
{ "heatingactive": "off", "tapwateractive": "off", "selflowtemp": 32, "selburnpow": 40, "heatingpump2mod": 67, "outdoortemp": 0.2, "curflowtemp": 30.6, "rettemp": 48.3, "syspress": 0, "burngas": "off", "flamecurr": 0, "heatingpump": "off", "fanwork": "off", "ignwork": "off", "curburnpow": 67, "servicecodenumber": 0, "uptimecontrol": 136764, "uptimecompheating": 124964, "uptimecompcooling": 0, "uptimecompww": 11799, "uptimecomppool": 0, "totalcompstarts": 969, "heatingstarts": 757, "coolingstarts": 0, "wwstarts2": 212, "poolstarts": 0, "nrgconstotal": 1525, "nrgconscomptotal": 1521, "nrgconscompheating": 1264, "nrgconscompww": 257, "nrgconscompcooling": 0, "nrgconscomppool": 0, "auxelecheatnrgconstotal": 4, "auxelecheatnrgconsheating": 0, "auxelecheatnrgconsww": 4, "auxelecheatnrgconspool": 0, "nrgsupptotal": 6913, "nrgsuppheating": 6083, "nrgsuppww": 830, "nrgsuppcooling": 0, "nrgsupppool": 0, "hppower": 3.2, "hpcompon": "on", "hpactivity": "hot water", "hpheatingon": "off", "hpcoolingon": "off", "hpwwon": "on", "hppoolon": "off", "hpbrinepumpspd": 53, "hpswitchvalve": "off", "hpcompspd": 67, "hpcircspd": 10, "hpbrinein": 6.9, "hpbrineout": 4.4, "hpsuctiongas": 8.9, "hphotgas": 72.5, "hptc0": 48.3, "hptc1": 52.2, "hptc3": 50.1, "hptr3": 48, "hptl2": 0, "hppl1": -2.2, "hpph1": 52.8, "wwsettemp": 58, "wwcirc": "on", "wwcurtemp": 50.5, "wwcurtemp2": 50, "wwonetime": "off", "wwdisinfecting": "off", "wwcharging": "on", "wwrecharging": "off", "wwtempok": "on", "ww3wayvalve": "on", "wwstarts": 0, "wwworkm": 0 }

Thermostat
{ "datetime": "08:08:45 03.04.2022", "hc1": { "seltemp": 21, "mode": "manual", "modetype": "eco", "ecotemp": 15, "manualtemp": 21, "comforttemp": 21, "designtemp": 42, "minflowtemp": 22, "maxflowtemp": 42, "targetflowtemp": 0, "summermode": "off", "tempautotemp": -1, "fastheatup": 0 }, "hc2": { "seltemp": 21, "mode": "manual", "modetype": "eco", "ecotemp": 15, "manualtemp": 21, "comforttemp": 21, "targetflowtemp": 0, "summermode": "off", "tempautotemp": -1 } }

[mvjt]

Just rebooted again. Boiler entities went up to 75, when "Loading" was stuck when I refreshed, and all of a sudden the entitiy incrementation started all over again. And after that, I have 94/21 entities. So it is really inconsistent.

Boiler after second restart
{ "heatingactive": "off", "tapwateractive": "off", "selflowtemp": 29, "selburnpow": 39, "heatingpump2mod": 38, "outdoortemp": 5.1, "curflowtemp": 30.2, "rettemp": 28.1, "syspress": 0, "burngas": "off", "flamecurr": 0, "heatingpump": "off", "fanwork": "off", "ignwork": "off", "heatingactivated": "on", "heatingtemp": 80, "burnminperiod": 0, "burnminpower": 0, "burnmaxpower": 0, "boilhyston": 0, "boilhystoff": 0, "curburnpow": 38, "ubauptime": 186909, "lastcode": "A11(1051) 20.03.2022 12:46 - 20.03.2022 12:52", "servicecodenumber": 0, "uptimecontrol": 136782, "uptimecompheating": 124972, "uptimecompcooling": 0, "uptimecompww": 11810, "uptimecomppool": 0, "totalcompstarts": 970, "heatingstarts": 758, "coolingstarts": 0, "wwstarts2": 212, "poolstarts": 0, "nrgconstotal": 1526, "nrgconscomptotal": 1522, "nrgconscompheating": 1264, "nrgconscompww": 258, "nrgconscompcooling": 0, "nrgconscomppool": 0, "auxelecheatnrgconstotal": 4, "auxelecheatnrgconsheating": 0, "auxelecheatnrgconsww": 4, "auxelecheatnrgconspool": 0, "nrgsupptotal": 6914, "nrgsuppheating": 6083, "nrgsuppww": 831, "nrgsuppcooling": 0, "nrgsupppool": 0, "hppower": 2.1, "hpcompon": "on", "hpactivity": "heating", "hpheatingon": "on", "hpcoolingon": "off", "hpwwon": "off", "hppoolon": "off", "hpbrinepumpspd": 32, "hpswitchvalve": "off", "hpcompspd": 38, "hpcircspd": 8, "hpbrinein": 7.4, "hpbrineout": 4.8, "hpsuctiongas": 10.1, "hphotgas": 56.5, "hptc0": 28.1, "hptc1": 33.3, "hptc3": 32.2, "hptr3": 28.3, "hptl2": 0, "hppl1": -1.3, "hpph1": 32.6, "poolsettemp": 28, "wwsettemp": 58, "wwseltemp": 52, "wwseltemplow": 50, "wwseltempsingle": 65, "wwcircpump": "on", "wwhyston": 0, "wwhystoff": 0, "wwdisinfectiontemp": 65, "wwcircmode": "continuous", "wwcirc": "on", "wwcurtemp": 52.3, "wwcurtemp2": 51.9, "wwactivated": "on", "wwonetime": "off", "wwdisinfecting": "off", "wwcharging": "off", "wwrecharging": "off", "wwtempok": "off", "ww3wayvalve": "off", "wwstarts": 0, "wwworkm": 0 }

[mvjt]

And now I have 94/35

{ "datetime": "09:03:56 03.04.2022", "dampedoutdoortemp": 8, "building": "light", "minexttemp": -20, "wwmode": "low", "wwcircmode": "off", "wwchargeduration": 60, "wwcharge": "off", "wwdisinfecting": "off", "wwdisinfectday": "so", "wwdisinfecttime": 120, "hc1": { "seltemp": 21, "mode": "manual", "modetype": "eco", "ecotemp": 15, "manualtemp": 21, "comforttemp": 21, "summertemp": 18, "targetflowtemp": 0, "summersetmode": "auto", "summermode": "off", "tempautotemp": -1 }, "hc2": { "seltemp": 21, "mode": "manual", "modetype": "eco", "ecotemp": 15, "manualtemp": 21, "comforttemp": 21, "summertemp": 18, "targetflowtemp": 0, "summersetmode": "auto", "summermode": "off", "tempautotemp": -1 } }

[proddy]

are you getting the information pasted above from the API calls http://ems-esp.local/api/thermostat and http://ems-esp.local/api/boiler ? The first is the boiler, the second is the thermostat.

[MichaelDvP]

Uptime 318s, most of the handlers pending. People are always so impatient.

2022-04-03 08:51:21.814 E 10: [emsesp] Last Tx write rejected by host

For this we need a detailed log.

[mvjt]

are you getting the information pasted above from the API calls http://ems-esp.local/api/thermostat and http://ems-esp.local/api/boiler ? The first is the boiler, the second is the thermostat.

Yes. In original post I highlighted in bold before the payload. The second comment was the thermostat. Both coming from the API calls.

Its been three hours now and I still only have 35/40 from the thermostat.

What type of detailed log do you need?

[MichaelDvP]

In system info you have Uptime 318 seconds, bus reads (tx)": 438, "bus writes (tx)": 409. Something is sending more than 1 command and more than one read per second to the bus. The ems-bus normally handles ~3 messages per second, normal communication seems to be blocked by the ems-esp activity. Check with log all what's happening on the bus.

[mvjt]

From the log

Seems to be related to NTP and RCTime...Maybe this is why the GW is suddenly showing all kinds of weird issues. Because it lacking resources...For now (after extracting the log below), I've enabled ReadOnly mode in settings and disabled NTP...

After disabling TX (enabling REadOnly) and disabling NTP, all of a sudden I have all entities 94/51...And no Last Tx write rejected by host after restart...

000+00:08:42.554 N 349: [emsesp] Me(0x0B) -> Thermostat(0x10), RCTime(0x06), data: 16 04 0C 03 01 2B 06 03 000+00:08:42.752 N 350: [emsesp] Me(0x0B) <- Thermostat(0x10), RCTime(0x06), data: 1B 000+00:08:42.794 N 351: [emsesp] Thermostat(0x10) -> Me(0x0B), RCTime(0x06), data: 96 04 0C 03 01 00 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 000+00:08:42.794 I 352: [thermostat] thermostat time correction from ntp 000+00:08:43.092 N 353: [emsesp] Me(0x0B) -> Thermostat(0x10), RCTime(0x06), data: 16 04 0C 03 01 2C 06 03 000+00:08:43.377 N 354: [emsesp] Me(0x0B) <- Thermostat(0x10), RCTime(0x06), data: 1B 000+00:08:43.419 N 355: [emsesp] Thermostat(0x10) -> Me(0x0B), RCTime(0x06), data: 96 04 0C 03 01 00 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 000+00:08:43.419 I 356: [thermostat] thermostat time correction from ntp 000+00:08:43.717 N 357: [emsesp] Me(0x0B) -> Thermostat(0x10), RCTime(0x06), data: 16 04 0C 03 01 2C 06 03 000+00:08:44.402 N 358: [emsesp] Me(0x0B) <- Thermostat(0x10), RCTime(0x06), data: 1B 000+00:08:44.444 N 359: [emsesp] Thermostat(0x10) -> Me(0x0B), RCTime(0x06), data: 96 04 0C 03 01 00 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 000+00:08:44.444 I 360: [thermostat] thermostat time correction from ntp 000+00:08:44.654 N 361: [emsesp] Me(0x0B) -> Thermostat(0x10), RCTime(0x06), data: 16 04 0C 03 01 2D 06 03 000+00:08:44.852 N 362: [emsesp] Me(0x0B) <- Thermostat(0x10), RCTime(0x06), data: 1B 000+00:08:44.894 N 363: [emsesp] Thermostat(0x10) -> Me(0x0B), RCTime(0x06), data: 96 04 0C 03 01 00 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 000+00:08:44.894 I 364: [thermostat] thermostat time correction from ntp 000+00:08:45.192 N 365: [emsesp] Me(0x0B) -> Thermostat(0x10), RCTime(0x06), data: 16 04 0C 03 01 2E 06 03 000+00:08:45.402 N 366: [emsesp] Me(0x0B) <- Thermostat(0x10), RCTime(0x06), data: 1B 000+00:08:45.444 N 367: [emsesp] Thermostat(0x10) -> Me(0x0B), RCTime(0x06), data: 96 04 0C 03 01 00 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 000+00:08:45.444 I 368: [thermostat] thermostat time correction from ntp

[proddy]

if you disable NTP do you get back all the entities?

[mvjt]

if you disable NTP do you get back all the entities?

Previously I disabled both TX and NTP at the same time. Now I re-enabled TX only but kept NTP off, and I get the same flooded log again including It seems I need to disable TX (enable read-only) to not get NTP flooding...It seems it does not matter if NTP is enabled or not in settings...It still tries to synchronize time and I get the "ntp correction..." and RCTime flooding as soon as TX is enabled...

To be honest, I'm confused what is causing what. But it seems clear it was NTP and RCTime related flooding causing issues...

[proddy]

yes I think so too, I'm confident Michael will know what is going on here

[MichaelDvP]

The problem is, that this thermostat clock always returns seconds zero and give a difference to esp-clock. We need to check this before setting the time.
Check NTP status, if it show status inactive, the thermostat is not synct, i tried it here.

[mvjt]

Seems not true in my case. NTP is disabled but it still tries to sync time (new inPrivate Window). But if I disable TX it stops attempting to sync...

[mvjt]

Could there be two issues?:

1. This thermostat does not return what you expect and
2. No check if NTP is enabled or not here?
   

   EMS-ESP32/src/devices/thermostat.cpp

   Line 1183 in 29110e9

   if (telegram->message_data[7] & 0x0C) { // date and time not valid

[proddy]

#2 you're looking at the wrong branch, the ntp check is there:

EMS-ESP32/src/devices/thermostat.cpp

Line 1248 in 0bd122b

if (tset_ && EMSESP::system_.ntp_connected() && !EMSESP::system_.readonly_mode() && has_command(&dateTime_)) {

[mvjt]

WTF :-) Seem my version was from Friday evening can be considered old. Yesterday there was changes around NTP...Loading the FW from yesterday at least disabling NTP works as it should. So that problem is gone. So it seems the remaining issue is what @MichaelDvP identified around IVT/Bosch always reporting second as 0 causing the flood of attempts and unstable GW?

[proddy]

also, just to rule out memory issues (see #318) since you're on Ethernet make sure the WiFi SSID is empty (in settings) and also the Access Point is set to ''when Wifi disconnected"

[mvjt]

Not possible to clear WiFi SSID...But "When WiFi Disconnected" has always been set.

[MichaelDvP]

Are the [emsesp] Last Tx write rejected by host also releated to the time setting?
Please send a log where i can see the telegrams that are rejected.
Maybe the rego thermostat ismuch more different from RC300 and needs an extra flag to make time non writeable etc..

[mvjt]

@MichaelDvP yes they were related. At least I don´t get them when not using NTP. I will try to get logs...But I believe I only got it after restart of GW...Maybe the Last TX Write rejected was related to the fact that the EMS bus was flooded...Let me know the day when the 00-second issue might be fixed and I'll try it out :-)

[mvjt]

One interesting observation is that the date/time reported to EMS is 17:28 right now with correct date. So it is 20 minutes behind. But the clock on the HP display is correct...

[MichaelDvP]

You can try with this build, i've fixed a bug in time checking for IVT and disabled the automatic clock correction for IVT.
Please enable ntp and tx. Then try to log all and set from dashboard the datetime to "ntp"

and to time input (with day-of-week and daylightsaving)

log a minute longer, the clock normally is send out by thermostat every minute, but your IVT seems to stop broadcasting some telegrams if display sleeps, so we may need to fetch the clock active to get the thermostat time.

[mvjt]

Thanks @MichaelDvP.

Awesome! The ntp flooding is now gone!

I think I've done what you asked for. I changed value to "ntp" and later on a second time to a static time/date with your second syntax and waited a minutes (ish). All recorded with full logging.

[MichaelDvP]

Please the full log, but drag&drop the txt-file here as attachment.

[MichaelDvP]

Thanks, the thermostat does not broadcast any telegram i can't find Thermostat(0x10) -> All(0x00). So we have to set all telegrams to fetch. Also the thermostat ignores/changes offsets in tx-reads and fills the telgrams with zeros to requested lenght.
Very strange. Need to think about this.

I think I've done what you asked for. I changed value to "ntp" and later on a second time to a static time/date with your second syntax and waited a minutes (ish). All recorded with full logging.

Yes, thats what i want from you, thanks .But i can only see one change:

2022-04-03 18:58:52.647 TRACE 1821: [emsesp] Me(0x0B) -> Thermostat(0x10), RCTime(0x06), data: 16 04 12 03 3A 30 06 03
2022-04-03 18:58:52.647 DEBUG 1822: [emsesp] Process setting 0x06 for device 0x10
2022-04-03 18:58:52.654 DEBUG 1823: [emsesp] Last Tx write successful

Seems that writing the time is possible. But the thermostat reply is with seconds set to zero and wrong dst.

2022-04-03 18:58:52.983 TRACE 1828: [emsesp] Me(0x0B) <- Thermostat(0x10), RCTime(0x06), data: 1B
2022-04-03 18:58:53.024 DEBUG 1829: [emsesp] Last Tx read successful
2022-04-03 18:58:53.024 TRACE 1830: [emsesp] Thermostat(0x10) -> Me(0x0B), RCTime(0x06), data: 96 04 12 03 3A 00 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

[mvjt]

OK. Sounds good. Right now I only have 39 thermostat entities. I had 51 before this FW upgrade. Is it most recent code in general?

[mvjt]

Yes we noticed in our other issue that it seems to only send for a short while after the display has been touched. When I wake up the display. Seems controller is the source of time, not the thermostat...

2022-04-03 20:37:46.711 DEBUG 20470: [emsesp] No telegram type handler found for ID 0xF7 (src 0x08) 2022-04-03 20:37:47.066 TRACE 20471: [emsesp] Controller(0x09) -> All(0x00), RCTime(0x06), data: 16 04 14 03 24 2B 06 01 09 FF 00 2022-04-03 20:37:47.066 DEBUG 20472: [emsesp] No telegram type handler found for ID 0x06 (src 0x09) 2022-04-03 20:37:47.965 TRACE 20473: [emsesp] Controller(0x09) <- Thermostat(0x10), ?(0xF9), data: 11 FF 01 B9 0A 2022-04-03 20:37:48.004 TRACE 20474: [emsesp] Thermostat(0x10) -> Controller(0x09), ?(0xF9), data: FF 01 B9 0A 17 00 00 00 0A 00 00 00 2A 00 00 00 3C 00 00 00 2A 2022-04-03 20:37:48.004 DEBUG 20475: [emsesp] No telegram type handler found for ID 0xF9 (src 0x10) 2022-04-03 20:37:48.036 TRACE 20476: [emsesp] Controller(0x09) <- Thermostat(0x10), RC300Summer(0x02AF), data: 0A (offset 4) 2022-04-03 20:37:48.057 TRACE 20477: [emsesp] Thermostat(0x10) -> Controller(0x09), RC300Summer(0x02AF), data: 37 2A 00 00 15 1E 00 00 00 15 (offset 4) 2022-04-03 20:37:48.078 TRACE 20478: [emsesp] Controller(0x09) <- Thermostat(0x10), RC300Curves(0x029B), data: 02 (offset 7) 2022-04-03 20:37:48.098 TRACE 20479: [emsesp] Thermostat(0x10) -> Controller(0x09), RC300Curves(0x029B), data: 2A 37 (offset 7)

[MichaelDvP]

[emsesp] Controller(0x09) -> All(0x00), RCTime(0x06), data: 16 04 14 03 24 2B 06 01 09 FF 00

This clock has normal year data, seconds and DST set. Are there more telegrams broadcasted from the contoller? (containing: Controller(0x09) -> All(0x00))
I think i would be helpfull to make full logs of some minutes, one after the display is touched, one later after the thermostats stops broadcasting..

[mvjt]

Seems RCTime is broadcasted every minute by the controller even without touching the display. I have not touched it since yesterday and it was still sending every minute...The only other thing it is broadcasting is an error message

Controller(0x09) -> All(0x00), ErrorMessage(0xBF), data: 09 F0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

[proddy]

@MichaelDvP what do we need to do here?

[MichaelDvP]

Without knowing settings/info/entities and without complete logs we can do nothing.
We don't know which telegrams are not broadcasted in thermostat sleep and which entities are not updated/missing.
I think you can close this.