HomeAssistant Logfile overflowing with ems-esp-messages

[marc1de]

When I was experimenting with GPIO-inputs and GPIO-counters (see issue #327), I realized, that my HomeAssistant-Log gets spammed with messages:

Diving deeper into the logs I found repeating messages like this:

First I thought, this was due to an unknown state of the inputs, so I toggled the GPIO-Pins at the ems-esp. But that didn't help, the messages continued (One message every 10 sek. and the errorcounter rises by 10. So the event takes place ever 1 sek. / mqtt-reporting interval in ems-esp was set to 10sek!)

I tried to analyse the messages with MQTT-Explorer, but that added more confusion: All reported GPIO's contain a value .... and just more confusing: it contained the GPIO13 - which didn't appear in the HA-Logs ?!?

I know, that there surely exists the possibility to suppress this messages in HA, but due to the fact, that this messages were caused by the Sensors within ems-esp, I tought it was worth, reporting this here

My system:
Home Assistant: core-2121.12.10 on rpi (image)
HA-Supervisor-2021.12.2

ems-esp: special-Testversion of v3.4.0b2 (see #329) from MichaelDVP

Note: did several restartes of HA and ems-esp, tried to clear logfiles and also tried to delete the entities via MQTT-Browser. Nothing helped. Errormessages always reappear)

GPIO32 is configured as counter, all other GPIOS were inputs

[proddy]

I'm not sure why HA is reporting the errors. The config topics look correct and the data is available in the analogsensor_data topic.

It could be a template parsing problem which you can test in HA by going to Developer Tools->Template and in the editor write some Jinja2 code like

{% set analogsensor_data = {"39":{"name":"hello","value":2}} %}

value is {{ analogsensor_data['39'].value }}

but replacing with your real data from those screenshots

[MichaelDvP]

Could it be that HA is confused by number/string of the json? Maybe worth to try renaming from "39" to "io39"?

[proddy]

it works for me and my sensors. A good check is the HA template editor. Let's see what Marc comes back with

[marc1de]

@proddy:
well, i was just experimenting with that, but I'm not shure if I understood you correct.
Did you meant to put in the the Template editor ("Entwicklerwerzeuge/Template/Template Editor")
tought that is only for syntax-checking...
but tried to insert this:

{% set analogsensor_data = {"33":{"name":"GPIO33","value":7}} %}
value is {{ analogsensor_data['33'].value }}

but that had no effect in the logs.

After that, I tried to put it in my: /config/configuration.yaml
but that entry was not accepted (never shure wich format or template/entity to use - I'm always struggling with that damn syntax-format)
maybe you can give me a full example of how to integrate it there (eg: under "sensor or template"?)

but - other idea- ... I was just suspecting that it maybe dislikes the double quotes (") instead of the single ones('):

Until now i thought, HA accepts both variants.......but maybe it' not that tolerant in all situations than I tought.

[proddy]

there's no difference between single and double quotes in HA.

And you don't need to add anything to the yaml files, it should just work 'out of the box' so to speak.

Send me the contents of your ems-esp/analogsensor_data and homeassistant/analogsensor_15 and I'll see if it works on my system and show you what you can cut & paste into the Template tester in ha to verify it works.

[marc1de]

hmmm,... just not shure if I could understand:
Send me the contents of your ems-esp/analogsensor_data and homeassistant/analogsensor_15

How can I get this Information? In HA there are no such files.
All have is this screenshot from my MQTT-Browser (or did you mean to login via ssh to the ems-esp to find the configs there?)

and when I enter your code into the template editor it looks like this:

and this is the result:

but this had no effect in the log-files. The error will continue to be reported.

BTW: I was suspecting, that the error was caused by the data, that was provided by the ems-esp via mqtt. What confuses me, is that this mostly occurs with the analogsensor_data.

[proddy]

I wanted the copy&paste data from MQTTExplorer so I didn't have to manually type it from those screenshots you sent. But you tested the template and it works, as it showed the value of 7. Note the HA Template editor in the Home Assistant Development Tools is just for trying and testing things out. It has no effect on the running of HA so you would not find anything in the logs.

I can't find anything wrong. You config looks fine. It should work.

Are you sure you deleted everything in the MQTT broker? When you said

also tried to delete the entities via MQTT-Browser

did you really use MQTTExplorer and delete everything under homeassistant/ ? Try that again please.

[marc1de]

@proddy: thanks for your detailed explanation (ah, and sorry for the screenshots. I always prefer to "copy and paste" - and originaly I intended to give you the plain text: I just gave you the pictures because I had trouble copying the text in the left side of MQTT-Explorer.....but now I have discoverd, that I simply could have copied it from the right side to get it in textformat.)

analogsensor_32
config= {"stat_t":"ems-esp/analogsensor_data","val_tpl":"{{value_json['32'].value}}","name":"Analog Sensor GPIO32","uniq_id":"analogsensor_32","dev":{"ids":["ems-esp"]}}
analogsensor_33
config= {"stat_t":"ems-esp/analogsensor_data","val_tpl":"{{value_json['33'].value}}","name":"Analog Sensor GPIO33","uniq_id":"analogsensor_33","dev":{"ids":["ems-esp"]}}

and well: yes, I think I was very accurate in taking care to produce reliable results:
to be absolutely shure to avoid old entries I did this:

• disabled "mqtt" and disabled "mqtt-discover"in ems-esp, then saved
  (retain flag was not set, Quality of service is: 0)
• cleared logfiles in HA
• cleared all entities under "homeassistant in" MQTT-Explorer
  (and sometimes I additionally deleted the sensors in ems-esp too and recreated them completely new)
• restarted HASS (did it in the Menu "Fileexplorer")
• enabled "mqtt" and enabled "mqtt-discover"in ems-esp, then saved again

This time I repeated the steps plus did a complete Restart of HA-Server:
but still the same errors:

(as you can see there is another mysterios error that I have no explanation for):

Invalid value for number.boiler_burner_selected_max_power: 123 (range 0.0 - 100.0)
17:36:04 – (FEHLER) MQTT - Die Nachricht ist zum ersten Mal um 17:27:24 aufgetreten und erscheint 53 mal

in MQTT-Explorer:

boiler_selburnpow
config= {"~":"ems-esp","uniq_id":"boiler_selburnpow","command_topic":"~/boiler/selburnpow","min":0,"max":100,"ic":"mdi:percent-outline","stat_t":"~/boiler_data","name":"Boiler burner selected max power","val_tpl":"{{value_json.selburnpow}}","unit_of_meas":"%","dev":{"ids":["ems-esp-boiler"]}}

and thats what is contained in the data:

ems-esp
boiler_data= {"heatingactive":"on","tapwateractive":"off","selflowtemp":46,"selburnpow":40,"heatingpumpmod":10,"outdoortemp":8.7,"curflowtemp":48.1,"burngas":"on","flamecurr":21.1,"heatingpump":"on","fanwork":"on","ignwork":"off","heatingactivated":"on","heatingtemp":68,"burnminperiod":10,"burnmaxpower":40,"setflowtemp":46,"curburnpow":25,"burnstarts":265350,"burnworkmin":1255909,"heatworkmin":1046502,"ubauptime":3987806,"lastcode":"6A(227) 13.07.2021 12:56 (0 min)","servicecode":"-H","servicecodenumber":200,"maintenancemessage":"H00"}

I was now thinking of: defining the complete Analog_sensor manually in configuration.yaml (maybe with dummy-startvalue 99) and see if it helps (and hoping, that this won't conflict with the discovery).
Problem is: im still struggling with the syntax in yaml and didn't succeed yet.....but i'm still fighting and will report if I finaly succeed.

P.S.: this was my old configuratio.yaml that I used with the tests:
my_configuration.yaml.txt

[marc1de]

In issue 327 MichaelDVP solved the problem with the GPIO's. But still there are some other error messages that might have a similar cause:

The reason for the GPIO errors was, that HA expects "full topic reports" from mqtt. If only one attribute is missing in such an report, it throws an error in HA.
My suspicion is, that -after a restart of ems-esp-: some of this attributes are missing while ems-esp is still busy with detecting the Boiler and Thermostate entities.

But let's have a detailed look into the error messages:

and here is another one:

Above were the messages, that I think might be related to the "startup" of ems-esp while not all entities were fully discovered (because when i looked with mqtt-explorer, the data seemed to be ok).

{"heatingactive":"off","tapwateractive":"off","selflowtemp":48,"selburnpow":40,"heatingpumpmod":10,"outdoortemp":4.8,"curflowtemp":42.8,"burngas":"off","flamecurr":0,"heatingpump":"on","ignwork":"off","heatingactivated":"on","heatingtemp":68,"burnminperiod":10,"burnmaxpower":40,"setflowtemp":48,"curburnpow":0,"burnstarts":265647,"burnworkmin":1257516,"heatworkmin":1047932,"ubauptime":3990835,"lastcode":"6A(227) 13.07.2021 12:56 (0 min)","servicecode":"0Y","servicecodenumber":204,"maintenancemessage":"H00"}
.

The next error messages will probably have another cause:

did the unit of this value recently change? Or is it maybe caused because the initial definiton had a unit and the statusreport did not?
.

and here follows an error message where some values seem to have the wrong format:

[proddy]

@marc1de the HA error for the heatingtype and set summer mode I'd like to investigate. Is this happening all the time or only when either MQTT or EMS-ESP is restarted?

The other issues are indeed just how HA works with EMS-ESP, if you're using MQTT with persistence and not retaining the messages. HA has the config but can't find the data until its loaded. We could think about not retaining the HA config topics at some point

[MichaelDvP]

@marc1de

My suspicion is, that -after a restart of ems-esp-: some of this attributes are missing while ems-esp is still busy with detecting the Boiler and Thermostate entities.

Yes after a restart it takes a while to collect all data from ems, the first mqtt messages are not complete. That's by design of the bus, and a few log messages on a restart are not critical.

[MichaelDvP]

@proddy that is correlated with #335 and #305. If we want to be sure to publish only complete messages, we have to wait some minutes before publishing the first device_data, in this case we can also subscribe and remove all retained HA messages from broker, then unsubscribe and start publishing with new HA config. But there will be also lots of complains because emsesp does not start publishing immediatly.

[marc1de]

@proddy: ok, here is my update:
The situation seems to be better now, but meanwhile some parameters have changed:

• my current ems-esp-version is now v3.4.0b5
• HA-Core: 2022.2.3 with HA-OS: 7.3

To get clean results I did the following in this order:

• cleaned all HA-Logs
• cleaned all HA-mqtt-data and entities with MQTT-Explorer
• powered off my HA-raspberry
• restartet ems-esp
• started HA again and waited, until it was completly ready
  (after that ems-esp showed "disconnected" in mqtt-Tab so I pressed "save" in MQTT-settings and got connected again).

This are my mqtt-settings:

My HA is now running since 4 hours and I didn't see any mqtt-related errors.

[... or to be absolutely correct: I saw only this error every 10 seconds...
Invalid value for number.boiler_burner_selected_max_power: **123** (range 0.0 - **100.0**)
but that was, because the "selburnpow-value" in ems was in fact at 123 (no idea how this value got that high because normally it should be at 40%)
But after setting this value back to 40% the error was gone.
@MichaelDvP: maybe you can correct the range for selburnpow in some of the next releases?

So my conclusion is: if you follow exactly this startup-procedure, you won't see any errors, because ems-esp has allready all the values, so that HA "sees" no missing values.

To confirm that suspicion I did a restart of ems-esp and got the "typical-startup-errors":

> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'manualtemp' when rendering '{{value_json.manualtemp}}'
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.components.mqtt.number] Payload '{"seltemp":20,"mode":"manual","modetype":"comfort","targetflowtemp":43,"summermode":"off"}' is not a Number
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'offsettemp' when rendering '{{value_json.offsettemp}}'
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.components.mqtt.number] Payload '{"seltemp":20,"mode":"manual","modetype":"comfort","targetflowtemp":43,"summermode":"off"}' is not a Number
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'minflowtemp' when rendering '{{value_json.minflowtemp}}'
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.components.mqtt.number] Payload '{"seltemp":20,"mode":"manual","modetype":"comfort","targetflowtemp":43,"summermode":"off"}' is not a Number
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'maxflowtemp' when rendering '{{value_json.maxflowtemp}}'
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.components.mqtt.number] Payload '{"seltemp":20,"mode":"manual","modetype":"comfort","targetflowtemp":43,"summermode":"off"}' is not a Number
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'nofrosttemp' when rendering '{{value_json.nofrosttemp}}'
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.components.mqtt.number] Payload '{"seltemp":20,"mode":"manual","modetype":"comfort","targetflowtemp":43,"summermode":"off"}' is not a Number
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'heatingtype' when rendering '{{value_json.heatingtype}}'
> 2022-02-17 17:22:05 ERROR (MainThread) [homeassistant.components.mqtt.select] Invalid option for select.thermostat_hc1_heating_type: '' (valid options: ['off', 'radiator', 'convector', 'floor'])
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'summersetmode' when rendering '{{value_json.summersetmode}}'
> 2022-02-17 17:22:05 ERROR (MainThread) [homeassistant.components.mqtt.select] Invalid option for select.thermostat_hc1_set_summer_mode: '' (valid options: ['summer', 'auto', 'winter'])
> 2022-02-17 17:22:05 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'dict object' has no attribute 'program' when rendering '{{value_json.program}}'
> 2022-02-17 17:22:05 ERROR (MainThread) [homeassistant.components.mqtt.select] Invalid option for select.thermostat_hc1_program: '' (valid options: ['prog_1', 'prog_2'])
> 

