search

hassio-addons / addon-airsonos

AirSonos - Home Assistant Community Add-ons
https://addons.community
MIT License
86 stars 11 forks source link

10s lag when playing, but 0s when pausing #166

Open jeanluclaguerre opened 1 month ago

jeanluclaguerre commented 1 month ago

Problem/Motivation

I have about 10s latency when playing any music via AirSonos to any Sonos speaker I have (even the ones that support AirPlay 2 natively)

Expected behavior

Instant of <1s latency

Actual behavior

About 10s to start playing

Steps to reproduce

Open Music App on my iPhone, connect to "Office+" Sonos Playbar and press play ; but it is the same for any Sonos device in the hous

Proposed changes

Maybe add a parameter to reduce that latency ?

Here is the log :

[12:11:32.215] http_thread_func:985 HTTP close 22 [12:11:32.215] http_thread_func:956 [0x7f02f401c430]: got HTTP connection 22 [12:11:32.218] handle_http:1097 [0x7f02f401c430]: received HEAD HTTP/1.1 CONNECTION: close Host: 192.168.1.104:36625 USER-AGENT: Linux UPnP/1.0 Sonos/79.1-54060 (ZPS9) X-Sonos-SWGen: 2 X-Sonos-Firmware: 79.1-54060 X-Sonos-Muse-Api: 1.40.0 X-Sonos-Id-Hash: npOIGQONX4sSzg8DPPuK6vUjnfXg2VhLe5QYRqZikzA=

[12:11:32.218] handle_http:1142 [0x7f02f401c430]: responding: HTTP/1.0 200 OK Server: HairTunes Content-Type: audio/flac Connection: close

[12:11:32.218] http_thread_func:979 [0x7f02f401c430]: sending 187 silence frames [12:11:32.218] http_thread_func:985 HTTP close 22 [12:11:32.223] handle_rtsp:374 [0x7f030c014ad0]: received SET_PARAMETER [12:11:32.223] handle_rtsp:568 [0x7f030c014ad0]: received JPEG image of 109764 bytes

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 181

[12:11:32.224] buffer_put_packet:446 [0x7f02f401c430]: 1st accepted packet:7844, now playing [12:11:32.229] handle_rtsp:374 [0x7f030c014ad0]: received SET_PARAMETER

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 182

[12:11:32.235] handle_rtsp:374 [0x7f030c014ad0]: received SET_PARAMETER [12:11:32.235] handle_rtsp:559 [0x7f030c014ad0]: received metadata artist: Darude album: Before the Storm, Special Edition title: Sandstorm

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 183

[12:11:32.258] handle_rtsp:374 [0x7f030c014ad0]: received SET_PARAMETER [12:11:32.258] handle_rtsp:559 [0x7f030c014ad0]: received metadata artist: Darude album: Before the Storm, Special Edition title: Sandstorm

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 184

[12:11:32.773] ActionHandler:510 [0x7f031f84be90]: uPNP stopped [12:11:33.101] handle_rtsp:374 [0x7f030c014ad0]: received SET_PARAMETER [12:11:33.101] handle_rtsp:559 [0x7f030c014ad0]: received metadata artist: Darude album: Before the Storm, Special Edition title: Sandstorm

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 185

[12:11:33.108] handle_rtsp:374 [0x7f030c014ad0]: received SET_PARAMETER

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 186

[12:11:33.223] HandleRAOP:320 [0x7f031f84be90]: uPNP setURI http://192.168.1.104:36625/stream-2.flac (cookie 0x141) [12:11:33.223] AVTSetURI:69 [0x7f031f84be90]: uPNP setURI http://192.168.1.104:36625/stream-2.flac (cookie 0x141) [12:11:33.224] AVTPlay:123 [0x7f031f84be90]: uPNP play (cookie 0x142) [12:11:33.241] http_thread_func:956 [0x7f02f401c430]: got HTTP connection 22 [12:11:33.244] handle_http:1097 [0x7f02f401c430]: received GET HTTP/1.1 CONNECTION: close Host: 192.168.1.104:36625 ACCEPT: / USER-AGENT: Linux UPnP/1.0 Sonos/79.1-54060 (ZPS9) X-Sonos-SWGen: 2 X-Sonos-Firmware: 79.1-54060 X-Sonos-Muse-Api: 1.40.0 X-Sonos-Id-Hash: npOIGQONX4sSzg8DPPuK6vUjnfXg2VhLe5QYRqZikzA=

