search

philippe44 / SpotConnect

Turn any UPnP or AirPlay player into a Spotify Connect device
MIT License
66 stars 3 forks source link

Apple TV only shows metadata for SpotRaop audio once; requires restart to display again #16

Closed nano9g closed 9 months ago

nano9g commented 11 months ago

While testing the Apple TV 4K for the pause issue (#15), I discovered that the AirPlay part of the Apple TV connection works one time and will not play again until the Apple TV is restarted. I can reproduce this 100% of the time by doing the following:

  1. Start a SpotConnect session to the Apple TV
  2. Disconnect from the Apple TV via the Spotify devices menu (doesn't seem to matter how short or long the audio was playing)
  3. Reconnect to the Apple TV some period of time later (I've waited up to about 30 seconds)

The log will seem to indicate that audio is playing normally (no errors I can see), but audio never starts playing on the Apple TV and the widget in Control Center shows "Not Playing".

When things are in this state, restarting SpotConnect doesn't help; the only resolution I've found is to restart the Apple TV. AirPlaying audio from other devices (Mac, iPhone) still works fine without the restart.

Just in case I'm missing something, here are the debug logs for a successful and unsuccessful session.

Successful (audio plays on Apple TV) ```none I spotify.cpp:381: Spotify client connected for Den Apple TV D Session.cpp:63: Connecting with AP D PlainConnection.cpp:101: Connected to spotify server I Session.cpp:39: Received APHello response D Session.cpp:44: Received shannon keys D Session.cpp:82: Authorization successful I MercurySession.cpp:42: Received packet, command: 4 D TimeProvider.cpp:15: Time synced with spotify servers I MercurySession.cpp:42: Received packet, command: 2 I MercurySession.cpp:42: Received packet, command: 118 I MercurySession.cpp:42: Received packet, command: 27 I MercurySession.cpp:42: Received packet, command: 80 I MercurySession.cpp:42: Received packet, command: 31 D MercurySession.cpp:251: Executing Mercury Request, type SUB I MercurySession.cpp:42: Received packet, command: 105 D spotify.cpp:416: keepAlive Den Apple TV D MercurySession.cpp:153: Received country code US I MercurySession.cpp:42: Received packet, command: 181 I AccessKeyFetcher.cpp:99: Access token expired, fetching new one... 238 I MercurySession.cpp:42: Received packet, command: 74 I MercurySession.cpp:42: Received packet, command: 179 D MercurySession.cpp:174: Received mercury packet D MercurySession.cpp:251: Executing Mercury Request, type SEND D SpircHandler.cpp:59: Sent kMessageTypeHello! I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:124: Notify frame I MercurySession.cpp:42: Received packet, command: 178 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D MercurySession.cpp:174: Received mercury packet I AccessKeyFetcher.cpp:114: Access token sucessfully fetched I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:170: Load frame 8! D MercurySession.cpp:251: Executing Mercury Request, type SEND I TrackPlayer.cpp:94: Resetting state D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Coalescence Cascade I TrackQueue.cpp:159: Track duration: 1080000 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/9601f3a3e1b525316a5705a11732dfc9935043dd?1691191980_4v0_VRwK17LLybBgyhm1Ine-1wL-0fW2OnHUh3M0JlA= I TrackPlayer.cpp:167: Got track ID=9601f3a3e1b525316a5705a11732dfc9935043dd I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-fa.scdn.co/audio/9601f3a3e1b525316a5705a11732dfc9935043dd?1691191980_4v0_VRwK17LLybBgyhm1Ine-1wL-0fW2OnHUh3M0JlA= D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Broken Chroma I TrackQueue.cpp:159: Track duration: 1080006 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/a2ac0c42588c5ce4cfb8e82554281183ffa637a8?1691191980_jL3OwvlkDFMk2wUsZ-YNqZd54K1A8turyPMZ-0rnw5g= D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Know Your Shadow I TrackQueue.cpp:159: Track duration: 1080012 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I CDNAudioFile.cpp:70: Header and footer bytes received D MercurySession.cpp:251: Executing Mercury Request, type SEND I spotify.cpp:235: new track will start at 682789 [19:33:01.208272] shadowRequest:219 [0xa572c8]: spotify LOAD request I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/604f05ea7406c84e346203bad424dc9e15b05dca?1691191981_G68IFXafH76sVkrRLik9F2BQHaQfAH5OWu2psPdFaCA= [19:33:01.312689] raopcl_connect:996 [0x7f8c014580]: local interface [RPI IP] [19:33:01.314188] exec_request:614 [0x7f8c018920]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 31 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:33:01.340725] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:01.341116] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:01 GMT [19:33:01.341340] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 96 [19:33:01.341734] exec_request:650 [0x7f8c018920]: <------ : Content-Type: application/octet-stream [19:33:01.342006] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:01.342143] exec_request:650 [0x7f8c018920]: <------ : CSeq: 31 [19:33:01.342215] exec_request:691 [0x7f8c018920]: Body data len 96 0000 c7 7c cf 33 12 9b 9c 05 91 c5 6d b8 8e af 3c b9 | 3 m < 0010 c9 8a 1e 9f bf d7 5a a9 86 28 55 e7 54 6c ce 7f Z (U Tl 0020 31 5e 3f 19 ab 5d 77 35 45 2f df 01 45 c4 f1 80 1^? ]w5E/ E 0030 05 7f fc b5 d5 40 7b 92 53 62 e3 e8 48 a6 a0 dd @{ Sb H 0040 62 cf 18 aa dc 6d c8 3e f8 7b e4 4d 63 85 b1 51 b m > { Mc Q 0050 fa 2b e1 e8 6a 91 e6 73 9a d1 b1 5b c5 e3 a5 c9 + j s [ [19:33:01.350231] exec_request:614 [0x7f8c018920]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 32 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 [19:33:01.356721] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:01.357110] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:01 GMT [19:33:01.357327] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:01.357722] exec_request:650 [0x7f8c018920]: <------ : Content-Type: application/octet-stream [19:33:01.357995] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:01.358130] exec_request:650 [0x7f8c018920]: <------ : CSeq: 32 [19:33:01.358445] exec_request:614 [0x7f8c018920]: ----> : write ANNOUNCE rtsp://[ATV IP]/3618308148 RTSP/1.0 Content-Type: application/sdp Content-Length: 178 CSeq: 33 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 v=0 o=iTunes 3618308148 0 IN IP4 [RPI IP] s=iTunes c=IN IP4 [ATV IP] t=0 0 m=audio 0 RTP/AVP 96 a=rtpmap:96 AppleLossless a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100 [19:33:01.416729] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:01.417127] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:01 GMT [19:33:01.417343] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:01.417618] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:01.417753] exec_request:650 [0x7f8c018920]: <------ : CSeq: 33 [19:33:01.417918] exec_request:614 [0x7f8c018920]: ----> : write SETUP rtsp://[ATV IP]/3618308148 RTSP/1.0 Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=45947;timing_port=49416 CSeq: 34 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 [19:33:01.424604] _rtp_timing_thread:1296 [0x7f8c014580]: NTP remote port: 50720 [19:33:01.424732] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105581.1823999596 (ref 2208988800.1374218630) [19:33:01.428602] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105581.1840741378 (ref 1691105581.1833069543) [19:33:01.432594] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105581.1857904068 (ref 1691105581.1852109312) [19:33:01.462742] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:01.463124] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:01 GMT [19:33:01.463340] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:01.464206] exec_request:650 [0x7f8c018920]: <------ : Transport: RTP/AVP/UDP;unicast;mode=record;server_port=57445;control_port=53453;timing_port=0 [19:33:01.464361] exec_request:650 [0x7f8c018920]: <------ : Session: 1 [19:33:01.464668] exec_request:650 [0x7f8c018920]: <------ : Audio-Jack-Status: connected [19:33:01.464942] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:01.465097] exec_request:650 [0x7f8c018920]: <------ : CSeq: 34 [19:33:01.465170] rtspcl_setup:239 [0x7f8c018920]: <------ : session:1 [19:33:01.465219] raopcl_analyse_setup:943 [0x7f8c014580]: missing timing port, will get it later [19:33:01.465269] raopcl_connect:1058 [0x7f8c014580]:opened audio socket l:47047 r:57445 [19:33:01.465315] raopcl_connect:1059 [0x7f8c014580]:opened timing socket l:49416 r:0 [19:33:01.465360] raopcl_connect:1060 [0x7f8c014580]:opened control socket l:45947 r:53453 [19:33:01.465444] exec_request:614 [0x7f8c018920]: ----> : write RECORD rtsp://[ATV IP]/3618308148 RTSP/1.0 Range: npt=0- RTP-Info: seq=56508;rtptime=4238982175 CSeq: 35 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:33:01.472733] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:01.473145] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:01 GMT [19:33:01.473363] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:01.473595] exec_request:650 [0x7f8c018920]: <------ : Audio-Latency: 3579 [19:33:01.473869] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:01.474003] exec_request:650 [0x7f8c018920]: <------ : CSeq: 35 [19:33:01.474233] raopcl_connect:1080 [0x7f8c014580]: setting volume as part of connect -30.00 [19:33:01.474344] exec_request:614 [0x7f8c018920]: ----> : write SET_PARAMETER rtsp://[ATV IP]/3618308148 RTSP/1.0 Content-Type: text/parameters Content-Length: 20 CSeq: 36 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 volume: -30.000000 [19:33:01.481726] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:01.482101] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:01 GMT [19:33:01.482315] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:01.482587] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:01.482724] exec_request:650 [0x7f8c018920]: <------ : CSeq: 36 D MercurySession.cpp:251: Executing Mercury Request, type SEND [19:33:01.483083] shadowRequest:223 [0xa572c8]: spotify play request I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackPlayer.cpp:200: Playing I spotify.cpp:133: trackUniqueId update => 9601f3a3e1b525316a5705a11732dfc9935043dd [19:33:01.655747] raopcl_send_chunk:519 [0x7f8c014580]: begining to stream (LATE) hts:74577739831693 n:1691105581.2816403329 [19:33:01.655880] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105211.2589917184 (ts:74577739831693) [19:33:01.917018] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183434588 p:3183072676 ts:74577740147437 sn:57404 retr: 0, avail: 0, send: 0, select: 0) [19:33:02.284707] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183434956 p:3183082678 ts:74577740588493 sn:58657 retr: 0, avail: 0, send: 0, select: 0) [19:33:02.475363] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105234.994639872 (ts:74577740829613) [19:33:02.632892] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183435304 p:3183092679 ts:74577741029549 sn:59910 retr: 0, avail: 0, send: 0, select: 0) D MercurySession.cpp:251: Executing Mercury Request, type SEND I spotify.cpp:249: Got next track id 7599745a6d784390ad20b70154995851 => [19:33:02.822806] exec_request:614 [0x7f8c018920]: ----> : write SET_PARAMETER rtsp://[ATV IP]/3618308148 RTSP/1.0 RTP-Info: rtptime=4224109165 Content-Type: application/x-dmap-tagged Content-Length: 80 CSeq: 37 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 mlit [19:33:02.826816] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:02.827184] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:02 GMT [19:33:02.827387] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:02.827639] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:02.827750] exec_request:650 [0x7f8c018920]: <------ : CSeq: 37 I spotify.cpp:169: Setting track position 1736 / 1080000 [19:33:02.828102] exec_request:614 [0x7f8c018920]: ----> : write SET_PARAMETER rtsp://[ATV IP]/3618308148 RTSP/1.0 Content-Type: text/parameters Content-Length: 44 CSeq: 38 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 progress: 4238965710/4239042267/4286593710 [19:33:02.831809] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:02.832263] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:02 GMT [19:33:02.832488] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:02.832765] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:02.832902] exec_request:650 [0x7f8c018920]: <------ : CSeq: 38 D MercurySession.cpp:251: Executing Mercury Request, type SEND I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:33:02.951747] exec_request:614 [0x7f8c018920]: ----> : write SET_PARAMETER rtsp://[ATV IP]/3618308148 RTSP/1.0 RTP-Info: rtptime=4224180269 Content-Type: image/jpeg Content-Length: 23934 CSeq: 39 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 ���� [19:33:02.960805] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:02.961260] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:02 GMT [19:33:02.961483] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:02.961756] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:02.961895] exec_request:650 [0x7f8c018920]: <------ : CSeq: 39 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:33:03.067006] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183435738 p:3183102672 ts:74577741470253 sn:61162 retr: 0, avail: 0, send: 0, select: 0) [19:33:03.419794] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183436091 p:3183112673 ts:74577741911309 sn:62415 retr: 0, avail: 0, send: 0, select: 0) [19:33:03.476569] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105260.2386952192 (ts:74577741990509) [19:33:03.769749] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105583.3305947996 (ref 1691105583.3298583105) [19:33:03.794238] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183436466 p:3183122675 ts:74577742352365 sn:63668 retr: 0, avail: 0, send: 0, select: 0) [19:33:04.143406] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183436815 p:3183132676 ts:74577742793421 sn:64921 retr: 0, avail: 0, send: 0, select: 0) [19:33:04.477738] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105287.2843869184 (ts:74577743185901) [19:33:04.507407] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183437179 p:3183142677 ts:74577743234477 sn:638 retr: 0, avail: 0, send: 0, select: 0) [19:33:04.917856] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183437589 p:3183152678 ts:74577743675533 sn:1891 retr: 0, avail: 0, send: 0, select: 0) [19:33:05.280259] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183437952 p:3183162672 ts:74577744116237 sn:3143 retr: 0, avail: 0, send: 0, select: 0) [19:33:05.478925] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105314.1689583616 (ts:74577744364749) [19:33:05.653795] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183438325 p:3183172673 ts:74577744557293 sn:4396 retr: 0, avail: 0, send: 0, select: 0) [19:33:05.897850] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105585.3856133307 (ref 1691105585.3848643900) [19:33:05.997756] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183438669 p:3183182674 ts:74577744998349 sn:5649 retr: 0, avail: 0, send: 0, select: 0) [19:33:06.362093] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183439033 p:3183192676 ts:74577745439405 sn:6902 retr: 0, avail: 0, send: 0, select: 0) [19:33:06.480101] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105342.1794048000 (ts:74577745600621) [19:33:06.703217] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183439375 p:3183202677 ts:74577745880461 sn:8155 retr: 0, avail: 0, send: 0, select: 0) [19:33:07.090948] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183439762 p:3183212678 ts:74577746321517 sn:9408 retr: 0, avail: 0, send: 0, select: 0) [19:33:07.433623] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183440105 p:3183222679 ts:74577746762573 sn:10661 retr: 0, avail: 0, send: 0, select: 0) [19:33:07.481343] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105370.664272896 (ts:74577746823821) [19:33:07.836501] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183440508 p:3183232673 ts:74577747203277 sn:11913 retr: 0, avail: 0, send: 0, select: 0) [19:33:08.182403] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183440854 p:3183242674 ts:74577747644333 sn:13166 retr: 0, avail: 0, send: 0, select: 0) [19:33:08.482611] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105397.264175616 (ts:74577748010413) [19:33:08.556933] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183441228 p:3183252675 ts:74577748085389 sn:14419 retr: 0, avail: 0, send: 0, select: 0) [19:33:08.600971] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105588.2581047711 (ref 1691105588.2571348426) [19:33:08.901188] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183441573 p:3183262676 ts:74577748526445 sn:15672 retr: 0, avail: 0, send: 0, select: 0) [19:33:09.270573] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183441942 p:3183272678 ts:74577748967501 sn:16925 retr: 0, avail: 0, send: 0, select: 0) [19:33:09.483743] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105425.1362755584 (ts:74577749256493) [19:33:09.616623] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183442288 p:3183282679 ts:74577749408557 sn:18178 retr: 0, avail: 0, send: 0, select: 0) [19:33:09.976402] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183442648 p:3183292672 ts:74577749849261 sn:19430 retr: 0, avail: 0, send: 0, select: 0) [19:33:10.365461] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183443037 p:3183302674 ts:74577750290317 sn:20683 retr: 0, avail: 0, send: 0, select: 0) [19:33:10.484871] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105452.242745344 (ts:74577750435693) [19:33:10.736720] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183443408 p:3183312675 ts:74577750731373 sn:21936 retr: 0, avail: 0, send: 0, select: 0) [19:33:11.051106] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105591.219391224 (ref 1691105591.211910757) [19:33:11.078686] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183443750 p:3183322676 ts:74577751172429 sn:23189 retr: 0, avail: 0, send: 0, select: 0) [19:33:11.429997] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183444101 p:3183332677 ts:74577751613485 sn:24442 retr: 0, avail: 0, send: 0, select: 0) [19:33:11.486045] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105480.72941568 (ts:74577751668749) [19:33:11.809455] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183444481 p:3183342679 ts:74577752054541 sn:25695 retr: 0, avail: 0, send: 0, select: 0) [19:33:12.169430] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183444841 p:3183352672 ts:74577752495245 sn:26947 retr: 0, avail: 0, send: 0, select: 0) [19:33:12.487219] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105507.598409216 (ts:74577752864845) [19:33:12.540492] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183445212 p:3183362673 ts:74577752936301 sn:28200 retr: 0, avail: 0, send: 0, select: 0) [19:33:12.939526] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183445611 p:3183372674 ts:74577753377357 sn:29453 retr: 0, avail: 0, send: 0, select: 0) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame [19:33:13.341129] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183446013 p:3183382676 ts:74577753818413 sn:30706 retr: 0, avail: 0, send: 0, select: 0) [19:33:13.488403] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105532.3303211008 (ts:74577753995117) [19:33:13.697087] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183446368 p:3183392677 ts:74577754259469 sn:31959 retr: 0, avail: 0, send: 0, select: 0) [19:33:13.709241] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105593.3046050935 (ref 1691105593.3040097245) [19:33:14.083534] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183446755 p:3183402678 ts:74577754700525 sn:33212 retr: 0, avail: 0, send: 0, select: 0) [19:33:14.343340] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:34020 nb:1 (mis:0) [19:33:14.459542] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183447131 p:3183412672 ts:74577755141229 sn:34464 retr: 1, avail: 0, send: 0, select: 0) D spotify.cpp:416: keepAlive Den Apple TV [19:33:14.824046] exec_request:614 [0x7f8c018920]: ----> : write OPTIONS * RTSP/1.0 CSeq: 40 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:33:14.829384] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:14.829745] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:14 GMT [19:33:14.829939] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:14.830928] exec_request:650 [0x7f8c018920]: <------ : Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET, PUT [19:33:14.831179] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:14.831294] exec_request:650 [0x7f8c018920]: <------ : CSeq: 40 [19:33:14.856295] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183447528 p:3183422673 ts:74577755582285 sn:35717 retr: 1, avail: 0, send: 0, select: 0) [19:33:14.918362] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:35890 nb:1 (mis:0) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:129: Another player took control, pausing playback I TrackPlayer.cpp:94: Resetting state I TrackPlayer.cpp:249: Playing done I spotify.cpp:104: Disconnecting Den Apple TV I MercurySession.cpp:42: Received packet, command: 181 [19:33:15.891455] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105595.3828409293 (ref 1691105595.3822614004) [19:33:16.892870] exec_request:614 [0x7f8c018920]: ----> : write FLUSH rtsp://[ATV IP]/3618308148 RTSP/1.0 RTP-Info: seq=36059;rtptime=4238541870 CSeq: 41 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:33:16.898478] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:16.898859] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:16 GMT [19:33:16.899079] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:16.899389] exec_request:650 [0x7f8c018920]: <------ : RTP-Info: rtptime=4238541517 [19:33:16.899665] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:16.899802] exec_request:650 [0x7f8c018920]: <------ : CSeq: 41 [19:33:16.899902] exec_request:614 [0x7f8c018920]: ----> : write TEARDOWN rtsp://[ATV IP]/3618308148 RTSP/1.0 CSeq: 42 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: d60b3df46a5809ab DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:33:17.511517] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:17.511937] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:17 GMT [19:33:17.512157] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:17.512434] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:17.512570] exec_request:650 [0x7f8c018920]: <------ : CSeq: 42 I TrackPlayer.cpp:94: Resetting state I MercurySession.cpp:128: Disconnecting mercury session I PlainConnection.cpp:197: Closing socket... E PlainConnection.cpp:146: Connection lost, will need to reconnect... E MercurySession.cpp:53: Error while receiving packet: Reconnection required I spotify.cpp:441: disconnecting player Den Apple TV ```
Unsuccessful (SpotConnect seems to think audio is playing, but it Apple TV disagrees) ```none I spotify.cpp:381: Spotify client connected for Den Apple TV D Session.cpp:63: Connecting with AP D PlainConnection.cpp:101: Connected to spotify server I Session.cpp:39: Received APHello response D Session.cpp:44: Received shannon keys D Session.cpp:82: Authorization successful I MercurySession.cpp:42: Received packet, command: 4 D TimeProvider.cpp:15: Time synced with spotify servers I MercurySession.cpp:42: Received packet, command: 2 I MercurySession.cpp:42: D Received packet, command: 118MercurySession.cpp:251: Executing Mercury Request, type SUB D spotify.cpp:416: keepAlive Den Apple TV I MercurySession.cpp:42: Received packet, command: 27 D MercurySession.cpp:153: Received country code US I MercurySession.cpp:42: Received packet, command: 80 I MercurySession.cpp:42: Received packet, command: 31 I MercurySession.cpp:42: Received packet, command: 105 I MercurySession.cpp:42: Received packet, command: 181 I AccessKeyFetcher.cpp:99: Access token expired, fetching new one... 238 I MercurySession.cpp:42: Received packet, command: 74 I MercurySession.cpp:42: Received packet, command: 179 D MercurySession.cpp:174: Received mercury packet D MercurySession.cpp:251: Executing Mercury Request, type SEND D SpircHandler.cpp:59: Sent kMessageTypeHello! I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:124: Notify frame D I SpircHandler.cpp:67: Received subscription response MercurySession.cpp:42: Received packet, command: 178 D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D MercurySession.cpp:174: Received mercury packet I AccessKeyFetcher.cpp:114: Access token sucessfully fetched I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:170: Load frame 8! D MercurySession.cpp:251: Executing Mercury Request, type SEND I TrackPlayer.cpp:94: Resetting state D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Coalescence Cascade I TrackQueue.cpp:159: Track duration: 1080000 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/9601f3a3e1b525316a5705a11732dfc9935043dd?1691192025_HkcCPSB5aSoQpK-ISPrf4S5Z1t2TTOHnpa3N2dNTB2Y= I TrackPlayer.cpp:167: Got track ID=9601f3a3e1b525316a5705a11732dfc9935043dd I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-fa.scdn.co/audio/9601f3a3e1b525316a5705a11732dfc9935043dd?1691192025_HkcCPSB5aSoQpK-ISPrf4S5Z1t2TTOHnpa3N2dNTB2Y= D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Broken Chroma I TrackQueue.cpp:159: Track duration: 1080006 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I CDNAudioFile.cpp:70: Header and footer bytes received D MercurySession.cpp:251: Executing Mercury Request, type SEND I spotify.cpp:235: new track will start at 1736 [19:33:45.392838] shadowRequest:219 [0xa572c8]: spotify LOAD request [19:33:45.496821] raopcl_connect:996 [0x7f8c014580]: local interface [RPI IP] [19:33:45.498294] exec_request:614 [0x7f8c018920]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 43 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/a2ac0c42588c5ce4cfb8e82554281183ffa637a8?1691192025_a_Las1CCrZEhVkiHOmjebBxmEdhcL--UWJ2O6uCh97s= [19:33:45.519862] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:45.520241] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:45 GMT [19:33:45.520464] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 96 [19:33:45.520858] exec_request:650 [0x7f8c018920]: <------ : Content-Type: application/octet-stream [19:33:45.521150] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:45.521288] exec_request:650 [0x7f8c018920]: <------ : CSeq: 43 [19:33:45.521362] exec_request:691 [0x7f8c018920]: Body data len 96 0000 7f fb 13 eb 4d a0 cc c2 94 e7 da 1f 04 c1 a5 bc M 0010 a9 84 d3 3e 6e eb 4a 5e 01 a1 c4 e4 e4 0b ba 74 >n J^ t 0020 a7 95 49 70 b9 fd be d9 ba 71 88 d4 7e 6a 89 15 Ip q ~j 0030 8a 43 39 79 48 17 e5 40 64 d1 bd 59 37 c3 84 4b C9yH @d Y7 K 0040 be f5 ac 35 84 f6 49 63 28 c1 8f 5f 4a f9 49 4b 5 Ic( _J IK 0050 02 ce fb 47 f2 c3 4c d4 2c 97 d0 b3 9f 98 2e 5e G L , .^ [19:33:45.529307] exec_request:614 [0x7f8c018920]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 44 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 [19:33:45.535856] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:45.536230] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:45 GMT [19:33:45.536446] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:45.536841] exec_request:650 [0x7f8c018920]: <------ : Content-Type: application/octet-stream [19:33:45.537130] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:45.537268] exec_request:650 [0x7f8c018920]: <------ : CSeq: 44 [19:33:45.537586] exec_request:614 [0x7f8c018920]: ----> : write ANNOUNCE rtsp://[ATV IP]/1425739616 RTSP/1.0 Content-Type: application/sdp Content-Length: 178 CSeq: 45 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 v=0 o=iTunes 1425739616 0 IN IP4 [RPI IP] s=iTunes c=IN IP4 [ATV IP] t=0 0 m=audio 0 RTP/AVP 96 a=rtpmap:96 AppleLossless a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100 [19:33:45.594874] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:45.595277] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:45 GMT [19:33:45.595496] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:45.595773] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:45.595910] exec_request:650 [0x7f8c018920]: <------ : CSeq: 45 [19:33:45.596083] exec_request:614 [0x7f8c018920]: ----> : write SETUP rtsp://[ATV IP]/1425739616 RTSP/1.0 Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=60604;timing_port=47633 CSeq: 46 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 [19:33:45.600723] _rtp_timing_thread:1296 [0x7f8c014580]: NTP remote port: 62215 [19:33:45.600822] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105625.2580373401 (ref 2208988800.2137256614) [19:33:45.604729] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105625.2597213968 (ref 1691105625.2589455918) [19:33:45.608728] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105625.2614398132 (ref 1691105625.2606669073) D MercurySession.cpp:251: Executing Mercury Request, type GET [19:33:45.625877] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:45.626267] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:45 GMT [19:33:45.626482] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:45.627344] exec_request:650 [0x7f8c018920]: <------ : Transport: RTP/AVP/UDP;unicast;mode=record;server_port=56554;control_port=52617;timing_port=0 [19:33:45.627498] exec_request:650 [0x7f8c018920]: <------ : Session: 1 [19:33:45.627807] exec_request:650 [0x7f8c018920]: <------ : Audio-Jack-Status: connected [19:33:45.628081] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:45.628216] exec_request:650 [0x7f8c018920]: <------ : CSeq: 46 [19:33:45.628287] rtspcl_setup:239 [0x7f8c018920]: <------ : session:1 [19:33:45.628337] raopcl_analyse_setup:943 [0x7f8c014580]: missing timing port, will get it later [19:33:45.628383] raopcl_connect:1058 [0x7f8c014580]:opened audio socket l:35944 r:56554 [19:33:45.628429] raopcl_connect:1059 [0x7f8c014580]:opened timing socket l:47633 r:0 [19:33:45.628474] raopcl_connect:1060 [0x7f8c014580]:opened control socket l:60604 r:52617 [19:33:45.628558] exec_request:614 [0x7f8c018920]: ----> : write RECORD rtsp://[ATV IP]/1425739616 RTSP/1.0 Range: npt=0- RTP-Info: seq=36059;rtptime=4240929769 CSeq: 47 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:33:45.635862] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:45.636235] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:45 GMT [19:33:45.636450] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:45.636681] exec_request:650 [0x7f8c018920]: <------ : Audio-Latency: 3579 [19:33:45.636952] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:45.637107] exec_request:650 [0x7f8c018920]: <------ : CSeq: 47 [19:33:45.637362] raopcl_connect:1080 [0x7f8c014580]: setting volume as part of connect -30.00 [19:33:45.637469] exec_request:614 [0x7f8c018920]: ----> : write SET_PARAMETER rtsp://[ATV IP]/1425739616 RTSP/1.0 Content-Type: text/parameters Content-Length: 20 CSeq: 48 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 volume: -30.000000 [19:33:45.641882] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:45.642254] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:45 GMT [19:33:45.642467] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:45.642741] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:45.642877] exec_request:650 [0x7f8c018920]: <------ : CSeq: 48 D MercurySession.cpp:251: Executing Mercury Request, type SEND [19:33:45.643228] shadowRequest:223 [0xa572c8]: spotify play request I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Know Your Shadow I TrackQueue.cpp:159: Track duration: 1080012 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I TrackPlayer.cpp:200: Playing I spotify.cpp:133: trackUniqueId update => 9601f3a3e1b525316a5705a11732dfc9935043dd [19:33:45.747716] raopcl_send_chunk:519 [0x7f8c014580]: begining to stream (LATE) hts:74577755702317 n:1691105625.3211407176 [19:33:45.747848] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105571.2066350080 (ts:74577755702317) I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 178 I MercurySession.cpp:42: Received packet, command: 13 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... [19:33:45.928789] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:36639 nb:1 (mis:0) [19:33:45.996981] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183478668 p:3183432674 ts:74577756023341 sn:36970 retr: 1, avail: 0, send: 0, select: 0) I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/604f05ea7406c84e346203bad424dc9e15b05dca?1691192026_osBrXPzX88tdJwnmg7zcyhIWA-kGIs8hGYrR1INT-Vo= [19:33:46.368418] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183479040 p:3183442675 ts:74577756464397 sn:38223 retr: 1, avail: 0, send: 0, select: 0) [19:33:46.528101] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:38585 nb:1 (mis:0) [19:33:46.776278] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183479448 p:3183452677 ts:74577756905453 sn:39476 retr: 2, avail: 0, send: 0, select: 0) D MercurySession.cpp:251: Executing Mercury Request, type SEND I spotify.cpp:249: Got next track id 7599745a6d784390ad20b70154995851 => [19:33:46.853003] exec_request:614 [0x7f8c018920]: ----> : write SET_PARAMETER rtsp://[ATV IP]/1425739616 RTSP/1.0 RTP-Info: rtptime=4239848845 Content-Type: application/x-dmap-tagged Content-Length: 80 CSeq: 49 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 mlit [19:33:46.857920] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:46.858276] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:46 GMT [19:33:46.858468] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:46.858721] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:46.858834] exec_request:650 [0x7f8c018920]: <------ : CSeq: 49 I spotify.cpp:169: Setting track position 0 / 1080000 [19:33:46.873607] exec_request:614 [0x7f8c018920]: ----> : write SET_PARAMETER rtsp://[ATV IP]/1425739616 RTSP/1.0 Content-Type: text/parameters Content-Length: 44 CSeq: 50 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 progress: 4240984674/4240984674/4288612674 [19:33:46.877945] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:46.878321] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:46 GMT [19:33:46.878537] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:46.878816] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:46.878955] exec_request:650 [0x7f8c018920]: <------ : CSeq: 50 D MercurySession.cpp:251: Executing Mercury Request, type SEND [19:33:46.963012] exec_request:614 [0x7f8c018920]: ----> : write SET_PARAMETER rtsp://[ATV IP]/1425739616 RTSP/1.0 RTP-Info: rtptime=4239918541 Content-Type: image/jpeg Content-Length: 23934 CSeq: 51 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 ���� [19:33:46.971933] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:46.972338] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:46 GMT [19:33:46.972561] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:46.972841] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:46.972979] exec_request:650 [0x7f8c018920]: <------ : CSeq: 51 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:33:47.015845] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:40118 nb:1 (mis:0) I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:33:47.182426] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183479854 p:3183462678 ts:74577757346509 sn:40729 retr: 3, avail: 0, send: 0, select: 0) [19:33:47.530562] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183480202 p:3183472679 ts:74577757787565 sn:41982 retr: 3, avail: 0, send: 0, select: 0) [19:33:48.016978] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105628.37093376 (ts:74577758195181) [19:33:48.161885] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105628.695213471 (ref 1691105628.687989599) [19:33:48.165897] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:43153 nb:1 (mis:0) [19:33:48.795658] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183481467 p:3183482672 ts:74577758228269 sn:43234 retr: 4, avail: 0, send: 0, select: 0) [19:33:49.166998] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105629.644415488 (ts:74577758245517) [19:33:50.168125] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105630.600375296 (ts:74577758289165) [19:33:50.586123] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105630.2517198727 (ref 1691105630.2508664143) [19:33:51.169255] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105631.693501952 (ts:74577758334221) [19:33:52.170401] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105632.580911104 (ts:74577758377165) [19:33:52.682080] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105632.2929433983 (ref 1691105632.2923625907) [19:33:53.171532] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105633.536870912 (ts:74577758420813) [19:33:54.172659] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105634.698548224 (ts:74577758466573) [19:33:54.837220] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:43989 nb:1 (mis:0) [19:33:55.486257] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105635.2088363423 (ref 1691105635.2079508425) [19:33:55.838352] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105635.3534225408 (ts:74577758539789) [19:33:56.751419] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:44229 nb:1 (mis:0) [19:33:57.116337] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:44275 nb:1 (mis:0) [19:33:58.117142] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105638.453902336 (ts:74577758640461) [19:33:58.773816] raopcl_send_chunk:588 [0x7f8c014580]: check n:3183491445 p:3183492674 ts:74577758669325 sn:44487 retr: 7, avail: 0, send: 0, select: 0) [19:33:59.118275] _raopcl_send_sync:1254 [0x7f8c014580]: sync ntp:1691105639.409862144 (ts:74577758684109) [19:33:59.258437] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:44543 nb:1 (mis:0) D spotify.cpp:416: keepAlive Den Apple TV [19:33:59.446187] exec_request:614 [0x7f8c018920]: ----> : write OPTIONS * RTSP/1.0 CSeq: 52 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:33:59.451539] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:33:59.451888] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:33:59 GMT [19:33:59.452080] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:33:59.453066] exec_request:650 [0x7f8c018920]: <------ : Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET, PUT [19:33:59.453343] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:33:59.453456] exec_request:650 [0x7f8c018920]: <------ : CSeq: 52 [19:33:59.871457] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:44620 nb:1 (mis:0) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame [19:34:00.076566] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:44646 nb:1 (mis:0) [19:34:00.229490] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:44665 nb:1 (mis:0) [19:34:00.592487] _rtp_timing_thread:1328 [0x7f8c014580]: NTP sync: 1691105640.2544609209 (ref 1691105640.2538179799) [19:34:00.914519] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:44751 nb:1 (mis:0) [19:34:01.477535] _rtp_control_thread:1430 [0x7f8c014580]: retransmit packet sn:44821 nb:1 (mis:0) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:129: Another player took control, pausing playback I TrackPlayer.cpp:94: Resetting state I TrackPlayer.cpp:249: Playing done I spotify.cpp:104: Disconnecting Den Apple TV I MercurySession.cpp:42: Received packet, command: 181 [19:34:02.595148] exec_request:614 [0x7f8c018920]: ----> : write FLUSH rtsp://[ATV IP]/1425739616 RTSP/1.0 RTP-Info: seq=44840;rtptime=4241632782 CSeq: 53 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:34:02.600938] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:34:02.601845] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:34:02 GMT [19:34:02.602325] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:34:02.603035] exec_request:650 [0x7f8c018920]: <------ : RTP-Info: rtptime=4241628205 [19:34:02.603656] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:34:02.603939] exec_request:650 [0x7f8c018920]: <------ : CSeq: 53 [19:34:02.604123] exec_request:614 [0x7f8c018920]: ----> : write TEARDOWN rtsp://[ATV IP]/1425739616 RTSP/1.0 CSeq: 54 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 26a9b2add01294fd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:34:03.198743] exec_request:640 [0x7f8c018920]: <------ : 200: request ok [19:34:03.199132] exec_request:650 [0x7f8c018920]: <------ : Date: Thu, 03 Aug 2023 23:34:03 GMT [19:34:03.199326] exec_request:650 [0x7f8c018920]: <------ : Content-Length: 0 [19:34:03.199577] exec_request:650 [0x7f8c018920]: <------ : Server: AirTunes/695.5.1 [19:34:03.199689] exec_request:650 [0x7f8c018920]: <------ : CSeq: 54 I TrackPlayer.cpp:94: Resetting state I MercurySession.cpp:128: Disconnecting mercury session I PlainConnection.cpp:197: Closing socket... E PlainConnection.cpp:146: Connection lost, will need to reconnect... E MercurySession.cpp:53: Error while receiving packet: Reconnection required I spotify.cpp:441: disconnecting player Den Apple TV ```
philippe44 commented 11 months ago

I've tried on my ATV which is A1842, so 4K 1st gen and could pair and play multiple time. I'm using the Windows version of SpotRaop

nano9g commented 11 months ago

My ATV 4K is A2169 (2nd Gen).

Do you need me to test running SpotRaop on other platforms?

philippe44 commented 11 months ago

If by chance you have a Windows machine as well it could be useful

nano9g commented 11 months ago

I just tested with a Windows 11 VM and got the exact same behavior. I don't think this is related, but the initial playback attempt aborted for some reason. I've demarcated all three playback sessions in the log.

Let me know if you'd like me to test anything else!

📃 Log ``` > .\spotraop.exe -x .\spotraop-config.xml -d all=debug [19:36:36.703] main:1134 Starting spotraop version: v0.1.4 (Aug 6 2023 @ 15:29:58) [19:36:36.718] Start:903 Binding to [Main Network IP] [19:36:36.718] StartActiveRemote:788 DACP port: 50938 [19:36:40.281] AddRaopDevice:514 [00A7F7C0]: creating MAC [19:36:40.281] AddRaopDevice:529 [00A7F7C0]: adding renderer (DEVF6GT4QEDWK3TEFQNZ@[IOT Network IP]) with mac AAAA-XXXXXXXX [19:36:40.281] raopcl_create:713 [07AECC60]: using ALAC coding [19:36:40.281] AddRaopDevice:481 [00A7FC40]: AppleTV with valid authentication key [key] I BellHTTPServer.cpp:191: Server listening on port 0 [19:36:40.296] AddRaopDevice:529 [00A7FC40]: adding renderer (Sunroom-Apple-TV@[Main Network IP]) with mac AAAA-XXXXXXXX [19:36:40.312] raopcl_create:713 [07B04190]: using ALAC coding I spotify.cpp:366: Server using actual port 50941 [19:36:40.312] AddRaopDevice:481 [00A800C0]: AppleTV with valid authentication key [key] I MDNSService.cpp:69: mDNS on interface [Main Network IP] I BellHTTPServer.cpp:191: Server listening on port 0 [19:36:40.328] AddRaopDevice:529 [00A800C0]: adding renderer (Den-Apple-TV@[Main Network IP]) with mac AAAA-XXXXXXXX [19:36:40.328] raopcl_create:713 [07B5F860]: using ALAC coding I BellHTTPServer.cpp:191: Server listening on port 0 I spotify.cpp:366: Server using actual port 50944 I spotify.cpp:366: Server using actual port 50945 [19:36:41.486] AddRaopDevice:529 [00A80540]: adding renderer (Kitchen-HomePod@[Main Network IP]) with mac AAAA-XXXXXXXX [19:36:41.486] raopcl_create:713 [0C3B8058]: using ALAC coding I BellHTTPServer.cpp:191: Server listening on port 0 I spotify.cpp:366: Server using actual port 50946 ======================================== FIRST ATTEMPT (Aborted for unknown reason) ======================================== I spotify.cpp:388: Spotify client connected for Den Apple TV D Session.cpp:63: Connecting with AP D PlainConnection.cpp:101: Connected to spotify server I Session.cpp:39: Received APHello response D Session.cpp:44: Received shannon keys D Session.cpp:82: Authorization successful I MercurySession.cpp:42: Received packet, command: 4 D TimeProvider.cpp:15: Time synced with spotify servers I MercurySession.cpp:42: Received packet, command: 2 I MercurySession.cpp:42: D MercurySession.cpp:252: Executing Mercury Request, type SUB Received packet, command: 118 D spotify.cpp:423: keepAlive Den Apple TV I MercurySession.cpp:42: Received packet, command: 27 D MercurySession.cppI MercurySession.cpp:42: Received packet, command: 80 :153: Received country code US I MercurySession.cpp:42: Received packet, command: 31 I MercurySession.cpp:42: Received packet, command: 105 I MercurySession.cpp:42: Received packet, command: 181 I AccessKeyFetcher.cpp:100: Access token expired, fetching new one... 234 I MercurySession.cpp:42: Received packet, command: 74 I MercurySession.cpp:42: Received packet, command: 179 D MercurySession.cpp:174: Received mercury packet D MercurySession.cpp:252: Executing Mercury Request, type SEND D SpircHandler.cpp:59: Sent kMessageTypeHello! I AccessKeyFetcher.cpp:114: Access token sucessfully fetched I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:170: Load frame 10! D MercurySession.cpp:252: Executing Mercury Request, type SEND I TrackPlayer.cpp:94: Resetting state D MercurySession.cpp:252: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Only You I TrackQueue.cpp:159: Track duration: 220000 D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 178 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:129: Another player took control, pausing playback I TrackPlayer.cpp:94: Resetting state I TrackQueue.cppI MercurySession.cpp:42: :301: Received CDN URL, https://audio-fa.scdn.co/audio/45155e5a08607368c80357694d6da9d595b9d4d6?1691451409_SPMi6fPS-b5kyO-DIIHAIsay54P09hzPB4yQXnvpNMk= Received packet, command: 178 I TrackPlayer.cpp:167: Got track ID=45155e5a08607368c80357694d6da9d595b9d4d6 I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-fa.scdn.co/audio/45155e5a08607368c80357694d6da9d595b9d4d6?1691451409_SPMi6fPS-b5kyO-DIIHAIsay54P09hzPB4yQXnvpNMk= D MercurySession.cpp:252: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 I CDNAudioFile.cpp:70: Header and footer bytes received I spotify.cpp:104: Disconnecting Den Apple TV I TrackPlayer.cpp:94: Resetting state I MercurySession.cpp:128: Disconnecting mercury session I PlainConnection.cpp:197: Closing socket... E MercurySession.cpp:53: Error while receiving packet: Error in read I spotify.cpp:448: disconnecting player Den Apple TV ======================================== SECOND ATTEMPT (Successful) ======================================== I spotify.cpp:388: Spotify client connected for Den Apple TV D Session.cpp:63: Connecting with AP D PlainConnection.cpp:101: Connected to spotify server I Session.cpp:39: Received APHello response D Session.cpp:44: Received shannon keys D Session.cpp:82: Authorization successful I MercurySession.cpp:42: Received packet, command: 4 D TimeProvider.cpp:15: Time synced with spotify servers I MercurySession.cpp:42: Received packet, command: 2 I MercurySession.cpp:42: Received packet, command: 118D MercurySession.cpp:252: Executing Mercury Request, type SUB I MercurySession.cpp:42: Received packet, command: 27 D spotify.cpp:423: keepAlive Den Apple TV I MercurySession.cpp:42: Received packet, command: 80 D MercurySession.cpp:153: Received country code US I MercurySession.cpp:42: Received packet, command: 31 I MercurySession.cpp:42: Received packet, command: 105 I MercurySession.cpp:42: Received packet, command: 181 I AccessKeyFetcher.cpp:100: Access token expired, fetching new one... 234 I MercurySession.cpp:42: Received packet, command: 74 I MercurySession.cpp:42: Received packet, command: 179 D MercurySession.cpp:174: Received mercury packet D MercurySession.cpp:252: Executing Mercury Request, type SEND D SpircHandler.cpp:59: Sent kMessageTypeHello! I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 178 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D MercurySession.cpp:174: Received mercury packet I AccessKeyFetcher.cpp:114: Access token sucessfully fetched I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:170: Load frame 10! D MercurySession.cpp:252: Executing Mercury Request, type SEND I TrackPlayer.cpp:94: Resetting state D MercurySession.cpp:252: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Only You I TrackQueue.cpp:159: Track duration: 220000 D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/45155e5a08607368c80357694d6da9d595b9d4d6?1691451419_o7WX9O3_OT9rx4yErD8qTzM_gx-mzT7-f1O1ko2xCEE= I TrackPlayer.cpp:167: Got track ID=45155e5a08607368c80357694d6da9d595b9d4d6 I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-fa.scdn.co/audio/45155e5a08607368c80357694d6da9d595b9d4d6?1691451419_o7WX9O3_OT9rx4yErD8qTzM_gx-mzT7-f1O1ko2xCEE= D MercurySession.cpp:252: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: These Things Take Time I TrackQueue.cpp:159: Track duration: 272961 D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I CDNAudioFile.cpp:70: Header and footer bytes received D MercurySession.cpp:252: Executing Mercury Request, type SEND I spotify.cpp:235: new track will start at 0 [19:36:59.703] shadowRequest:219 [00A800C0]: spotify LOAD request [19:36:59.817] raopcl_connect:996 [07B5F860]: local interface [Main Network IP] [19:36:59.817] exec_request:614 [07B62BB8]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 1 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936  I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:36:59.974] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:36:59.974] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:00 GMT [19:36:59.974] exec_request:650 [07B62BB8]: <------ : Content-Length: 96 [19:36:59.974] exec_request:650 [07B62BB8]: <------ : Content-Type: application/octet-stream [19:36:59.974] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:36:59.974] exec_request:650 [07B62BB8]: <------ : CSeq: 1 [19:36:59.974] exec_request:691 [07B62BB8]: Body data len 96 0000 ab 4d 80 09 75 18 4a 76 3b 92 16 1d 3c 70 eb 61 M u Jv;

: write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 2 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 [19:37:00.000] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:00.015] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:00 GMT [19:37:00.015] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:00.015] exec_request:650 [07B62BB8]: <------ : Content-Type: application/octet-stream [19:37:00.015] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:00.015] exec_request:650 [07B62BB8]: <------ : CSeq: 2 [19:37:00.015] exec_request:614 [07B62BB8]: ----> : write ANNOUNCE rtsp://[Main Network IP]/0002115686 RTSP/1.0 Content-Type: application/sdp Content-Length: 178 CSeq: 3 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 v=0 o=iTunes 0002115686 0 IN IP4 [Main Network IP] s=iTunes c=IN IP4 [Main Network IP] t=0 0 m=audio 0 RTP/AVP 96 a=rtpmap:96 AppleLossless a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100 [19:37:00.079] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:00.079] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:00 GMT [19:37:00.079] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:00.079] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:00.079] exec_request:650 [07B62BB8]: <------ : CSeq: 3 [19:37:00.079] exec_request:614 [07B62BB8]: ----> : write SETUP rtsp://[Main Network IP]/0002115686 RTSP/1.0 Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=55248;timing_port=55247 CSeq: 4 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 [19:37:00.093] _rtp_timing_thread:1296 [07B5F860]: NTP remote port: 52908 [19:37:00.093] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925532.402992486 (ref 2208988800.814133062) [19:37:00.093] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925532.402992486 (ref 2659925532.420826044) [19:37:00.110] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925532.475775002 (ref 2659925532.447538057) I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/12bad368491a23ddf9d94910da934112314d193a?1691451420_SZ38SuvDpv2AFnAFRslhlbRVonOg2odfZNyP9shu56Y= [19:37:00.156] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:00.156] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:00 GMT [19:37:00.156] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:00.156] exec_request:650 [07B62BB8]: <------ : Transport: RTP/AVP/UDP;unicast;mode=record;server_port=54742;control_port=50321;timing_port=0 [19:37:00.156] exec_request:650 [07B62BB8]: <------ : Session: 1 [19:37:00.156] exec_request:650 [07B62BB8]: <------ : Audio-Jack-Status: connected [19:37:00.156] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:00.156] exec_request:650 [07B62BB8]: <------ : CSeq: 4 [19:37:00.156] rtspcl_setup:239 [07B62BB8]: <------ : session:1 [19:37:00.156] raopcl_analyse_setup:943 [07B5F860]: missing timing port, will get it later [19:37:00.156] raopcl_connect:1058 [07B5F860]:opened audio socket l:55249 r:54742 [19:37:00.156] raopcl_connect:1059 [07B5F860]:opened timing socket l:55247 r:0 [19:37:00.156] raopcl_connect:1060 [07B5F860]:opened control socket l:55248 r:50321 [19:37:00.156] exec_request:614 [07B62BB8]: ----> : write RECORD rtsp://[Main Network IP]/0002115686 RTSP/1.0 Range: npt=0- RTP-Info: seq=6335;rtptime=2864147044 CSeq: 5 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:37:00.156] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:00.156] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:00 GMT [19:37:00.171] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:00.171] exec_request:650 [07B62BB8]: <------ : Audio-Latency: 3579 [19:37:00.171] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:00.171] exec_request:650 [07B62BB8]: <------ : CSeq: 5 [19:37:00.171] raopcl_connect:1080 [07B5F860]: setting volume as part of connect -30.00 [19:37:00.171] exec_request:614 [07B62BB8]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/0002115686 RTSP/1.0 Content-Type: text/parameters Content-Length: 20 CSeq: 6 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 volume: -30.000000 [19:37:00.171] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:00.171] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:00 GMT [19:37:00.171] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:00.171] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:00.171] exec_request:650 [07B62BB8]: <------ : CSeq: 6 D MercurySession.cpp:252: Executing Mercury Request, type SEND [19:37:00.171] shadowRequest:223 [00A800C0]: spotify PLAY request D MercurySession.cpp:252: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Synesthesia I TrackQueue.cpp:159: Track duration: 268541 D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackPlayer.cpp:200: Playing I spotify.cpp:133: trackUniqueId update => 45155e5a08607368c80357694d6da9d595b9d4d6 [19:37:00.750] raopcl_accept_frames:416 [07B5F860]: begining to stream hts:0 n:2659925532.3221401565 [19:37:00.750] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925532.3221291008 (ts:117302715994276) [19:37:00.750] raopcl_accept_frames:424 [07B5F860]: restarting w/o pause n:2659925532.3221401565, hts:117302715994276 [19:37:01.174] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925533.537591808 (ts:117302716010820) I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/3a743fc0ca3aab69ffa5e3a6d4f5c4b0dc85f6c4?1691451421_vxjdPJs-n2-dqAxl48Qqt0w1ptcmMn-uW5Nv7fwtOa8= D MercurySession.cpp:252: Executing Mercury Request, type SEND I spotify.cpp:249: Got next track id 7bcc02362ac34f848765d115702813a6 => [19:37:01.953] exec_request:614 [07B62BB8]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/0002115686 RTSP/1.0 RTP-Info: rtptime=2864225668 Content-Type: application/x-dmap-tagged Content-Length: 76 CSeq: 7 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 mlit [19:37:02.190] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925534.493551616 (ts:117302716054468) [19:37:02.266] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:02.266] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:02 GMT [19:37:02.266] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:02.266] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:02.266] exec_request:650 [07B62BB8]: <------ : CSeq: 7 I spotify.cpp:169: Setting track position 502 / 220000 [19:37:02.281] exec_request:614 [07B62BB8]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/0002115686 RTSP/1.0 Content-Type: text/parameters Content-Length: 44 CSeq: 8 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 progress: 2864218610/2864240748/2873920610 [19:37:02.281] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:02.281] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:02 GMT [19:37:02.281] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:02.281] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:02.281] exec_request:650 [07B62BB8]: <------ : CSeq: 8 D MercurySession.cpp:252: Executing Mercury Request, type SEND I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 178 [19:37:02.829] exec_request:614 [07B62BB8]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/0002115686 RTSP/1.0 RTP-Info: rtptime=2864262276 Content-Type: image/jpeg Content-Length: 19163 CSeq: 9 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1  ╪ α D MercurySession.cpp:174: Received mercury packet [19:37:02.843] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:02.843] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:03 GMT [19:37:02.843] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:02.843] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:02.843] exec_request:650 [07B62BB8]: <------ : CSeq: 9 [19:37:03.206] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925535.655228928 (ts:117302716100228) [19:37:03.282] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925535.1212533692 (ref 2659925534.3934734912) [19:37:04.222] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925536.782630912 (ts:117302716145636) [19:37:05.234] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925537.875692032 (ts:117302716190692) [19:37:06.234] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925538.865992704 (ts:117302716234692) [19:37:06.441] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925538.1896000427 (ref 2659925538.868877231) [19:37:06.797] raopcl_send_chunk:592 [07B5F860]: check n:1340782573 p:1340783778 ts:117302716259332 sn:7087 retr: 0, avail: 0, send: 0, select: 0) [19:37:07.236] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925539.719126528 (ts:117302716277284) [19:37:08.250] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925540.777912320 (ts:117302716321988) [19:37:09.267] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925541.871038976 (ts:117302716367044) [19:37:09.390] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925541.1678112442 (ref 2659925541.1475999661) [19:37:10.281] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925542.929890304 (ts:117302716411748) [19:37:11.285] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925543.988676096 (ts:117302716456452) [19:37:11.516] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925543.2216435052 (ref 2659925543.2175786517) [19:37:12.298] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925544.807534592 (ts:117302716498692) D spotify.cpp:423: keepAlive Den Apple TV [19:37:13.234] exec_request:614 [07B62BB8]: ----> : write OPTIONS * RTSP/1.0 CSeq: 10 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:37:13.234] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:13.234] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:13 GMT [19:37:13.234] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:13.234] exec_request:650 [07B62BB8]: <------ : Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET, PUT [19:37:13.234] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:13.234] exec_request:650 [07B62BB8]: <------ : CSeq: 10 [19:37:13.300] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925545.1140588544 (ts:117302716546212) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame [19:37:14.312] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925546.1342898834 (ref 2659925546.1303357841) [19:37:14.329] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925546.1062338560 (ts:117302716589508) [19:37:15.381] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925547.1395392512 (ts:117302716637028) [19:37:16.392] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925548.1351352320 (ts:117302716680676) [19:37:16.767] raopcl_send_chunk:592 [07B5F860]: check n:1340792543 p:1340793779 ts:117302716700388 sn:8340 retr: 0, avail: 0, send: 0, select: 0) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:129: Another player took control, pausing playback I TrackPlayer.cpp:94: Resetting state I TrackPlayer.cpp:249: Playing done I spotify.cpp:104: Disconnecting Den Apple TV [19:37:17.031] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925549.136549895 (ref 2659925549.72274899) [19:37:18.051] exec_request:614 [07B62BB8]: ----> : write FLUSH rtsp://[Main Network IP]/0002115686 RTSP/1.0 RTP-Info: seq=8355;rtptime=2864884261 CSeq: 11 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:37:18.051] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:18.051] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:18 GMT [19:37:18.051] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:18.051] exec_request:650 [07B62BB8]: <------ : RTP-Info: rtptime=2864884179 [19:37:18.051] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:18.051] exec_request:650 [07B62BB8]: <------ : CSeq: 11 [19:37:18.051] exec_request:614 [07B62BB8]: ----> : write TEARDOWN rtsp://[Main Network IP]/0002115686 RTSP/1.0 CSeq: 12 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: bf41edbecfe380cd DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:37:18.642] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:18.642] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:18 GMT [19:37:18.642] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:18.642] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:18.642] exec_request:650 [07B62BB8]: <------ : CSeq: 12 I TrackPlayer.cpp:94: Resetting state I MercurySession.cpp:128: Disconnecting mercury session I PlainConnection.cpp:197: Closing socket... E MercurySession.cpp:53: Error while receiving packet: Error in read I spotify.cpp:448: disconnecting player Den Apple TV ======================================== THIRD ATTEMPT (Appears successful but no audio plays) ======================================== I spotify.cpp:388: Spotify client connected for Den Apple TV D Session.cpp:63: Connecting with AP D PlainConnection.cpp:101: Connected to spotify server I Session.cpp:39: Received APHello response D Session.cpp:44: Received shannon keys D Session.cpp:82: Authorization successful I MercurySession.cpp:42: Received packet, command: 4 D TimeProvider.cpp:15: Time synced with spotify servers I MercurySession.cpp:42: Received packet, command: 2 I MercurySession.cpp:42: Received packet, command: 118 I D MercurySession.cpp:252: Executing Mercury Request, type SUB MercurySession.cpp:42: Received packet, command: 27 I MercurySession.cpp:42: Received packet, command: 80 I MercurySession.cpp:42: Received packet, command: 31 I MercurySession.cpp:42: Received packet, command: 105 D spotify.cpp:423: keepAlive Den Apple TV D MercurySession.cpp:153: Received country code US I MercurySession.cpp:42: Received packet, command: 181 I AccessKeyFetcher.cpp:100: Access token expired, fetching new one... 234 I MercurySession.cpp:42: Received packet, command: 74 I MercurySession.cpp:42: Received packet, command: 179 D MercurySession.cpp:174: Received mercury packet D MercurySession.cpp:252: Executing Mercury Request, type SEND D SpircHandler.cpp:59: Sent kMessageTypeHello! I AccessKeyFetcher.cpp:114: Access token sucessfully fetched I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 178 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:170: Load frame 10! D MercurySession.cpp:252: Executing Mercury Request, type SEND I TrackPlayer.cpp:94: Resetting state D MercurySession.cpp:252: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Only You I TrackQueue.cpp:159: Track duration: 220000 D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/45155e5a08607368c80357694d6da9d595b9d4d6?1691451446_YCWiommESWvZNdyM4s1PgDTwCzu9DI4JuRqXQDzbtWI= I TrackPlayer.cpp:167: Got track ID=45155e5a08607368c80357694d6da9d595b9d4d6 I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-fa.scdn.co/audio/45155e5a08607368c80357694d6da9d595b9d4d6?1691451446_YCWiommESWvZNdyM4s1PgDTwCzu9DI4JuRqXQDzbtWI= D MercurySession.cpp:252: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: These Things Take Time I TrackQueue.cpp:159: Track duration: 272961 D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I CDNAudioFile.cpp:70: Header and footer bytes received D MercurySession.cpp:252: Executing Mercury Request, type SEND I spotify.cpp:235: new track will start at 502 [19:37:26.031] shadowRequest:219 [00A800C0]: spotify LOAD request I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... [19:37:26.142] raopcl_connect:996 [07B5F860]: local interface [Main Network IP] [19:37:26.142] exec_request:614 [07B62BB8]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 13 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936  [19:37:26.172] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:26.172] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:26 GMT [19:37:26.172] exec_request:650 [07B62BB8]: <------ : Content-Length: 96 [19:37:26.172] exec_request:650 [07B62BB8]: <------ : Content-Type: application/octet-stream [19:37:26.172] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:26.172] exec_request:650 [07B62BB8]: <------ : CSeq: 13 [19:37:26.172] exec_request:691 [07B62BB8]: Body data len 96 0000 36 33 27 4b db ae e3 23 64 84 36 83 9c 45 2e 3c 63'K #d 6 E.< 0010 93 6e 2b f6 9b 29 1a fc 9b ec 20 ad ef 32 01 1a n+ ) 2 0020 42 1f 0f 8c b6 6b b5 58 67 38 d5 56 50 6e 93 31 B k Xg8 VPn 1 0030 d5 c8 bb 1f 7b e0 5f bd c9 24 a4 28 4e 99 f5 a5 { _ $ (N 0040 4d f9 67 cb 16 e1 3c 27 bb 4d 98 7f 60 9a bc 88 M g <' M ` 0050 6f 57 40 49 fe be b2 2d f2 2a 66 17 1a 4a 98 0c oW@I - *f J [19:37:26.187] exec_request:614 [07B62BB8]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 14 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 [19:37:26.187] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:26.187] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:26 GMT [19:37:26.187] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:26.187] exec_request:650 [07B62BB8]: <------ : Content-Type: application/octet-stream [19:37:26.187] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:26.187] exec_request:650 [07B62BB8]: <------ : CSeq: 14 [19:37:26.187] exec_request:614 [07B62BB8]: ----> : write ANNOUNCE rtsp://[Main Network IP]/1361447705 RTSP/1.0 Content-Type: application/sdp Content-Length: 178 CSeq: 15 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 v=0 o=iTunes 1361447705 0 IN IP4 [Main Network IP] s=iTunes c=IN IP4 [Main Network IP] t=0 0 m=audio 0 RTP/AVP 96 a=rtpmap:96 AppleLossless a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:37:26.250] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:26.250] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:26 GMT [19:37:26.250] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:26.250] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:26.250] exec_request:650 [07B62BB8]: <------ : CSeq: 15 [19:37:26.250] exec_request:614 [07B62BB8]: ----> : write SETUP rtsp://[Main Network IP]/1361447705 RTSP/1.0 Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=55251;timing_port=55250 CSeq: 16 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 [19:37:26.266] _rtp_timing_thread:1296 [07B5F860]: NTP remote port: 53566 [19:37:26.266] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925558.1146120612 (ref 2208988800.1545631491) [19:37:26.266] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925558.1146120612 (ref 2659925558.1163970629) [19:37:26.283] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925558.1219186596 (ref 2659925558.1194179640) [19:37:26.297] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:26.297] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:26 GMT [19:37:26.297] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:26.297] exec_request:650 [07B62BB8]: <------ : Transport: RTP/AVP/UDP;unicast;mode=record;server_port=60328;control_port=55197;timing_port=0 [19:37:26.297] exec_request:650 [07B62BB8]: <------ : Session: 1 [19:37:26.297] exec_request:650 [07B62BB8]: <------ : Audio-Jack-Status: connected [19:37:26.297] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:26.297] exec_request:650 [07B62BB8]: <------ : CSeq: 16 [19:37:26.297] rtspcl_setup:239 [07B62BB8]: <------ : session:1 [19:37:26.297] raopcl_analyse_setup:943 [07B5F860]: missing timing port, will get it later [19:37:26.297] raopcl_connect:1058 [07B5F860]:opened audio socket l:55252 r:60328 [19:37:26.297] raopcl_connect:1059 [07B5F860]:opened timing socket l:55250 r:0 [19:37:26.297] raopcl_connect:1060 [07B5F860]:opened control socket l:55251 r:55197 [19:37:26.297] exec_request:614 [07B62BB8]: ----> : write RECORD rtsp://[Main Network IP]/1361447705 RTSP/1.0 Range: npt=0- RTP-Info: seq=8355;rtptime=2865299876 CSeq: 17 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/12bad368491a23ddf9d94910da934112314d193a?1691451446_RrSS60Q9mkJ1HpPgth_TYG75skuX1oEbYiYRcKxd894= [19:37:26.313] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:26.313] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:26 GMT [19:37:26.313] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:26.313] exec_request:650 [07B62BB8]: <------ : Audio-Latency: 3579 [19:37:26.313] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:26.313] exec_request:650 [07B62BB8]: <------ : CSeq: 17 [19:37:26.313] raopcl_connect:1080 [07B5F860]: setting volume as part of connect -30.00 [19:37:26.313] exec_request:614 [07B62BB8]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/1361447705 RTSP/1.0 Content-Type: text/parameters Content-Length: 20 CSeq: 18 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 volume: -30.000000 [19:37:26.313] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:26.313] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:26 GMT [19:37:26.313] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:26.313] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:26.313] exec_request:650 [07B62BB8]: <------ : CSeq: 18 D MercurySession.cpp:252: Executing Mercury Request, type SEND [19:37:26.328] shadowRequest:223 [00A800C0]: spotify PLAY request D MercurySession.cpp:252: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Synesthesia I TrackQueue.cpp:159: Track duration: 268541 D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackPlayer.cpp:200: Playing I spotify.cpp:133: trackUniqueId update => 45155e5a08607368c80357694d6da9d595b9d4d6 [19:37:26.782] raopcl_send_chunk:519 [07B5F860]: begining to stream (LATE) hts:117302716705316 n:2659925558.3359849836 [19:37:26.782] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925548.3751084032 (ts:117302716705316) I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/3a743fc0ca3aab69ffa5e3a6d4f5c4b0dc85f6c4?1691451447_2XUZqYx3MkasdhIpK6IWK8JvcD-vn7aQexcX9PuPSrg= [19:37:27.323] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925557.303824896 (ts:117302717066820) [19:37:27.391] raopcl_send_chunk:592 [07B5F860]: check n:1340803167 p:1340803780 ts:117302717141444 sn:9593 retr: 0, avail: 0, send: 0, select: 0) D MercurySession.cpp:252: Executing Mercury Request, type SEND I spotify.cpp:249: Got next track id 7bcc02362ac34f848765d115702813a6 => [19:37:27.800] exec_request:614 [07B62BB8]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/1361447705 RTSP/1.0 RTP-Info: rtptime=2865365796 Content-Type: application/x-dmap-tagged Content-Length: 76 CSeq: 19 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 mlit [19:37:27.813] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:27.813] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:28 GMT [19:37:27.813] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:27.813] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:27.813] exec_request:650 [07B62BB8]: <------ : CSeq: 19 I spotify.cpp:169: Setting track position 22805 / 220000 [19:37:27.876] exec_request:614 [07B62BB8]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/1361447705 RTSP/1.0 Content-Type: text/parameters Content-Length: 44 CSeq: 20 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 progress: 2864363806/2865369506/2874065806 [19:37:27.876] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:27.876] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:28 GMT [19:37:27.876] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:27.876] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:27.876] exec_request:650 [07B62BB8]: <------ : CSeq: 20 D MercurySession.cpp:252: Executing Mercury Request, type SEND I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:37:27.973] exec_request:614 [07B62BB8]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/1361447705 RTSP/1.0 RTP-Info: rtptime=2865373540 Content-Type: image/jpeg Content-Length: 19163 CSeq: 21 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1  ╪ α [19:37:27.984] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:27.984] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:28 GMT [19:37:27.984] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:27.984] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:27.984] exec_request:650 [07B62BB8]: <------ : CSeq: 21 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [19:37:28.333] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925560.1268776960 (ts:117302717209028) [19:37:29.312] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925561.1342374848 (ref 2659925561.1048727591) [19:37:29.344] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925561.1396178944 (ts:117302717254436) [19:37:30.361] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925562.1215037440 (ts:117302717296676) [19:37:31.375] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925563.1445265408 (ts:117302717343140) [19:37:32.300] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925564.1291986292 (ref 2659925564.1280209146) [19:37:32.375] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925564.1366949888 (ts:117302717386436) [19:37:33.391] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925565.1322909696 (ts:117302717430084) [19:37:34.407] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925566.1656029184 (ts:117302717477604) [19:37:34.781] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925566.3355932826 (ref 2659925566.3324396812) [19:37:35.438] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925567.1543438336 (ts:117302717520548) [19:37:36.438] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925568.1807941632 (ts:117302717567364) [19:37:36.766] raopcl_send_chunk:592 [07B5F860]: check n:1340812542 p:1340813782 ts:117302717582500 sn:10846 retr: 0, avail: 0, send: 0, select: 0) [19:37:36.969] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925568.4163923548 (ref 2659925568.4136912631) [19:37:37.454] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925569.1695350784 (ts:117302717610308) [19:37:38.459] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925570.1788477440 (ts:117302717655364) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame [19:37:39.424] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925571.1824252999 (ref 2659925571.1820772292) [19:37:39.468] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925571.1915879424 (ts:117302717700772) D spotify.cpp:423: keepAlive Den Apple TV [19:37:40.000] exec_request:614 [07B62BB8]: ----> : write OPTIONS * RTSP/1.0 CSeq: 22 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:37:40.000] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:40.000] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:40 GMT [19:37:40.000] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:40.016] exec_request:650 [07B62BB8]: <------ : Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET, PUT [19:37:40.016] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:40.016] exec_request:650 [07B62BB8]: <------ : CSeq: 22 [19:37:40.472] _raopcl_send_sync:1254 [07B5F860]: sync ntp:2659925572.1871839232 (ts:117302717744420) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:129: Another player took control, pausing playback I TrackPlayer.cpp:94: Resetting state I TrackPlayer.cpp:249: Playing done I spotify.cpp:104: Disconnecting Den Apple TV [19:37:41.712] _rtp_timing_thread:1329 [07B5F860]: NTP sync: 2659925573.3059150586 (ref 2659925573.2972921284) [19:37:41.718] exec_request:614 [07B62BB8]: ----> : write FLUSH rtsp://[Main Network IP]/1361447705 RTSP/1.0 RTP-Info: seq=11323;rtptime=2865928997 CSeq: 23 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:37:41.718] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:41.718] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:42 GMT [19:37:41.718] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:41.718] exec_request:650 [07B62BB8]: <------ : RTP-Info: rtptime=2865928644 [19:37:41.718] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:41.718] exec_request:650 [07B62BB8]: <------ : CSeq: 23 [19:37:41.718] exec_request:614 [07B62BB8]: ----> : write TEARDOWN rtsp://[Main Network IP]/1361447705 RTSP/1.0 CSeq: 24 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 07f746d3a83eb752 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 719455936 Session: 1 [19:37:42.303] exec_request:640 [07B62BB8]: <------ : 200: request ok [19:37:42.303] exec_request:650 [07B62BB8]: <------ : Date: Sun, 06 Aug 2023 23:37:42 GMT [19:37:42.303] exec_request:650 [07B62BB8]: <------ : Content-Length: 0 [19:37:42.303] exec_request:650 [07B62BB8]: <------ : Server: AirTunes/695.5.1 [19:37:42.303] exec_request:650 [07B62BB8]: <------ : CSeq: 24 I TrackPlayer.cpp:94: Resetting state I MercurySession.cpp:128: Disconnecting mercury session I PlainConnection.cpp:197: Closing socket... E MercurySession.cpp:53: Error while receiving packet: Error in read I spotify.cpp:448: disconnecting player Den Apple TV exit [19:37:49.190] main:1252 stopping cspot devices ... [19:37:49.190] main:1254 stopping Raop devices ... [19:37:49.190] Stop:926 terminate search thread ... [19:37:49.250] Stop:935 flush renderers ... [19:37:49.250] DelRaopDevice:588 [00A7F7C0]: Raop device stopped [19:37:49.250] DelRaopDevice:588 [00A7FC40]: Raop device stopped [19:37:49.250] DelRaopDevice:588 [00A800C0]: Raop device stopped [19:37:49.250] DelRaopDevice:588 [00A80540]: Raop device stopped [19:37:49.250] Stop:939 terminate mDNS responder [19:37:49.250] Stop:942 terminate main thread ... [19:37:49.265] main:1256 all done ```

