Cutting off power from one speaker breaks the integration

Niekmanz commented 2 months ago

The problem

In my setup the power to my media setup (TV, receiver and Bluesound Node 2i) is cut off completely at night and when we're away. Another speaker (Pulse Mini P200) is always on. Everytime the Node is cut off from power all Bluesound speakers are reported 'off' in HA; they cant be controlled anymore. When power comes back on their status doesn't update until I reload the integration. And even then it's a hit or miss. Accessing the speaker directly through a browser works fine.

In the previous (yaml) configuration this problem didn't occur. Also, HA would correctly present the status of the Node as 'unavailable' when power was cut off.

What version of Home Assistant Core has the issue?

core-2024.8.1

What was the last working version of Home Assistant Core?

core-2024.7.4

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Bluesound

Link to integration documentation on our website

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

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2024-08-12 21:41:57.577 ERROR (MainThread) [homeassistant.components.media_player] Platform bluesound does not generate unique IDs. ID 90:56:82:af:2f:c5-11000 already exists - ignoring media_player.dikke_box
2024-08-12 21:43:55.151 ERROR (MainThread) [homeassistant.components.media_player] Platform bluesound does not generate unique IDs. ID 90:56:82:af:2f:c5-11000 already exists - ignoring media_player.dikke_box
2024-08-12 21:44:47.602 ERROR (MainThread) [homeassistant.components.media_player] Platform bluesound does not generate unique IDs. ID 90:56:82:af:2f:c5-11000 already exists - ignoring media_player.dikke_box
2024-08-12 21:46:00.680 ERROR (MainThread) [homeassistant.components.media_player] Platform bluesound does not generate unique IDs. ID 90:56:82:af:2f:c5-11000 already exists - ignoring media_player.dikke_box

Additional information

No response

home-assistant[bot] commented 2 months ago

Hey there @thrawnarn, @louischrist, mind taking a look at this issue as it has been labeled with an integration (bluesound) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `bluesound` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign bluesound` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

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

LouisChrist commented 2 months ago

I have created a PR which fixes two things:

The status should update now when the power comes back on. There was a bug which broke the update loop.
The status is set to unavailable when the speaker is not reachable.

There are two things i cannot test/reproduce:

All players showing the state off, when one player is not reachable. I have only one speaker.
The log about non unique IDs.

TuomasPakkanen commented 2 months ago

Think I'm having a similar issue but maybe the next HA patch will now fix it hopefully. I'm not cutting the power to my Node 2i but it seems it drops offline in HA randomly. Works normally via BluOS app and reloading the integration does indeed seem to restore it back online. I'll wait until the PR is accepted to see if the fix helped.

LouisChrist commented 2 months ago

It should get back to available in 2024.8.2 without a reload. That's due to #123790.

But it should not stop in the first place. Do you have any errors Logs? There should be one of those:

Node 192.168.1.1:11000 is offline, retrying later
Unexpected error in 192.168.1.1:11000, retrying later

LouisChrist commented 2 months ago

@Niekmanz Can you try 2024.8.2 and check if the errors have been fixed? Especially if all speakers go to unavailable when one is cut from power.

TuomasPakkanen commented 2 months ago

It should get back to available in 2024.8.2 without a reload. That's due to #123790.

But it should not stop in the first place. Do you have any errors Logs? There should be one of those:

Node 192.168.1.1:11000 is offline, retrying later

Unexpected error in 192.168.1.1:11000, retrying later

I've updated to 2024.8.2 but not yet sure if that fixed the issue as it was sort of random when it occurs. However I checked the logs and see these two from earlier today:

Logger: homeassistant.components.bluesound.media_player Source: components/bluesound/media_player.py:404 integration: Bluesound (documentation, issues) First occurred: 12:01:03 (1 occurrences) Last logged: 12:01:03

Client connection error, marking Living Room as offline

Logger: homeassistant.components.bluesound.media_player Source: components/bluesound/media_player.py:318 integration: Bluesound (documentation, issues) First occurred: 12:01:03 (1 occurrences) Last logged: 12:01:03

Node 192.168.1.252:11000 is offline, retrying later.

Edit: seems it was only unavailable for 3-4 minutes, but I'll monitor it.

I have recently changed Google wifi routers to Unifi equipment so I'm not totally sure if there could be some new issue caused by that hw change.

Br Tuomas

LouisChrist commented 2 months ago

That seems to work as expected. 3 Minutes is the timeout between retries. I left that one as is, but i think it might be reasonable to reduce it. Or use an exponential backoff.

Off Topic regarding WiFi a the Node 2i: I think PMF(Protected Management Frames) are not supported by the Node 2i. I have a separate WiFi where i disabled them completely.

TuomasPakkanen commented 2 months ago

Mine has been working normally now after updating to 2024.8.2. Thanks for the tip regarding the wifi. Will look into that if the problems would reoccur.

klingbing commented 2 months ago

First, thanks for the work you guys are putting into this integration!

Unfortunately I am also experiencing issues with a Bluesound Node 2i and a Powernode 2i that are cut off from power when not in use. Updating (currently on 2024.8.3) has not resolved this for me unfortunately, the media_player entities remains in state unavailable. It works fine again after a HA reboot, but fails as soon as the Bluesound player has been cut from power.

I have tried removing all/both players, rebooting HA and adding them again which does not resolve I'm afraid. I had no issues up until version 2024.7.4.

Here are some related logs:

Logger: homeassistant.components.media_player
Quelle: helpers/entity_platform.py:764
Integration: Mediaplayer ([Dokumentation](https://www.home-assistant.io/integrations/media_player), [Probleme](https://github.com/home-assistant/core/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+media_player%22))
Erstmals aufgetreten: 06:05:09 (1 Vorkommnisse)
Zuletzt protokolliert: 06:05:09

Platform bluesound does not generate unique IDs. ID 90:56:85:49:35:c5-11000 already exists - ignoring media_player.esszimmer

Logger: homeassistant.components.media_player
Quelle: helpers/entity_platform.py:930
Integration: Mediaplayer ([Dokumentation](https://www.home-assistant.io/integrations/media_player), [Probleme](https://github.com/home-assistant/core/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+media_player%22))
Erstmals aufgetreten: 06:05:09 (1 Vorkommnisse)
Zuletzt protokolliert: 06:05:09

Error while removing entity media_player.esszimmer
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1073, in _wrap_create_connection
    sock = await aiohappyeyeballs.start_connection(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohappyeyeballs/impl.py", line 104, in start_connection
    raise first_exception
  File "/usr/local/lib/python3.12/site-packages/aiohappyeyeballs/impl.py", line 81, in start_connection
    sock = await _connect_sock(
           ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohappyeyeballs/impl.py", line 166, in _connect_sock
    await loop.sock_connect(sock, address)
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 641, in sock_connect
    return await fut
           ^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/selector_events.py", line 681, in _sock_connect_cb
    raise OSError(err, f'Connect call failed {address}')
OSError: [Errno 113] Connect call failed ('192.168.1.15', 11000)

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluesound/media_player.py", line 316, in _start_poll_command
    await self.async_update_status()
  File "/usr/src/homeassistant/homeassistant/components/bluesound/media_player.py", line 369, in async_update_status
    status = await self._player.status(etag=etag, poll_timeout=120, timeout=125)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pyblu/_player.py", line 73, in status
    async with self._session.get(f"{self.base_url}/Status", params=params, timeout=timeout) as response:
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 1353, in __aenter__
    self._resp = await self._coro
                 ^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/client.py", line 657, in _request
    conn = await self._connector.connect(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 564, in connect
    proto = await self._create_connection(req, traces, timeout)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 975, in _create_connection
    _, proto = await self._create_direct_connection(req, traces, timeout)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1350, in _create_direct_connection
    raise last_exc
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1319, in _create_direct_connection
    transp, proto = await self._wrap_create_connection(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/connector.py", line 1088, in _wrap_create_connection
    raise client_error(req.connection_key, exc) from exc
aiohttp.client_exceptions.ClientConnectorError: Cannot connect to host 192.168.1.15:11000 ssl:default [Connect call failed ('192.168.1.15', 11000)]

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1385, in async_remove
    await self.__async_remove_impl(force_remove)
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1401, in __async_remove_impl
    await self.async_will_remove_from_hass()
  File "/usr/src/homeassistant/homeassistant/components/bluesound/media_player.py", line 348, in async_will_remove_from_hass
    await self._polling_task
  File "/usr/src/homeassistant/homeassistant/components/bluesound/media_player.py", line 321, in _start_poll_command
    await asyncio.sleep(NODE_OFFLINE_CHECK_TIMEOUT)
  File "/usr/local/lib/python3.12/asyncio/tasks.py", line 665, in sleep
    return await future
           ^^^^^^^^^^^^
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 930, in async_reset
    await entity.async_remove()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1390, in async_remove
    self.__remove_future.set_result(None)
asyncio.exceptions.InvalidStateError: invalid state

Logger: homeassistant.components.bluesound.media_player
Quelle: components/bluesound/media_player.py:318
Integration: Bluesound ([Dokumentation](https://www.home-assistant.io/integrations/bluesound), [Probleme](https://github.com/home-assistant/core/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+bluesound%22))
Erstmals aufgetreten: 28. August 2024 um 23:51:51 (123 Vorkommnisse)
Zuletzt protokolliert: 06:04:10

Node 192.168.1.15:11000 is offline, retrying later

Logger: homeassistant.components.bluesound.media_player
Quelle: components/bluesound/media_player.py:404
Integration: Bluesound ([Dokumentation](https://www.home-assistant.io/integrations/bluesound), [Probleme](https://github.com/home-assistant/core/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+bluesound%22))
Erstmals aufgetreten: 28. August 2024 um 23:51:51 (123 Vorkommnisse)
Zuletzt protokolliert: 06:04:10

Client connection error, marking Esszimmer as offline

LouisChrist commented 1 month ago

@klingbing I found a small bug(the second log you posted), but still not the main one.

Is the second player instantly unavailable, when power is cut from the first one? Or after a few minutes? Or once the the power is restored to the first one?

The first log is very suspicious: Platform bluesound does not generate unique IDs. ID 90:56:85:49:35:c5-11000 already exists - ignoring media_player.esszimmer Is 90:56:85:49:35:c5 the MAC you are expecting for media_player.esszimmer? You can look it up by navigating to the IP of media_player.esszimer and selecting Diagnostics there.

klingbing commented 1 month ago

EDIT: updating HA to 2024.9 appears to have resolved this for me.

@LouisChrist I can confirm the MAC address is the one that belongs to this player.

The two Bluesound players are powered on/off independently and they are behaving the same regardless of order powered or time between a power cycle: Working fine after a HA reboot, but failing (media_player entity remains unavailable and both logged with Platform bluesound does not generate unique IDs.) once they've been power cycled.

LouisChrist commented 1 month ago

@Niekmanz can you try 2024.9 and see if it is fixed for you too?

Niekmanz commented 1 month ago

I haven't had any issues since updating in my usecase. But that is because the power is cut off at night and I don't use the other speaker at that time. Testing shows that de second speaker(pulse mini) becomes unavailable within a minute of cutting of power to the first player(node 2i). Availability is restored in 3 minutes time after restoring power. version 2024.9.1

Van: Louis Christ @.> Verzonden: donderdag 5 september 2024 19:37 Aan: home-assistant/core @.> CC: Niekmanz @.>; Mention @.> Onderwerp: Re: [home-assistant/core] Cutting off power from one speaker breaks the integration (Issue #123745)

@Niekmanzhttps://github.com/Niekmanz can you try 2024.9 and see if it is fixed for you too?

— Reply to this email directly, view it on GitHubhttps://github.com/home-assistant/core/issues/123745#issuecomment-2332290724, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AGDCH5JHZCW74DG7UBH6CGTZVCJFHAVCNFSM6AAAAABMM4C3LGVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGMZSGI4TANZSGQ. You are receiving this because you were mentioned.Message ID: @.***>

clintongormley commented 1 month ago

Hi @LouisChrist

I have 4 BluSound nodes and a NAD amplifier for home cine. I sometimes include the NAD amplifier in the blusound group, but often I will leave the amplifier turned off.

When I restart HA with the amp on, everything works beautifully. But if I turn the amp off at any stage then all of the BluSound nodes become unavailable. After 3 minutes they show their real status again but as soon as I try to add/remove a node then the whole group becomes unavailable again (unless the amp is turned on).

This used to work perfectly before. I'm on 2024.9.1

home-assistant_bluesound_2024-09-14T10-55-42.585Z.log

LouisChrist commented 1 month ago

Thank you for the log. I am pretty sure that your bug is fixed with #125779. It is already merged and should be part of the next release.

clintongormley commented 1 month ago

Thank you for the log. I am pretty sure that your bug is fixed with #125779. It is already merged and should be part of the next release.

Just to confirm that this is fixed for me in 2024.9.2. Many thanks! 👍

clintongormley commented 1 month ago

Thank you for the log. I am pretty sure that your bug is fixed with #125779. It is already merged and should be part of the next release.

Just to confirm that this is fixed for me in 2024.9.2. Many thanks! 👍

I don't know whether I tested it incorrectly or whether there has been another regression, but I'm getting the same problem as before. Log attached, thanks home-assistant_bluesound_2024-09-24T14-58-11.784Z.log

LouisChrist commented 1 month ago

I had a look at the CHANGELOG and it seems that my fix is not part of 2024.9.2 or 2024.9.3. I assume it will be part of 2024.10.0 instead.

LouisChrist commented 3 weeks ago

It is part of 2024.10.0. Could you check again to verify that it is fixed now?

clintongormley commented 3 weeks ago

Heya @LouisChrist - It is fixed now, thank you

There's a related issue dealing with an intermittently available amp, but I'll open a separate issue for that.

thanks

LouisChrist commented 3 weeks ago

@home-assistant close

clintongormley commented 3 weeks ago

Opened https://github.com/home-assistant/core/issues/127632

home-assistant / core