[12:11:33.244] handle_http:1142 [0x7f02f401c430]: responding: HTTP/1.0 200 OK Server: HairTunes Content-Type: audio/flac Connection: close

[12:11:33.244] http_thread_func:979 [0x7f02f401c430]: sending 183 silence frames [12:11:38.024] ActionHandler:505 [0x7f031f84be90]: uPNP transition [12:11:44.354] ActionHandler:514 [0x7f031f84be90]: uPNP playing

tukane commented 1 month ago

Same here! Extreme delay whatever configured in the xml file.

github-actions[bot] commented 1 week ago

There hasn't been any activity on this issue recently, so we clean up some of the older and inactive issues. Please make sure to update to the latest version and check if that solves the issue. Let us know if that works for you by leaving a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thanks!

sparkiemark99 commented 1 week ago

I've been experiencing the same issue as well. Version is 4.2.1, Home Assistant is 2024.8.2, running in VirtualBox on a fairly powerful - but oldish - laptop. No resource issues on the laptop or VM noted. It was happening with 2024.7.x as well.

Here is the log from request to connection:

06:54:50 request - 06:54:57 start. It has been as much as a 15-second delay at times.

[06:54:50.360] http_parse_simple:1030 sock: 14, received RTP-Info: rtptime=1733450080 [06:54:50.360] http_parse_simple:1030 sock: 14, received Content-Length: 124 [06:54:50.360] http_parse_simple:1030 sock: 14, received Content-Type: application/x-dmap-tagged [06:54:50.360] http_parse_simple:1030 sock: 14, received CSeq: 12 [06:54:50.360] http_parse_simple:1030 sock: 14, received DACP-ID: 6BB869616BC59671 [06:54:50.360] http_parse_simple:1030 sock: 14, received Active-Remote: 320476324 [06:54:50.361] http_parse_simple:1030 sock: 14, received User-Agent: AirPlay/770.8.1 [06:54:50.361] handle_rtsp:374 [0x7f249c001dd0]: received SET_PARAMETER [06:54:50.361] handle_rtsp:559 [0x7f249c001dd0]: received metadata artist: 06:00 - 09:00 • Today album:
title: Radio 4

RTSP/1.0 200 OK Audio-Jack-Status: connected; type=analog CSeq: 12

