search

hassio-addons / addon-airsonos

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

AirSonos devices disappearing after a few minutes #125

Closed jonsteinmetz closed 1 year ago

jonsteinmetz commented 1 year ago

Problem/Motivation

The AirSonos add on seems to be dropping the connection to my speakers after a few minutes or after some audio is played on an AirSonos speaker.

Steps to reproduce

Here are the AirSonos logs in debug mode:

s6-rc: info: service base-addon-banner: starting
-----------------------------------------------------------
 Add-on: AirSonos
 AirPlay capabilities for your Sonos (and UPnP) devices.
-----------------------------------------------------------
 Add-on version: 3.5.1
 You are running the latest version of this add-on.
 System: Home Assistant OS 9.5  (amd64 / generic-x86-64)
 Home Assistant Core: 2023.2.5
 Home Assistant Supervisor: 2023.01.1
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service base-addon-banner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service base-addon-timezone: starting
s6-rc: info: service base-addon-log-level: starting
s6-rc: info: service fix-attrs successfully started
[08:25:43] INFO: Configuring timezone (America/Chicago)...
Log level is set to DEBUG
s6-rc: info: service base-addon-timezone successfully started
s6-rc: info: service base-addon-log-level successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service init-airsonos: starting
s6-rc: info: service init-airsonos successfully started
s6-rc: info: service airsonos: starting
s6-rc: info: service airsonos successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
[08:25:44] INFO: Starting the AirSonos server...
[08:25:44.627390] main:1355 Starting airupnp version: v1.0.13 (Dec 10 2022 @ 11:10:19)
[08:25:44.679056] Start:1087 Binding to 10.0.23.23:49152
[08:25:44.769013] AddMRDevice:1009 [0x7ffa66560010]: adding renderer (Office) with mac BBBB9CCCD901
[08:25:44.769206] bind_socket:616 socket binding 10 on port 45287
[08:25:44.769390] UpdateThread:836 Updating configuration /config/airsonos.xml
[08:25:44.776801] MasterHandler:640 [0x7ffa66560010]: subscribe success
[08:25:44.794470] ProcessEvent:445 [0x7ffa66560010]: UPnP Volume local change 33:33 (master)
[08:25:44.809961] AddMRDevice:1009 [0x7ffa665623b8]: adding renderer (Playroom) with mac BBBB43B76C0
[08:25:44.810159] bind_socket:616 socket binding 12 on port 50483
[08:25:44.810648] UpdateThread:836 Updating configuration /config/airsonos.xml
[08:25:44.819920] MasterHandler:640 [0x7ffa665623b8]: subscribe success
[08:25:44.847855] ProcessEvent:445 [0x7ffa665623b8]: UPnP Volume local change 26:26 (master)
[08:25:44.957769] AddMRDevice:1009 [0x7ffa66564760]: adding renderer (Living Room) with mac BBBB528B4997
[08:25:44.957940] bind_socket:616 socket binding 13 on port 35783
[08:25:44.958268] UpdateThread:836 Updating configuration /config/airsonos.xml
[08:25:44.962000] MasterHandler:640 [0x7ffa66564760]: subscribe success
[08:25:44.971031] ProcessEvent:445 [0x7ffa66564760]: UPnP Volume local change 10:10 (master)
[08:25:45.041044] AddMRDevice:1009 [0x7ffa66566b08]: adding renderer (Master Bathroom) with mac BBBBB7BCDF50
[08:25:45.041201] bind_socket:616 socket binding 15 on port 37777
[08:25:45.041568] UpdateThread:836 Updating configuration /config/airsonos.xml
[08:25:45.043282] MasterHandler:640 [0x7ffa66566b08]: subscribe success
[08:25:45.054199] ProcessEvent:445 [0x7ffa66566b08]: UPnP Volume local change 45:45 (master)
[08:25:45.069093] AddMRDevice:1009 [0x7ffa66568eb0]: adding renderer (Master Bedroom) with mac BBBBE05EA705
[08:25:45.069239] bind_socket:616 socket binding 17 on port 35431
[08:25:45.069374] UpdateThread:836 Updating configuration /config/airsonos.xml
[08:25:45.074240] MasterHandler:640 [0x7ffa66568eb0]: subscribe success
[08:25:45.087577] ProcessEvent:445 [0x7ffa66568eb0]: UPnP Volume local change 12:12 (master)
[08:25:45.103689] AddMRDevice:1009 [0x7ffa6656b258]: adding renderer (Kitchen) with mac BBBB501490FC
[08:25:45.103921] bind_socket:616 socket binding 20 on port 49897
[08:25:45.104021] UpdateThread:836 Updating configuration /config/airsonos.xml
[08:25:45.113263] MasterHandler:640 [0x7ffa6656b258]: subscribe success
[08:25:45.151672] ProcessEvent:445 [0x7ffa6656b258]: UPnP Volume local change 33:33 (master)
[08:25:45.222746] AddMRDevice:1009 [0x7ffa6656d600]: adding renderer (Sonos Move) with mac BBBBA400E70E
[08:25:45.222884] bind_socket:616 socket binding 19 on port 54347
[08:25:45.223319] UpdateThread:836 Updating configuration /config/airsonos.xml
[08:25:45.228385] MasterHandler:640 [0x7ffa6656d600]: subscribe success
[08:25:45.244432] ProcessEvent:445 [0x7ffa6656d600]: UPnP Volume local change 51:51 (master)
[08:25:45.263875] UpdateThread:744 [0x7ffa665623b8] UPnP keep alive: Playroom+
[08:25:45.290938] UpdateThread:744 [0x7ffa66560010] UPnP keep alive: Office+
[08:25:48.056769] rtsp_thread:322 got RTSP connection 23
[08:25:48.057000] http_parse_simple:689 sock: 23, received CSeq: 1
[08:25:48.057544] http_read_line:760 disconnected on the other end 23
[08:25:48.057740] rtsp_thread:337 RTSP close 23
[08:25:48.058470] rtsp_thread:322 got RTSP connection 22
[08:25:48.058723] http_parse_simple:689 sock: 22, received CSeq: 1
[08:25:48.059115] http_read_line:760 disconnected on the other end 22
[08:25:48.059229] rtsp_thread:337 RTSP close 22
[08:25:48.060129] rtsp_thread:322 got RTSP connection 21
[08:25:48.060336] http_parse_simple:689 sock: 21, received CSeq: 1
[08:25:48.060733] http_read_line:760 disconnected on the other end 21
[08:25:48.060860] rtsp_thread:337 RTSP close 21
[08:25:48.061661] rtsp_thread:322 got RTSP connection 18
[08:25:48.061960] http_parse_simple:689 sock: 18, received CSeq: 1
[08:25:48.062506] http_read_line:760 disconnected on the other end 18
[08:25:48.062633] rtsp_thread:337 RTSP close 18
[08:25:48.063529] rtsp_thread:322 got RTSP connection 16
[08:25:48.063760] http_parse_simple:689 sock: 16, received CSeq: 1
[08:25:48.064129] http_read_line:760 disconnected on the other end 16
[08:25:48.064245] rtsp_thread:337 RTSP close 16
[08:25:48.065341] rtsp_thread:322 got RTSP connection 14
[08:25:48.065548] http_parse_simple:689 sock: 14, received CSeq: 1
[08:25:48.065955] http_read_line:760 disconnected on the other end 14
[08:25:48.066068] rtsp_thread:337 RTSP close 14
[08:25:48.067128] rtsp_thread:322 got RTSP connection 11
[08:25:48.067329] http_parse_simple:689 sock: 11, received CSeq: 1
[08:25:48.067745] http_read_line:760 disconnected on the other end 11
[08:25:48.067873] rtsp_thread:337 RTSP close 11

