search

philippe44 / SpotConnect

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

Cannot play to Kodi's AirPlay implementation (OSMC/Arm) #33

Closed GioF71 closed 6 months ago

GioF71 commented 7 months ago

Hello, I am trying to use Kodi AirPlay as a Spotify Connect device, but it does not seem to work. Every time it gets stuck on "GetArtworkThread:322". Nothing shows on the screen. I have run this test with Docker stopped on a Pi4 box running OSMC. On the same box, with docker running, Kodi's own airplay disabled, I can use an instance of shairport-sync using docker perfectly.

Here is the log using Kodi's own AirPlay (again, docker service is stopped here):

spotconnect-airplay | [07:48:00.020] raopcl_connect:1003 [0x7ff7f80095b0]: local interface 192.168.1.173
spotconnect-airplay | [07:48:00.021] http_read_line:1038 disconnected on the other end 16
spotconnect-airplay | [07:48:00.021] exec_request:655 [0x7ff7f800d990]: response :  request failed
spotconnect-airplay | [07:48:01.022] shadowRequest:275 [0x64c160]: spotify VOLUME request -5.161364
spotconnect-airplay | [07:48:01.023] shadowRequest:275 [0x64c160]: spotify VOLUME request -0.968185
spotconnect-airplay | [07:48:01.024] shadowRequest:275 [0x64c160]: spotify VOLUME request -0.000000
spotconnect-airplay | [07:48:03.420] GetArtworkThread:322 got artwork for https://i.scdn.co/image/ab67616d00001e026b8d89248315d098fc864098
spotconnect-airplay | [07:48:04.899] mDNSsearchCallback:437 Updating configuration /config/raop-config.xml
spotconnect-airplay | [07:47:58.931] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:47:58.931] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:47:58.982] I TrackQueue.cpp:305: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/12db28a105c550349549edd47139bf6e6fd5abe4?__token__=exp=REDACTED
spotconnect-airplay | [07:47:59.886] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:47:59.886] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:47:59.887] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:47:59.918] I spotify.cpp:252: new track will start at 16785
spotconnect-airplay | [07:47:59.918] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:48:00.005] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:00.005] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:00.068] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:00.068] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:00.095] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:48:00.095] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:48:00.095] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:48:00.200] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:00.313] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:48:00.532] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:48:01.023] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:01.023] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:48:01.023] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:48:01.023] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:48:01.023] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:48:01.131] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:01.131] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:01.152] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:01.152] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:01.203] I TrackPlayer.cpp:206: Playing
spotconnect-airplay | [07:48:01.203] I spotify.cpp:145: trackUniqueId update  => ID_REDACTED
spotconnect-airplay | [07:48:03.356] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:48:03.356] I spotify.cpp:484: started track id 02b04b6836224be794a1e65531c4df2f => <Oh Woman Oh Man>
spotconnect-airplay | [07:48:03.471] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:03.471] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:18.502] D spotify.cpp:452: keepAlive KodiLivingPi4+
spotconnect-airplay | [07:48:20.840] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:48:20.840] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:48:20.840] D SpircHandler.cpp:179: Load frame 18!
spotconnect-airplay | [07:48:20.840] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:48:20.841] I TrackPlayer.cpp:98: Resetting state
spotconnect-airplay | [07:48:20.841] I TrackPlayer.cpp:255: Playing done
spotconnect-airplay | [07:48:20.903] D MercurySession.cpp:251: Executing Mercury Request, type GET
spotconnect-airplay | [07:48:20.931] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:21.224] shadowRequest:257 [0x64c160]: spotify LOAD request
spotconnect-airplay | [07:48:21.325] raopcl_connect:1003 [0x7ff7f80095b0]: local interface 192.168.1.173
spotconnect-airplay | [07:48:21.326] http_read_line:1038 disconnected on the other end 17
spotconnect-airplay | [07:48:21.326] exec_request:655 [0x7ff7f800d990]: response :  request failed
spotconnect-airplay | [07:48:20.931] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:20.931] I TrackQueue.cpp:162: Track name: Oh Woman Oh Man
spotconnect-airplay | [07:48:20.931] I TrackQueue.cpp:163: Track duration: 277613
spotconnect-airplay | [07:48:20.931] D TrackQueue.cpp:165: trackInfo.restriction.size() = 1
spotconnect-airplay | [07:48:20.931] D TrackQueue.cpp:216: File format: 2
spotconnect-airplay | [07:48:20.957] I MercurySession.cpp:42: Received packet, command: 13
spotconnect-airplay | [07:48:20.958] I TrackQueue.cpp:256: Got audio key
spotconnect-airplay | [07:48:20.958] I TrackQueue.cpp:279: Received access key, fetching CDN URL...
spotconnect-airplay | [07:48:21.091] I TrackQueue.cpp:305: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/ID_REDACTED?__token__=exp=REDACTED
spotconnect-airplay | [07:48:21.091] I TrackPlayer.cpp:171: Got track ID=ID_REDACTED
spotconnect-airplay | [07:48:21.091] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/ID_REDACTED?__token__=exp=REDACTED
spotconnect-airplay | [07:48:21.091] D MercurySession.cpp:251: Executing Mercury Request, type GET
spotconnect-airplay | [07:48:21.116] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:21.116] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:21.116] I TrackQueue.cpp:162: Track name: Hell To The Liars
spotconnect-airplay | [07:48:21.116] I TrackQueue.cpp:163: Track duration: 364506
spotconnect-airplay | [07:48:21.116] D TrackQueue.cpp:165: trackInfo.restriction.size() = 1
spotconnect-airplay | [07:48:21.117] D TrackQueue.cpp:216: File format: 2
spotconnect-airplay | [07:48:21.141] I MercurySession.cpp:42: Received packet, command: 13
spotconnect-airplay | [07:48:21.141] I TrackQueue.cpp:256: Got audio key
spotconnect-airplay | [07:48:21.141] I TrackQueue.cpp:279: Received access key, fetching CDN URL...
spotconnect-airplay | [07:48:21.223] I CDNAudioFile.cpp:70: Header and footer bytes received
spotconnect-airplay | [07:48:21.224] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:48:21.250] I TrackQueue.cpp:305: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/781ef0194b04caf14436cdcd670e42a424479ff5?__token__=exp=1702972101~hmac=01746021506d58d759c32bca1bd10875d05286073b10559ba0acc9a49df4e8a6
spotconnect-airplay | [07:48:21.351] D MercurySession.cpp:251: Executing Mercury Request, type GET
spotconnect-airplay | [07:48:21.375] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:21.375] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:21.375] I TrackQueue.cpp:162: Track name: Everyone Else
spotconnect-airplay | [07:48:21.375] I TrackQueue.cpp:163: Track duration: 245240
spotconnect-airplay | [07:48:21.375] D TrackQueue.cpp:165: trackInfo.restriction.size() = 1
spotconnect-airplay | [07:48:21.375] D TrackQueue.cpp:216: File format: 2
spotconnect-airplay | [07:48:21.403] I MercurySession.cpp:42: Received packet, command: 13
spotconnect-airplay | [07:48:21.403] I TrackQueue.cpp:256: Got audio key
spotconnect-airplay | [07:48:21.403] I TrackQueue.cpp:279: Received access key, fetching CDN URL...
spotconnect-airplay | [07:48:21.516] I TrackQueue.cpp:305: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/12db28a105c550349549edd47139bf6e6fd5abe4?__token__=exp=1702972101~hmac=d25a82c0b3adcce4215a6ec3904b640b6cbf25b68222f395a275f6791f4e7a68
spotconnect-airplay | [07:48:21.591] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:48:21.592] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:48:22.328] shadowRequest:261 [0x64c160]: spotify PLAY request
spotconnect-airplay | [07:48:22.430] raopcl_connect:1003 [0x7ff7f80095b0]: local interface 192.168.1.173
spotconnect-airplay | [07:48:22.431] http_read_line:1038 disconnected on the other end 16
spotconnect-airplay | [07:48:22.431] exec_request:655 [0x7ff7f800d990]: response :  request failed
spotconnect-airplay | [07:48:25.704] GetArtworkThread:322 got artwork for https://i.scdn.co/image/ab67616d00001e026b8d89248315d098fc864098

