DLNA Digital Media Renderer fails to connect to Cambridge Audio CXN V2

swedishlars commented 2 years ago

The problem

After upgrading HA Core to 2022.4.7 dlna_dmr fails to connect to my Cambridge Audio CXN v2 music streamer. Errors point to async_upnp_client.aiohttp and dlna_dmr, so not sure which is the culprit.

What version of Home Assistant Core has the issue?

core-2022.4.7

What was the last working version of Home Assistant Core?

core-2022.3.8

What type of installation are you running?

Home Assistant Core

Integration causing the issue

DLNA Digital Media Renderer

Link to integration documentation on our website

https://www.home-assistant.io/integrations/dlna_dmr/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: async_upnp_client.aiohttp
Source: /srv/homeassistant/lib/python3.9/site-packages/async_upnp_client/aiohttp.py:247
First occurred: 00:45:52 (12 occurrences)
Last logged: 01:22:58

Failed to create HTTP server at fe80::96c6:91ff:feaf:dc87:0: [Errno 22] error while attempting to bind on address ('fe80::96c6:91ff:feaf:dc87', 0, 0, 0): invalid argument

Logger: homeassistant.components.dlna_dmr
Source: components/dlna_dmr/media_player.py:267
Integration: DLNA Digital Media Renderer (documentation, issues)
First occurred: 00:46:40 (4 occurrences)
Last logged: 01:22:58

Failed connecting to recently alive device at http://[fe80::9a5d:adff:fe6d:65d6%2]:8050/eb46d37a-e84e-426b-9ce1-6776cbc4a1b1/description.xml: UpnpServerOSError(None)

Additional information

Please let me know if I can be of any further help!

Regards, Lars

probot-home-assistant[bot] commented 2 years ago

dlna_dmr documentation dlna_dmr source _{^{(message by IssueLinks)}}

probot-home-assistant[bot] commented 2 years ago

Hey there @stevenlooman, @chishm, mind taking a look at this issue as it has been labeled with an integration (dlna_dmr) you are listed as a code owner for? Thanks! _{^{(message by CodeOwnersMention)}}

swedishlars commented 2 years ago

Updated homeassistant core to 2022.5.2 and now with async-upnp-client 0.29.0 all errors have gone away. However created entity is unavailable. Perhaps same issue as #71306?

chishm commented 2 years ago

Thank you for the bug report. I'll continue working through this issue in #71306. Feel free to post any relevant logs here or there (I'll monitor both issue threads).

DazWorrall commented 2 years ago

I am having a similar problemm to this and #71306 - no IPv6 in my setup though, so I'll post my logs here. dmr is an LG TV, I can setup the integration and the media player is available for a few seconds, and then unavailable:

2022-05-10 13:55:17 DEBUG (MainThread) [homeassistant.components.dlna_dmr.config_flow] async_step_user: user_input: None
2022-05-10 13:55:17 DEBUG (MainThread) [homeassistant.components.dlna_dmr.config_flow] _get_discoveries
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr.config_flow] async_step_user: user_input: {'host': 'Some TV'}
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr.config_flow] _async_set_info_from_discovery: location: http://XXX.XXX.XXX.XXX:1224/, UDN: uuid:1b5f0efb-2c25-745a-b94d-cd4a76600271
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr.config_flow] _async_create_entry: location: http://XXX.XXX.XXX.XXX:1224/, UDN: uuid:1b5f0efb-2c25-745a-b94d-cd4a76600271
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Setting up config entry: uuid:1b5f0efb-2c25-745a-b94d-cd4a76600271
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr] media_player.async_setup_entry 5444621243253ce6fa3c29eeed208711 (Some TV)
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Connecting to device at http://XXX.XXX.XXX.XXX:1224/
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Getting event handler for EventListenAddr(host='YYY.YYY.YYY.YYY', port=0, callback_url=None)
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Started event handler at http://YYY.YYY.YYY.YYY:37635/notify
2022-05-10 13:55:20 DEBUG (MainThread) [homeassistant.components.dlna_dmr] SSDP SsdpChange.ALIVE notification of device uuid:1b5f0efb-2c25-745a-b94d-cd4a76600271::urn:schemas-upnp-org:device:MediaRenderer:1 at http://XXX.XXX.XXX.XXX:1224/
2022-05-10 13:55:30 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Device unavailable: UpnpActionResponseError('Error during async_call(), status: 500, upnp error: 606 (Action not authorized)')
2022-05-10 13:55:30 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Disconnecting from Some TV

2022-05-10 13:55:30 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Device unavailable: UpnpActionResponseError('Error during async_call(), status: 500, upnp error: 606 (Action not authorized)')

Seems to be the relevant problem for me, not having much luck getting more info searching around for that.

swedishlars commented 2 years ago

Only relevant warning I find in my log today is this:

Failed connecting to recently alive device at http://[fe80::9a5d:adff:fe6d:65d6%2]:8050/eb46d37a-e84e-426b-9ce1-6776cbc4a1b1/description.xml: UpnpConnectionError('[Errno 104] Connection reset by peer', None)