### This is the point after startup where things seem to be working.

[08:26:49.692754] handle_rtsp:562 [0x7ffa54002470]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 28

[08:26:50.394998] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1675968474 rtp:1676045649 remote ntp:83b009dc1954477f, local time 1952364939(now: 1952364954)
[08:26:50.556641] http_parse_simple:689 sock: 11, received CSeq: 29
[08:26:50.556785] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:26:50.556895] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:26:50.557017] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:26:50.614251] buffer_put_packet:617 [0x7ffa2001ca70]: fill [level:1] [W:10548 R:10548]
[08:26:50.621058] _buffer_get_frame:954 [0x7ffa2001ca70]: drain [level:1 gap:1006] [W:10549 R:10548] [R:7 S:0 F:0]
[08:26:51.446635] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676012589 rtp:1676089764 remote ntp:83b009dd196a0125, local time 1952365939(now: 1952366006)
[08:26:52.557349] http_parse_simple:689 sock: 11, received CSeq: 30
[08:26:52.557450] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:26:52.557512] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:26:52.557584] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:26:53.389116] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676100832 rtp:1676178007 remote ntp:83b009df19aa3ad1, local time 1952367940(now: 1952367949)
[08:26:54.390384] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676144949 rtp:1676222124 remote ntp:83b009e019c2c1b1, local time 1952368940(now: 1952368950)
[08:26:54.390435] rtp_request_timing:834 [0x7ffa2001ca70]: timing request now:1952368950 (port: 59625)
[08:26:54.393673] rtp_thread_func:814 [0x7ffa2001ca70]: Timing references local:1952368950, remote: 83b009e01ac7a716 (delta : 5, sum : -2, adjust : 0, gaps :  0)
[08:26:54.591272] http_parse_simple:689 sock: 11, received CSeq: 31
[08:26:54.591429] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:26:54.591540] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:26:54.591709] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:26:54.702063] buffer_put_packet:617 [0x7ffa2001ca70]: fill [level:1] [W:11060 R:11060]
[08:26:54.705783] _buffer_get_frame:954 [0x7ffa2001ca70]: drain [level:1 gap:1008] [W:11061 R:11060] [R:7 S:0 F:0]
[08:26:55.391295] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676189064 rtp:1676266239 remote ntp:83b009e119d98caa, local time 1952369946(now: 1952369951)
[08:26:55.690608] http_parse_simple:689 sock: 11, received RTP-Info: rtptime=1676192638
[08:26:55.690765] http_parse_simple:689 sock: 11, received Content-Length: 167
[08:26:55.690928] http_parse_simple:689 sock: 11, received Content-Type: application/x-dmap-tagged
[08:26:55.690985] http_parse_simple:689 sock: 11, received CSeq: 32
[08:26:55.691093] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:26:55.691231] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:26:55.691361] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:26:55.691437] handle_rtsp:363 [0x7ffa54002470]: received SET_PARAMETER
[08:26:55.691478] handle_rtsp:544 [0x7ffa54002470]: received metadata
    artist: MacBreak Weekly (Audio)ascp
    album:  February 14, 2023asar
    title:  Appleback - Ventura 13.2.1, 2nd Gen HomePod, Ted Lassocaps