Thank you!

Edit: some details

GioF71 commented 7 months ago

It might be worth mentioning that if Docker is enabled on the box (but with shairport-sync stopped), I get this error loop instead:

spotconnect-airplay | [07:56:44.584] mDNSsearchCallback:394 [0x64c160]: changed ip:port 192.168.1.44:36666
spotconnect-airplay | [07:56:46.587] mDNSsearchCallback:394 [0x64cf00]: changed ip:port 172.19.0.1:5000
spotconnect-airplay | [07:56:46.587] mDNSsearchCallback:394 [0x64c160]: changed ip:port 172.19.0.1:36666
spotconnect-airplay | [07:56:46.588] mDNSsearchCallback:394 [0x64cf00]: changed ip:port 192.168.1.44:5000
spotconnect-airplay | [07:56:46.588] mDNSsearchCallback:394 [0x64c160]: changed ip:port 192.168.1.44:36666
spotconnect-airplay | [07:56:48.577] mDNSsearchCallback:394 [0x64cf00]: changed ip:port 172.19.0.1:5000
spotconnect-airplay | [07:56:48.577] mDNSsearchCallback:394 [0x64c160]: changed ip:port 172.19.0.1:36666

where 192.168.1.44 is the actual box ip and 172.19.0.1 is a docker network.