philippe44 commented 11 months ago

Do you see the same issue with the other ATVs? I can't reproduce on my A1842 and A1625

nano9g commented 11 months ago

I'll test it out and let you know.

nano9g commented 11 months ago

I'm seeing the same issue on my A1625 with tvOS 16.6 (all my ATVs are on 16.6). I wonder what is different between our setups that it's so consistent for me.

📃 Log ``` $ ./spotraop-linux-aarch64-static -x ./spotraop-config.xml -d all=debug [13:14:29.740968] main:1137 Starting spotraop version: v0.1.5 (Aug 6 2023 @ 16:57:26) [13:14:29.751537] Start:906 Binding to [Main Network IP] [13:14:29.752142] StartActiveRemote:788 DACP port: 42177 [13:14:29.789542] AddRaopDevice:514 [0xa56e10]: creating MAC [13:14:29.789655] AddRaopDevice:528 [0xa56e10]: adding renderer (DEVF6GT4QEDWK3TEFQNZ@[IOT Network IP]) with mac AAAA-XXXXXXXX [13:14:29.789982] raopcl_create:713 [0x7fac0090b0]: using ALAC coding I BellHTTPServer.cpp:191: Server listening on port 0 [13:14:29.805253] AddRaopDevice:481 [0xa572c8]: AppleTV with valid authentication key [key] [13:14:29.805413] AddRaopDevice:528 [0xa572c8]: adding renderer (Den-Apple-TV@[Main Network IP]) with mac AAAA-XXXXXXXX [13:14:29.805599] raopcl_create:713 [0x7fac013e40]: using ALAC coding I BellHTTPServer.cpp:191: Server listening on port 0 I spotify.cpp:366: Server using actual port 38697 I MDNSService.cpp:181: using built-in mDNS for Shop Cone+ I spotify.cpp:366: Server using actual port 42481 I MDNSService.cpp:181: using built-in mDNS for Den Apple TV [13:14:29.980504] AddRaopDevice:481 [0xa57780]: AppleTV with valid authentication key [key] [13:14:29.980716] AddRaopDevice:528 [0xa57780]: adding renderer (Sunroom-Apple-TV@[Main Network IP]) with mac AAAA-XXXXXXXX [13:14:29.980964] raopcl_create:713 [0x7fac01e390]: using ALAC coding I BellHTTPServer.cpp:191: Server listening on port 0 I spotify.cpp:366: Server using actual port 36573 I MDNSService.cpp:181: using built-in mDNS for Sunroom Apple TV [13:14:30.093062] AddRaopDevice:528 [0xa57c38]: adding renderer (Kitchen-HomePod@[Main Network IP]) with mac AAAA-XXXXXXXX [13:14:30.093447] raopcl_create:713 [0x7fac0280f0]: using ALAC coding I BellHTTPServer.cpp:191: Server listening on port 0 I spotify.cpp:366: Server using actual port 41365 I MDNSService.cpp:181: using built-in mDNS for Kitchen HomePod I spotify.cpp:388: Spotify client connected for Sunroom Apple TV D Session.cpp:63: Connecting with AP D PlainConnection.cpp:101: Connected to spotify server I Session.cpp:39: Received APHello response D Session.cpp:44: Received shannon keys D Session.cpp:82: Authorization successful I MercurySession.cpp:42: Received packet, command: 4 D TimeProvider.cpp:15: Time synced with spotify servers I MercurySession.cpp:42: Received packet, command: 2 D MercurySession.cpp:251: Executing Mercury Request, type SUB I MercurySession.cpp:42: Received packet, command: 118 D spotify.cpp:423: keepAlive Sunroom Apple TV I MercurySession.cpp:42: Received packet, command: 27 D MercurySession.cpp:153: Received country code US I MercurySession.cpp:42: Received packet, command: 80 I MercurySession.cpp:42: Received packet, command: 31 I MercurySession.cpp:42: Received packet, command: 105 I MercurySession.cpp:42: Received packet, command: 181 I AccessKeyFetcher.cpp:99: Access token expired, fetching new one... 237 I MercurySession.cpp:42: Received packet, command: 74 I MercurySession.cpp:42: Received packet, command: 179 D MercurySession.cpp:174: Received mercury packet D MercurySession.cpp:251: Executing Mercury Request, type SEND D SpircHandler.cpp:59: Sent kMessageTypeHello! I AccessKeyFetcher.cpp:114: Access token sucessfully fetched I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:124: Notify frameI D MercurySession.cpp:42: SpircHandler.cpp:67: Received subscription response Received packet, command: 178 D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:170: Load frame 9! D MercurySession.cpp:251: Executing Mercury Request, type SEND I TrackPlayer.cpp:94: Resetting state D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: House of Light I TrackQueue.cpp:159: Track duration: 239018 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/130cc877ebef270ce112533c47e2deff46f661e9?1691514904_sK0tbzDQfspMrgRN8TQdPHpj0-pmuB_WN0L7E8cSTow= I TrackPlayer.cpp:167: Got track ID=130cc877ebef270ce112533c47e2deff46f661e9 I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-fa.scdn.co/audio/130cc877ebef270ce112533c47e2deff46f661e9?1691514904_sK0tbzDQfspMrgRN8TQdPHpj0-pmuB_WN0L7E8cSTow= D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Hearken I TrackQueue.cpp:159: Track duration: 299870 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I CDNAudioFile.cpp:70: Header and footer bytes received D MercurySession.cpp:251: Executing Mercury Request, type SEND I spotify.cpp:235: new track will start at 0 [13:15:04.483972] shadowRequest:219 [0xa57780]: spotify LOAD request [13:15:04.587678] raopcl_connect:996 [0x7fac01e390]: local interface [Main Network IP] [13:15:04.589192] exec_request:614 [0x7fac022730]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 1 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [13:15:04.624763] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:04.625156] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:04 GMT [13:15:04.625362] exec_request:650 [0x7fac022730]: <------ : Content-Length: 96 [13:15:04.625736] exec_request:650 [0x7fac022730]: <------ : Content-Type: application/octet-stream [13:15:04.625987] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:04.626093] exec_request:650 [0x7fac022730]: <------ : CSeq: 1 [13:15:04.626143] exec_request:691 [0x7fac022730]: Body data len 96 0000 2f 46 50 f0 7f db c4 fb 52 7f 78 b2 4b 6b 90 0f /FP R x Kk 0010 10 d8 b5 87 85 3c 5f f3 94 66 3f 25 d1 ac 4f 41 <_ f?% OA 0020 73 8e 5d ee c8 8b 9b 47 39 30 70 e3 fb 9b 94 5f s ] G90p _ 0030 b7 98 06 c2 f7 2c 36 07 77 c9 f4 ea a6 e1 d9 5c ,6 w \ 0040 05 69 69 0d bb cb 6d 1c 5a ca f8 07 09 a8 c2 7c ii m Z | 0050 eb 90 95 1d 05 15 3f e5 9f 6e fb 8f c2 a4 3d 6c ? n =l [13:15:04.631930] exec_request:614 [0x7fac022730]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 2 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 [13:15:04.637773] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:04.638126] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:04 GMT [13:15:04.638318] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:04.638689] exec_request:650 [0x7fac022730]: <------ : Content-Type: application/octet-stream [13:15:04.638940] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:04.639045] exec_request:650 [0x7fac022730]: <------ : CSeq: 2 [13:15:04.639328] exec_request:614 [0x7fac022730]: ----> : write ANNOUNCE rtsp://[Main Network IP]/2602457379 RTSP/1.0 Content-Type: application/sdp Content-Length: 178 CSeq: 3 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 v=0 o=iTunes 2602457379 0 IN IP4 [Main Network IP] s=iTunes c=IN IP4 [Main Network IP] t=0 0 m=audio 0 RTP/AVP 96 a=rtpmap:96 AppleLossless a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100 I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/7465722788965f5b73e6c64d3903792096ccc818?1691514904_oPFBvoySKqjTVGwzsrQ2yLkp34vQiH60MvB1Xs1vhrI= D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: In Return I TrackQueue.cpp:159: Track duration: 594616 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 [13:15:04.846989] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:04.847372] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:04 GMT [13:15:04.847567] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:04.847820] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:04.847925] exec_request:650 [0x7fac022730]: <------ : CSeq: 3 [13:15:04.848080] exec_request:614 [0x7fac022730]: ----> : write SETUP rtsp://[Main Network IP]/2602457379 RTSP/1.0 Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=60372;timing_port=54885 CSeq: 4 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... [13:15:04.891597] _rtp_timing_thread:1296 [0x7fac01e390]: NTP remote port: 56165 [13:15:04.891870] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428504.3830359208 (ref 2208988800.3783849365) [13:15:04.895845] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428504.3847509013 (ref 1691428504.3842292941) [13:15:05.000523] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428505.2040109 (ref 1691428504.4291510908) I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/4ba5ee905ca0b60e474d52f09028ed6037050098?1691514905_xzq96oZoj_Ps6iO4CU1aYDQDgEkaR-j0O56xVKO8NYM= [13:15:05.184812] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:05.185781] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:05 GMT [13:15:05.186267] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:05.188389] exec_request:650 [0x7fac022730]: <------ : Transport: RTP/AVP/UDP;unicast;mode=record;server_port=53956;control_port=50271;timing_port=0 [13:15:05.188717] exec_request:650 [0x7fac022730]: <------ : Session: 1 [13:15:05.189452] exec_request:650 [0x7fac022730]: <------ : Audio-Jack-Status: connected [13:15:05.190082] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:05.190341] exec_request:650 [0x7fac022730]: <------ : CSeq: 4 [13:15:05.190458] rtspcl_setup:239 [0x7fac022730]: <------ : session:1 [13:15:05.190529] raopcl_analyse_setup:943 [0x7fac01e390]: missing timing port, will get it later [13:15:05.190591] raopcl_connect:1058 [0x7fac01e390]:opened audio socket l:35202 r:53956 [13:15:05.190649] raopcl_connect:1059 [0x7fac01e390]:opened timing socket l:54885 r:0 [13:15:05.190707] raopcl_connect:1060 [0x7fac01e390]:opened control socket l:60372 r:50271 [13:15:05.190867] exec_request:614 [0x7fac022730]: ----> : write RECORD rtsp://[Main Network IP]/2602457379 RTSP/1.0 Range: npt=0- RTP-Info: seq=18548;rtptime=1300049280 CSeq: 5 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:15:05.210165] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:05.211056] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:05 GMT [13:15:05.211535] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:05.212056] exec_request:650 [0x7fac022730]: <------ : Audio-Latency: 3579 [13:15:05.212682] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:05.212942] exec_request:650 [0x7fac022730]: <------ : CSeq: 5 [13:15:05.213439] raopcl_connect:1080 [0x7fac01e390]: setting volume as part of connect -30.00 [13:15:05.213627] exec_request:614 [0x7fac022730]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/2602457379 RTSP/1.0 Content-Type: text/parameters Content-Length: 20 CSeq: 6 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 volume: -30.000000 [13:15:05.256535] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:05.257316] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:05 GMT [13:15:05.257730] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:05.258265] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:05.258488] exec_request:650 [0x7fac022730]: <------ : CSeq: 6 D MercurySession.cpp:251: Executing Mercury Request, type SEND [13:15:05.259128] shadowRequest:223 [0xa57780]: spotify PLAY request I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackPlayer.cpp:200: Playing I spotify.cpp:133: trackUniqueId update => 130cc877ebef270ce112533c47e2deff46f661e9 [13:15:05.478029] raopcl_accept_frames:416 [0x7fac01e390]: begining to stream hts:0 n:1691428505.2053093151 [13:15:05.478453] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428505.2052980736 (ts:74591997091580) [13:15:05.478766] raopcl_accept_frames:424 [0x7fac01e390]: restarting w/o pause n:1691428505.2053093151, hts:74591997091580 [13:15:06.214624] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428506.774832128 (ts:74591997122556) D MercurySession.cpp:251: Executing Mercury Request, type SEND I spotify.cpp:249: Got next track id 9c73f95466564438a4eb25ddd631daf4 => [13:15:06.586895] exec_request:614 [0x7fac022730]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/2602457379 RTSP/1.0 RTP-Info: rtptime=1300110524 Content-Type: application/x-dmap-tagged Content-Length: 86 CSeq: 7 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 mlit [13:15:06.590234] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:06.591295] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:06 GMT [13:15:06.591932] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:06.592655] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:06.593006] exec_request:650 [0x7fac022730]: <------ : CSeq: 7 I spotify.cpp:169: Setting track position 5790 / 239018 [13:15:06.636462] exec_request:614 [0x7fac022730]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/2602457379 RTSP/1.0 Content-Type: text/parameters Content-Length: 44 CSeq: 8 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 progress: 1299857676/1300113014/1310398369 [13:15:06.645624] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:06.646617] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:06 GMT [13:15:06.647169] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:06.647871] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:06.648192] exec_request:650 [0x7fac022730]: <------ : CSeq: 8 D MercurySession.cpp:251: Executing Mercury Request, type SEND [13:15:06.717528] exec_request:614 [0x7fac022730]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/2602457379 RTSP/1.0 RTP-Info: rtptime=1300115804 Content-Type: image/jpeg Content-Length: 9869 CSeq: 9 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 ���� [13:15:06.722282] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:06.722962] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:06 GMT [13:15:06.723330] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:06.723808] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:06.724288] exec_request:650 [0x7fac022730]: <------ : CSeq: 9 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [13:15:07.216152] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428507.730791936 (ts:74591997166204) [13:15:08.009994] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428508.42726334 (ref 1691428508.36586704) [13:15:08.217275] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428508.926744576 (ts:74591997212316) [13:15:08.778292] raopcl_send_chunk:588 [0x7fac01e390]: check n:3506361450 p:3506362672 ts:74591997236252 sn:18958 retr: 0, avail: 0, send: 0, select: 0) [13:15:09.217921] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428509.916979712 (ts:74591997256316) [13:15:10.219066] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428510.770113536 (ts:74591997298908) [13:15:10.972905] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428510.4178440538 (ref 1691428510.4171898649) [13:15:11.220197] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428511.760414208 (ts:74591997342908) [13:15:12.221402] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428512.750649344 (ts:74591997386908) [13:15:13.222659] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428513.809500672 (ts:74591997431612) [13:15:13.458069] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428513.1967120791 (ref 1691428513.1960973135) [13:15:13.714756] _rtp_control_thread:1430 [0x7fac01e390]: retransmit packet sn:19575 nb:1 (mis:0) [13:15:14.715894] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428514.2959474688 (ts:74591997497788) [13:15:15.717027] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428515.3052601344 (ts:74591997542844) [13:15:15.962428] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428515.4133446460 (ref 1691428515.4128280060) [13:15:16.718172] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428516.3042836480 (ts:74591997586844) [13:15:17.719307] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428517.3033137152 (ts:74591997630844) [13:15:18.036497] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428518.156478543 (ref 1691428518.151331095) D spotify.cpp:423: keepAlive Sunroom Apple TV [13:15:18.426468] exec_request:614 [0x7fac022730]: ----> : write OPTIONS * RTSP/1.0 CSeq: 10 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:15:18.450250] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:18.451019] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:18 GMT [13:15:18.451431] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:18.453711] exec_request:650 [0x7fac022730]: <------ : Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET, PUT [13:15:18.454266] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:18.454508] exec_request:650 [0x7fac022730]: <------ : CSeq: 10 [13:15:18.720467] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428518.3023372288 (ts:74591997674844) [13:15:18.761404] raopcl_send_chunk:588 [0x7fac01e390]: check n:3506371433 p:3506372673 ts:74591997677308 sn:20211 retr: 1, avail: 0, send: 0, select: 0) [13:15:19.721640] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428519.2945056768 (ts:74591997718140) [13:15:20.722782] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428520.2901082112 (ts:74591997761788) [13:15:21.011078] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428521.47317654 (ref 1691428521.42946296) [13:15:21.723908] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428521.2891317248 (ts:74591997805788) [13:15:22.725039] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428522.3052994560 (ts:74591997851548) [13:15:23.130629] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428523.560785289 (ref 1691428523.555913445) [13:15:23.726231] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428523.3077570560 (ts:74591997895900) [13:15:24.727460] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428524.3033530368 (ts:74591997939548) [13:15:25.239686] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428525.1029280322 (ref 1691428525.1023659670) [13:15:25.728728] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428525.3058040832 (ts:74591997983900) [13:15:26.729717] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428526.3048341504 (ts:74591998027900) [13:15:27.608263] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428527.2612332253 (ref 1691428527.2606989372) [13:15:27.730883] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428527.3004301312 (ts:74591998071548) [13:15:28.732032] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428528.3097427968 (ts:74591998116604) [13:15:28.777539] raopcl_send_chunk:588 [0x7fac01e390]: check n:3506381449 p:3506382675 ts:74591998118364 sn:21464 retr: 1, avail: 0, send: 0, select: 0) [13:15:29.733193] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428529.3087663104 (ts:74591998160604) [13:15:29.938598] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428529.4031101685 (ref 1691428529.4026126556) [13:15:30.734435] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428530.2940796928 (ts:74591998203196) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame [13:15:31.735635] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428531.2965372928 (ts:74591998247548) [13:15:32.160421] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428532.688861214 (ref 1691428532.683885986) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:129: Another player took control, pausing playback I TrackPlayer.cpp:94: Resetting state I TrackPlayer.cpp:249: Playing done I spotify.cpp:104: Disconnecting Sunroom Apple TV I MercurySession.cpp:42: Received packet, command: 181 [13:15:33.161731] exec_request:614 [0x7fac022730]: ----> : write FLUSH rtsp://[Main Network IP]/2602457379 RTSP/1.0 RTP-Info: seq=21915;rtptime=1301247133 CSeq: 11 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:15:33.165274] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:33.165628] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:33 GMT [13:15:33.165820] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:33.166107] exec_request:650 [0x7fac022730]: <------ : RTP-Info: rtptime=1301232700 [13:15:33.166356] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:33.166469] exec_request:650 [0x7fac022730]: <------ : CSeq: 11 [13:15:33.166546] exec_request:614 [0x7fac022730]: ----> : write TEARDOWN rtsp://[Main Network IP]/2602457379 RTSP/1.0 CSeq: 12 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 6de9227948e7bdf8 DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:15:33.967060] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:33.967484] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:33 GMT [13:15:33.967708] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:33.967989] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:33.968126] exec_request:650 [0x7fac022730]: <------ : CSeq: 12 D spotify.cpp:423: keepAlive Sunroom Apple TV I TrackPlayer.cpp:94: Resetting state I MercurySession.cpp:128: Disconnecting mercury session I PlainConnection.cpp:197: Closing socket... E PlainConnection.cpp:146: Connection lost, will need to reconnect... E MercurySession.cpp:53: Error while receiving packet: Reconnection required I spotify.cpp:448: disconnecting player Sunroom Apple TV I spotify.cpp:388: Spotify client connected for Sunroom Apple TV D Session.cpp:63: Connecting with AP D PlainConnection.cpp:101: Connected to spotify server I Session.cpp:39: Received APHello response D Session.cpp:44: Received shannon keys D Session.cpp:82: Authorization successful I MercurySession.cpp:42: Received packet, command: 4 D TimeProvider.cpp:15: Time synced with spotify servers I MercurySession.cpp:42: Received packet, command: 2 D MercurySession.cpp:251: Executing Mercury Request, type SUB D spotify.cpp:423: keepAlive Sunroom Apple TV I MercurySession.cpp:42: Received packet, command: 118 I MercurySession.cpp:42: Received packet, command: 27 D MercurySession.cpp:153: Received country code US I MercurySession.cpp:42: Received packet, command: 80 I MercurySession.cpp:42: Received packet, command: 31 I MercurySession.cpp:42: Received packet, command: 105 I MercurySession.cpp:42: Received packet, command: 181 I AccessKeyFetcher.cpp:99: Access token expired, fetching new one... 237 I MercurySession.cpp:42: Received packet, command: 74 I MercurySession.cpp:42: Received packet, command: 179 D MercurySession.cpp:174: Received mercury packet D MercurySession.cpp:251: Executing Mercury Request, type SEND D SpircHandler.cpp:59: Sent kMessageTypeHello! I AccessKeyFetcher.cpp:114: Access token sucessfully fetched I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D I MercurySession.cppSpircHandler.cpp:124: Notify frame :42: D SpircHandler.cpp:67: Received packet, command: 181 Received subscription response D SpircHandler.cppI :124: Notify frame MercurySession.cppD SpircHandler.cpp:42: Received packet, command: 178 :67: Received subscription response D SpircHandler.cpp:124: Notify frame D MercurySession.cpp:174: Received mercury packet I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:170: Load frame 9! D MercurySession.cpp:251: Executing Mercury Request, type SEND I TrackPlayer.cpp:94: Resetting state D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: House of Light I TrackQueue.cpp:159: Track duration: 239018 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 181 I MercurySession.cpp:42: Received packet, command: 13 I MercurySession.cpp:42: Received packet, command: 178 I TrackQueue.cpp:252: Got audio key D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/130cc877ebef270ce112533c47e2deff46f661e9?1691514941_RfmIVJuyO6hz6sqlAqslvxwnhJJYW4jWthVDlugKxhg= I TrackPlayer.cpp:167: Got track ID=130cc877ebef270ce112533c47e2deff46f661e9 I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-fa.scdn.co/audio/130cc877ebef270ce112533c47e2deff46f661e9?1691514941_RfmIVJuyO6hz6sqlAqslvxwnhJJYW4jWthVDlugKxhg= D MercurySession.cpp:251: Executing Mercury Request, type GET I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: Hearken I TrackQueue.cpp:159: Track duration: 299870 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I CDNAudioFile.cpp:70: Header and footer bytes received D MercurySession.cpp:251: Executing Mercury Request, type SEND I spotify.cpp:235: new track will start at 5790 [13:15:41.960243] shadowRequest:219 [0xa57780]: spotify LOAD request [13:15:42.064962] raopcl_connect:996 [0x7fac01e390]: local interface [Main Network IP] [13:15:42.068016] exec_request:614 [0x7fac022730]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 13 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [13:15:42.100131] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:42.100916] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:42 GMT [13:15:42.101404] exec_request:650 [0x7fac022730]: <------ : Content-Length: 96 [13:15:42.102227] exec_request:650 [0x7fac022730]: <------ : Content-Type: application/octet-stream [13:15:42.102786] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:42.103090] exec_request:650 [0x7fac022730]: <------ : CSeq: 13 [13:15:42.103200] exec_request:691 [0x7fac022730]: Body data len 96 0000 07 e9 b7 97 2f 34 bd 01 1b 6c 9a 14 49 13 fe 43 /4 l I C 0010 ee b1 ef a4 d6 9c 30 95 03 38 07 25 4d 6b 4f 5d 0 8 %MkO] 0020 54 58 8e ac 18 05 d2 4c 20 3a fe b6 31 03 62 92 TX L : 1 b 0030 05 a6 a0 f2 d9 98 ab 43 c3 db 4d d1 71 63 a1 ad C M qc 0040 b0 52 c0 f0 f5 9d 26 f6 31 da f7 46 b1 87 72 20 R & 1 F r 0050 5c 47 59 80 aa c8 b4 3f c7 b8 1c ff 95 14 33 67 \GY ? 3g [13:15:42.116383] exec_request:614 [0x7fac022730]: ----> : write POST /pair-verify RTSP/1.0 Content-Type: application/octet-stream Content-Length: 68 CSeq: 14 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 [13:15:42.122240] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:42.123018] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:42 GMT [13:15:42.123452] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:42.124272] exec_request:650 [0x7fac022730]: <------ : Content-Type: application/octet-stream [13:15:42.124830] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:42.125120] exec_request:650 [0x7fac022730]: <------ : CSeq: 14 [13:15:42.125869] exec_request:614 [0x7fac022730]: ----> : write ANNOUNCE rtsp://[Main Network IP]/0027736414 RTSP/1.0 Content-Type: application/sdp Content-Length: 178 CSeq: 15 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 v=0 o=iTunes 0027736414 0 IN IP4 [Main Network IP] s=iTunes c=IN IP4 [Main Network IP] t=0 0 m=audio 0 RTP/AVP 96 a=rtpmap:96 AppleLossless a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100 I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/7465722788965f5b73e6c64d3903792096ccc818?1691514942_Hltu6Us2v0mnXu-l9dc5wgJjSBaiXTWIde-AymoaL6E= D MercurySession.cpp:251: Executing Mercury Request, type GET [13:15:42.303625] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:42.304016] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:42 GMT [13:15:42.304220] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:42.304483] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:42.304606] exec_request:650 [0x7fac022730]: <------ : CSeq: 15 [13:15:42.304778] exec_request:614 [0x7fac022730]: ----> : write SETUP rtsp://[Main Network IP]/0027736414 RTSP/1.0 Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=56679;timing_port=36115 CSeq: 16 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackQueue.cpp:158: Track name: In Return I TrackQueue.cpp:159: Track duration: 594616 D TrackQueue.cpp:161: trackInfo.restriction.size() = 1 D TrackQueue.cpp:212: File format: 2 D TrackQueue.cpp:212: File format: 1 D TrackQueue.cpp:212: File format: 0 [13:15:42.319322] _rtp_timing_thread:1296 [0x7fac01e390]: NTP remote port: 58411 [13:15:42.319460] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428542.1371859798 (ref 2208988800.1326808276) [13:15:42.326409] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428542.1401830080 (ref 1691428542.1398071319) [13:15:42.328616] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428542.1411321958 (ref 1691428542.1406790461) I MercurySession.cpp:42: Received packet, command: 13 I TrackQueue.cpp:252: Got audio key I TrackQueue.cpp:275: Received access key, fetching CDN URL... I TrackQueue.cpp:301: Received CDN URL, https://audio-fa.scdn.co/audio/4ba5ee905ca0b60e474d52f09028ed6037050098?1691514942_OhsPKnLajpZ5ZjlaPPhZRYL-ZTyi4ZVps7mxGs5d86M= [13:15:42.824455] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:42.824868] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:42 GMT [13:15:42.825094] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:42.825960] exec_request:650 [0x7fac022730]: <------ : Transport: RTP/AVP/UDP;unicast;mode=record;server_port=53507;control_port=50725;timing_port=0 [13:15:42.826104] exec_request:650 [0x7fac022730]: <------ : Session: 1 [13:15:42.826401] exec_request:650 [0x7fac022730]: <------ : Audio-Jack-Status: connected [13:15:42.826663] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:42.826786] exec_request:650 [0x7fac022730]: <------ : CSeq: 16 [13:15:42.826839] rtspcl_setup:239 [0x7fac022730]: <------ : session:1 [13:15:42.826868] raopcl_analyse_setup:943 [0x7fac01e390]: missing timing port, will get it later [13:15:42.826903] raopcl_connect:1058 [0x7fac01e390]:opened audio socket l:37324 r:53507 [13:15:42.826927] raopcl_connect:1059 [0x7fac01e390]:opened timing socket l:36115 r:0 [13:15:42.826962] raopcl_connect:1060 [0x7fac01e390]:opened control socket l:56679 r:50725 [13:15:42.827053] exec_request:614 [0x7fac022730]: ----> : write RECORD rtsp://[Main Network IP]/0027736414 RTSP/1.0 Range: npt=0- RTP-Info: seq=21915;rtptime=1301709037 CSeq: 17 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:15:42.842410] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:42.842780] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:42 GMT [13:15:42.842983] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:42.843202] exec_request:650 [0x7fac022730]: <------ : Audio-Latency: 3579 [13:15:42.843465] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:42.843588] exec_request:650 [0x7fac022730]: <------ : CSeq: 17 [13:15:42.843804] raopcl_connect:1080 [0x7fac01e390]: setting volume as part of connect -30.00 [13:15:42.843895] exec_request:614 [0x7fac022730]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/0027736414 RTSP/1.0 Content-Type: text/parameters Content-Length: 20 CSeq: 18 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 volume: -30.000000 [13:15:42.860772] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:42.861156] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:42 GMT [13:15:42.861362] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:42.861624] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:42.861746] exec_request:650 [0x7fac022730]: <------ : CSeq: 18 D MercurySession.cpp:251: Executing Mercury Request, type SEND [13:15:42.862160] shadowRequest:223 [0xa57780]: spotify PLAY request I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet I TrackPlayer.cpp:200: Playing I spotify.cpp:133: trackUniqueId update => 130cc877ebef270ce112533c47e2deff46f661e9 [13:15:43.082411] raopcl_send_chunk:519 [0x7fac01e390]: begining to stream (LATE) hts:74591998276764 n:1691428543.353939664 [13:15:43.082564] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428532.1515782144 (ts:74591998276764) [13:15:43.367212] raopcl_send_chunk:588 [0x7fac01e390]: check n:3506396039 p:3506392676 ts:74591998559420 sn:22717 retr: 0, avail: 0, send: 0, select: 0) [13:15:43.844886] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428543.3396993024 (ts:74591998781180) D MercurySession.cpp:251: Executing Mercury Request, type SEND I spotify.cpp:249: Got next track id 9c73f95466564438a4eb25ddd631daf4 => [13:15:44.196703] exec_request:614 [0x7fac022730]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/0027736414 RTSP/1.0 RTP-Info: rtptime=1301768444 Content-Type: application/x-dmap-tagged Content-Length: 86 CSeq: 19 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 mlit [13:15:44.202083] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:44.202475] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:44 GMT [13:15:44.202702] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:44.202989] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:44.203136] exec_request:650 [0x7fac022730]: <------ : CSeq: 19 I spotify.cpp:169: Setting track position 39466 / 239018 [13:15:44.231771] exec_request:614 [0x7fac022730]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/0027736414 RTSP/1.0 Content-Type: text/parameters Content-Length: 44 CSeq: 20 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 progress: 1300030534/1301770984/1310571227 [13:15:44.247090] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:44.247490] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:44 GMT [13:15:44.247707] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:44.247983] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:44.248121] exec_request:650 [0x7fac022730]: <------ : CSeq: 20 D MercurySession.cpp:251: Executing Mercury Request, type SEND [13:15:44.311850] exec_request:614 [0x7fac022730]: ----> : write SET_PARAMETER rtsp://[Main Network IP]/0027736414 RTSP/1.0 RTP-Info: rtptime=1301773724 Content-Type: image/jpeg Content-Length: 9869 CSeq: 21 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 ���� [13:15:44.315672] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:44.316031] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:44 GMT [13:15:44.316226] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:44.316481] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:44.316596] exec_request:650 [0x7fac022730]: <------ : CSeq: 21 I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [13:15:44.362105] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428544.1555121758 (ref 1691428544.1551198568) I MercurySession.cpp:42: Received packet, command: 178 D MercurySession.cpp:174: Received mercury packet [13:15:44.846051] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428544.3455778816 (ts:74591998825884) [13:15:45.847184] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428545.3480354816 (ts:74591998870236) [13:15:46.848318] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428546.3470589952 (ts:74591998914236) [13:15:47.234485] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428547.1006877773 (ref 1691428547.999965107) [13:15:47.849510] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428547.3563716608 (ts:74591998959292) [13:15:48.804572] raopcl_send_chunk:588 [0x7fac01e390]: check n:3506401476 p:3506402677 ts:74591999000476 sn:23970 retr: 0, avail: 0, send: 0, select: 0) [13:15:48.850719] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428548.3451125760 (ts:74591999002236) [13:15:49.796435] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428549.3420559199 (ref 1691428549.3417187904) [13:15:49.851832] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428549.3441426432 (ts:74591999046236) [13:15:50.853115] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428550.3637379072 (ts:74591999092348) [13:15:51.854446] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428551.3627614208 (ts:74591999136348) [13:15:52.303301] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428552.1302547616 (ref 1691428552.1298504905) [13:15:52.855776] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428552.3583574016 (ts:74591999179996) [13:15:53.857177] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428553.3539533824 (ts:74591999223644) [13:15:54.828677] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428554.3559037534 (ref 1691428554.3555333665) [13:15:54.858759] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428554.3529834496 (ts:74591999267644) D spotify.cpp:423: keepAlive Sunroom Apple TV [13:15:55.792325] exec_request:614 [0x7fac022730]: ----> : write OPTIONS * RTSP/1.0 CSeq: 22 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:15:55.796613] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:15:55.796971] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:15:55 GMT [13:15:55.797191] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:15:55.798211] exec_request:650 [0x7fac022730]: <------ : Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET, PUT [13:15:55.798480] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:15:55.798604] exec_request:650 [0x7fac022730]: <------ : CSeq: 22 [13:15:55.860001] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428555.3520069632 (ts:74591999311644) [13:15:56.838175] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428556.3599826839 (ref 1691428556.3595295522) [13:15:56.861128] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428556.3476094976 (ts:74591999355292) [13:15:57.862212] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428557.3569156096 (ts:74591999400348) [13:15:58.784379] raopcl_send_chunk:588 [0x7fac01e390]: check n:3506411456 p:3506412678 ts:74591999441532 sn:25223 retr: 0, avail: 0, send: 0, select: 0) [13:15:58.863337] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428558.3559456768 (ts:74591999444348) [13:15:59.520255] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428559.2234117433 (ref 1691428559.2230162189) [13:15:59.864497] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428559.3652517888 (ts:74591999489404) [13:16:00.865686] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428560.3677093888 (ts:74591999533756) [13:16:01.811201] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428561.3483982981 (ref 1691428561.3481225773) [13:16:01.866817] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428561.3667329024 (ts:74591999577756) [13:16:02.867947] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428562.3520462848 (ts:74591999620348) [13:16:03.869104] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428563.3510763520 (ts:74591999664348) [13:16:04.001788] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428564.7584912 (ref 1691428564.4965042) [13:16:04.870225] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428564.3706716160 (ts:74591999710460) [13:16:05.871430] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428565.3594125312 (ts:74591999753404) [13:16:06.046069] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428566.197740294 (ref 1691428566.195375883) [13:16:06.872632] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428566.3721461760 (ts:74591999798812) [13:16:07.873543] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428567.3574595584 (ts:74591999841404) [13:16:08.148049] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428568.635758239 (ref 1691428568.633704227) [13:16:08.779289] raopcl_send_chunk:588 [0x7fac01e390]: check n:3506421451 p:3506422672 ts:74591999882236 sn:26475 retr: 0, avail: 0, send: 0, select: 0) [13:16:08.874677] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428568.3564896256 (ts:74591999885404) [13:16:09.875801] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428569.3555131392 (ts:74591999929404) D spotify.cpp:423: keepAlive Sunroom Apple TV [13:16:10.805298] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428570.3458616904 (ref 1691428570.3455004752) [13:16:10.805463] exec_request:614 [0x7fac022730]: ----> : write OPTIONS * RTSP/1.0 CSeq: 23 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:16:10.810766] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:16:10.811183] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:16:10 GMT [13:16:10.811415] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:16:10.812454] exec_request:650 [0x7fac022730]: <------ : Public: ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER, POST, GET, PUT [13:16:10.812744] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:16:10.812891] exec_request:650 [0x7fac022730]: <------ : CSeq: 23 [13:16:10.876922] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428570.3751084032 (ts:74591999975516) [13:16:11.878082] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428571.3707109376 (ts:74592000019164) [13:16:12.879294] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428572.3731619840 (ts:74592000063516) [13:16:13.567642] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428573.2437922221 (ref 1691428573.2432506566) [13:16:13.880453] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428573.3687579648 (ts:74592000107164) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame [13:16:14.881611] _raopcl_send_sync:1254 [0x7fac01e390]: sync ntp:1691428574.3677880320 (ts:74592000151164) I MercurySession.cpp:42: Received packet, command: 181 D SpircHandler.cpp:67: Received subscription response D SpircHandler.cpp:124: Notify frame D SpircHandler.cpp:129: Another player took control, pausing playback I TrackPlayer.cpp:94: Resetting state I TrackPlayer.cpp:249: Playing done I spotify.cpp:104: Disconnecting Sunroom Apple TV I MercurySession.cpp:42: Received packet, command: 181 [13:16:16.328088] _rtp_timing_thread:1328 [0x7fac01e390]: NTP sync: 1691428576.1408878122 (ref 1691428576.1405625383) [13:16:16.328352] exec_request:614 [0x7fac022730]: ----> : write FLUSH rtsp://[Main Network IP]/0027736414 RTSP/1.0 RTP-Info: seq=27342;rtptime=1303157437 CSeq: 24 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:16:16.333306] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:16:16.333715] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:16:16 GMT [13:16:16.333943] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:16:16.334265] exec_request:650 [0x7fac022730]: <------ : RTP-Info: rtptime=1303136668 [13:16:16.334549] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:16:16.334694] exec_request:650 [0x7fac022730]: <------ : CSeq: 24 [13:16:16.334806] exec_request:614 [0x7fac022730]: ----> : write TEARDOWN rtsp://[Main Network IP]/0027736414 RTSP/1.0 CSeq: 25 User-Agent: iTunes/7.6.2 (Windows; N;) Client-Instance: 9273d86d4cce6abf DACP-ID: 1A2B3D4EA1B2C3D4 Active-Remote: 1158605793 Session: 1 [13:16:17.063339] exec_request:640 [0x7fac022730]: <------ : 200: request ok [13:16:17.064233] exec_request:650 [0x7fac022730]: <------ : Date: Mon, 07 Aug 2023 17:16:17 GMT [13:16:17.064726] exec_request:650 [0x7fac022730]: <------ : Content-Length: 0 [13:16:17.065386] exec_request:650 [0x7fac022730]: <------ : Server: AirTunes/695.5.1 [13:16:17.065705] exec_request:650 [0x7fac022730]: <------ : CSeq: 25 I TrackPlayer.cpp:94: Resetting state I MercurySession.cpp:128: Disconnecting mercury session I PlainConnection.cpp:197: Closing socket... E PlainConnection.cpp:146: Connection lost, will need to reconnect... E MercurySession.cpp:53: Error while receiving packet: Reconnection required I spotify.cpp:448: disconnecting player Sunroom Apple TV exit [13:16:20.942922] main:1255 stopping cspot devices ... [13:16:20.943056] main:1257 stopping Raop devices ... [13:16:20.943119] Stop:929 terminate search thread ... [13:16:20.973489] Stop:938 flush renderers ... Segmentation fault ```
philippe44 commented 11 months ago