after a while, when all values were discoverd and submitted by ems-esp, the errors stopped

@MichaelDvP: I agree with you, that it would be no good idea to wait several minutes to start publishing the mqtt-data.....I think more people will get confused and complaining an error (maybe, a few seconds will be ok and the rest of the errors -if they appear only in the beginning-, will be ok and tolerable)
.... and if you unsubsribe all mqtt-entities on restart that might cause some other issues in HA (because all defined entities in the dashboards might complain "unknown" or missing"values")

[MichaelDvP]

You can update to v3.4.0b6, the max. selburnpower is corrected and you can clear old mqtt-discovery entries by disable mqtt-discovery, wait some minutes, enable discovery again. This does not help for temporary missing entries after restarting emsesp, but if you have retained mqtt-entries from older versions giving permanent errors.
I think most users have emsesp connected and running a long time, a few messages after restart do not matter much.

[proddy]

I switched to the MQTT option "as individual topics" and now seeing HA warnings like "Template variable error: 'dict object' has no attribute 'hc1' when rendering '{{ value_json.hc1.seltemp }}'" so something needs fixing. I'll take a look later

[marc1de]

@MichaelDvP:

I think most users have emsesp connected and running a long time, a few messages after restart do not matter much.

I fully agree!
..... but the:

disable mqtt-discovery, wait some minutes, enable discovery again.