Thanks

GioF71 commented 7 months ago

Hello again, would like to mention that, in the docker/shairport scenario, despite perfect functionality, there are looping logs like the following:

spotconnect-airplay | [08:19:32.412] mDNSsearchCallback:394 [0x64c160]: changed ip:port 172.19.0.1:5000 spotconnect-airplay | [08:19:32.413] mDNSsearchCallback:394 [0x64c160]: changed ip:port 192.168.1.44:5000

supposedly related to docker networks.

Thank you

philippe44 commented 7 months ago

Usually, shairport-type (all AirPlay clones) require encryption to be enabled

GioF71 commented 7 months ago

So I understand AirPlay in kodi does not support encryption.

Anyway, I have been able to successfully stream Spotify to Kodi via SpotConnect over Kodi's UPnP/DLNA service. It's not the best, there is latency between tracks, I believe it's related to the fact that Kodi's UPnP service is not gapless (not even close). Other renderers (like upmpdcli) behave much better IMO. But at least it is possible to use Kodi as a Spotify Connect device, even if the solution in this case is a bit convoluted.

Thank you, again, for your great software!

GioF71 commented 7 months ago

Thinking again, the kodi solution I mentioned is not more convoluted than using SpotConnect on any other upnp device. It's just Kodi's UPnP that's slow and not gapless, that's all.

philippe44 commented 7 months ago

If you still want to try with AirPlay, I would need a more detailed log, with level = debug to better see where the AirPlay connection fails.

GioF71 commented 7 months ago

Ok I will try

philippe44 commented 7 months ago

Otherwise if gapless is the most important feature for you, you can try the "flow" mode. I've not tested it as much, but does solve that issue.

GioF71 commented 6 months ago

