Closed WolfRevo closed 2 years ago
mdeweerd
commented
2 years ago Statest could be related to zha-toolkit. We have stateObj = hass.states.get(entity_id)inutils.py` - possibly that's undefined now.
The at 1364 and 21072 make no sense - only services.yaml is big enough for 1364 lines and no file is 21072 lines long.
I am on vacation, for some reason my access to HA is out of order, but will try updating another HA system to see what happens.
mdeweerd
commented
2 years ago Updated a system to 2022.8.3 - I read a zcl attribute and wrote it to an new state - the error was not reproduced.
jes1417
commented
2 years ago Seeing this in my logs
Logger: homeassistant.components.recorder.core
Source: components/recorder/core.py:760
Integration: Recorder (documentation, issues)
First occurred: 12:24:38 AM (1 occurrences)
Last logged: 12:24:38 AM
Unhandled database error while processing task EventTask(event=<Event state_changed[L]: entity_id=update.zha_toolkit_service_for_advanced_zigbee_usage_update, old_state=None, new_state=<state update.zha_toolkit_service_for_advanced_zigbee_usage_update=off; auto_update=False, installed_version=v0.8.11, in_progress=False, latest_version=v0.8.11, release_summary=None, release_url=https://github.com/mdeweerd/zha-toolkit/releases/v0.8.11, skipped_version=None, title=None, entity_picture=https://brands.home-assistant.io/_/zha_toolkit/icon.png, friendly_name=🧰 ZHA Toolkit - Service for advanced Zigbee Usage update, supported_features=21 @ 2022-08-15T00:22:31.560428-05:00>>): (MySQLdb.OperationalError) (1267, "Illegal mix of collations (utf8mb4_unicode_ci,IMPLICIT) and (utf8mb3_general_ci,COERCIBLE) for operation '='") [SQL: SELECT state_attributes.attributes_id FROM state_attributes WHERE state_attributes.hash = %s AND state_attributes.shared_attrs = %s] [parameters: (438846145, '{"auto_update":false,"installed_version":"v0.8.11","latest_version":"v0.8.11","release_url":"https://github.com/mdeweerd/zha-toolkit/releases/v0.8.11","skipped_version":null,"title":null,"friendly_name":"🧰 ZHA Toolkit - Service for advanced Zigbee Usage update"}')] (Background on this error at: https://sqlalche.me/e/14/e3q8)
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/engine/base.py", line 1819, in _execute_context
self.dialect.do_execute(
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/engine/default.py", line 732, in do_execute
cursor.execute(statement, parameters)
File "/usr/local/lib/python3.10/site-packages/MySQLdb/cursors.py", line 206, in execute
res = self._query(query)
File "/usr/local/lib/python3.10/site-packages/MySQLdb/cursors.py", line 319, in _query
db.query(q)
File "/usr/local/lib/python3.10/site-packages/MySQLdb/connections.py", line 254, in query
_mysql.connection.query(self, query)
MySQLdb.OperationalError: (1267, "Illegal mix of collations (utf8mb4_unicode_ci,IMPLICIT) and (utf8mb3_general_ci,COERCIBLE) for operation '='")
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/recorder/core.py", line 645, in _process_one_task_or_recover
return task.run(self)
File "/usr/src/homeassistant/homeassistant/components/recorder/tasks.py", line 211, in run
instance._process_one_event(self.event)
File "/usr/src/homeassistant/homeassistant/components/recorder/core.py", line 741, in _process_one_event
self._process_state_changed_event_into_session(event)
File "/usr/src/homeassistant/homeassistant/components/recorder/core.py", line 847, in _process_state_changed_event_into_session
if attributes_id := self._find_shared_attr_in_db(attr_hash, shared_attrs):
File "/usr/src/homeassistant/homeassistant/components/recorder/core.py", line 760, in _find_shared_attr_in_db
if attributes_id := self.event_session.execute(
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/orm/session.py", line 1712, in execute
result = conn._execute_20(statement, params or {}, execution_options)
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/engine/base.py", line 1631, in _execute_20
return meth(self, args_10style, kwargs_10style, execution_options)
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/sql/lambdas.py", line 516, in _execute_on_connection
return connection._execute_clauseelement(
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/engine/base.py", line 1498, in _execute_clauseelement
ret = self._execute_context(
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/engine/base.py", line 1862, in _execute_context
self._handle_dbapi_exception(
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/engine/base.py", line 2043, in _handle_dbapi_exception
util.raise_(
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/util/compat.py", line 208, in raise_
raise exception
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/engine/base.py", line 1819, in _execute_context
self.dialect.do_execute(
File "/usr/local/lib/python3.10/site-packages/sqlalchemy/engine/default.py", line 732, in do_execute
cursor.execute(statement, parameters)
File "/usr/local/lib/python3.10/site-packages/MySQLdb/cursors.py", line 206, in execute
res = self._query(query)
File "/usr/local/lib/python3.10/site-packages/MySQLdb/cursors.py", line 319, in _query
db.query(q)
File "/usr/local/lib/python3.10/site-packages/MySQLdb/connections.py", line 254, in query
_mysql.connection.query(self, query)
sqlalchemy.exc.OperationalError: (MySQLdb.OperationalError) (1267, "Illegal mix of collations (utf8mb4_unicode_ci,IMPLICIT) and (utf8mb3_general_ci,COERCIBLE) for operation '='")
[SQL: SELECT state_attributes.attributes_id
FROM state_attributes
WHERE state_attributes.hash = %s AND state_attributes.shared_attrs = %s]
[parameters: (438846145, '{"auto_update":false,"installed_version":"v0.8.11","latest_version":"v0.8.11","release_url":"https://github.com/mdeweerd/zha-toolkit/releases/v0.8.11","skipped_version":null,"title":null,"friendly_name":"🧰 ZHA Toolkit - Service for advanced Zigbee Usage update"}')]
(Background on this error at: https://sqlalche.me/e/14/e3q8)
WolfRevo
commented
2 years ago Let's try it differently ... it always happens, after one of my automations is executed:
2022-08-15 09:17:04.561 INFO (MainThread) [homeassistant.components.automation.ext_temp_kinozimmer_update] 018.9 Ext_Temp_Kinozimmer.update: Running automation actions
2022-08-15 09:17:04.562 INFO (MainThread) [homeassistant.components.automation.ext_temp_kinozimmer_update] 018.9 Ext_Temp_Kinozimmer.update: Executing step call serviceThis automation is straight forward (reduced to the action part):
service: script.turn_on
target:
entity_id: script.danfossgeneric_update_ext_temperature
data:
variables:
IEEE_ADR: 84:2e:14:ff:fe:2a:b8:f3
TEMP_SENSOR: >-
{{ (states("sensor.temperatur_luftfeuchtigkeit_kinozimmer") | float *100)
| round(0) }}This automation executes the script with the coresponding temperature update for the thermostat:
2022-08-15 09:17:04.581 INFO (MainThread) [homeassistant.components.script.danfossgeneric_update_ext_temperature] DANFOSS.generic_update_ext_temperature: Running script sequence
2022-08-15 09:17:04.581 INFO (MainThread) [homeassistant.components.script.danfossgeneric_update_ext_temperature] DANFOSS.generic_update_ext_temperature: Executing step call serviceThe script is also straight forward:
alias: DANFOSS.generic_update_ext_temperature
sequence:
- service: zha_toolkit.attr_write
data:
ieee: "{{ IEEE_ADR }}"
endpoint: 1
cluster: 513
attribute: 16405
attr_val: "{{ TEMP_SENSOR }}"
tries: 3
mode: queued
max: 10There is the call to the zha_toolkit which now kicks in:
2022-08-15 09:17:04.596 INFO (MainThread) [custom_components.zha_toolkit] Running ZHA Toolkit service: <ServiceCall zha_toolkit.attr_write (c:01GAG5SYX3YF60CRAAXBYS317D): ieee=84:2e:14:ff:fe:2a:b8:f3, endpoint=1, cluster=513, attribute=16405, attr_val=2260, tries=3>And now the weird part starts (still occurs after all my tries of updating/resetting etc.):
2022-08-15 09:17:04.612 DEBUG (MainThread) [custom_components.zha_toolkit] module is <module 'custom_components.zha_toolkit' from '/config/custom_components/zha_toolkit/__init__.py'>
2022-08-15 09:17:04.616 DEBUG (MainThread) [custom_components.zha_toolkit.utils] Read version from /config/custom_components/zha_toolkit/manifest.json 1660143114.0872574<>0
2022-08-15 09:17:04.617 DEBUG (MainThread) [custom_components.zha_toolkit] Reload services because version changed from to v0.8.11
2022-08-15 09:17:04.619 DEBUG (MainThread) [custom_components.zha_toolkit] Add service zha_toolkit.executeI think the other mentioned errors do not take part in the issue. It is about the exection of automations, maybe in conjunction with executing scripts ...
mdeweerd
commented
2 years ago @jes1417 My best guess: You are using MySql and the state_attributes table is using utf8mb3_general_ci encoding, while the provided data is using utf8mb4_unicode_ci encoding.
My recommendation is to change the encoding for the table to utf8mb4_unicode_ci .
This is because the friendly name has 🧰 in it and it is presented or detected as utf8mb4 encoding in the request. This highlights an encoding discrepency in the HA setup- when creating the MySql database it should have selected the proper endoding (...mb4) compatible with the requests that are made. IMHO this should be reported to HA (if the DB was created by HA), or elsewhere (if the database was created using a method/procedure not managed by HA core).
https://dev.mysql.com/doc/refman/8.0/en/charset-unicode-conversion.html discusses some of that and shows example queries for converting a table/column - this may also be possible using a more userfriendly interface such as phpmyadmin.
mdeweerd
commented
2 years ago @WolfRevo The "version changed from to v0.8.11" related messages are normal and I should probably avoid at least the messages when it first occurs, and maybe also avoid it on the first call to a zha service.
The messages indicate a change in the version because it was not checked yet at that point. The last known version is stored in memory and checked agains the manifest.json on every version call. That allows the user to update zha-toolkit using HACS or git and use the updated version without requiring the user to restart HA. The services are reloaded when a change is detected so that any change there is reflected in HA's internals, and the modules are also reloaded.
I guess that I can set the version when zha-toolkit is initially loaded which is probably not the case now, and this will avoid those messages.
However, you write "this always happens". Now I also get it once a day when the backup is made so possibly I need to change the way the last known version is stored in memory. I'll check that out.
WolfRevo
commented
2 years ago If you need further log information I can provide it. Automations run on every temperature change for 11 different thermostats (I use this to update the externally measured temperature within the thermostat itself for more accurate heating) so this happens quiet often a day 😉
mdeweerd
commented
2 years ago Version 0.8.12 should fix it. I guess this behavior was introduced following a python version upgrade.
WolfRevo
commented
2 years ago I will watch it from time to time. First check after installation looks promising:
2022-08-15 14:33:29.921 INFO (MainThread) [homeassistant.components.automation.ext_temp_lieblingszimmer_update] 014.9 Ext_Temp_Lieblingszimmer.update: Running automation actions
2022-08-15 14:33:29.921 INFO (MainThread) [homeassistant.components.automation.ext_temp_lieblingszimmer_update] 014.9 Ext_Temp_Lieblingszimmer.update: Executing step call service
2022-08-15 14:33:29.949 INFO (MainThread) [homeassistant.components.script.danfossgeneric_update_ext_temperature] DANFOSS.generic_update_ext_temperature: Running script sequence
2022-08-15 14:33:29.950 INFO (MainThread) [homeassistant.components.script.danfossgeneric_update_ext_temperature] DANFOSS.generic_update_ext_temperature: Executing step call service
2022-08-15 14:33:29.956 INFO (MainThread) [custom_components.zha_toolkit] Running ZHA Toolkit service: <ServiceCall zha_toolkit.attr_write (c:01GAGQXB9N8VDBSXZCPHMB36S5): ieee=84:2e:14:ff:fe:62:0c:85, endpoint=1, cluster=513, attribute=16405, attr_val=2410, tries=3>
2022-08-15 14:33:29.990 DEBUG (MainThread) [custom_components.zha_toolkit] module is <module 'custom_components.zha_toolkit' from '/config/custom_components/zha_toolkit/__init__.py'>
2022-08-15 14:33:29.993 INFO (MainThread) [custom_components.zha_toolkit] COMPARED VERSION IS v0.8.12
2022-08-15 14:33:29.993 DEBUG (MainThread) [custom_components.zha_toolkit.utils] Parameters '{'ieee': 84:2e:14:ff:fe:62:0c:85, 'endpoint': 1, 'cluster': 513, 'attribute': 16405, 'attr_val': 2410, 'tries': 3}'
...@WolfRevo Ok, I close this as your observation seems to confirm the fix.
I have a strange issue using zha-toolkit in the lateset version with the latest HA 2022.8.x When my automations call the toolkit the following happens and zha-toolkit is litterally restarted:
This has some side effects I don't understand so far but at least one my switches shorty goes on and off without me seeing anything in the HA protocol unfortunately.
I tried it with re-installation of HACS and zha-toolkit but that doesn't help. Also in the runup there is something strange:
Maybe it's related to HACS itself? Any help appreciated.