Just to be sure: volume setting can be missed sometimes from Spotify and although the UI says it's mid-level in fact it's muted, have you tried to change it after the connection has been made

nano9g commented 11 months ago

I will try that, but I'm doubtful it will help because when it's in this state, the Now Playing widget in the Apple TV Control Center shows "Not Playing" instead of displaying the track information.

nano9g commented 11 months ago

I just tested and you were right - it is playing, but the volume is at zero and needs to be increased. So that was a good catch!

I still think something isn't quite right though, since the first SpotRaop session with the ATV has metadata but subsequent ones don't.

philippe44 commented 11 months ago

I still think something isn't quite right though, since the first SpotRaop session with the ATV has metadata but subsequent ones don't.

Yes you're right. I've totally missed that up to now and it seems to be something in my core library. First session works but artwork is one track behind. Then the ATV seems to be in a state where is plays audio but does "realize" it, nor does it display any metadata

philippe44 commented 11 months ago

I really can't figure out what's happening there. I've even taken Wireshark logs and all are the same/similar to what iTunes does, So I have no idea...

philippe44 commented 11 months ago

I've changed timing of the artwork/metadata as it seems to bother ATV when the timestamps are too close to the present. It seems to work better on my ATVs. If artwork is desync or not displayed, it corrects after ~15 sec.