Hello, thank you for the suggestion. I enabled flow mode on the Kodi device, and gapless works. OTOH, I lose metadata and the latency, which was already high in non-flow mode with kodi, increases considerably. As I mentioned earlier, other upnp renderers like upmpdcli have a really small latency (I don't even notice) so the issue is totally kodi-related.

So mostly for the high latency than the missing metadata, I think I will probably rever to the non-flow mode, as this was just me exploring a fallback solution when a 'proper' stream is not available. Considering that I have PIs around all the house, this would happen only in the kitchen where I have a really cheap soundbar, so a small latency (with non-flow mode) and missing gapless would be totally fine.

Thank you for your support!

philippe44 commented 6 months ago

BTW, the latency issue is strange typically b/c it's usually a UPnP issue when the player wants to buffer a lot and expects that there will be a large inrush of data at the beginning. Of course, such in-rush does not happen if the source is airplay like my AirConnect application, but that's not the case here

GioF71 commented 6 months ago

Hello, thank you. I am about to try with debug enabled. Though I found something I don't understand in the help sections. For example this output is for raop with --help:

root@gruesome03:/app/bin# ./spotraop-linux --help
v0.8.5 (Dec 27 2023 @ 00:21:12)
See -t for license terms
Usage: [options]
  -b <ip>             network interface/IP address to bind to
  -a <port>[:<count>] set inbound port and range for RTP and HTTP
  -J <path>           path to Spotify credentials files
  -j                   store Spotify credentials in XML config file
  -U <user>           Spotify username
  -P <password>       Spotify password
  -L                  set AirPlay player password
  -c <alac|pcm>       audio format send to player (alac)
  -r <96|160|320>     set Spotify vorbis codec rate (160)
  -N <format>         transform device name using C format (%s=name)
  -x <config file>    read config from file (default is ./config.xml)
  -i <config file>    discover players, save <config file> and exit
  -I                  auto save config at every network scan
  -f <logfile>        write debug to logfile
  -l                  AppleTV pairing
  -p <pid file>       write PID in file
  -m <n1,n2...>       exclude devices whose model include tokens
  -n <m1,m2,...>      exclude devices whose name includes tokens
  -o <m1,m2,...>      include only listed models; overrides -m and -n (use <NULL> if player don't return a model)
  -d <log>=<level>    set logging level, logs: all|main|util|upnp, level: error|warn|info|debug|sdebug
  -z               daemonize
  -Z               NOT interactive
  -k               immediate exit on SIGQUIT and SIGTERM
  -t               license terms

Build options: LINUX

Is "upnp" correct as a log type in raop mode?

Also the "--help" switch doesn't seem to work on the "upnp" version, it seems that the program starts instead of displaying the help information.

GioF71 commented 6 months ago

Also when I run spotraop with "--help", it seems there is a mismatch with the version, it shows 0.8.5 while when running the version "0.8.6" is shown, am I doing something wrong?

GioF71 commented 6 months ago

Hello, here are the debug logs:

spotconnect-airplay | [07:58:16.971] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/3fb26d0282375bab7b0326f28d33d53057f251c6?__token__=exp=1704959896~hmac=one-redacted-hmac
spotconnect-airplay | [07:58:16.998] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:58:16.998] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:58:16.998] I TrackQueue.cpp:162: Track name: F For You
spotconnect-airplay | [07:58:16.998] I TrackQueue.cpp:163: Track duration: 268935
spotconnect-airplay | [07:58:16.999] D TrackQueue.cpp:165: trackInfo.restriction.size() = 1
spotconnect-airplay | [07:58:16.999] D TrackQueue.cpp:216: File format: 2
spotconnect-airplay | [07:58:17.026] I MercurySession.cpp:42: Received packet, command: 13
spotconnect-airplay | [07:58:17.026] I TrackQueue.cpp:256: Got audio key
spotconnect-airplay | [07:58:17.026] I TrackQueue.cpp:279: Received access key, fetching CDN URL...
spotconnect-airplay | [07:58:17.081] I CDNAudioFile.cpp:70: Header and footer bytes received
spotconnect-airplay | [07:58:17.081] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:58:17.142] I TrackQueue.cpp:305: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/e176a0c7a4ed368bf99812686b8e116f965bd636?__token__=exp=1704959897~hmac=two-redacted-hmac
spotconnect-airplay | [07:58:17.242] D MercurySession.cpp:251: Executing Mercury Request, type GET
spotconnect-airplay | [07:58:17.267] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:58:17.267] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:58:17.291] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:58:17.291] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:58:17.291] I TrackQueue.cpp:162: Track name: White Noise
spotconnect-airplay | [07:58:17.291] I TrackQueue.cpp:163: Track duration: 277687
spotconnect-airplay | [07:58:17.291] D TrackQueue.cpp:165: trackInfo.restriction.size() = 1
spotconnect-airplay | [07:58:17.291] D TrackQueue.cpp:216: File format: 2
spotconnect-airplay | [07:58:17.318] I MercurySession.cpp:42: Received packet, command: 13
spotconnect-airplay | [07:58:17.318] I TrackQueue.cpp:256: Got audio key
spotconnect-airplay | [07:58:17.319] I TrackQueue.cpp:279: Received access key, fetching CDN URL...
spotconnect-airplay | [07:58:17.429] I TrackQueue.cpp:305: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/f2c43d8e1410f850ecf64e6f57647c26e42b3342?__token__=exp=1704959897~hmac=another-redacted-hmac
spotconnect-airplay | [07:58:18.186] I spotify.cpp:252: new track will start at 23937
spotconnect-airplay | [07:58:18.186] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:58:18.353] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:58:18.354] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:58:19.507] I TrackPlayer.cpp:206: Playing
spotconnect-airplay | [07:58:19.507] I spotify.cpp:145: trackUniqueId update  => 3fb26d0282375bab7b0326f28d33d53057f251c6
spotconnect-airplay | [07:58:21.558] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:58:21.559] I spotify.cpp:484: started track id 8e806c09bd1e47728e094e2a27eb0b86 => <Latch>
spotconnect-airplay | [07:58:21.746] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:58:21.746] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:58:36.569] D spotify.cpp:452: keepAlive Xeon10 (Kodi) (AirPlay)
spotconnect-airplay | [07:58:51.596] D spotify.cpp:452: keepAlive Xeon10 (Kodi) (AirPlay)
spotconnect-airplay | [07:59:06.622] D spotify.cpp:452: keepAlive Xeon10 (Kodi) (AirPlay)
spotconnect-airplay | [07:59:07.387] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:59:07.388] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:59:07.388] D SpircHandler.cpp:132: Notify frame
spotconnect-airplay | [07:59:09.090] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:59:09.090] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:59:09.091] D SpircHandler.cpp:132: Notify frame
spotconnect-airplay | [07:59:09.091] D SpircHandler.cpp:137: Another player took control, pausing playback
spotconnect-airplay | [07:59:09.091] I TrackPlayer.cpp:98: Resetting state
spotconnect-airplay | [07:59:09.102] I TrackPlayer.cpp:255: Playing done
spotconnect-airplay | [07:59:09.102] I spotify.cpp:110: Disconnecting Xeon10 (Kodi) (AirPlay)
spotconnect-airplay | [07:59:09.143] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:59:10.444] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:59:10.444] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:59:10.444] D SpircHandler.cpp:132: Notify frame
spotconnect-airplay | [07:59:11.652] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:59:11.652] D SpircHandler.cpp:69: Received subscription response
spotconnect-airplay | [07:59:11.652] D SpircHandler.cpp:179: Load frame 18!
spotconnect-airplay | [07:59:11.652] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-airplay | [07:59:11.652] I TrackPlayer.cpp:98: Resetting state
spotconnect-airplay | [07:59:11.702] D MercurySession.cpp:251: Executing Mercury Request, type GET
spotconnect-airplay | [07:59:11.728] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:59:11.728] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:59:11.728] I TrackQueue.cpp:162: Track name: Latch
spotconnect-airplay | [07:59:11.728] I TrackQueue.cpp:163: Track duration: 255631
spotconnect-airplay | [07:59:11.728] D TrackQueue.cpp:165: trackInfo.restriction.size() = 1
spotconnect-airplay | [07:59:11.728] D TrackQueue.cpp:216: File format: 2
spotconnect-airplay | [07:59:11.751] I MercurySession.cpp:42: Received packet, command: 181
spotconnect-airplay | [07:59:11.775] I MercurySession.cpp:42: Received packet, command: 13
spotconnect-airplay | [07:59:11.775] I TrackQueue.cpp:256: Got audio key
spotconnect-airplay | [07:59:11.775] I TrackQueue.cpp:279: Received access key, fetching CDN URL...
spotconnect-airplay | [07:59:11.837] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:59:11.837] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:59:11.889] I TrackQueue.cpp:305: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/3fb26d0282375bab7b0326f28d33d53057f251c6?__token__=exp=1704959951~hmac=redacted-hmac
spotconnect-airplay | [07:59:11.890] I TrackPlayer.cpp:171: Got track ID=3fb26d0282375bab7b0326f28d33d53057f251c6
spotconnect-airplay | [07:59:11.890] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/3fb26d0282375bab7b0326f28d33d53057f251c6?__token__=exp=1704959951~hmac=redacted-hmac
spotconnect-airplay | [07:59:11.990] D MercurySession.cpp:251: Executing Mercury Request, type GET
spotconnect-airplay | [07:59:12.017] I MercurySession.cpp:42: Received packet, command: 178
spotconnect-airplay | [07:59:12.017] D MercurySession.cpp:174: Received mercury packet
spotconnect-airplay | [07:59:12.017] I TrackQueue.cpp:162: Track name: F For You
spotconnect-airplay | [07:59:12.017] I TrackQueue.cpp:163: Track duration: 268935
spotconnect-airplay | [07:59:12.017] D TrackQueue.cpp:165: trackInfo.restriction.size() = 1
spotconnect-airplay | [07:59:12.017] D TrackQueue.cpp:216: File format: 2
spotconnect-airplay | [07:59:12.044] I MercurySession.cpp:42: Received packet, command: 13
spotconnect-airplay | [07:59:12.072] shadowRequest:257 [0x64c160]: spotify LOAD request
spotconnect-airplay | [07:59:12.173] raopcl_connect:1003 [0x7f5d48009990]: local interface 192.168.1.173
spotconnect-airplay | [07:59:12.173] exec_request:645 [0x7f5d4800dd70]: ----> : write ANNOUNCE rtsp://192.168.1.8/2725955051 RTSP/1.0
spotconnect-airplay | Content-Type: application/sdp
spotconnect-airplay | Content-Length: 182
spotconnect-airplay | CSeq: 5
spotconnect-airplay | User-Agent: iTunes/7.6.2 (Windows; N;)
spotconnect-airplay | Client-Instance: 3bbad4b8db1e1fcb
spotconnect-airplay | DACP-ID: 1A2B3D4EA1B2C3D5
spotconnect-airplay | Active-Remote: 229073126
spotconnect-airplay | 
spotconnect-airplay | v=0
spotconnect-airplay | o=iTunes 2725955051 0 IN IP4 192.168.1.173
spotconnect-airplay | s=iTunes
spotconnect-airplay | c=IN IP4 192.168.1.8
spotconnect-airplay | t=0 0
spotconnect-airplay | m=audio 0 RTP/AVP 96
spotconnect-airplay | a=rtpmap:96 AppleLossless
spotconnect-airplay | a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100
spotconnect-airplay | 
spotconnect-airplay | [07:59:12.174] exec_request:666 [0x7f5d4800dd70]: <------ : 200: request ok
spotconnect-airplay | [07:59:12.174] exec_request:676 [0x7f5d4800dd70]: <------ : CSeq: 5
spotconnect-airplay | [07:59:12.174] exec_request:676 [0x7f5d4800dd70]: <------ : Apple-Jack-Status: connected; type=analog
spotconnect-airplay | [07:59:12.175] exec_request:645 [0x7f5d4800dd70]: ----> : write SETUP rtsp://192.168.1.8/2725955051 RTSP/1.0
spotconnect-airplay | Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=58772;timing_port=46222
spotconnect-airplay | CSeq: 6
spotconnect-airplay | User-Agent: iTunes/7.6.2 (Windows; N;)
spotconnect-airplay | Client-Instance: 3bbad4b8db1e1fcb
spotconnect-airplay | DACP-ID: 1A2B3D4EA1B2C3D5
spotconnect-airplay | Active-Remote: 229073126
spotconnect-airplay | 
spotconnect-airplay | 
spotconnect-airplay | [07:59:12.175] http_read_line:1101 disconnected on the other end 13
spotconnect-airplay | [07:59:12.175] exec_request:655 [0x7f5d4800dd70]: response :  request failed
spotconnect-airplay | [07:59:13.176] shadowRequest:261 [0x64c160]: spotify PLAY request
spotconnect-airplay | [07:59:13.277] raopcl_connect:1003 [0x7f5d48009990]: local interface 192.168.1.173
spotconnect-airplay | [07:59:13.277] exec_request:645 [0x7f5d4800dd70]: ----> : write ANNOUNCE rtsp://192.168.1.8/4278507504 RTSP/1.0
spotconnect-airplay | Content-Type: application/sdp
spotconnect-airplay | Content-Length: 182
spotconnect-airplay | CSeq: 7
spotconnect-airplay | User-Agent: iTunes/7.6.2 (Windows; N;)
spotconnect-airplay | Client-Instance: 18e4621b30baf0ee
spotconnect-airplay | DACP-ID: 1A2B3D4EA1B2C3D5
spotconnect-airplay | Active-Remote: 229073126
spotconnect-airplay | 
spotconnect-airplay | v=0
spotconnect-airplay | o=iTunes 4278507504 0 IN IP4 192.168.1.173
spotconnect-airplay | s=iTunes
spotconnect-airplay | c=IN IP4 192.168.1.8
spotconnect-airplay | t=0 0
spotconnect-airplay | m=audio 0 RTP/AVP 96
spotconnect-airplay | a=rtpmap:96 AppleLossless
spotconnect-airplay | a=fmtp:96 352 0 16 40 10 14 2 255 0 0 44100
spotconnect-airplay | 
spotconnect-airplay | [07:59:13.278] exec_request:666 [0x7f5d4800dd70]: <------ : 200: request ok
spotconnect-airplay | [07:59:13.278] exec_request:676 [0x7f5d4800dd70]: <------ : CSeq: 7
spotconnect-airplay | [07:59:13.278] exec_request:676 [0x7f5d4800dd70]: <------ : Apple-Jack-Status: connected; type=analog
spotconnect-airplay | [07:59:13.278] exec_request:645 [0x7f5d4800dd70]: ----> : write SETUP rtsp://192.168.1.8/4278507504 RTSP/1.0
spotconnect-airplay | Transport: RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=52669;timing_port=57964
spotconnect-airplay | CSeq: 8
spotconnect-airplay | User-Agent: iTunes/7.6.2 (Windows; N;)
spotconnect-airplay | Client-Instance: 18e4621b30baf0ee
spotconnect-airplay | DACP-ID: 1A2B3D4EA1B2C3D5
spotconnect-airplay | Active-Remote: 229073126
spotconnect-airplay | 
spotconnect-airplay | 
spotconnect-airplay | [07:59:13.278] http_read_line:1101 disconnected on the other end 12
spotconnect-airplay | [07:59:13.278] exec_request:655 [0x7f5d4800dd70]: response :  request failed
spotconnect-airplay | [07:59:16.816] GetArtworkThread:322 got artwork for https://i.scdn.co/image/ab67616d00001e02d3462d1395189dc76a326031
GioF71 commented 6 months ago

