Closed shbatm closed 1 year ago
This also shows up in core-2023.5.0b1
2023-04-28 06:55:53.389 ERROR (MainThread) [homeassistant.helpers.entity] Update for media_player.receiver fails
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 554, in async_update_ha_state
await self.async_device_update()
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 784, in async_device_update
await coro
File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/usr/src/homeassistant/homeassistant/components/onkyo/media_player.py", line 295, in update
status = self.command("system-power query")
File "/usr/src/homeassistant/homeassistant/components/onkyo/media_player.py", line 282, in command
result = self._receiver.command(command)
File "/usr/local/lib/python3.10/site-packages/eiscp/core.py", line 480, in command
response = self.raw(iscp_message)
File "/usr/local/lib/python3.10/site-packages/eiscp/core.py", line 470, in raw
return filter_for_message(self.get, iscp_message)
File "/usr/local/lib/python3.10/site-packages/eiscp/core.py", line 260, in filter_for_message
candidate = getter_func(0.05)
File "/usr/local/lib/python3.10/site-packages/eiscp/core.py", line 443, in get
ready = select.select([self.command_socket], [], [], timeout or 0)
TypeError: argument must be an int, or have a fileno() method.
Same issue here. Commands to the library onkyo-eiscp work fine from shell. Only in Home Assistant environment is eiscp having issue getting a socket.
This is still an issue in 2023.5.0 The log is filling up with lots of this error for zone 1, 2 and 3. Worked fine in 2023.4.6
Yeah ive got same issue after 2023.5.0+
Some additional logging. It looks like it's resetting the socket frequently, even thought it's able to get values for certain zones:
2023-05-05 01:26:33.149 DEBUG (SyncWorker_9) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 3
2023-05-05 01:26:33.149 INFO (SyncWorker_5) [homeassistant.components.onkyo.media_player] Game Room Receiver is disconnected. Attempting to reconnect
2023-05-05 01:26:33.152 INFO (SyncWorker_2) [homeassistant.components.onkyo.media_player] Game Room Receiver Zone 2 is disconnected. Attempting to reconnect
2023-05-05 01:26:43.254 DEBUG (SyncWorker_8) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 3
2023-05-05 01:26:43.255 INFO (SyncWorker_6) [homeassistant.components.onkyo.media_player] Game Room Receiver is disconnected. Attempting to reconnect
2023-05-05 01:26:47.987 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 2
2023-05-05 01:26:53.239 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 3
2023-05-05 01:26:53.240 INFO (SyncWorker_1) [homeassistant.components.onkyo.media_player] Game Room Receiver is disconnected. Attempting to reconnect
2023-05-05 01:26:53.242 ERROR (MainThread) [homeassistant.helpers.entity] Update for media_player.game_room_receiver_zone_2 fails
Traceback (most recent call last):
File "/workspaces/home-assistant-core/homeassistant/helpers/entity.py", line 554, in async_update_ha_state
await self.async_device_update()
File "/workspaces/home-assistant-core/homeassistant/helpers/entity.py", line 784, in async_device_update
await coro
File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/workspaces/home-assistant-core/homeassistant/components/onkyo/media_player.py", line 469, in update
status = self.command(f"zone{self._zone}.power=query")
File "/workspaces/home-assistant-core/homeassistant/components/onkyo/media_player.py", line 282, in command
result = self._receiver.command(command)
File "/home/vscode/.local/lib/python3.10/site-packages/eiscp/core.py", line 480, in command
response = self.raw(iscp_message)
File "/home/vscode/.local/lib/python3.10/site-packages/eiscp/core.py", line 470, in raw
return filter_for_message(self.get, iscp_message)
File "/home/vscode/.local/lib/python3.10/site-packages/eiscp/core.py", line 260, in filter_for_message
candidate = getter_func(0.05)
File "/home/vscode/.local/lib/python3.10/site-packages/eiscp/core.py", line 443, in get
ready = select.select([self.command_socket], [], [], timeout or 0)
TypeError: argument must be an int, or have a fileno() method.
2023-05-05 01:27:03.292 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 3
2023-05-05 01:27:03.293 INFO (SyncWorker_9) [homeassistant.components.onkyo.media_player] Game Room Receiver is disconnected. Attempting to reconnect
2023-05-05 01:27:03.366 DEBUG (SyncWorker_2) [homeassistant.components.onkyo.media_player] Result for zone2.power=query: ('power', 'standby')
2023-05-05 01:27:13.112 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 2
2023-05-05 01:27:13.113 INFO (SyncWorker_8) [homeassistant.components.onkyo.media_player] Game Room Receiver is disconnected. Attempting to reconnect
2023-05-05 01:27:17.996 DEBUG (SyncWorker_5) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 3
2023-05-05 01:27:22.969 DEBUG (SyncWorker_6) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 3
2023-05-05 01:27:22.970 INFO (SyncWorker_7) [homeassistant.components.onkyo.media_player] Game Room Receiver Zone 2 is disconnected. Attempting to reconnect
2023-05-05 01:27:23.157 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Result for system-power query: ('system-power', 'on')
2023-05-05 01:27:23.200 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Result for volume query: ('master-volume', 68)
2023-05-05 01:27:23.241 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Result for audio-muting query: ('audio-muting', 'off')
2023-05-05 01:27:23.282 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Result for input-selector query: ('input-selector', ('dvd', 'bd', 'dvd'))
2023-05-05 01:27:23.324 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Result for hdmi-output-selector query: ('hdmi-output-selector', ('both', 'sub'))
2023-05-05 01:27:23.365 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Result for preset query: ('preset', 0)
2023-05-05 01:27:23.406 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Result for audio-information query: ('audio-information', 'N/A')
2023-05-05 01:27:23.447 DEBUG (SyncWorker_0) [homeassistant.components.onkyo.media_player] Result for video-information query: ('video-information', 'HDMI 1,4K(3840x2160) 59 Hz,YCbCr420,36bit,MAIN+SUB,4K(3840x2160) 59 Hz,YCbCr420,36bit,,HDR10,')
2023-05-05 01:27:33.020 DEBUG (SyncWorker_9) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver
2023-05-05 01:27:33.021 INFO (SyncWorker_2) [homeassistant.components.onkyo.media_player] Game Room Receiver Zone 2 is disconnected. Attempting to reconnect
2023-05-05 01:27:33.208 DEBUG (SyncWorker_1) [homeassistant.components.onkyo.media_player] Result for zone3.power=query: ('power', 'standby')
2023-05-05 01:27:43.121 DEBUG (SyncWorker_5) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 2
2023-05-05 01:27:43.122 INFO (SyncWorker_8) [homeassistant.components.onkyo.media_player] Game Room Receiver is disconnected. Attempting to reconnect
2023-05-05 01:27:43.297 DEBUG (SyncWorker_7) [homeassistant.components.onkyo.media_player] Result for zone3.power=query: ('power', 'standby')
2023-05-05 01:27:53.114 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for system-power query: ('system-power', 'on')
2023-05-05 01:27:53.115 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 3
2023-05-05 01:27:53.115 INFO (SyncWorker_0) [homeassistant.components.onkyo.media_player] Game Room Receiver Zone 2 is disconnected. Attempting to reconnect
2023-05-05 01:27:53.186 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for volume query: ('master-volume', 68)
2023-05-05 01:27:53.281 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for audio-muting query: ('audio-muting', 'off')
2023-05-05 01:27:53.334 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for input-selector query: ('input-selector', ('dvd', 'bd', 'dvd'))
2023-05-05 01:27:53.375 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for hdmi-output-selector query: ('hdmi-output-selector', ('both', 'sub'))
2023-05-05 01:27:53.516 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for preset query: ('preset', 0)
2023-05-05 01:27:53.560 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for audio-information query: ('audio-information', 'N/A')
2023-05-05 01:27:53.599 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for video-information query: ('video-information', 'HDMI 1,4K(3840x2160) 59 Hz,YCbCr420,36bit,MAIN+SUB,4K(3840x2160) 59 Hz,YCbCr420,36bit,,HDR10,')
2023-05-05 01:28:03.012 DEBUG (SyncWorker_1) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver Zone 2
2023-05-05 01:28:03.013 INFO (SyncWorker_2) [homeassistant.components.onkyo.media_player] Game Room Receiver is disconnected. Attempting to reconnect
2023-05-05 01:28:03.208 DEBUG (SyncWorker_6) [homeassistant.components.onkyo.media_player] Result for zone3.power=query: ('power', 'standby')
2023-05-05 01:28:13.020 DEBUG (SyncWorker_8) [homeassistant.components.onkyo.media_player] Resetting connection to Game Room Receiver
2023-05-05 01:28:13.021 INFO (SyncWorker_7) [homeassistant.components.onkyo.media_player] Game Room Receiver Zone 2 is disconnected. Attempting to reconnect
2023-05-05 01:28:13.022 ERROR (MainThread) [homeassistant.helpers.entity] Update for media_player.game_room_receiver_zone_3 fails
Traceback (most recent call last):
File "/workspaces/home-assistant-core/homeassistant/helpers/entity.py", line 554, in async_update_ha_state
await self.async_device_update()
File "/workspaces/home-assistant-core/homeassistant/helpers/entity.py", line 784, in async_device_update
await coro
File "/usr/local/lib/python3.10/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/workspaces/home-assistant-core/homeassistant/components/onkyo/media_player.py", line 469, in update
status = self.command(f"zone{self._zone}.power=query")
File "/workspaces/home-assistant-core/homeassistant/components/onkyo/media_player.py", line 282, in command
result = self._receiver.command(command)
File "/home/vscode/.local/lib/python3.10/site-packages/eiscp/core.py", line 480, in command
response = self.raw(iscp_message)
File "/home/vscode/.local/lib/python3.10/site-packages/eiscp/core.py", line 470, in raw
return filter_for_message(self.get, iscp_message)
File "/home/vscode/.local/lib/python3.10/site-packages/eiscp/core.py", line 260, in filter_for_message
candidate = getter_func(0.05)
File "/home/vscode/.local/lib/python3.10/site-packages/eiscp/core.py", line 443, in get
ready = select.select([self.command_socket], [], [], timeout or 0)
TypeError: argument must be an int, or have a fileno() method.
@bdraco I have no idea why, but it appears this is caused by your changes in https://github.com/home-assistant/core/pull/91067. Reverting commit 3d1556a
immediately resolves the issue and Onkyo loads normally.
2023-05-05 02:40:00.966 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Checking for zone 2 capability
2023-05-05 02:40:00.979 INFO (MainThread) [homeassistant.components.notify] Setting up notify.mobile_app
2023-05-05 02:40:00.980 INFO (MainThread) [custom_components.hacs] <HacsData restore> Restore started
2023-05-05 02:40:00.989 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.energy
2023-05-05 02:40:01.121 INFO (MainThread) [custom_components.hacs] <HacsData restore> Restore done
2023-05-05 02:40:01.122 INFO (MainThread) [homeassistant.setup] Setup of domain tts took 0.2 seconds
2023-05-05 02:40:01.124 INFO (MainThread) [homeassistant.components.light] Setting up light.group
2023-05-05 02:40:01.124 INFO (MainThread) [homeassistant.setup] Setting up assist_pipeline
2023-05-05 02:40:01.130 INFO (MainThread) [homeassistant.setup] Setup of domain assist_pipeline took 0.0 seconds
2023-05-05 02:40:01.134 INFO (MainThread) [homeassistant.setup] Setting up default_config
2023-05-05 02:40:01.135 INFO (SyncWorker_4) [homeassistant.loader] Loaded backup from homeassistant.components.backup
2023-05-05 02:40:01.232 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Checking for zone 3 capability
2023-05-05 02:40:01.235 INFO (MainThread) [homeassistant.setup] Setting up backup
2023-05-05 02:40:01.235 INFO (MainThread) [homeassistant.setup] Setup of domain backup took 0.0 seconds
2023-05-05 02:40:01.237 INFO (MainThread) [homeassistant.setup] Setup of domain default_config took 0.1 seconds
2023-05-05 02:40:01.280 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Setting up zone 2
2023-05-05 02:40:01.280 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Setting up zone 3
2023-05-05 02:40:01.322 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for system-power query: ('system-power', 'on')
2023-05-05 02:40:01.366 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for volume query: ('master-volume', 90)
2023-05-05 02:40:01.417 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for audio-muting query: ('audio-muting', 'off')
2023-05-05 02:40:01.459 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for input-selector query: ('input-selector', ('dvd', 'bd', 'dvd'))
2023-05-05 02:40:01.483 INFO (MainThread) [custom_components.hacs] Enable category: integration
2023-05-05 02:40:01.484 INFO (MainThread) [custom_components.hacs] Enable category: plugin
2023-05-05 02:40:01.484 INFO (MainThread) [custom_components.hacs] Enable category: theme
2023-05-05 02:40:01.489 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.hacs
2023-05-05 02:40:01.492 INFO (MainThread) [custom_components.hacs] Stage changed: setup
2023-05-05 02:40:01.494 INFO (MainThread) [custom_components.hacs] Stage changed: waiting
2023-05-05 02:40:01.494 INFO (MainThread) [custom_components.hacs] Setup complete, waiting for Home Assistant before startup tasks starts
2023-05-05 02:40:01.503 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for hdmi-output-selector query: ('hdmi-output-selector', ('both', 'sub'))
2023-05-05 02:40:01.541 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for preset query: ('preset', 0)
2023-05-05 02:40:01.583 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for audio-information query: ('audio-information', 'HDMI 1,Dolby Audio - DD+,48 kHz,2.0 ch,Dolby Audio - Surr,5.1.4 ch,')
2023-05-05 02:40:01.625 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for video-information query: ('video-information', 'HDMI 1,4K(3840x2160) 59 Hz,YCbCr420,36bit,MAIN+SUB,4K(3840x2160) 59 Hz,YCbCr420,36bit,,HDR10,')
2023-05-05 02:40:01.766 DEBUG (SyncWorker_3) [homeassistant.components.onkyo.media_player] Result for zone2.power=query: ('power', 'standby')
2023-05-05 02:40:01.808 DEBUG (SyncWorker_2) [homeassistant.components.onkyo.media_player] Result for zone3.power=query: ('power', 'standby')
That commit now avoids creating a another task in most cases.
It’s likely the integration has a race condition bug in it that relied on the update yielding to the event loop.
You could probably restore the previous behavior by doing the update in a task and awaiting the task but that’s probably a horrible workaround
Just noticed that the integration is sync so that even more surprising since it’s being run in the executor. I assume it’s somehow relying asyncio.wait semantics.
except (ValueError, OSError, AttributeError, AssertionError):
if self._receiver.command_socket:
self._receiver.command_socket = None
That code in the integration looks a bit suspect
That code in the integration looks a bit suspect
In general, the integration and underlying package looks like it's very much still early python 2.x mentality of Try Catch Fix, but I don't think it has any codeowners here and is built on essentially a polling command-line interface in the package.
The only thing that led me to your PR was backing up the error stack to find a recent change. Nothing in that integration has been touched for several months and looks like the package release was a while ago too.
except (ValueError, OSError, AttributeError, AssertionError): if self._receiver.command_socket: self._receiver.command_socket = None
That code in the integration looks a bit suspect
This looks like it just resets the command socket in an abstract way... The package looks for a valid socket and if it's None then it sets up a new one:
My logs are getting spammed with every few minutes for the whole day. Is there a solution for this?
@shbatm It looks like I broke the parallel updates locking in that commit. I’m not sure if that will fix this case though. I’m working on a solution now.
@shbatm can you try the fix in https://github.com/home-assistant/core/pull/92681 ?
@shbatm can you try the fix in https://github.com/home-assistant/core/pull/92681 ?
Yep. I'll check it shortly.
Confirmed #92681 looks like it fixes this issue. No errors in logs and updating normally.
2023-05-06 13:26:01.592 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for system-power query: ('system-power', ('standby', 'off'))
2023-05-06 13:26:01.839 DEBUG (SyncWorker_1) [homeassistant.components.onkyo.media_player] Result for zone2.power=query: ('power', 'standby')
2023-05-06 13:26:02.045 DEBUG (SyncWorker_2) [homeassistant.components.onkyo.media_player] Result for zone3.power=query: ('power', 'standby')
2023-05-06 13:26:11.594 DEBUG (SyncWorker_7) [homeassistant.components.onkyo.media_player] Result for system-power query: ('system-power', ('standby', 'off'))
2023-05-06 13:26:11.847 DEBUG (SyncWorker_4) [homeassistant.components.onkyo.media_player] Result for zone2.power=query: ('power', 'standby')
2023-05-06 13:26:12.108 DEBUG (SyncWorker_1) [homeassistant.components.onkyo.media_player] Result for zone3.power=query: ('power', 'standby')
2023-05-06 13:26:21.616 DEBUG (SyncWorker_2) [homeassistant.components.onkyo.media_player] Result for system-power query: ('system-power', ('standby', 'off'))
2023-05-06 13:26:21.833 DEBUG (SyncWorker_6) [homeassistant.components.onkyo.media_player] Result for zone2.power=query: ('power', 'standby')
2023-05-06 13:26:22.032 DEBUG (SyncWorker_7) [homeassistant.components.onkyo.media_player] Result for zone3.power=query: ('power', 'standby')
Thanks for testing 👍
Hi guys! I have the same problem as yours. I think you alredy got where is the problem. But i didn't see released yet. Really appreciate your work guys, you rock!
Should have been fixed with 2023.5.3
The problem
Onkyo reporting unable to connect to receiver in the new 2023.5.0b0, while working fine when downgrading back to 2023.4.6.
See error reported below.
What version of Home Assistant Core has the issue?
core-2023.5.0b0
What was the last working version of Home Assistant Core?
core-2023.4.6
What type of installation are you running?
Home Assistant OS
Integration causing the issue
Onkyo
Link to integration documentation on our website
https://www.home-assistant.io/integrations/onkyo/
Diagnostics information
No response
Example YAML snippet
Anything in the logs that might be useful for us?
Additional information
No response