search

crowbarz / ha-pioneer_async

Home Assistant media_player component for Pioneer AVRs, rewritten in asyncio and supporting the UI config flow.
Apache License 2.0
28 stars 10 forks source link

Integration fails to setup if AVR is off when integration starts #48

Open PhAzE-Variance opened 3 weeks ago

PhAzE-Variance commented 3 weeks ago

Love this integration for my older Pioneer VSX-1325K. The only issue I'm coming across is that the integration will fail to setup if the receiver is off (but has network standby enabled). My server updates every night or two so this integration spends most of the time in a failed state.

Receiver: VSX-1325k Standby: Enabled IP: Static

Are there any settings in the integration that can be changed to detect the receiver in standby mode upon initialization?

crowbarz commented 3 weeks ago

Does this mean your AVR can be turned off (ie. standby) by the integration when it is on, but never turned on if it is standby?

A debug log of a successful setup and an unsuccessful setup would probably help me better understand what is going on here, and whether the issue can be worked around.

PhAzE-Variance commented 3 weeks ago

No, it turns off and on just fine, however if it is in off (standby) and I restart home assistant, it the integration will fail to locate my AVR and failed to initialize the integration. If ai turn the AVar on manually and restart hone assistant with the AVR on, then it initialize normally.

crowbarz commented 2 weeks ago

Ok, so it sounds like your AVR doesn't respond to one or more query commands that the integration sends on integration setup, when the AVR is in standby.

Can you enable debug logging from the integration page on your HA instance, then reload the integration instance (via the dots menu)? Then disable debugging, save the downloaded log, and post the relevant excerpts from the log. Hopefully I can work out which command(s) your AVR is not responding to.

PhAzE-Variance commented 2 weeks ago

home-assistant_pioneer_async_2024-11-12T15-13-04.626Z.log

Here is the debug log. I've tried to remove as much of the other integrations as possible.

webmeister commented 1 week ago

For your device query_volume fails, for my device (VSX-S510) in a similar situation query_source_id fails. So I'd say that when power is off, no other queries are guaranteed to succeed. https://github.com/crowbarz/aiopioneer/pull/39/commits/06b9b40c5118d26456fec5f41359246571efdb65 fixes this (part of https://github.com/crowbarz/aiopioneer/pull/39).

dondonini commented 4 days ago

Hia, it seems I'm having the same issue as the OP, but mine also disconnects when it's on standby after a long time. The time of how long it will be controllable until it disconnects is unknown to me. When it does disconnect it spits out...

2024-11-21 21:47:34.371 INFO (MainThread) [aiopioneer.pioneer_avr] Starting aiopioneer 0.7.0
2024-11-21 21:47:34.372 INFO (MainThread) [aiopioneer.pioneer_avr] determining available listening modes
2024-11-21 21:47:37.453 ERROR (MainThread) [custom_components.pioneer_async] exception on initialising Pioneer AVR: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-21 21:47:37.454 WARNING (MainThread) [aiopioneer.pioneer_avr] AVR not connected, skipping disconnect
...
2024-11-21 21:48:57.920 INFO (MainThread) [aiopioneer.pioneer_avr] Starting aiopioneer 0.7.0
2024-11-21 21:48:57.921 INFO (MainThread) [aiopioneer.pioneer_avr] determining available listening modes
2024-11-21 21:49:00.973 ERROR (MainThread) [custom_components.pioneer_async] exception on initialising Pioneer AVR: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-21 21:49:00.974 WARNING (MainThread) [aiopioneer.pioneer_avr] AVR not connected, skipping disconnect
...
2024-11-21 21:50:21.167 INFO (MainThread) [aiopioneer.pioneer_avr] Starting aiopioneer 0.7.0
2024-11-21 21:50:21.168 INFO (MainThread) [aiopioneer.pioneer_avr] determining available listening modes
2024-11-21 21:50:24.237 ERROR (MainThread) [custom_components.pioneer_async] exception on initialising Pioneer AVR: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-21 21:50:24.238 WARNING (MainThread) [aiopioneer.pioneer_avr] AVR not connected, skipping disconnect

... every few minutes.

I can get it working again if I turn on my receiver and reload the integration.

crowbarz commented 4 days ago

PR crowbarz/aiopioneer#39 might help with reconnects, but it can't be merged at the moment because it breaks zone detection on other AVRs.

It would help if you could enable debug logging to ascertain what is happening in the integration when the disconnects occur. To enable debug logging, add the following logging config to configuration.yaml:

logger:
  logs:
    custom_components.pioneer_async: debug
    aiopioneer: debug
dondonini commented 3 minutes ago

This is what I got:

HA History: image

HA Core Log:

2024-11-26 04:24:54.627 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: volume: 57 -> 55 (055)
2024-11-26 04:24:54.628 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
2024-11-26 04:24:55.027 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: volume: 55 -> 53 (053)
2024-11-26 04:24:55.027 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
2024-11-26 04:24:55.347 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: volume: 53 -> 47 (047)
2024-11-26 04:24:55.347 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
2024-11-26 04:24:55.668 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: volume: 47 -> 41 (041)
2024-11-26 04:24:55.669 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
2024-11-26 04:24:59.291 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: volume: 41 -> 39 (039)
2024-11-26 04:24:59.292 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
2024-11-26 04:24:59.626 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: volume: 39 -> 37 (037)
2024-11-26 04:24:59.627 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
2024-11-26 04:24:59.977 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: volume: 37 -> 35 (035)
2024-11-26 04:24:59.978 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
...
2024-11-26 10:50:15.849 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.disconnect() started
2024-11-26 10:50:15.850 DEBUG (MainThread) [aiopioneer.pioneer_avr] disconnecting AVR connection
2024-11-26 10:50:15.850 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
2024-11-26 10:50:15.866 DEBUG (MainThread) [custom_components.pioneer_async.coordinator] Manually updated pioneer_async data
2024-11-26 10:50:15.869 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR._updater() completed
2024-11-26 10:50:15.980 DEBUG (MainThread) [aiopioneer.pioneer_avr] closing AVR connection
2024-11-26 10:50:15.981 DEBUG (MainThread) [aiopioneer.pioneer_avr] ignoring disconnect exception: [Errno 110] Operation timed out
2024-11-26 10:50:15.981 INFO (MainThread) [aiopioneer.pioneer_avr] AVR connection closed
2024-11-26 10:50:15.981 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR._reconnect_schedule()
2024-11-26 10:50:15.982 INFO (MainThread) [aiopioneer.pioneer_avr] reconnecting to AVR
2024-11-26 10:50:15.982 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.disconnect() completed
2024-11-26 10:50:15.982 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR._connection_listener() completed
2024-11-26 10:50:15.983 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.reconnect() started
2024-11-26 10:50:15.983 DEBUG (MainThread) [aiopioneer.pioneer_avr] waiting 4s before retrying connection
...
2024-11-26 10:50:20.662 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2024-11-26 10:50:20.663 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2024-11-26 10:50:23.721 DEBUG (MainThread) [aiopioneer.pioneer_avr] could not reconnect to AVR: OSError: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-26 10:50:23.721 DEBUG (MainThread) [aiopioneer.pioneer_avr] waiting 4s before retrying connection
2024-11-26 10:50:28.476 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2024-11-26 10:50:28.477 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2024-11-26 10:50:31.529 DEBUG (MainThread) [aiopioneer.pioneer_avr] could not reconnect to AVR: OSError: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-26 10:50:31.529 DEBUG (MainThread) [aiopioneer.pioneer_avr] waiting 4s before retrying connection
2024-11-26 10:50:35.973 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2024-11-26 10:50:35.973 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2024-11-26 10:50:39.049 DEBUG (MainThread) [aiopioneer.pioneer_avr] could not reconnect to AVR: OSError: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-26 10:50:39.050 DEBUG (MainThread) [aiopioneer.pioneer_avr] waiting 8s before retrying connection
2024-11-26 10:50:47.071 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2024-11-26 10:50:47.071 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2024-11-26 10:50:50.153 DEBUG (MainThread) [aiopioneer.pioneer_avr] could not reconnect to AVR: OSError: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-26 10:50:50.153 DEBUG (MainThread) [aiopioneer.pioneer_avr] waiting 16s before retrying connection
...
2024-11-26 10:51:06.930 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2024-11-26 10:51:06.930 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2024-11-26 10:51:07.339 DEBUG (MainThread) [aiopioneer.pioneer_avr] could not reconnect to AVR: OSError: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-26 10:51:07.339 DEBUG (MainThread) [aiopioneer.pioneer_avr] waiting 32s before retrying connection
...
2024-11-26 10:51:40.177 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2024-11-26 10:51:40.178 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2024-11-26 10:51:43.241 DEBUG (MainThread) [aiopioneer.pioneer_avr] could not reconnect to AVR: OSError: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-26 10:51:43.242 DEBUG (MainThread) [aiopioneer.pioneer_avr] waiting 64s before retrying connection
...
2024-11-26 10:52:47.644 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2024-11-26 10:52:47.644 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2024-11-26 10:52:50.697 DEBUG (MainThread) [aiopioneer.pioneer_avr] could not reconnect to AVR: OSError: [Errno 113] Connect call failed ('192.168.50.59', 8102)
2024-11-26 10:52:50.698 DEBUG (MainThread) [aiopioneer.pioneer_avr] waiting 64s before retrying connection

I just realized that it never detects when I turn off the receiver. I turned it off at around 10 am.