BTW, the latency issue is strange typically b/c it's usually a UPnP issue when the player wants to buffer a lot and expects that there will be a large inrush of data at the beginning. Of course, such in-rush does not happen if the source is airplay like my AirConnect application, but that's not the case here

Hello, yes but this latency only happens when using kodi's upnp service. With upmpdcli the latency is minimal!

philippe44 commented 6 months ago

I don't know what kodi is doing then. I could have a look with a SpotUPnP log.

philippe44 commented 6 months ago

Can you give me a kodi/AirPlay log with encryption enabled?

GioF71 commented 6 months ago

oh dear, it works with encryption enabled on kodi (enabled at device level), thank you! I suppose the logs are not needed then. There are the metadata and latency is very low. Sorry, I overlooked this aspect. I will try with upnp and debug logging enabled later today!

GioF71 commented 6 months ago

Hello, I tried again with upnp and debug log enabled. I was playing on "Kodi (Xeon10) (av)". I don't see anything special on the logs while kodi was displaying a "wait" cue. It seems kodi is just buffering too much as you were saying. The first song I played took 17 seconds to actually start playing.

spotconnect-upnp | [11:12:39.327] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-upnp | [11:12:39.328] I spotify.cpp:406: started track id de3b6a3bce4d40e8a7b9ea6a6fc4912c => <I Love You>
spotconnect-upnp | [11:12:39.328] D MercurySession.cpp:251: Executing Mercury Request, type SEND
spotconnect-upnp | [11:12:39.328] I spotify.cpp:485: track bbbb17f59396_2 started by URL (1)
spotconnect-upnp | [11:12:39.328] I spotify.cpp:438: adjusting real position 9000 from 0 (offset is 0)
spotconnect-upnp | [11:12:39.328] D MercurySession.cpp:251: Executing Mercury Re[11:12:39.863] UpdateThread:953 Updating configuration /config/upnp-config.xml
spotconnect-upnp | [11:12:40.002] UpdateThread:798 Presence checking
spotconnect-upnp | [11:12:40.475] UpdateThread:859 [0x7f5ac3f141d0] UPnP keep alive: Aune S6 (8x) (av)
spotconnect-upnp | [11:12:42.107] UpdateThread:859 [0x7f5ac3f0f010] UPnP keep alive: Kodi (Xeon10) (av)
spotconnect-upnp | [11:12:44.009] UpdateThread:859 [0x7f5ac3f0f010] UPnP keep alive: Kodi (Xeon10) (av)
spotconnect-upnp | [11:12:45.881] UpdateThread:859 [0x7f5ac3f118f0] UPnP keep alive: Aune S6 (Vanilla) (av)
spotconnect-upnp | [11:12:46.811] UpdateThread:859 [0x7f5ac3f118f0] UPnP keep alive: Aune S6 (Vanilla) (av)
spotconnect-upnp | [11:12:49.112] UpdateThread:859 [0x7f5ac3f141d0] UPnP keep alive: Aune S6 (8x) (av)
spotconnect-upnp | [11:12:54.763] UpdateThread:953 Updating configuration /config/upnp-config.xml
spotconnect-upnp | [11:13:04.820] UpdateThread:953 Updating configuration /config/upnp-config.xml
spotconnect-upnp | [11:13:05.297] UpdateThread:953 Updating configuration /config/upnp-config.xml
spotconnect-upnp | [11:13:07.280] UpdateThread:953 Updating configuration /config/upnp-config.xml
spotconnect-upnp | [11:13:10.006] UpdateThread:798 Presence checking
spotconnect-upnp | [11:13:10.108] UpdateThread:859 [0x7f5ac3f0f010] UPnP keep alive: Kodi (Xeon10) (av)
spotconnect-upnp | [11:13:11.008] UpdateThread:859 [0x7f5ac3f0f010] UPnP keep alive: Kodi (Xeon10) (av)
spotconnect-upnp | [11:13:11.033] UpdateThread:859 [0x7f5ac3f141d0] UPnP keep alive: Aune S6 (8x) (av)
GioF71 commented 6 months ago