nano9g commented 11 months ago

I wish I could say that helped, but unfortunately the behavior remains the same for me. Just like before, the ATV displays metadata during the first post-ATV-reboot SpotRaop session, but every subsequent session the audio plays without metadata (often starting at zero volume). No matter how long I wait, no metadata appears.

Is there anything I can do to help troubleshoot further?

philippe44 commented 11 months ago

Well, I tried something I should have done in a long while: using the Spotify app from my iPhone to AirPlay directly to my ATV and the result is ... almost the same. Very often (but not all the time, it's true) the metadata is not refreshed after a disconnect/reconnect and stay stuck to either nothing or the last artwork and not title, album... It seems that there is more than my mistakes here, probably the continuation of Apple not caring much about AirPlay

nano9g commented 11 months ago

That's fascinating, because AirPlaying Spotify to my ATV from my iPhone shows metadata every time. I can disconnect and reconnect any number of times and it's rock solid.

I had been thinking the problem could be related to AirPlay 1 from SpotRaop versus AirPlay 2 from Apple devices, but if you're having a similar issue with AirPlay 2 then I'm at a loss.

philippe44 commented 11 months ago

Yep ... disheartening

philippe44 commented 11 months ago

In fact I double checked and also metadata fails sometimes from my iPhone, it mostly works you're right. I just had a couple of "bad luck" cases to start with. Now, I looked into it again because of your AP1 vs AP2 comment and this is the issue. iTunes for Windows still uses AP1 and here the problem happens very often as well. So it is probably an AP1 issue where Apple does not care anymore about it and maybe even cripples it to force people to upgrade ... nice but not unexpected.

BTW, when I mean cripples it, I don't mean that a developer has the task assigned to make it fail, there are more subtle that companies use like outsourcing an "update" or a "rewrite" to the cheapest and least experienced offshore house. And you get what you want with plausible deniability.

Anyway, I'm afraid that regardless, its going to be difficult to fix.

nano9g commented 9 months ago

Great! I’ll reopen if I see it again.