[08:26:55.691648] handle_rtsp:562 [0x7ffa54002470]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 32

[08:26:56.419246] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676233551 rtp:1676310726 remote ntp:83b009e21c18b502, local time 1952370955(now: 1952370979)
[08:26:56.555766] http_parse_simple:689 sock: 11, received CSeq: 33
[08:26:56.555918] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:26:56.556038] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:26:56.556168] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:26:58.400970] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676321790 rtp:1676398965 remote ntp:83b009e41c531b9b, local time 1952372956(now: 1952372960)
[08:26:58.657791] http_parse_simple:689 sock: 11, received CSeq: 34
[08:26:58.657936] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:26:58.658047] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:26:58.658171] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:26:58.786982] buffer_put_packet:617 [0x7ffa2001ca70]: fill [level:13] [W:11572 R:11560]
[08:26:58.795385] _buffer_get_frame:954 [0x7ffa2001ca70]: drain [level:1 gap:1011] [W:11573 R:11572] [R:7 S:0 F:0]
[08:26:59.401736] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676365912 rtp:1676443087 remote ntp:83b009e51c7384a3, local time 1952373956(now: 1952373961)
[08:26:59.401787] rtp_request_timing:834 [0x7ffa2001ca70]: timing request now:1952373961 (port: 59625)
[08:26:59.407841] rtp_thread_func:814 [0x7ffa2001ca70]: Timing references local:1952373961, remote: 83b009e51e2216f2 (delta : -3, sum : -5, adjust : 0, gaps :  0)
[08:27:00.557769] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676410033 rtp:1676487208 remote ntp:83b009e61c92a0ec, local time 1952374954(now: 1952375117)
[08:27:00.753165] http_parse_simple:689 sock: 11, received CSeq: 35
[08:27:00.753308] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:27:00.753417] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:27:00.753539] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:27:01.408853] rtp_thread_func:738 [0x7ffa2001ca70]: sync packet rtp_latency:1676454153 rtp:1676531328 remote ntp:83b009e71caf9229, local time 1952375955(now: 1952375968)
[08:27:02.683398] http_parse_simple:689 sock: 11, received CSeq: 36
[08:27:02.683497] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:27:02.683559] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:27:02.683639] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:27:02.849343] http_parse_simple:689 sock: 11, received CSeq: 37
[08:27:02.849485] http_parse_simple:689 sock: 11, received DACP-ID: EE7DD4979CEA63CB
[08:27:02.849602] http_parse_simple:689 sock: 11, received Active-Remote: 4142624873
[08:27:02.849750] http_parse_simple:689 sock: 11, received User-Agent: AirPlay/675.4.1
[08:27:02.849771] handle_rtsp:363 [0x7ffa54002470]: received TEARDOWN
[08:27:02.849782] HandleRAOP:293 [0x7ffa66560010]: Stop
[08:27:02.849789] AVTStop:204 [0x7ffa66560010]: uPNP stop (cookie 0x32)
[08:27:02.863460] http_thread_func:1211 [0x7ffa2001ca70]: terminating
[08:27:02.873499] ActionHandler:478 [0x7ffa66560010]: Waited action StopResponse
[08:27:02.899084] rtp_thread_func:822 [0x7ffa2001ca70]: terminating
[08:27:02.902035] handle_rtsp:562 [0x7ffa54002470]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 37

