VSX-AX4AVi via IP2Serial: Pioneer AVR integration eventually hangs Home Assistant entirely when device is turned off manually (and blocks HA startup)

[stephanbosch]

If the amplifier is turned off while Home Assistant is running, it will fill the system and home assistant log with connection/timeout error messages overnight until the filesystems are full and HA service is lost. By logging in as root I can remove the logs and fix it with a reboot. (Sadly I did not copy one of this errors for you this time).

However, home assistant will not start while the amplifier is still off. It will log about starting addons and integrations, but it does not allow client connection. Once the amplifier is turned on, Home Assistant comes back to life.

Note that this setup uses an IP to Serial converter running as a windows service. One symptom of that is that it will allow TCP connection but it might never get a response because the Serial port is likely not responding when the device is off.

[stephanbosch]

This is all that was logged involving "pioneer" during the hanging startup:

# grep pioneer home-assistant.log
2025-01-16 13:52:30.548 WARNING (SyncWorker_0) [homeassistant.loader] We found a custom integration pioneer_async which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2025-01-16 13:52:35.438 WARNING (MainThread) [aiopioneer.pioneer_avr] AVR device model unavailable, no model parameters set
2025-01-16 13:52:46.836 WARNING (MainThread) [homeassistant.components.media_player] Setup of media_player platform pioneer_async is taking over 10 seconds.

[crowbarz]

If the amplifier is turned off while Home Assistant is running, it will fill the system and home assistant log with connection/timeout error messages overnight until the filesystems are full and HA service is lost. By logging in as root I can remove the logs and fix it with a reboot. (Sadly I did not copy one of this errors for you this time).

By "turned off" do you mean a) the AVR unit itself has its power cut, or b) the AVR unit itself has power supplied, but the main AVR zone is powered off?

I'd need to see the logs to see whether they can be excluded from logging or avoided.

However, home assistant will not start while the amplifier is still off. It will log about starting addons and integrations, but it does not allow client connection. Once the amplifier is turned on, Home Assistant comes back to life.

At integration startup, if it is able to connect to the configured IP but does not get a response to the ?RGD command, then it will abort startup. HA will keep trying to start the integration in the background but it should not stop the rest of HA from starting.

When using the AVR serial port, I don't know if it responds to commands if the AVR itself is powered but the main zone is powered off. On network enabled AVRs, there is usually a Network Standby toggle in the AVR settings that needs to be enabled for the AVR to respond in this scenario.

This is all that was logged involving "pioneer" during the hanging startup:

Those logs show that the integration has started up properly, notwithstanding the AVR device model unavailable log as discussed in #54

[stephanbosch]

By "turned off" do you mean a) the AVR unit itself has its power cut, or b) the AVR unit itself has power supplied, but the main AVR zone is powered off?

Turned off by the button on the front of the device, which I assume is what you mean by turning the main AVR zone off.

[stephanbosch]

(I am looking at this remotely right now, so I cannot mess with the AMP)

Oh, I found this at the end in the home-assistant.log.1:

2025-01-16 13:52:23.649 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.13/site-packages/aiopioneer/connection.py", line 422, in _wait_for_response
    raise AVRUnavailableError
aiopioneer.exceptions.AVRUnavailableError

[stephanbosch]

I had the integration disabled all day, until now. I enabled it while the amp was on, and I waited for it to finish initializing. Then I pushed the button on the front of the amp to turn it off. Then I looked at the home-assistant.log. Nothing happened for a minute or so. Then it started bombing the log. I uploaded a fragment here. It starts at the point I re-enabled the integration and ends 4096 lines later.

log-fragment.txt

The actual log increased to 50Mb in a very short time before I disabled the integration and Github doesn't allow me to upload the full thing (and that is likely not useful either).

I hope this is enough for you to see what is happening.

[pantherale0]

Looking at those logs, it seems your serial bridge is reseting the connection. Is that stable or crashing? What software are you using to provide the bridge?

[stephanbosch]

The bridge is using https://github.com/tdelenikas/comm2ip

From what I can tell in it's (on this system partially Dutch) logs it has a timeout of its own, upon which it will terminate the connection.

[stephanbosch]

This wasn't an issue obviously for the official Pioneer integration I used before, as that doesn't keep the connection open from what I understand.

[pantherale0]

That could be the problem then. Can you try and use a different serial bridge such as ser2net just to rule out software connectivity problems? I notice that comm2ip hasn't been updated for some years.

[stephanbosch]

It is likely the trigger of this issue, but aiopioneer should probably also not bomb the logs upon connectivity issues or other weird/erroneous behavior of other software and should use e.g. some sort of back-off scheme to prevent that.

I looked at the Comm2IP sources and that uses a hard-coded 15 sec read and write timeout upon which the connection is indeed terminated. The reconnect and log spam cycle for aiopioneer is much faster than that though. So I wonder if that is the whole story.

I'll get back to you once I try ser2net.

[crowbarz]

The integration does use a backoff before reconnect, but the maximum reconnect interval is hard coded to 64 seconds so that network AVRs reconnect soon after it becomes available again. But I don't think this is what you are seeing here.

The logs show that the integration is not handling the case where the connection is reset by the AVR end. I have never seen that happen on a network AVR - they never seems to deliberately close the API connection, and the connection just times out if the AVR unit loses power. Let me review the exception handling code to see how the exception generated in this case can be handled more gracefully.

[crowbarz]

Can you see if upgrading to 0.10.2rc1 resolves this issue. I have tried to replicate your scenario by using nc to proxy the AVR connection, and pausing the proxy to simulate an AVR that isn't responding, and killing it to simulate the disconnect/reconnect that you describe. The integration now survives both of these scenarios more gracefully.

[stephanbosch]

I am currently quite ill. It will take a while before I can test this.