I’ll turn logging on and see if something shows up.
Running two older rec’ers.
VSX-1325
VSX-1125
Mine tend to not get cycled daily, the 1325 is the home theater and the 1125 is for my sons gaming.
Edit: I guess since this is a home automation platform I could set up an automation to cycle them… lol
Anyone else had trouble getting the HD Zone entity to generate? Have a vsx-1123. Main and zone 2 show up, just not hd zone
I don’t have a VSX-1123, but if you attach some debug logs from integration startup, when it queries the AVR about its capabilities, then I might be able to help you figure that out.
Thanks for the response. Avoiding pasting in a bunch of lines from the log at least right now, for both Zone 1 and Zone 2, the summarized order of events is:
Send command to query zone power state
Receive response for zone power state
Info level acknowledge zone power state
Send command to query zone volume
Receive response for zone volume
Info level acknowledge zone volume
Info output “Zone _ discovered”
The difference in the HDZone checks is the volume query “?HZV” returns an “E04” response, then signals the updater task and moves on to checking sources.
It at least looks like a valid volume response is part of the requirements for confirming HDZone, but at least on the vsx-1123, HDZone does not have a volume control to report.
I can share more specifics from the logs too, if they are needed still.
Yes, the code checks that volume can be queried when determining whether a zone is available on the AVR. I guess the ability to power on/off the zone and change the input is still useful even if you can’t report on the zone’s current volume or probably control it. I take it from a quick look at the specs that HDZone on the VSX-1123 just passes through the audio from the input source straight to the HDMI output for the downstream device to process?
I am thinking about modifying the requirement to report on current volume when checking for an available zone. Obviously the integration will not be able to report current volume to HA if the underlying zone doesn’t support it. The ignored_zones param could be used for the cases where zones report power status for zones even though those zones don’t actually exist, and this can be set by default in profiles for specific models based on the AVR’s reported model number. Any commands unsupported by the AVR should already generate an error in the HA logs, so the changes should be straightforward (once I find some time to implement them).
That is correct. The HDZone on my unit just passes through audio from the selected input. Basically just lets me have the ability to use the same devices on a second tv.
In HA, what model is your AVR detected as? You can find that in Configuration > Devices and searching for your AVR. I want to add code to automatically set the parameter to ignore the volume check when your model is detected.
I’ve assumed it reports as VSX-1123, for this AVR model (as well as SC-LX57 as discussed in crowbar/aiopioneer#3) I’ve changed the default to not query volume when detecting zones in version 0.6.1 of the HA integration.
If you’re using the UI, reconfigure the integration, enable ignore_volume_check, save, then restart HA. Alternatively, remove and re-add the integration to pick up the new default. If you’re using configuration.yaml, then configure this via params:
- platform: pioneer_async
[...]
params:
ignore_volume_check: true
Thank you! My HDZone is working now. You are correct, it reports as VSX-1123. Only thing I noticed is the new omit volume query checkbox (was pre-checked for me, too) does not have any text in the ui
It looks like the old labels have been cached somewhere - in the new version that I released, I added the parameter names to the labels, but these don’t appear on your screenshot. Do the labels update if you clear your browser cache, or alternatively open a new HA session in an incognito/private browsing window?
All good with incognito.
Heads up, updating to 2022.3.0 from 2022.2.5, my integration broke. Reverting to my backup fixed it.
Clicking the Configure button on the UI Integrations page, the window read there is a 500 internal server error. Same thing after a reboot.
Got a logbook error: “AVR “192.168.[AVR IP]:[PORT]” is already configured”
Then an error handling request:
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/aiohttp/web_protocol.py", line 435, in _handle_request
resp = await request_handler(request)
File "/usr/local/lib/python3.9/site-packages/aiohttp/web_app.py", line 504, in _handle
resp = await handler(request)
File "/usr/local/lib/python3.9/site-packages/aiohttp/web_middlewares.py", line 117, in impl
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 60, in security_filter_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 100, in forwarded_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 28, in request_context_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 79, in ban_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 219, in auth_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 137, in handle
result = await result
File "/usr/src/homeassistant/homeassistant/components/config/config_entries.py", line 201, in post
return await super().post(request)
File "/usr/src/homeassistant/homeassistant/components/http/data_validator.py", line 62, in wrapper
result = await method(view, request, *args, **kwargs)
File "/usr/src/homeassistant/homeassistant/helpers/data_entry_flow.py", line 72, in post
result = await self._flow_mgr.async_init(
File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 203, in async_init
flow, result = await task
File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 230, in _async_init
result = await self._async_handle_step(flow, flow.init_step, data, init_done)
File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 325, in _async_handle_step
result: FlowResult = await getattr(flow, method)(user_input)
File "/config/custom_components/pioneer_async/config_flow.py", line 125, in async_step_init
pioneer = self.hass.data[DOMAIN][entry.entry_id]
KeyError: 'f2644c7712830906a5419fb96651f624'
I’ve not been able to replicate this by installing 2022.2.9, adding the integration via the UI, then upgrading to 2022.3.0.
The error message suggests that the same AVR is defined in configuration.yaml as well as added as an integration via the UI. You only need do configure it via one method, not both. What could be happening here is that the UI added integration was initialised first under the previous HA version, whereas in the new HA version the configuration.yaml integration was initialised first and is causing the error above when you try to configure it via the UI. The order in which platforms and integrations are set up sometimes changes across HA versions.
If this is the case, then the solution is to remove the configuration from configuration.yaml and use the UI to configure integration settings.
If you definitely don’t configure the AVR via configuration.yaml, then there could be a stale/duplicate config entry in .storage/core.config_entries for the AVR, you may have to manually remove it (after first stopping HA and verifying that the JSON is still valid after removing).
If none of these solve your issue, then turn on debug level logging for the integration, this should help pinpoint what is happening.
Nothing in config and no extras in core.config_entries.
It now configures correctly on the boot after a core update, then breaks on reboots.
On reboot, log shows the below after the “opening AVR connection” step.
WARNING (MainThread) [homeassistant.config_entries] Config entry 'Pioneer' for pioneer_async integration not ready yet; Retrying in background
DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.__del__()
and a number of seconds later:
DEBUG (MainThread) [custom_components.pioneer_async] >> async_setup_entry(entry_id=.....)
ERROR (MainThread) [custom_components.pioneer_async.media_player] AVR "192.168.50.123:8102" is already configured
It ends after that.
I was able to force it back to making the media players by changing the “return None” to “return device_unique_id” in media_player.py, line #187, but then I had 2 listening processes running and checking the AVR.
If you have 2 listening processes after your code mod, then you do seem to have duplicated config somewhere causing the integration to instantiate twice, each starting its own listener. Do you see multiple calls to async_setup_entry with different entry_id values, or both async_setup_entry and async_setup_platform calls in the logs?
I’ve released 0.6.2 which contains some additional debugging. Can you include all the debug logs from pioneer_async so I can get a better idea of what’s going on?
Will do. Been a bit busy lately, but planning on getting to it soon.
Hi @crowbarz !
It’s good to know you’re still working on this integration. It’s been a long time since I used it on my VSX-S510 but I can’t get it to work again.
This is my media_player.yaml
- platform: pioneer_async
host: 192.168.1.171
sources: { TV: '06', GCast: '15' }
My AVR seems OK
bash-5.1# nc -vv 192.168.1.171 8102
192.168.1.171 (192.168.1.171:8102) open
But I have a timeout error
2022-04-26 13:14:38 DEBUG (MainThread) [custom_components.pioneer_async.media_player] >> async_setup_platform(OrderedDict([('platform', 'pioneer_async'), ('host', '192.168.1.171'), ('sources', OrderedDict([('TV', '06'), ('GCast', '15')])), ('name', 'Pioneer AVR'), ('timeout', 2.0), ('params', {}), ('scan_interval', datetime.timedelta(seconds=60)), ('port', 8102)]))
2022-04-26 13:14:38 DEBUG (MainThread) [custom_components.pioneer_async.media_player] Configuring AVR "192.168.1.171:8102"
2022-04-26 13:14:38 INFO (MainThread) [aiopioneer.pioneer_avr] Starting aiopioneer 0.1.8
2022-04-26 13:14:38 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.__init__(host="192.168.1.171", port=8102, timeout=2.0, params={})
2022-04-26 13:14:38 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.set_user_params({})
2022-04-26 13:14:38 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2022-04-26 13:14:38 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2022-04-26 13:14:42 ERROR (MainThread) [custom_components.pioneer_async.media_player] Could not open AVR connection: TimeoutError:
2022-04-26 13:14:42 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.__del__()
Do you have an idea of what I could try please ?
Edit : I reverted back to 0.5 (last known working version)
Hi @2t0m, you could try increasing the timeout to eg. 10. The default is 2 (seconds), which I think may have been inherited from the pioneer integration. Otherwise it’s not immediately apparent why v0.5 works for you whereas v0.6.2 does not. What version of HA are you running?
Hi @crowbarz. I increased the timeout and it works, thanks !
2022-05-23 07:19:08 DEBUG (MainThread) [custom_components.pioneer_async.media_player] >> async_setup_platform(OrderedDict([('platform', 'pioneer_async'), ('host', '192.168.1.171'), ('timeout', 10.0), ('sources', OrderedDict([('Google TV', '06'), ('RecalBox', '15'), ('PS3', '49')])), ('params', OrderedDict([('volume_step', True), ('ignored_zones', ['2'])])), ('scan_interval', datetime.timedelta(seconds=60)), ('name', 'Pioneer AVR'), ('port', 8102)]))
2022-05-23 07:19:08 DEBUG (MainThread) [custom_components.pioneer_async.media_player] Configuring AVR "192.168.1.171:8102"
2022-05-23 07:19:08 INFO (MainThread) [aiopioneer.pioneer_avr] Starting aiopioneer 0.1.8
2022-05-23 07:19:08 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.__init__(host="192.168.1.171", port=8102, timeout=10.0, params={'volume_step': True, 'ignored_zones': ['2']})
2022-05-23 07:19:08 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.set_user_params({'volume_step': True, 'ignored_zones': ['2']})
2022-05-23 07:19:08 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() started
2022-05-23 07:19:08 DEBUG (MainThread) [aiopioneer.pioneer_avr] opening AVR connection
2022-05-23 07:19:11 INFO (MainThread) [aiopioneer.pioneer_avr] AVR connection established
2022-05-23 07:19:11 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR._listener_schedule()
2022-05-23 07:19:11 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR._connection_listener() started
2022-05-23 07:19:11 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR._updater_schedule()
2022-05-23 07:19:12 INFO (MainThread) [aiopioneer.pioneer_avr] updating AVR status (full=True, last updated 1653290352.533 s ago)
2022-05-23 07:19:12 DEBUG (MainThread) [aiopioneer.pioneer_avr] >> PioneerAVR.connect() completed
2022-05-23 07:19:12 INFO (MainThread) [aiopioneer.pioneer_avr] querying device information from Pioneer AVR
2022-05-23 07:19:12 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?RGD
2022-05-23 07:19:14 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?RGD returned response: RGD<003><VSX-S510/SYXE8 >
2022-05-23 07:19:14 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?SVB
2022-05-23 07:19:25 DEBUG (MainThread) [aiopioneer.pioneer_avr] Task-1522: timed out waiting for data
2022-05-23 07:19:25 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?SVB timed out
2022-05-23 07:19:25 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?SSI
2022-05-23 07:19:35 DEBUG (MainThread) [aiopioneer.pioneer_avr] Task-1522: timed out waiting for data
2022-05-23 07:19:35 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?SSI timed out
2022-05-23 07:19:35 INFO (MainThread) [aiopioneer.pioneer_avr] applying default parameters for model VSX-S510 (^VSX-S510)
2022-05-23 07:19:35 INFO (MainThread) [aiopioneer.pioneer_avr] querying available zones on AVR
2022-05-23 07:19:35 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?P
2022-05-23 07:19:35 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: Power: False
2022-05-23 07:19:35 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?P returned response: PWR2
2022-05-23 07:19:35 DEBUG (MainThread) [aiopioneer.pioneer_avr] delaying command for 0.093 s
2022-05-23 07:19:35 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?V
2022-05-23 07:19:35 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: Volume: 121
2022-05-23 07:19:35 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?V returned response: VOL121
2022-05-23 07:19:35 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1 discovered
2022-05-23 07:19:35 DEBUG (MainThread) [aiopioneer.pioneer_avr] delaying command for 0.094 s
2022-05-23 07:19:36 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?AP
2022-05-23 07:19:37 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 2: Power: False
2022-05-23 07:19:37 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?AP returned response: APR1
2022-05-23 07:19:37 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?ZV
2022-05-23 07:19:38 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 2: Volume: 0
2022-05-23 07:19:38 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?ZV returned response: ZV00
2022-05-23 07:19:38 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?BP
2022-05-23 07:19:49 DEBUG (MainThread) [aiopioneer.pioneer_avr] Task-1522: timed out waiting for data
2022-05-23 07:19:49 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?BP timed out
2022-05-23 07:19:49 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?ZEP
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] Task-1522: timed out waiting for data
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?ZEP timed out
2022-05-23 07:20:00 INFO (MainThread) [custom_components.pioneer_async.media_player] Adding entities for zones ['1']
2022-05-23 07:20:00 DEBUG (MainThread) [custom_components.pioneer_async.media_player] PioneerZone.__init__(1)
2022-05-23 07:20:00 DEBUG (MainThread) [custom_components.pioneer_async.media_player] Created entity Pioneer AVR for zone 1
2022-05-23 07:20:00 INFO (MainThread) [aiopioneer.pioneer_avr] updating AVR status (full=True, last updated 10.004 s ago)
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?P
2022-05-23 07:20:00 DEBUG (MainThread) [custom_components.pioneer_async.media_player] >> PioneerZone.async_update(1)
2022-05-23 07:20:00 DEBUG (MainThread) [custom_components.pioneer_async.media_player] >> PioneerZone.async_added_to_hass(1)
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?P returned response: PWR2
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] delaying command for 0.090 s
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?V
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?V returned response: VOL121
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] delaying command for 0.096 s
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?M
2022-05-23 07:20:00 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: Mute: False
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] calling callback for zone 1
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?M returned response: MUT1
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] sending AVR command: ?F
2022-05-23 07:20:00 INFO (MainThread) [aiopioneer.pioneer_avr] Zone 1: Source: 06 (Google TV)
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] calling callback for zone 1
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] AVR command ?F returned response: FN06
2022-05-23 07:20:00 DEBUG (MainThread) [aiopioneer.pioneer_avr] calling callback for zone 1
2022-05-23 07:24:51 DEBUG (MainThread) [custom_components.pioneer_async.media_player] >> PioneerZone.async_added_to_hass(1)
Did you ever resolve this issue? Experiencing the same issue after adding the integration through the UI and removing it.
How do I remove the zombie config?
I can reach the avr via telnet no problem