might cause a little bit confusion:
The reason is this: You have an option to seleqt mqtt:

and a second option for the mqtt-discovery:

From my point of view I'd expect the first option to enable/disable the reporting of the mqtt-values ...
.. and the second option would enable/disable the "discovery" (= to search and report "NEW" entities/values).

So if someone for example deletes some unwanted entities in HA ....and therefore disables "mqtt-discovery" to prevent this entities coming up again, he will run into a problem because HA starts reporting the missing entities!

(I know, that you could disable the unwanted items in "ems/settings"...but unfortunaly, that would disable this values in the ems-ui too. So if someone wants to have some values available in ems-esp but not having them reported to mqtt, he'd run into another problem).

In other words: Your idea to "delete old entries" is very good,...but maybe this option should better be connected with the "enable mqtt" and not the "enable mqtt-discovery"?
In fact I'm not really shure about the consequences of that idea....another idea to solve that dilemma could be to add an additional option in the ems-settings so that someone can select wich entity will be completly disabled ... and which one should only be exclude from mqtt-reporting.....

but I think, this are just some ideas with minor priority [for for future enhancements if you are really bored and need some new ideas to change something ;-) ] ....

in fact, @ALL programmers and contributers: I'am full of respect for what's already done and how impressive this product is (including the perfect support and service). Thanks for that.

[MichaelDvP]

@proddy I can not reproduce, switching to individual topics removes the entrie and creates a new one, that looks right for me.

But i think i will never understand the logic of HA and HA-users.

[proddy]

@MichaelDvP yes you're correct again. It was an error in some custom sensors I had in HA.

[proddy]

(I know, that you could disable the unwanted items in "ems/settings"...but unfortunaly, that would disable this values in the ems-ui too. So if someone wants to have some values available in ems-esp but not having them reported to mqtt, he'd run into another problem).

This may be a good addition to #317, where you can select for each entity whether its visible in the WebUI and/or MQTT payload

[proddy]

closing this bug