Hello, I just want to confirm that this issue happens also when using kodi upnp as a player in LMS. Roughly I see the same delays, so I believe the issue has nothing to do with SpotConnect. Also the issue with AirPlay is solved (for who might read just one the latest post, we simply need to enable encryption for the specific device in the configuration file). So I think this can be closed, thank you for the support.

philippe44 commented 6 months ago

Still, LMS UPnP bridge and SpotConnect share a lot of common code as I'm the author of both.

GioF71 commented 6 months ago

Still, LMS UPnP bridge and SpotConnect share a lot of common code as I'm the author of both.

Yes, I knew that, and I must congratulate with you for your excellent works. In particular I am enjoying LMS UPnP bridge a lot more recently, especially when I noticed that it supports hires. Correct me if I am wrong, but I remember that some time ago that 16/44.1 was the limit. Not that I am able to hear the difference between the same master at different sampling rates but I try to avoid resampling to happen on my devices if it is possible.

About the specific issue with Kodi: I tested to stream a song from bubbleupnp player, using its own "Qobuz" source, to Kodi UPnP. It is definitely faster than from LMS (so using UPnP bridge). Like a few moments against more than ten seconds. So maybe something can be improved there... May I help you somehow, maybe performing some tests and collecting the relevant logs? If so, should we re-open this issue or open a new one?

Thank you again.