So by the looks of it same ipv6 issue as https://github.com/home-assistant/core/issues/71306 ?

chishm commented 2 years ago

@swedishlars: Interesting, it's a link-local IPv6 address that it's connecting to. When you enable debug logging for the dlna_dmr component (as described at https://github.com/home-assistant/core/issues/71306#issuecomment-1122346294), can you see what address it uses for the event handler (look for "Getting event handler" and "Started event handler"). A full log would be even more useful.

DazWorrall commented 2 years ago

@chishm should I start a new issue for my permission error above?

swedishlars commented 2 years ago

Hi, attached full debug log. It shows full restart of homeassistant core. Around time code 2022-05-11 14:28:42 is when I add and configure dlna_dmr integration.

dlna_dmr_debug_log.txt

Let me know if I can help with further tests/logs

swedishlars commented 2 years ago

Hi @chishm, In case it helps, sifting through my log I see 3 lines for "Getting event handler". "started event handler" follows the same pattern.

Line 244, the host ip here is the Intel Nuc hosting my homeassistant core instance: 2022-05-11 14:29:08 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Getting event handler for EventListenAddr(host='192.168.50.146', port=0, callback_url=None)

Line 366: 2022-05-11 14:30:38 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Getting event handler for EventListenAddr(host='fe80::96c6:91ff:feaf:dc87%eno1', port=0, callback_url=None)

Line 606: 2022-05-11 14:32:38 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Getting event handler for EventListenAddr(host='fe80::96c6:91ff:feaf:dc87%eno1', port=0, callback_url=None)

chishm commented 2 years ago

@swedishlars, This line looks the most significant to me:

2022-05-11 14:29:18 DEBUG (MainThread) [homeassistant.components.dlna_dmr] Device unavailable: UpnpActionResponseError('Error during async_call(), status: 500, upnp error: 602 (Not implemented)')

Unfortunately I can't see what caused that. Could you please retry the logging with the additional setting of async_upnp_client.traffic: debug? This will get the lower level messages to/from all UPnP devices.

chishm commented 2 years ago

@DazWorrall: I'm beginning to suspect yours and @swedishlars' problems are related to initial polling of state variables. If you could try the async_upnp_client.traffic: debug log setting too, then that will confirm. No need to open a separate issue just yet.

swedishlars commented 2 years ago

@chishm First of all, thank you so much for dedicating time to this. I'm a developer myself so I know how time consuming this is. I wish I could help more but upnp/dlna tcp networking is Greek to me. I've attached a startup log with async_upnp_client.traffic debug enabled.

Let me know if there is anything else I can help with!

dlna_dmr_debug_log_2.txt

chishm commented 2 years ago

First of all, thank you so much for dedicating time to this. I'm a developer myself so I know how time consuming this is. I wish I could help more but upnp/dlna tcp networking is Greek to me.

You're welcome! I've only got a few DLNA devices, so I'm relying on other people to tell me when something doesn't work and to help diagnose the problem.

I've attached a startup log with async_upnp_client.traffic debug enabled.

Thank you for the newest debug log. This does appear to be the same problem as in #71306.

Let me know if there is anything else I can help with!

I'll have to submit a fix to async_upnp_client for this to get resolved. When I've got something I'm happy with, I might get you to test it out before it gets merged.

chishm commented 2 years ago

If you'd like to test this, could you please try pip installing git+https://github.com/chishm/async_upnp_client@7408798b5ddb49cae2fe004376a1cb87824031ab into your HA test environment and seeing if that resolves your issue? You'll need to start HA with --skip-pip, so that it doesn't reinstall the PyPI version of the package.

swedishlars commented 2 years ago

Can you check the link please? It comes up empty for me.

On Tue, 17 May 2022, 14:28 Michael Chisholm, @.***> wrote:

If you'd like to test this, could you please try pip installing git+ @.*** into your HA test environment and seeing if that resolves your issue? You'll need to start HA with --skip-pip, so that it doesn't reinstall the PyPI version of the package.

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/70611#issuecomment-1128871052, or unsubscribe https://github.com/notifications/unsubscribe-auth/ATQTTXWGDG74ILUKTXA2JK3VKONH5ANCNFSM5UHAQ6GQ . You are receiving this because you were mentioned.Message ID: @.***>

swedishlars commented 2 years ago

@chism Ignore me, I found your [poll-variables-gracefully] branch

swedishlars commented 2 years ago

Hi, I pip installed you branch, fired up hass with --skip-pip. Unfortunately dlna_dmr entity is still unavailable.

Tried removing integration, adding back, testing both auto discovered dmr and also manually adding url to description.xml. Integration and device is added fine by the looks of it. But entity refuses to show up I'm afraid. I have attached the resulting log.

dlna_dmr_debug_log_3.txt

chishm commented 2 years ago

Hi @swedishlars, I've had a look at that 3rd log, and I don't think you've got the specific commit installed. The way to do it is a bit complicated. You have to enter the hass virtual environment (something like source /path-to-hass-installation/bin/active), then use the pip command:

pip install 'git+https://github.com/chishm/async_upnp_client@7408798b5ddb49cae2fe004376a1cb87824031ab'

You should then get some output like:

Collecting git+https://github.com/chishm/async_upnp_client@7408798b5ddb49cae2fe004376a1cb87824031ab
  Cloning https://github.com/chishm/async_upnp_client (to revision 7408798b5ddb49cae2fe004376a1cb87824031ab) to /tmp/pip-req-build-sxywtu2g

swedishlars commented 2 years ago

Hi @chishm , that's what I did and everything looked ok to me. But let me try again and get back to you.

chishm commented 2 years ago

Ok. You should be able to tell if it's installed the right version by using grep -r 'poll missing action' /path-to-hass-installation/.

swedishlars commented 2 years ago

@chishm Tried this again, installed into my ha venv /srv/homeassistant. But I do not get a grep result with: grep -r 'poll missing action' /srv/homeassistant

swedishlars commented 2 years ago

Hmm, not sure what I am doing wrong here...

When I run (in my venv): pip install 'git+https://github.com/chishm/async_upnp_client@7408798b5ddb49cae2fe004376a1cb87824031ab'

I get:

Collecting git+https://github.com/chishm/async_upnp_client@7408798b5ddb49cae2fe004376a1cb87824031ab Cloning https://github.com/chishm/async_upnp_client (to revision 7408798b5ddb49cae2fe004376a1cb87824031ab) to /tmp/pip-req-build-eql6e0we Running command git clone --filter=blob:none --quiet https://github.com/chishm/async_upnp_client /tmp/pip-req-build-eql6e0we Running command git rev-parse -q --verify 'sha^7408798b5ddb49cae2fe004376a1cb87824031ab' Running command git fetch -q https://github.com/chishm/async_upnp_client 7408798b5ddb49cae2fe004376a1cb87824031ab Running command git checkout -q 7408798b5ddb49cae2fe004376a1cb87824031ab Resolved https://github.com/chishm/async_upnp_client to commit 7408798b5ddb49cae2fe004376a1cb87824031ab Preparing metadata (setup.py) ... done Requirement already satisfied: aiohttp>=3.7.4 in /srv/homeassistant/lib/python3.9/site-packages (from async-upnp-client==0.29.0) (3.8.1) Requirement already satisfied: async-timeout<5.0,>=3.0 in /srv/homeassistant/lib/python3.9/site-packages (from async-upnp-client==0.29.0) (4.0.2) Requirement already satisfied: defusedxml>=0.6.0 in /srv/homeassistant/lib/python3.9/site-packages (from async-upnp-client==0.29.0) (0.7.1) Requirement already satisfied: python-didl-lite~=1.3.2 in /srv/homeassistant/lib/python3.9/site-packages (from async-upnp-client==0.29.0) (1.3.2) Requirement already satisfied: voluptuous>=0.12.1 in /srv/homeassistant/lib/python3.9/site-packages (from async-upnp-client==0.29.0) (0.13.1) Requirement already satisfied: attrs>=17.3.0 in /srv/homeassistant/lib/python3.9/site-packages (from aiohttp>=3.7.4->async-upnp-client==0.29.0) (21.2.0) Requirement already satisfied: frozenlist>=1.1.1 in /srv/homeassistant/lib/python3.9/site-packages (from aiohttp>=3.7.4->async-upnp-client==0.29.0) (1.2.0) Requirement already satisfied: aiosignal>=1.1.2 in /srv/homeassistant/lib/python3.9/site-packages (from aiohttp>=3.7.4->async-upnp-client==0.29.0) (1.2.0) Requirement already satisfied: multidict<7.0,>=4.5 in /srv/homeassistant/lib/python3.9/site-packages (from aiohttp>=3.7.4->async-upnp-client==0.29.0) (6.0.2) Requirement already satisfied: yarl<2.0,>=1.0 in /srv/homeassistant/lib/python3.9/site-packages (from aiohttp>=3.7.4->async-upnp-client==0.29.0) (1.7.2) Requirement already satisfied: charset-normalizer<3.0,>=2.0 in /srv/homeassistant/lib/python3.9/site-packages (from aiohttp>=3.7.4->async-upnp-client==0.29.0) (2.0.12) Requirement already satisfied: idna>=2.0 in /srv/homeassistant/lib/python3.9/site-packages (from yarl<2.0,>=1.0->aiohttp>=3.7.4->async-upnp-client==0.29.0) (3.3) WARNING: You are using pip version 22.0.4; however, version 22.1 is available. You should consider upgrading via the '/srv/homeassistant/bin/python3 -m pip install --upgrade pip' command.

pip show async-upnp-client gives:

Name: async-upnp-client Version: 0.29.0 Summary: Async UPnP Client Home-page: https://github.com/StevenLooman/async_upnp_client Author: Steven Looman Author-email: steven.looman@gmail.com License: Apache 2 Location: /srv/homeassistant/lib/python3.9/site-packages Requires: aiohttp, async-timeout, defusedxml, python-didl-lite, voluptuous Required-by:

home-assistant / core