Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
PhAzE-Variance opened this issue Oct 30, 2024 · 15 comments
Closed

Comments

@PhAzE-Variance
Copy link

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
Copy link
Owner

crowbarz commented Nov 4, 2024

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
Copy link
Author

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
Copy link
Owner

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
Copy link
Author

PhAzE-Variance commented Nov 12, 2024

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
Copy link
Contributor

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. crowbarz/aiopioneer@06b9b40 fixes this (part of crowbarz/aiopioneer#39).

@dondonini
Copy link

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
Copy link
Owner

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
Copy link

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.

@PhAzE-Variance
Copy link
Author

Maybe this integration shouldn't try to re-detect after initial setup has been completed. If a user needs to make a change they can always remove the device and re-add it again.

@pantherale0
Copy link
Contributor

Maybe this integration shouldn't try to re-detect after initial setup has been completed. If a user needs to make a change they can always remove the device and re-add it again.

The polling interval could be increased to rely more on events raised by the AVR itself.

Problem is, these older AVRs have some really flaky firmware, even my top of the range amp has some problems in it's IP stack and sometimes doesn't raise events at all, so without the polling, things that I actually use (detecting the number of channels a audio source has for example) actually sometimes never updates. And that's just because the AVR never raises an event to say something has happened.

I think I've said this before somewhere, but if you have a serial port on the back of the device, you could use a bridge like ser2net instead.

@crowbarz
Copy link
Owner

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

This reconnect issue looks to me like a different issue to the OP's issue. In the OP's case, the AVR does respond on the network, but the integration disconnects from the AVR because it does not respond to the initial commands that are sent by the integration. In your case, the AVR completely stops responding and becomes unreachable on the network.

I logged #51 to track this issue separately.

@crowbarz
Copy link
Owner

@PhAzE-Variance have you tried enabling the Don't check volume when querying AVR source setting? I looked at your logs again and the query_volume command is timing out. Enabling that setting should stop query_volume from being sent at integration startup, even before crowbarz/aiopioneer#39 is merged.

@PhAzE-Variance
Copy link
Author

I tried it with the volume option disabled, The integration will complete, then it becomes unavailable after 60 seconds or so.

I did some tinkering with my unit through telnet. First, this VSX-1325K is a rebranded VSX-33.
It only responds to power commands when in standby mode, and nothing else:

?P (Zone 1 power query) - Responses: PWR1 (off) - PWR1 (on)
?AP (Zone 2 power query) - Responses: APR1 (off) - APR1 (on)
?BP (Zone 3 power query) - Responses: BPR1 (off) - BPR1 (on)

Volume query, source query, listening mode query, tone query, bass query, treble query, etc, all fail to respond (not errors given).

Power commands do work from standby:
PO - Power zone 1 on
PF - Power zone 1 off
APO - Power zone 2 on
APF - Power zone 2 off
BPO - Power zone 3 on
BPF - Power zone 3 off

I'm not sure if these are the commands this integration is using, but the power state for sure doesn't detect correct as is when the unit is off. After removing the receiver from the integration, I can't seem to add it back in at all when its on or off and with settings enabled or disabled for source and volume scanning.

@crowbarz
Copy link
Owner

crowbarz commented Dec 3, 2024

They are indeed the power commands and queries that are used by the integration.

The 0.9.2 release should help with this issue. In this release, if a zone is discovered to be off on integration startup, then the integration does not send any further queries for that zone. Additionally, it sends 4 system query commands to collect AVR system information, but a response is expected only from system_query_model (?RGD) which is used to set model specific param defaults. If AVR zone 1 is off during integration startup, it retries the system query commands when zone 1 is turned on. Here are the logs from my AVR at integration startup, with all zones off and Don't check volume when querying AVR source enabled (the default for my AVR model):

2024-12-03 23:17:11.912 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?SVB
2024-12-03 23:17:11.932 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command system_query_mac_addr returned error: E03
2024-12-03 23:17:12.043 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?SSI
2024-12-03 23:17:12.076 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command system_query_software_version returned error: E02
2024-12-03 23:17:12.151 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?RGD
2024-12-03 23:17:12.167 INFO (MainThread) [aiopioneer.pioneer_avr] Global: model: None -> VSX-930 (<005><VSX-930/SYXEV8><E2>)
2024-12-03 23:17:12.253 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?RGB
2024-12-03 23:17:12.270 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command system_query_source_name returned error: E04
2024-12-03 23:17:12.270 INFO (MainThread) [aiopioneer.pioneer_avr] applying default parameters for model VSX-930 (^VSX-930)
2024-12-03 23:17:12.278 INFO (MainThread) [aiopioneer.pioneer_avr] determining available listening modes
2024-12-03 23:17:12.278 INFO (MainThread) [aiopioneer.pioneer_avr] querying available zones on AVR
2024-12-03 23:17:12.367 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?P
2024-12-03 23:17:12.377 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: power: None -> False (1)
2024-12-03 23:17:12.379 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1 discovered
2024-12-03 23:17:12.473 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?AP
2024-12-03 23:17:12.505 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command query_power returned error: E03
2024-12-03 23:17:12.577 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?BP
2024-12-03 23:17:12.588 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command query_power returned error: E03
2024-12-03 23:17:12.685 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?ZEP
2024-12-03 23:17:12.693 INFO (MainThread) [aiopioneer.pioneer_avr] Zone Z: power: None -> False (1)
2024-12-03 23:17:12.693 INFO (MainThread) [aiopioneer.pioneer_avr] Zone Z discovered
2024-12-03 23:17:12.695 INFO (MainThread) [aiopioneer.pioneer_avr] refreshing AVR status (zones=[<Zones.Z1: '1'>, <Zones.HDZ: 'Z'>], last refreshed 0.002s ago)
2024-12-03 23:17:12.786 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?P
2024-12-03 23:17:12.888 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending command: ?ZEP
2024-12-03 23:17:12.898 DEBUG (MainThread) [aiopioneer.pioneer_avr] queuing command _query_av_information
2024-12-03 23:17:13.365 INFO (MainThread) [custom_components.pioneer_async.media_player] Adding entities for zones [<Zones.Z1: '1'>, <Zones.HDZ: 'Z'>]
2024-12-03 23:17:13.366 DEBUG (MainThread) [custom_components.pioneer_async.media_player] Created entity for zone 1
2024-12-03 23:17:13.366 DEBUG (MainThread) [custom_components.pioneer_async.media_player] Created entity for zone Z

@PhAzE-Variance
Copy link
Author

Just updated to 0.9.2, and enabled skip audio in the config. I turned off the ARV and restarted home assistant, and it appears that it was able to startup properly now, maintaining the originally discovered items. It also doesn't seem to go into an unavailable state anymore, so the power commands work while off. Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants