Sonos: Read timed out. (read timeout=9.5)

[TheNightmanX]

The problem

Getting the following error multiple times a day when setting the source for playback on a Sonos system. The source is played despite the error (so it works). But the error is still noted in the error log.

Error while executing automation automation.sonos_wz_antenne_duesseldorf: Error calling SonosMediaPlayerEntity.select_source on media_player.sonos_wohnzimmer: HTTPConnectionPool(host='192.168.1.30', port=1400): Read timed out. (read timeout=9.5)

What version of Home Assistant Core has the issue?

core-2024.4.0

What was the last working version of Home Assistant Core?

never

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Sonos

Link to integration documentation on our website

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

Diagnostics information

No response

Example YAML snippet

service: media_player.select_source
metadata: {}
data:
  source: Antenne Düsseldorf
target:
  device_id: c1f10d91e4df29100305b45400f702f9

Anything in the logs that might be useful for us?

No response

Additional information

No response

[home-assistant]

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

Code owner commands

Code owners of sonos 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 sonos 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)}}

---

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

[PeteRager]

Thanks for the report.

Couple of questions.

What is the source type that you are activating?
Is this one of your Sonos favorites? How would I go about setting that up in Sonos?
When you run the automation how long does it take before the source starts playing?

Please provide the full text from home-assistant.log

[tdejneka]

I'm running 2024.4.2 and have also noticed the timeout error.

2024-04-10 07:47:50.545 ERROR (MainThread) [homeassistant.components.automation.speak] Speak: Error executing script. Error for call_service at pos 5: Error calling SonosMediaPlayerEntity.set_volume_level on media_player.move: HTTPConnectionPool(host='192.168.1.47', port=1400): Read timed out. (read timeout=9.5)

2024-04-10 07:47:50.549 ERROR (MainThread) [homeassistant.components.automation.speak] Error while executing automation automation.speak: Error calling SonosMediaPlayerEntity.set_volume_level on media_player.move: HTTPConnectionPool(host='192.168.1.47', port=1400): Read timed out. (read timeout=9.5)

automation.speak is used to play a TTS message in the morning (a WAV file produced by a local TTS engine). It makes a snapshot of several speakers, groups them in a new group (basically all speakers on the ground floor), sets their volume, plays the message, then restores the speakers. It worked flawlessly in past versions but lately I've noticed it all too frequently fails to play the message (unlike TheNightmanX where it does ultimately play). When that happens I see the posted error messages where some aspect of the automation's actions failed due to a timeout. In this case it was the Move device but it can be another speaker in the group.

FWIW, no new hardware has been added to the network.

Let me know if there's anything else needed to help narrow down the cause.

---

EDIT

This might be a red herring but someone reported an excessive amount of mDNS traffic produced by Home Assistant. Given that it uses UDP and so does the Sonos integration then maybe the flood of traffic is affecting timing. Apologies if I have misinterpreted how all of this actually operates under the hood.

https://community.home-assistant.io/t/homeassistant-sends-out-5353-udp-multicast-more-than-100-times-minute/715212

[PeteRager]

I am able to reproduce the issue reported by @TheNightmanX, that radio station always seems to take ~15 seconds to play. So I believe that raising the timeout when using select_source may be a good solution. I am testing a change for this.

@tdejneka - while the error message you are seeing is the same, it is from the call to set the volume which should occur very fast. When it doesn't that usually indicates some type of network problem.

[TheNightmanX]

Thanks for the report.

Couple of questions.

What is the source type that you are activating?

Is this one of your Sonos favorites? How would I go about setting that up in Sonos?

When you run the automation how long does it take before the source starts playing?

Please provide the full text from home-assistant.log

I am sorry for not providing logs so far, but I was not able to do it due to time constraints. I apologize for that.

• Source type is internet radio stream.
• Yes, it is a Sonos favorite.
• 15-20 seconds to start.

[tdejneka]

usually indicates some type of network problem

What's perplexing is it happened at 7 in the morning when there's ostensibly the least amount of network traffic because there's no activity yet (no audio/video streaming, internet browsing, etc).

Anyways, I'll keep a record of when the timeouts occur (they're very infrequent) and try to find anything they have in common (and possibly correlate them with other network activity). Think I need some kind of network monitoring software to give me visibility into UDP traffic. The only thing I use now is pihole (and the router's log) and that's not the right tool for this job.

[PeteRager]

I've had some sluggishness on one of my Sonos S2 networks when using the Sonos appI looked at this article

https://support.sonos.com/en-gb/article/reduce-wireless-interference

I checked my router and I had channel 9 selected - not sure why - and there's not a lot of other WiFi in this area. So I changed it to 1, rebooted the router. 3 out of 5 Sonos devices joined, the other 2 (which are the newer models Sonos 1) did not despite power cycling several times. I used the Sonos App to repair them and now they are back. Anyways,....

I was surprised that changing the channel causes an issue. This should be transparent as client should be looking for the SSID and connecting with the password. But apparently the Sonos 1 were tied to the channel assignment.

You may want to look at the WIFI channel assignment in the router.

[tdejneka]

In my case, it's fixed at channel 11, chosen for least interference with neighboring (weaker) WiFi channels and local Zigbee channel. All Sonos speakers are S2 and connect to WiFi promptly after they, or the router, are rebooted.

[PeteRager]

@jjlawren - working on a fix for this, there are a couple of options. The timeout is 100% reproducible using the station in this issue. The select_source call ends up in this function and calls play_uri. play_uri is using the default timeout of 9.5 seconds and does not allow the timeout to be specified.

    def _play_favorite(self, favorite: DidlFavorite) -> None:
        """Play a favorite."""
        uri = favorite.reference.get_uri()
        soco = self.coordinator.soco
        if soco.music_source_from_uri(uri) in [
            MUSIC_SRC_RADIO,
            MUSIC_SRC_LINE_IN,
        ]:
            soco.play_uri(uri, title=favorite.title)
        else:
            soco.clear_queue()
            soco.add_to_queue(favorite.reference, timeout=LONG_SERVICE_TIMEOUT)
            soco.play_from_queue(0)

One choice is to open a pull request on Soco to add the timeout. I have this protoyped - and then we change the call to use the LONG_SERVICE_TIMEOUT

            soco.play_uri(uri, title=favorite.title, timeout=LONG_SERVICE_TIMEOUT)

The other alternative is to temporarily override it:

            soco_config.REQUEST_TIMEOUT = LONG_SERVICE_TIMEOUT
            soco.play_uri(uri, title=favorite.title)
            soco_config.REQUEST_TIMEOUT = SOCO_DEFAULT_SERVICE_TIMEOUT

Both work.

[jjlawren]

Overriding & resetting a module state attribute around every call seems a little gross. The first option to add the argument to the call feels better.

Alternatively we could just increase the global "short" timeout, but that seems like it would hide more problems.

[PeteRager]

The first option to add the argument to the call feels better.

Agreed - opened a pull request on Soco

SoCo/SoCo#961

[TheNightmanX]

Fix is working. Thank you all so much for your help 👍🏻