[08:27:02.985883] http_read_line:760 disconnected on the other end 11
[08:27:02.986050] rtsp_thread:337 RTSP close 11
[08:27:03.285757] ActionHandler:513 [0x7ffa66560010]: uPNP stopped
[08:27:04.001839] UpdateThread:692 Presence checking
[08:27:04.042914] UpdateThread:744 [0x7ffa66560010] UPnP keep alive: Office+
[08:27:04.136495] UpdateThread:744 [0x7ffa66564760] UPnP keep alive: Living Room+
[08:27:04.267774] UpdateThread:744 [0x7ffa665623b8] UPnP keep alive: Playroom+
[08:27:04.316441] UpdateThread:744 [0x7ffa6656d600] UPnP keep alive: Sonos Move+
[08:27:04.346905] UpdateThread:744 [0x7ffa66568eb0] UPnP keep alive: Master Bedroom+
[08:27:04.434468] UpdateThread:744 [0x7ffa66566b08] UPnP keep alive: Master Bathroom+
[08:27:04.454974] UpdateThread:744 [0x7ffa6656b258] UPnP keep alive: Kitchen+
[08:27:04.479884] UpdateThread:744 [0x7ffa66560010] UPnP keep alive: Office+

I added a comment in the log with "###" at the point where things were working. The logs after are during the period where the AirSonos speakers no longer appear.

I think this issue coincided with a Home Assistant update but I also moved from running Home Assistant on VMWare on macOS to running on a VM in TrueNAS. Unfortunately I cannot say which change caused this.

Thank you and any suggestions are appreciated.

github-actions[bot] commented 1 year 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!