[06:54:50.366] http_parse_simple:1030 sock: 14, received CSeq: 13 [06:54:50.366] http_parse_simple:1030 sock: 14, received DACP-ID: 6BB869616BC59671 [06:54:50.366] http_parse_simple:1030 sock: 14, received Active-Remote: 320476324 [06:54:50.366] http_parse_simple:1030 sock: 14, received User-Agent: AirPlay/770.8.1 [06:54:51.371] rtp_thread_func:664 [0x7f248001c3e0]: sync packet rtp_latency:1733501996 rtp:1733579171 remote ntp:83bfd3a0223b8acc, local time 2024205612(now: 2024205675) [06:54:51.829] ActionHandler:505 [0x7f24b10c4f50]: uPNP transition [06:54:52.331] rtp_thread_func:664 [0x7f248001c3e0]: sync packet rtp_latency:1733546808 rtp:1733623983 remote ntp:83bfd3a1265d0529, local time 2024206628(now: 2024206635) [06:54:52.435] http_parse_simple:1030 sock: 14, received CSeq: 14 [06:54:52.436] http_parse_simple:1030 sock: 14, received DACP-ID: 6BB869616BC59671 [06:54:52.436] http_parse_simple:1030 sock: 14, received Active-Remote: 320476324 [06:54:52.436] http_parse_simple:1030 sock: 14, received User-Agent: AirPlay/770.8.1 [06:54:53.329] rtp_thread_func:664 [0x7f248001c3e0]: sync packet rtp_latency:1733590917 rtp:1733668092 remote ntp:83bfd3a2266b228d, local time 2024207628(now: 2024207633) [06:54:53.329] rtp_request_timing:769 [0x7f248001c3e0]: timing request now:2024207633 (port: 52397) [06:54:53.332] rtp_thread_func:750 [0x7f248001c3e0]: Timing references local:2024207633, remote: 83bfd3a2276e1dea (delta : 0, sum : 0, adjust : 0, gaps : 0) [06:54:54.517] http_parse_simple:1030 sock: 14, received CSeq: 15 [06:54:54.517] http_parse_simple:1030 sock: 14, received DACP-ID: 6BB869616BC59671 [06:54:54.518] http_parse_simple:1030 sock: 14, received Active-Remote: 320476324 [06:54:54.518] http_parse_simple:1030 sock: 14, received User-Agent: AirPlay/770.8.1 [06:54:55.290] rtp_thread_func:664 [0x7f248001c3e0]: sync packet rtp_latency:1733677394 rtp:1733754569 remote ntp:83bfd3a41c69ee45, local time 2024209589(now: 2024209594) [06:54:56.421] http_parse_simple:1030 sock: 14, received CSeq: 16 [06:54:56.422] http_parse_simple:1030 sock: 14, received DACP-ID: 6BB869616BC59671 [06:54:56.423] http_parse_simple:1030 sock: 14, received Active-Remote: 320476324 [06:54:56.423] http_parse_simple:1030 sock: 14, received User-Agent: AirPlay/770.8.1 [06:54:57.285] rtp_thread_func:664 [0x7f248001c3e0]: sync packet rtp_latency:1733765366 rtp:1733842541 remote ntp:83bfd3a61b183c13, local time 2024211584(now: 2024211589)

There can also be a lag when changing volume as well.

Still love the addon! :)

Regards, Mark

sparkiemark99 commented 1 week ago

Additional log which was using Spotify through to the same Sonos stereo pair:

[11:22:31.159] buffer_put_packet:531 [0x7ff0d801c9d0]: fill [level:88] [W:8940 R:8853] [11:22:31.345] rtp_request_resend:805 resend request [W:8957 R:8853 first=8958 last=8960] [11:22:31.345] buffer_put_packet:520 [0x7ff0d801c9d0]: packet newer seqno:8961 rtptime:537958342 (W:8957 R:8853) [11:22:31.348] buffer_put_packet:524 [0x7ff0d801c9d0]: packet recovered seqno:8958 rtptime:537957286 (W:8963 R:8853) [11:22:31.349] buffer_put_packet:524 [0x7ff0d801c9d0]: packet recovered seqno:8959 rtptime:537957638 (W:8963 R:8853) [11:22:31.349] buffer_put_packet:524 [0x7ff0d801c9d0]: packet recovered seqno:8960 rtptime:537957990 (W:8963 R:8853) [11:22:31.647] http_thread_func:956 [0x7ff0d801c9d0]: got HTTP connection 20 [11:22:31.648] http_parse_simple:1030 sock: 20, received CONNECTION: close [11:22:31.648] http_parse_simple:1030 sock: 20, received Host: 192.168.0.20:50221 [11:22:31.648] http_parse_simple:1030 sock: 20, received ACCEPT: / [11:22:31.648] http_parse_simple:1030 sock: 20, received USER-AGENT: Linux UPnP/1.0 Sonos/80.1-55240 (ZPS1) [11:22:31.648] http_parse_simple:1030 sock: 20, received X-Sonos-SWGen: 2 [11:22:31.648] http_parse_simple:1030 sock: 20, received X-Sonos-Firmware: 80.1-55240 [11:22:31.648] http_parse_simple:1030 sock: 20, received X-Sonos-Muse-Api: 1.41.2 [11:22:31.648] http_parse_simple:1030 sock: 20, received X-Sonos-Id-Hash: v9QenfOQNAwa9F4PK/rUgaDqVa8CMmlQdh3ue6tz2XI= [11:22:31.648] handle_http:1097 [0x7ff0d801c9d0]: received GET HTTP/1.1 CONNECTION: close Host: 192.168.0.20:50221 ACCEPT: / USER-AGENT: Linux UPnP/1.0 Sonos/80.1-55240 (ZPS1) X-Sonos-SWGen: 2 X-Sonos-Firmware: 80.1-55240 X-Sonos-Muse-Api: 1.41.2 X-Sonos-Id-Hash: v9QenfOQNAwa9F4PK/rUgaDqVa8CMmlQdh3ue6tz2XI=

[11:22:31.648] handle_http:1142 [0x7ff0d801c9d0]: responding: HTTP/1.0 200 OK Server: HairTunes Content-Type: audio/flac Connection: close

[11:22:31.648] http_thread_func:979 [0x7ff0d801c9d0]: sending 101 silence frames [11:22:31.649] _buffer_get_frame:908 [0x7ff0d801c9d0]: drain [level:148 gap:-152] [W:9001 R:8853] [R:12 S:0 F:0] [11:22:31.653] _buffer_get_frame:908 [0x7ff0d801c9d0]: drain [level:85 gap:346] [W:9001 R:8916] [R:12 S:0 F:0] [11:22:31.654] ActionHandler:480 [0x7ff0f7ee4f50]: Waited action PlayResponse [11:22:32.565] rtp_thread_func:664 [0x7ff0d801c9d0]: sync packet rtp_latency:537931647 rtp:538008822 remote ntp:83bfe3d4cfc4a4bc, local time 2040266808(now: 2040266869) [11:22:32.639] http_parse_simple:1030 sock: 13, received CSeq: 14 [11:22:32.640] http_parse_simple:1030 sock: 13, received DACP-ID: 999EF04A3F3EB15 [11:22:32.640] http_parse_simple:1030 sock: 13, received Active-Remote: 1113526471 [11:22:32.640] http_parse_simple:1030 sock: 13, received User-Agent: AirPlay/770.8.1 [11:22:33.614] rtp_thread_func:664 [0x7ff0d801c9d0]: sync packet rtp_latency:537977222 rtp:538054397 remote ntp:83bfe3d5d853cc77, local time 2040267841(now: 2040267918) [11:22:34.547] rtp_thread_func:664 [0x7ff0d801c9d0]: sync packet rtp_latency:538021516 rtp:538098691 remote ntp:83bfe3d6d97432b3, local time 2040268846(now: 2040268851) [11:22:34.547] rtp_request_timing:769 [0x7ff0d801c9d0]: timing request now:2040268851 (port: 58880) [11:22:34.552] rtp_thread_func:750 [0x7ff0d801c9d0]: Timing references local:2040268851, remote: 83bfe3d6daec460e (delta : -1, sum : -1, adjust : 0, gaps : 0) [11:22:34.668] http_parse_simple:1030 sock: 13, received CSeq: 15 [11:22:34.668] http_parse_simple:1030 sock: 13, received DACP-ID: 999EF04A3F3EB15 [11:22:34.668] http_parse_simple:1030 sock: 13, received Active-Remote: 1113526471 [11:22:34.668] http_parse_simple:1030 sock: 13, received User-Agent: AirPlay/770.8.1 [11:22:35.255] ActionHandler:505 [0x7ff0f7ee4f50]: uPNP transition [11:22:35.550] rtp_thread_func:664 [0x7ff0d801c9d0]: sync packet rtp_latency:538065806 rtp:538142981 remote ntp:83bfe3d7da8e4755, local time 2040269849(now: 2040269854) [11:22:36.761] http_parse_simple:1030 sock: 13, received CSeq: 16 [11:22:36.761] http_parse_simple:1030 sock: 13, received DACP-ID: 999EF04A3F3EB15 [11:22:36.761] http_parse_simple:1030 sock: 13, received Active-Remote: 1113526471 [11:22:36.761] http_parse_simple:1030 sock: 13, received User-Agent: AirPlay/770.8.1 [11:22:37.541] rtp_thread_func:664 [0x7ff0d801c9d0]: sync packet rtp_latency:538153616 rtp:538230791 remote ntp:83bfe3d9d84b9ecf, local time 2040271840(now: 2040271845) [11:22:38.858] http_parse_simple:1030 sock: 13, received CSeq: 17 [11:22:38.858] http_parse_simple:1030 sock: 13, received DACP-ID: 999EF04A3F3EB15 [11:22:38.858] http_parse_simple:1030 sock: 13, received Active-Remote: 1113526471 [11:22:38.858] http_parse_simple:1030 sock: 13, received User-Agent: AirPlay/770.8.1 [11:22:39.002] UpdateThread:690 Presence checking [11:22:39.243] UpdateThread:750 [0x7ff0f7ee4f50] UPnP keep alive: 192.168.0.15 - Sonos Play:1+ [11:22:39.274] GetMaster:101 Found Master RINCON_5CAAFD21246401400 uuid:RINCON_5CAAFD21266E01400 [11:22:39.274] UpdateThread:750 [0x7ff0f7ee2f90] UPnP keep alive: 192.168.0.18 - Sonos Play:1+ [11:22:39.420] UpdateThread:750 [0x7ff0f7edf010] UPnP keep alive: Kitchen Sonos+ [11:22:39.467] GetMaster:101 Found Master RINCON_B8E937B4818A01400 uuid:RINCON_5CAAFD21266E01400 [11:22:39.467] UpdateThread:750 [0x7ff0f7ee0fd0] UPnP keep alive: Back Room Sonos+ [11:22:39.549] rtp_thread_func:664 [0x7ff0d801c9d0]: sync packet rtp_latency:538242140 rtp:538319315 remote ntp:83bfe3dbda2cd39d, local time 2040273848(now: 2040273853) [11:22:39.904] buffer_put_packet:531 [0x7ff0d801c9d0]: fill [level:78] [W:10028 R:9951] [11:22:40.436] buffer_put_packet:531 [0x7ff0d801c9d0]: fill [level:142] [W:10092 R:9951] [11:22:40.792] http_parse_simple:1030 sock: 13, received CSeq: 18 [11:22:40.793] http_parse_simple:1030 sock: 13, received DACP-ID: 999EF04A3F3EB15 [11:22:40.794] http_parse_simple:1030 sock: 13, received Active-Remote: 1113526471 [11:22:40.795] http_parse_simple:1030 sock: 13, received User-Agent: AirPlay/770.8.1 [11:22:40.865] buffer_put_packet:531 [0x7ff0d801c9d0]: fill [level:206] [W:10156 R:9951] [11:22:41.375] buffer_put_packet:531 [0x7ff0d801c9d0]: fill [level:270] [W:10220 R:9951] [11:22:41.542] rtp_thread_func:664 [0x7ff0d801c9d0]: sync packet rtp_latency:538330081 rtp:538407256 remote ntp:83bfe3ddd8ac9081, local time 2040275842(now: 2040275846) [11:22:41.542] rtp_request_timing:769 [0x7ff0d801c9d0]: timing request now:2040275846 (port: 58880) [11:22:41.546] rtp_thread_func:750 [0x7ff0d801c9d0]: Timing references local:2040275846, remote: 83bfe3ddd989fbba (delta : 0, sum : -1, adjust : 0, gaps : 0) [11:22:41.886] buffer_put_packet:531 [0x7ff0d801c9d0]: fill [level:334] [W:10284 R:9951] [11:22:42.026] http_thread_func:1062 [0x7ff0d801c9d0]: spent 2782 ms in send for 11958 bytes (sent 11958)! [11:22:42.027] _buffer_get_frame:908 [0x7ff0d801c9d0]: drain [level:297 gap:-1343] [W:10301 R:10004] [R:12 S:0 F:0] [11:22:42.355] http_thread_func:1062 [0x7ff0d801c9d0]: spent 327 ms in send for 12318 bytes (sent 12318)! [11:22:42.355] _buffer_get_frame:908 [0x7ff0d801c9d0]: drain [level:274 gap:-1160] [W:10342 R:10068] [R:12 S:0 F:0] [11:22:42.360] _buffer_get_frame:908 [0x7ff0d801c9d0]: drain [level:210 gap:-655] [W:10342 R:10132] [R:12 S:0 F:0] [11:22:42.397] buffer_put_packet:531 [0x7ff0d801c9d0]: fill [level:188] [W:10348 R:10161]