philippe44 / SpotConnect

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

Pressing pause takes around 30 seconds to be effective #25

Closed trilame closed 7 months ago

trilame commented 8 months ago

Hello, I'm running SpotConnect, on MacOS 13.5.1, simply with the command ./spotupnp-macos.

It correctly discovers locally my player. I then go to another device (an iPhone) to launch Spotify, choose the player (JBL OnBeat Air01D9BD+) and starts playing. If I choose another track, it changes instantly.

But if I press pause on the device controlling Spotify (in my example, the iPhone), on the iPhone screen the state of the button is pause, but the music keeps playing on the JBL OnBeat Air01D9BD+. I do nothing and wait, for about 30 seconds, and it eventually pauses the music. If I press play again, it starts again directly.

Below is a log of such scenario. I'm not sure what's wrong: I also tried with the credentials (./spotupnp-macos -x config.xml -j -I), but the result is the same.

[16:28:40.244] main:1546 Starting stopupnp version: v0.5.0 (Nov 10 2023 @ 17:47:24)
[16:28:40.246] Start:1259 Binding to iface en0@192.168.1.24:0
[16:28:40.247] Start:1273 Binding to 192.168.1.24:49152
[16:28:47.324] AddMRDevice:1185 [0x7fa7ec829000]: adding renderer (JBL OnBeat Air01D9BD) with mac BBBBBDD9015E
[16:28:47.330] MasterHandler:788 [0x7fa7ec829000]: subscribe success
[16:28:47.333] I BellHTTPServer.cpp:191: Server listening on port 0
[16:28:47.334] I spotify.cpp:556: ZeroConf mode (port 59393)
[16:28:47.341] ProcessEvent:515 [0x7fa7ec829000]: UPnP Volume local change 43:-1 (master)
[16:28:55.595] I spotify.cpp:599: Spotify client launched for JBL OnBeat Air01D9BD+
[16:28:55.643] D Session.cpp:67: Connecting with AP <ap-gew1.spotify.com:4070>
[16:28:55.651] D PlainConnection.cpp:101: Connected to spotify server
[16:28:55.666] I Session.cpp:43: Received APHello response
[16:28:55.676] D Session.cpp:48: Received shannon keys
[16:28:55.722] D Session.cpp:87: Authorization successful
[16:28:55.722] I MercurySession.cpp:42: Received packet, command: 4
[16:28:55.723] D TimeProvider.cpp:15: Time synced with spotify servers
[16:28:55.723] I MercurySession.cpp:42: Received packet, command: 2
[16:28:[55.723] I MercurySession.cpp:42: Received packet, command: 118
16:28:55.[723] D 16:MercurySession.cpp:251: 28:Executing Mercury Request, type SUB
55.723] I MercurySession.cpp:42: Received packet, command: 27
[16:28:55.723] D MercurySession.cpp:153: Received country code FR
[16:28:55.723] I MercurySession.cpp:42: Received packet, command: 80
[16:28:55.723] I MercurySession.cpp:42: Received packet, command: 31
[16:28:55.723] I MercurySession.cpp:42: Received packet, command: 105
[16:28:55.728] I MercurySession.cpp:42: Received packet, command: 181
[16:28:55.734] I MercurySession.cpp:42: Received packet, command: 74
[16:28:55.740] I MercurySession.cpp:42: Received packet, command: 179
[16:28:55.740] D MercurySession.cpp:174: Received mercury packet
[16:28:55.740] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:28:55.741] D SpircHandler.cpp:61: Sent kMessageTypeHello!
[16:28:55.800] I MercurySession.cpp:42: Received packet, command: 178
[16:28:55.800] D MercurySession.cpp:174: Received mercury packet
[16:28:55.805] I MercurySession.cpp:42: Received packet, command: 181
[16:28:55.806] I MercurySession.cpp:42: Received packet, command: 181
[16:28:55.806] D SpircHandler.cpp:69: Received subscription response
[16:28:55.806] D SpircHandler.cpp:132: Notify frame
[16:28:55.806] D SpircHandler.cpp:69: Received subscription response
[16:28:55.806] D SpircHandler.cpp:132: Notify frame
[16:28:55.827] I AccessKeyFetcher.cpp:99: Access token expired, fetching new one... 287
[16:28:55.889] I AccessKeyFetcher.cpp:114: Access token sucessfully fetched
[16:28:55.952] I MercurySession.cpp:42: Received packet, command: 181
[16:28:55.953] D SpircHandler.cpp:69: Received subscription response
[16:28:55.953] D SpircHandler.cpp:179: Load frame 50!
[16:28:55.953] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:28:55.953] I TrackPlayer.cpp:98: Resetting state
[16:28:55.990] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:28:55.998] I MercurySession.cpp:42: Received packet, command: 178
[16:28:55.998] D MercurySession.cpp:174: Received mercury packet
[16:28:55.998] I TrackQueue.cpp:158: Track name: Petit génie
[16:28:55.998] I TrackQueue.cpp:159: Track duration: 217259
[16:28:55.998] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:28:55.998] D TrackQueue.cpp:212: File format: 2
[16:28:55.998] D TrackQueue.cpp:212: File format: 1
[16:28:56.006] I MercurySession.cpp:42: Received packet, command: 13
[16:28:56.006] I TrackQueue.cpp:252: Got audio key
[16:28:56.006] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:28:56.046] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/
[16:28:56.054] I TrackPlayer.cpp:171: Got track ID=fdcf5375e92a6b8caa37d3f274d85cf3fb5cfcaf
[16:28:56.054] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:28:56.067] I MercurySession.cpp:42: Received packet, command: 178
[16:28:56.068] D MercurySession.cpp:174: Received mercury packet
[16:28:56.151] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:28:56.161] I MercurySession.cpp:42: Received packet, command: 178
[16:28:56.161] D MercurySession.cpp:174: Received mercury packet
[16:28:56.161] I TrackQueue.cpp:158: Track name: Si No Estás
[16:28:56.161] I TrackQueue.cpp:159: Track duration: 184061
[16:28:56.161] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:28:56.161] D TrackQueue.cpp:212: File format: 2
[16:28:56.161] D TrackQueue.cpp:212: File format: 1
[16:28:56.166] I CDNAudioFile.cpp:70: Header and footer bytes received
[16:28:56.166] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:28:56.167] shadowRequest:338 [0x7fa7ec829000]: Stop
[16:28:56.167] I spotify.cpp:300: new track will start at 12172
[16:28:56.168] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:28:56.168] I spotify.cpp:322: Play
[16:28:56.169] I MercurySession.cpp:42: Received packet, command: 13
[16:28:56.169] I TrackQueue.cpp:252: Got audio key
[16:28:56.169] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:28:56.210] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:28:56.261] I MercurySession.cpp:42: Received packet, command: 178
[16:28:56.261] D MercurySession.cpp:174: Received mercury packet
[16:28:56.280] I MercurySession.cpp:42: Received packet, command: 178
[16:28:56.280] D MercurySession.cpp:174: Received mercury packet
[16:28:56.311] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:28:56.314] I TrackPlayer.cpp:206: Playing
[16:28:56.314] I spotify.cpp:176: trackUniqueId update  => fdcf5375e92a6b8caa37d3f274d85cf3fb5cfcaf
[16:28:56.314] I spotify.cpp:245: new track id 287522acd0774c5eae9deacae0e6e7f0 => <Petit génie>
[16:28:56.315] I HTTPstreamer.cpp:134: Bound to port 59405
[16:28:56.315] I spotify.cpp:255: loading with id bbbb5e01d9bd_0
[16:28:56.315] shadowRequest:355 [0x7fa7ec829000]: spotify LOAD request
[16:28:56.315] AVTSetURI:77 [0x7fa7ec829000]: uPNP setURI http://192.168.1.24:59405/stream?id=bbbb5e01d9bd_0 (cookie 0x0)
[16:28:56.315] shadowRequest:369 [0x7fa7ec829000]: spotify play request
[16:28:56.315] AVTPlay:137 [0x7fa7ec829000]: uPNP play (cookie 0x1)
[16:28:56.319] I MercurySession.cpp:42: Received packet, command: 178
[16:28:56.319] D MercurySession.cpp:174: Received mercury packet
[16:28:56.319] I TrackQueue.cpp:158: Track name: LAISSE MOI
[16:28:56.319] I TrackQueue.cpp:159: Track duration: 168620
[16:28:56.319] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:28:56.319] D TrackQueue.cpp:212: File format: 2
[16:28:56.319] D TrackQueue.cpp:212: File format: 1
[16:28:56.327] I MercurySession.cpp:42: Received packet, command: 13
[16:28:56.327] I TrackQueue.cpp:252: Got audio key
[16:28:56.327] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:28:56.366] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:28:57.341] ActionHandler:595 [0x7fa7ec829000]: uPNP transition
[16:28:58.425] I MercurySession.cpp:42: Received packet, command: 181
[16:28:58.425] D SpircHandler.cpp:69: Received subscription response
[16:28:58.425] D SpircHandler.cpp:179: Load frame 50!
[16:28:58.425] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:28:58.427] I TrackPlayer.cpp:98: Resetting state
[16:28:58.438] I TrackPlayer.cpp:255: Playing done
[16:28:58.438] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:28:58.448] I MercurySession.cpp:42: Received packet, command: 178
[16:28:58.448] D MercurySession.cpp:174: Received mercury packet
[16:28:58.448] I TrackQueue.cpp:158: Track name: Dog Days Are Over
[16:28:58.448] I TrackQueue.cpp:159: Track duration: 252818
[16:28:58.448] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:28:58.448] D TrackQueue.cpp:212: File format: 2
[16:28:58.448] D TrackQueue.cpp:212: File format: 1
[16:28:58.459] I MercurySession.cpp:42: Received packet, command: 13
[16:28:58.459] I TrackQueue.cpp:252: Got audio key
[16:28:58.459] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:28:58.510] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:28:58.510] I TrackPlayer.cpp:171: Got track ID=10c5b543a879496d62e1d59db486696fed81fae5
[16:28:58.510] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:28:58.517] I MercurySession.cpp:42: Received packet, command: 178
[16:28:58.517] D MercurySession.cpp:174: Received mercury packet
[16:28:58.604] I CDNAudioFile.cpp:70: Header and footer bytes received
[16:28:58.605] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:28:58.606] shadowRequest:338 [0x7fa7ec829000]: Stop
[16:28:58.606] AVTStop:203 [0x7fa7ec829000]: uPNP stop (cookie 0x3)
[16:28:58.606] I spotify.cpp:300: new track will start at 0
[16:28:58.611] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:28:58.619] I MercurySession.cpp:42: Received packet, command: 178
[16:28:58.619] D MercurySession.cpp:174: Received mercury packet
[16:28:58.620] I TrackQueue.cpp:158: Track name: Heads Will Roll
[16:28:58.620] I TrackQueue.cpp:159: Track duration: 221000
[16:28:58.620] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:28:58.620] D TrackQueue.cpp:212: File format: 2
[16:28:58.620] D TrackQueue.cpp:212: File format: 1
[16:28:58.628] I MercurySession.cpp:42: Received packet, command: 13
[16:28:58.628] I TrackQueue.cpp:252: Got audio key
[16:28:58.628] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:28:58.644] I HTTPstreamer.cpp:147: HTTP streamer bbbb5e01d9bd_0 deleted
[16:28:58.645] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:28:58.645] I spotify.cpp:322: Play
[16:28:58.668] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:28:58.690] I MercurySession.cpp:42: Received packet, command: 178
[16:28:58.690] D MercurySession.cpp:174: Received mercury packet
[16:28:58.702] I TrackPlayer.cpp:206: Playing
[16:28:58.703] I spotify.cpp:176: trackUniqueId update  => 10c5b543a879496d62e1d59db486696fed81fae5
[16:28:58.703] I spotify.cpp:245: new track id 8622f5b4748e48739fe3a3459168e9d3 => <Dog Days Are Over>
[16:28:58.703] I HTTPstreamer.cpp:134: Bound to port 59414
[16:28:58.703] I spotify.cpp:255: loading with id bbbb5e01d9bd_1
[16:28:58.703] shadowRequest:355 [0x7fa7ec829000]: spotify LOAD request
[16:28:58.703] AVTSetURI:77 [0x7fa7ec829000]: uPNP setURI http://192.168.1.24:59414/stream?id=bbbb5e01d9bd_1 (cookie 0x4)
[16:28:58.704] shadowRequest:369 [0x7fa7ec829000]: spotify play request
[16:28:58.704] AVTPlay:137 [0x7fa7ec829000]: uPNP play (cookie 0x5)
[16:28:58.737] I MercurySession.cpp:42: Received packet, command: 178
[16:28:58.737] D MercurySession.cpp:174: Received mercury packet
[16:28:58.762] I HTTPstreamer.cpp:467: got HTTP connection 15
[16:28:58.762] I HTTPstreamer.cpp:210: HTTP received =>
GET /stream?id=bbbb5e01d9bd_1 HTTP/1.1
Host: 192.168.1.24:59414
Icy-MetaData: 1
Connection: close
transferMode.dlna.org: Streaming
User-Agent: WinampMPEG/2.8
Accept: */*

[16:28:58.763] I HTTPstreamer.cpp:327: HTTP response =>
HTTP/1.1 200 OK
transfermode.dlna.org: streaming
Server: spot-connect
Content-Type: audio/flac
Connection: close

[16:28:58.770] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:28:58.778] I MercurySession.cpp:42: Received packet, command: 178
[16:28:58.778] D MercurySession.cpp:174: Received mercury packet
[16:28:58.778] I TrackQueue.cpp:158: Track name: Ophelia
[16:28:58.778] I TrackQueue.cpp:159: Track duration: 160097
[16:28:58.778] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:28:58.778] D TrackQueue.cpp:212: File format: 2
[16:28:58.778] D TrackQueue.cpp:212: File format: 1
[16:28:58.786] I MercurySession.cpp:42: Received packet, command: 13
[16:28:58.786] I TrackQueue.cpp:252: Got audio key
[16:28:58.786] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:28:58.828] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:29:02.358] ActionHandler:595 [0x7fa7ec829000]: uPNP transition
[16:29:10.899] I MercurySession.cpp:42: Received packet, command: 181
[16:29:10.899] D SpircHandler.cpp:69: Received subscription response
[16:29:10.899] D SpircHandler.cpp:179: Load frame 50!
[16:29:10.899] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:29:10.901] I TrackPlayer.cpp:98: Resetting state
[16:29:10.906] I TrackPlayer.cpp:255: Playing done
[16:29:10.918] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:29:10.926] I MercurySession.cpp:42: Received packet, command: 178
[16:29:10.927] D MercurySession.cpp:174: Received mercury packet
[16:29:10.927] I TrackQueue.cpp:158: Track name: Heads Will Roll
[16:29:10.927] I TrackQueue.cpp:159: Track duration: 221000
[16:29:10.927] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:29:10.927] D TrackQueue.cpp:212: File format: 2
[16:29:10.927] D TrackQueue.cpp:212: File format: 1
[16:29:10.937] I MercurySession.cpp:42: Received packet, command: 13
[16:29:10.937] I TrackQueue.cpp:252: Got audio key
[16:29:10.937] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:29:10.982] I MercurySession.cpp:42: Received packet, command: 178
[16:29:10.982] D MercurySession.cpp:174: Received mercury packet
[16:29:10.991] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:29:10.991] I TrackPlayer.cpp:171: Got track ID=2af283208df96842d5563380f507fbca27cb951c
[16:29:10.991] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:29:11.094] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:29:11.102] I CDNAudioFile.cpp:70: Header and footer bytes received
[16:29:11.102] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:29:11.102] I MercurySession.cpp:42: Received packet, command: 178
[16:29:11.103] D MercurySession.cpp:174: Received mercury packet
[16:29:11.103] I TrackQueue.cpp:158: Track name: Ophelia
[16:29:11.103] I TrackQueue.cpp:159: Track duration: 160097
[16:29:11.103] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:29:11.103] D TrackQueue.cpp:212: File format: 2
[16:29:11.103] D TrackQueue.cpp:212: File format: 1
[16:29:11.104] shadowRequest:338 [0x7fa7ec829000]: Stop
[16:29:11.104] AVTStop:203 [0x7fa7ec829000]: uPNP stop (cookie 0x1e)
[16:29:11.104] I spotify.cpp:300: new track will start at 0
[16:29:11.111] I MercurySession.cpp:42: Received packet, command: 13
[16:29:11.111] I TrackQueue.cpp:252: Got audio key
[16:29:11.111] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:29:11.118] E HTTPstreamer.cpp:427: HTTP error 32 for bbbb5e01d9bd_1 => send 0 / 32768 (15)
[16:29:11.118] I HTTPstreamer.cpp:503: closing socket 15
[16:29:11.118] I HTTPstreamer.cpp:147: HTTP streamer bbbb5e01d9bd_1 deleted
[16:29:11.119] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:29:11.120] I spotify.cpp:322: Play
[16:29:11.150] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:29:11.176] I TrackPlayer.cpp:206: Playing
[16:29:11.177] I spotify.cpp:176: trackUniqueId update  => 2af283208df96842d5563380f507fbca27cb951c
[16:29:11.177] I spotify.cpp:245: new track id 60e8d6fd460748f6ab02d08b73bd84b2 => <Heads Will Roll>
[16:29:11.177] I HTTPstreamer.cpp:134: Bound to port 59448
[16:29:11.177] I spotify.cpp:255: loading with id bbbb5e01d9bd_2
[16:29:11.177] shadowRequest:355 [0x7fa7ec829000]: spotify LOAD request
[16:29:11.177] AVTSetURI:77 [0x7fa7ec829000]: uPNP setURI http://192.168.1.24:59448/stream?id=bbbb5e01d9bd_2 (cookie 0x1f)
[16:29:11.177] shadowRequest:369 [0x7fa7ec829000]: spotify play request
[16:29:11.177] AVTPlay:137 [0x7fa7ec829000]: uPNP play (cookie 0x20)
[16:29:11.197] I MercurySession.cpp:42: Received packet, command: 178
[16:29:11.197] D MercurySession.cpp:174: Received mercury packet
[16:29:11.213] I MercurySession.cpp:42: Received packet, command: 178
[16:29:11.213] D MercurySession.cpp:174: Received mercury packet
[16:29:11.233] I HTTPstreamer.cpp:467: got HTTP connection 15
[16:29:11.234] I HTTPstreamer.cpp:210: HTTP received =>
GET /stream?id=bbbb5e01d9bd_2 HTTP/1.1
Host: 192.168.1.24:59448
Icy-MetaData: 1
Connection: close
transferMode.dlna.org: Streaming
User-Agent: WinampMPEG/2.8
Accept: */*

[16:29:11.234] I HTTPstreamer.cpp:327: HTTP response =>
HTTP/1.1 200 OK
transfermode.dlna.org: streaming
Server: spot-connect
Content-Type: audio/flac
Connection: close

[16:29:11.253] D MercurySession.cpp:251: Executing Mercury Request, type GET
[16:29:11.260] I MercurySession.cpp:42: Received packet, command: 178
[16:29:11.260] D MercurySession.cpp:174: Received mercury packet
[16:29:11.260] I TrackQueue.cpp:158: Track name: Spectrum (Say My Name) - Calvin Harris Remix
[16:29:11.261] I TrackQueue.cpp:159: Track duration: 218190
[16:29:11.261] D TrackQueue.cpp:161: trackInfo.restriction.size() = 1
[16:29:11.261] D TrackQueue.cpp:212: File format: 2
[16:29:11.261] D TrackQueue.cpp:212: File format: 1
[16:29:11.268] I MercurySession.cpp:42: Received packet, command: 13
[16:29:11.268] I TrackQueue.cpp:252: Got audio key
[16:29:11.268] I TrackQueue.cpp:275: Received access key, fetching CDN URL...
[16:29:11.310] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/xxx
[16:29:11.450] ActionHandler:595 [0x7fa7ec829000]: uPNP transition
[16:29:15.313] I MercurySession.cpp:42: Received packet, command: 181
[16:29:15.313] D SpircHandler.cpp:69: Received subscription response
[16:29:15.313] D SpircHandler.cpp:285: External pause command
[16:29:15.314] D MercurySession.cpp:251: Executing Mercury Request, type SEND
[16:29:15.315] I spotify.cpp:322: Pause
[16:29:15.315] shadowRequest:378 [0x7fa7ec829000]: spotify pause request
[16:29:15.315] AVTBasic:187 [0x7fa7ec829000]: uPNP Pause (cookie 0x2b)
[16:29:15.399] I MercurySession.cpp:42: Received packet, command: 178
[16:29:15.399] D MercurySession.cpp:174: Received mercury packet

Also taking the opportunity to say thank you for all the work!

philippe44 commented 8 months ago

Thanks for the thank you 😄

Now, to your issue... well, UPnP is probably the biggest cluster f... you can ever see in term of standardization and lack of compliance and most company do whatever they do, especially device vendors who think that software happens magically (end of rant).

What you likely experience is something that I've seen a few times with faulty devices: UPnP uses HTTP to grab the audio data doing a classical "GET". Now, in HTTP if you know the content length of your file, you can put it in your answer, but it's optional and you might not know it. In fact, HTTP 1.1 has a special mode to handle unknown length (chunked-encoding). In my case, because I recode the audio, I don't know in advance the length so I'm silent about it.

Now, not knowing length might also means it is a live stream and UPnP adds special flags in addition to HTTP to inform the player of what it is receiving. The reason (yes, I'm getting there) is that pausing alive stream might not make sense and this let players decide if they want to allow that or not.

Now, when you combine these options together, many players are a mess and can't handle these properly. They think that no content length means live and don't pause. That does not mean that I don't have bugs or I missed something in my own app, but from experience the lack of pause is often a player issue.

So you can try different things.

1- change HTTP modes between -3, -2, -1 or 0. Try -3 first (chunked encoding). Then try 0 where I will always add a length, even if it is fake. It sometimes works. -2 adds length if known and -1 never adds length, so these are not for you

2- play with these DLNA flags that express server's capabilities and sometimes this makes the difference. You can have your own in the xml config file you'd create. The syntax is the following

/* DLNA.ORG_FLAGS, padded with 24 trailing 0s
 *     8000 0000  31  senderPaced
 *     4000 0000  30  lsopTimeBasedSeekSupported
 *     2000 0000  29  lsopByteBasedSeekSupported
 *     1000 0000  28  playcontainerSupported
 *      800 0000  27  s0IncreasingSupported
 *      400 0000  26  sNIncreasingSupported
 *      200 0000  25  rtspPauseSupported
 *      100 0000  24  streamingTransferModeSupported
 *       80 0000  23  interactiveTransferModeSupported
 *       40 0000  22  backgroundTransferModeSupported
 *       20 0000  21  connectionStallingSupported
 *       10 0000  20  dlnaVersion15Supported
 *
 *     Example: (1 << 24) | (1 << 22) | (1 << 21) | (1 << 20)
 *       DLNA.ORG_FLAGS=0170 0000[0000 0000 0000 0000 0000 0000] // [] show padding
 */

There is the "flow" version and the regular version, I assume you don' t use flow mode. To better understand these, Google and ChatGPT are your friends. I'm sorry I can't tell you more, but it's really a jungle here. Now, if you can make it work, I'd be interested because it gives me opportunity to figure out either my own mistakes or find a better compatibility.

Just you can see that in the "flow" mode, I use "c7..." which means I set that the beginning of the stream and end of the stream are moving which means a live stream (flow is a single continuing stream for all tracks). In regular (non-flow) mode, I'm not setting these bits "17..." so the player should know that the stream can be paused... Especially, you can remove the "streamingTransferModeSupported" flags (set value to 07...) to see what happens (although your player explicitly asks for streaming, so we'll see).

trilame commented 8 months ago

Thanks for the detailed reply, I'm learning a lot here!

I've tried the following and would like to share with you, in order to ensure that I ran the right commands/config file updates:

But unfortunately I got the same results, pause takes some time to be effective (still around 30 seconds).

I also tried through the config file as I wasn't sure of my previous commands:

A comment on this one: in your readme, you mention <http_length> but in the default config.xml, I found </http_content_length>. I suppose the one from the config.xml is the right one?

I will now look at playing with those flags, but this is totally new for me, I'm not familiar with C++. You mentioned the flow mode, I kept the default value in the config file, <flow>0</flow>

philippe44 commented 8 months ago

Yes, indeed I corrected the README. Regarding changing the flag, you don't need to worry about C/C++, just binary / hexadecimal encoding.

trilame commented 8 months ago

Hello Philippe44, I spent some time on this and start to get the concept.

However, I'm not sure to get what you mean with trying to remove streamingTransferModeSupported. In both default values we have in config.xml default file: `01700000000000000000000000000000

0c700000000000000000000000000000` If I got it right: - 01700000000000000000000000000000 gives: DLNA_ORG_FLAG_TIME_BASED_SEEK, DLNA_ORG_FLAG_PLAY_CONTAINER - 0c700000000000000000000000000000 gives: DLNA_ORG_FLAG_SENDER_PACED, DLNA_ORG_FLAG_TIME_BASED_SEEK, DLNA_ORG_FLAG_BYTE_BASED_SEEK, DLNA_ORG_FLAG_PLAY_CONTAINER So, streamingTransferModeSupported is already deactivated, right?
philippe44 commented 8 months ago

No, you have the example above

 *     Example: (1 << 24) | (1 << 22) | (1 << 21) | (1 << 20)
 *       DLNA.ORG_FLAGS=0170 0000[0000 0000 0000 0000 0000 0000] // [] show padding

You can concentrate on the 0170 0000 number which is a 32 bits hexadecimal and represent bits 31 to 0, and each digit is 4 bits,

0 = 0000 = b31..b28 1 = 0001 = b27..b24 = streamingTransferMode supported 7 = 0111 = b23..b20 = backgroundTransferModeSupported, connectionStallingSupported, dlnaVersion15Supported 0 = 0000 = b19..b16

(we don't care about the rest)

trilame commented 8 months ago

Ok thanks. Now I got it :)

I tried the followings. First one is the suggested, so removing streamingTransferModeSupported. <DLNA_FLAGS>00700000000000000000000000000000</DLNA_FLAGS> <DLNA_FLAGS>FFF00000000000000000000000000000</DLNA_FLAGS> <DLNA_FLAGS>00000000000000000000000000000000</DLNA_FLAGS>

In the 3 tests, results are the same as before (everything works well except pause). I will keep doing some others.

Just in case, my config file looks like:

<?xml version="1.0"?>
<spotupnp>
<common>
<protocolInfo>
<pcm>http-get:*:audio/L16;rate=44100;channels=2:DLNA.ORG_PN=LPCM;DLNA.ORG_OP=%s;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=%s</pcm>
<wav>http-get:*:audio/wav:DLNA.ORG_OP=%s;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=%s</wav>
<flac>http-get:*:audio/flac:DLNA.ORG_OP=%s;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=%s</flac>
<mp3>http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=%s;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=%s</mp3>
<DLNA_OP>01</DLNA_OP>
<DLNA_FLAGS>00700000000000000000000000000000</DLNA_FLAGS>
<DLNA_OP_flow>00</DLNA_OP_flow>
<DLNA_FLAGS_flow>0c700000000000000000000000000000</DLNA_FLAGS_flow>
</protocolInfo>
<enabled>1</enabled>
<max_volume>100</max_volume>
<http_content_length>-1</http_content_length>
<upnp_max>1</upnp_max>
<codec>flac</codec>
<vorbis_rate>160</vorbis_rate>
<flow>0</flow>
<gapless>1</gapless>
<artwork></artwork>
</common>
<main_log>info</main_log>
<upnp_log>info</upnp_log>
<util_log>warn</util_log>
<log_limit>-1</log_limit>
<max_players>32</max_players>
<interface>?</interface>
<credentials_path></credentials_path>
<credentials>0</credentials>
<ports>0:0</ports>
<device>
<udn>uuid:211a5de6-5f80-4b6b-9923-b91039fd12ae</udn>
<credentials></credentials>
<name>Samsung AU8005 43 TV+</name>
<mac>bb:bb:3d:ef:0a:ca</mac>
<enabled>0</enabled>
</device>
<device>
<udn>uuid:5f9ec1b3-ed59-1900-4530-9c645e01d9bd</udn>
<credentials></credentials>
<name>JBL OnBeat Air01D9BD+</name>
<mac>bb:bb:5e:01:d9:bd</mac>
<enabled>1</enabled>
</device>
<device>
<udn>uuid:92f32e53-f430-bf1d-1fcc-74eb2046f1b3</udn>
<credentials></credentials>
<name>Sound+</name>
<mac>bb:bb:d2:da:1a:da</mac>
<enabled>0</enabled>
</device>
</spotupnp>

And I run ./spotupnp-macos -x config.xml

trilame commented 8 months ago

Something else I just noticed, but I don't know if it is directly related to this issue: if I start a track, when it ends, the following track doesn't start. It stays at the end of the track just played. I tried from multiple Spotify apps (MacOS, iPhone).

philippe44 commented 8 months ago

Something else I just noticed, but I don't know if it is directly related to this issue: if I start a track, when it ends, the following track doesn't start. It stays at the end of the track just played. I tried from multiple Spotify apps (MacOS, iPhone).

This is a different issue. It's likely due to the capability of the player to go gapless. In the config file, set "gapless" to 0 to disable the use of the gapless feature. Some (many) players claim they can, but they don't.

philippe44 commented 8 months ago

BTW, with your other tests, it would be interesting to get the logs

trilame commented 8 months ago

Something else I just noticed, but I don't know if it is directly related to this issue: if I start a track, when it ends, the following track doesn't start. It stays at the end of the track just played. I tried from multiple Spotify apps (MacOS, iPhone).

This is a different issue. It's likely due to the capability of the player to go gapless. In the config file, set "gapless" to 0 to disable the use of the gapless feature. Some (many) players claim they can, but they don't.

Hello, I just tried but no success, the track ends and nothing happens:

Config file

``` http-get:*:audio/L16;rate=44100;channels=2:DLNA.ORG_PN=LPCM;DLNA.ORG_OP=%s;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=%s http-get:*:audio/wav:DLNA.ORG_OP=%s;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=%s http-get:*:audio/flac:DLNA.ORG_OP=%s;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=%s http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=%s;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=%s 01 01700000000000000000000000000000 00 0c700000000000000000000000000000 1 100 -1 1 flac 160 0 0 info info warn -1 32 ? 0 0:0 uuid:5f9ec1b3-ed59-1900-4530-9c645e01d9bd JBL OnBeat Air01D9BD+ bb:bb:5e:01:d9:bd 1 uuid:92f32e53-f430-bf1d-1fcc-74eb2046f1b3 Cat Sound+ bb:bb:d2:da:1a:da 0 ```

Logs

``` [21:30:12.699] main:1546 Starting stopupnp version: v0.5.0 (Nov 10 2023 @ 17:47:26) [21:30:12.702] Start:1259 Binding to iface en0@192.168.1.18:0 [21:30:12.702] Start:1273 Binding to 192.168.1.18:49152 [21:30:14.989] AddMRDevice:1185 [0x128028000]: adding renderer (JBL OnBeat Air01D9BD) with mac BBBBBDD9015E [21:30:14.997] I BellHTTPServer.cpp:191: Server listening on port 0 [21:30:14.997] I spotify.cpp:556: ZeroConf mode (port 64197) [21:30:15.001] MasterHandler:788 [0x128028000]: subscribe success [21:30:15.025] ProcessEvent:515 [0x128028000]: UPnP Volume local change 22:-1 (master) [21:30:39.479] I spotify.cpp:599: Spotify client launched for JBL OnBeat Air01D9BD+ [21:30:39.543] D Session.cpp:67: Connecting with AP [21:30:39.551] D PlainConnection.cpp:101: Connected to spotify server [21:30:39.569] I Session.cpp:43: Received APHello response [21:30:39.580] D Session.cpp:48: Received shannon keys [21:30:39.653] D Session.cpp:87: Authorization successful [21:30:39.654] I MercurySession.cpp:42: Received packet, command: 4 [21:30:39.654] D TimeProvider.cpp:15: Time synced with spotify servers [21:30:39.655] I MercurySession.cpp:42: Received packet, command: 2 [21:30:39.655] I MercurySession.cpp:42: Received packet, command: 118 [21:30:39.655] I [21:30:39.655] D MercurySession.cpp:252: Executing Mercury Request, type SUB MercurySession.cpp:42: Received packet, command: 27 [21:30:39.656] I MercurySession.cpp:42: Received packet, command: 80 [21:30:39.656] I MercurySession.cpp:42: Received packet, command: 31 [21:30:39.656] D MercurySession.cpp:153: Received country code FR [21:30:39.656] I MercurySession.cpp:42: Received packet, command: 105 [21:30:39.667] I MercurySession.cpp:42: Received packet, command: 181 [21:30:39.667] I MercurySession.cpp:42: Received packet, command: 74 [21:30:39.673] I MercurySession.cpp:42: Received packet, command: 179 [21:30:39.674] D MercurySession.cpp:174: Received mercury packet [21:30:39.674] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:39.674] D SpircHandler.cpp:61: Sent kMessageTypeHello! [21:30:39.721] I MercurySession.cpp:42: Received packet, command: 181 [21:30:39.721] I MercurySession.cpp:42: Received packet, command: 181 [21:30:39.721] I MercurySession.cpp:42: Received packet, command: 178 [21:30:39.722] D SpircHandler.cpp:69: Received subscription response [21:30:39.722] D SpircHandler.cpp:132: Notify frame [21:30:39.722] D SpircHandler.cpp:69: Received subscription response [21:30:39.722] D SpircHandler.cpp:132: Notify frame [21:30:39.722] D MercurySession.cpp:174: Received mercury packet [21:30:39.755] I AccessKeyFetcher.cpp:100: Access token expired, fetching new one... 286 [21:30:39.829] I AccessKeyFetcher.cpp:114: Access token sucessfully fetched [21:30:39.829] I MercurySession.cpp:42: Received packet, command: 181 [21:30:39.830] D SpircHandler.cpp:69: Received subscription response [21:30:39.830] D SpircHandler.cpp:179: Load frame 50! [21:30:39.830] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:39.832] I TrackPlayer.cpp:98: Resetting state [21:30:39.901] I MercurySession.cpp:42: Received packet, command: 178 [21:30:39.901] D MercurySession.cpp:174: Received mercury packet [21:30:39.934] D MercurySession.cpp:252: Executing Mercury Request, type GET [21:30:39.943] I MercurySession.cpp:42: Received packet, command: 178 [21:30:39.943] D MercurySession.cpp:174: Received mercury packet [21:30:39.943] I TrackQueue.cpp:158: Track name: Prayer In C (Robin Schulz Remix) [Radio Edit] [21:30:39.943] I TrackQueue.cpp:159: Track duration: 190243 [21:30:39.943] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [21:30:39.943] D TrackQueue.cpp:212: File format: 2 [21:30:39.943] D TrackQueue.cpp:212: File format: 1 [21:30:39.952] I MercurySession.cpp:42: Received packet, command: 13 [21:30:39.952] I TrackQueue.cpp:252: Got audio key [21:30:39.952] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [21:30:40.015] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/f29e00b7b7013c9b8b5f807568448633eea17ced?__token__=exp=1700166640~hmac=74d3f3cd1f95193a3d4aa536e57805cea40e388da40e30fd6fe9f6b01d2d36f4 [21:30:40.015] I TrackPlayer.cpp:171: Got track ID=f29e00b7b7013c9b8b5f807568448633eea17ced [21:30:40.015] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/f29e00b7b7013c9b8b5f807568448633eea17ced?__token__=exp=1700166640~hmac=74d3f3cd1f95193a3d4aa536e57805cea40e388da40e30fd6fe9f6b01d2d36f4 [21:30:40.078] I CDNAudioFile.cpp:70: Header and footer bytes received [21:30:40.079] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:40.079] shadowRequest:338 [0x128028000]: Stop [21:30:40.079] I spotify.cpp:300: new track will start at 182356 [21:30:40.079] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:40.079] I spotify.cpp:322: Play [21:30:40.117] D MercurySession.cpp:252: Executing Mercury Request, type GET [21:30:40.130] I MercurySession.cpp:42: Received packet, command: 178 [21:30:40.130] D MercurySession.cpp:174: Received mercury packet [21:30:40.130] I TrackQueue.cpp:158: Track name: Sugar (feat. Francesco Yates) [21:30:40.130] I TrackQueue.cpp:159: Track duration: 219043 [21:30:40.130] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [21:30:40.130] D TrackQueue.cpp:212: File format: 2 [21:30:40.130] D TrackQueue.cpp:212: File format: 1 [21:30:40.139] I MercurySession.cpp:42: Received packet, command: 13 [21:30:40.139] I TrackQueue.cpp:252: Got audio key [21:30:40.139] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [21:30:40.171] I MercurySession.cpp:42: Received packet, command: 178 [21:30:40.171] I MercurySession.cpp:42: Received packet, command: 178 [21:30:40.171] D MercurySession.cpp:174: Received mercury packet [21:30:40.171] D MercurySession.cpp:174: Received mercury packet [21:30:40.178] I TrackPlayer.cpp:206: Playing [21:30:40.178] I spotify.cpp:176: trackUniqueId update => f29e00b7b7013c9b8b5f807568448633eea17ced [21:30:40.178] I spotify.cpp:245: new track id bb30e84839804cf9aeb572e6463f9bff => [21:30:40.178] I HTTPstreamer.cpp:134: Bound to port 64216 [21:30:40.178] I spotify.cpp:255: loading with id bbbb5e01d9bd_0 [21:30:40.178] shadowRequest:355 [0x128028000]: spotify LOAD request [21:30:40.178] AVTSetURI:77 [0x128028000]: uPNP setURI http://192.168.1.18:64216/stream?id=bbbb5e01d9bd_0 (cookie 0x0) [21:30:40.178] shadowRequest:369 [0x128028000]: spotify play request [21:30:40.178] AVTPlay:137 [0x128028000]: uPNP play (cookie 0x1) [21:30:40.195] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/5fa7b45285c5bcf17eea1cd6ff41b52179e4dcd5?__token__=exp=1700166640~hmac=17e20a0b6b3ef9b7bc71508d9155733f4821ad43de736dbfc0b534303e3956b3 [21:30:40.300] D MercurySession.cpp:252: Executing Mercury Request, type GET [21:30:40.310] I MercurySession.cpp:42: Received packet, command: 178 [21:30:40.313] D MercurySession.cpp:174: Received mercury packet [21:30:40.313] I TrackQueue.cpp:158: Track name: Because You Move Me [21:30:40.313] I TrackQueue.cpp:159: Track duration: 196373 [21:30:40.313] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [21:30:40.313] D TrackQueue.cpp:212: File format: 2 [21:30:40.313] D TrackQueue.cpp:212: File format: 1 [21:30:40.335] I MercurySession.cpp:42: Received packet, command: 13 [21:30:40.335] I TrackQueue.cpp:252: Got audio key [21:30:40.346] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [21:30:40.392] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/2a5671ce0c5bb1957cc06efd144d1a9df01e1fc2?__token__=exp=1700166640~hmac=98673e26682c59f92ac356581b01131d2b72e209f0c9489e8480ca9b9b6d2bdd [21:30:40.475] I TrackPlayer.cpp:224: EOF [21:30:40.475] I TrackPlayer.cpp:255: Playing done [21:30:40.529] I TrackPlayer.cpp:171: Got track ID=5fa7b45285c5bcf17eea1cd6ff41b52179e4dcd5 [21:30:40.529] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/5fa7b45285c5bcf17eea1cd6ff41b52179e4dcd5?__token__=exp=1700166640~hmac=17e20a0b6b3ef9b7bc71508d9155733f4821ad43de736dbfc0b534303e3956b3 [21:30:40.640] I CDNAudioFile.cpp:70: Header and footer bytes received [21:30:40.724] I TrackPlayer.cpp:206: Playing [21:30:40.725] I spotify.cpp:176: trackUniqueId update f29e00b7b7013c9b8b5f807568448633eea17ced => 5fa7b45285c5bcf17eea1cd6ff41b52179e4dcd5 [21:30:40.725] I spotify.cpp:241: draining track bbbb5e01d9bd_0 [21:30:40.726] I spotify.cpp:245: new track id b3c802790aaa4f83adb6ca0b6c3c6f6a => [21:30:40.726] I HTTPstreamer.cpp:134: Bound to port 64221 [21:30:40.726] I spotify.cpp:255: loading with id bbbb5e01d9bd_1 [21:30:40.726] shadowRequest:355 [0x128028000]: spotify LOAD request [21:30:40.726] shadowRequest:362 [0x128028000]: Gapped next track http://192.168.1.18:64221/stream?id=bbbb5e01d9bd_1 [21:30:44.937] I MercurySession.cpp:42: Received packet, command: 181 [21:30:44.937] D SpircHandler.cpp:69: Received subscription response [21:30:44.937] D SpircHandler.cpp:179: Load frame 50! [21:30:44.937] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:44.940] I TrackPlayer.cpp:98: Resetting state [21:30:44.941] I TrackPlayer.cpp:255: Playing done [21:30:45.029] I MercurySession.cpp:42: Received packet, command: 178 [21:30:45.030] D MercurySession.cpp:174: Received mercury packet [21:30:45.031] D MercurySession.cpp:252: Executing Mercury Request, type GET [21:30:45.049] I MercurySession.cpp:42: Received packet, command: 178 [21:30:45.049] D MercurySession.cpp:174: Received mercury packet [21:30:45.049] I TrackQueue.cpp:158: Track name: The Spins [21:30:45.049] I TrackQueue.cpp:159: Track duration: 195873 [21:30:45.049] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [21:30:45.049] D TrackQueue.cpp:212: File format: 2 [21:30:45.049] D TrackQueue.cpp:212: File format: 1 [21:30:45.058] I MercurySession.cpp:42: Received packet, command: 13 [21:30:45.058] I TrackQueue.cpp:252: Got audio key [21:30:45.058] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [21:30:45.114] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/e86f7cbabd916603158fabba95fdb3bcff4ada1e?__token__=exp=1700166645~hmac=5a391ca5cae4f449f28c9199e75018ec4c713d4f492951c50d8c6f19d844b59b [21:30:45.115] I TrackPlayer.cpp:171: Got track ID=e86f7cbabd916603158fabba95fdb3bcff4ada1e [21:30:45.115] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/e86f7cbabd916603158fabba95fdb3bcff4ada1e?__token__=exp=1700166645~hmac=5a391ca5cae4f449f28c9199e75018ec4c713d4f492951c50d8c6f19d844b59b [21:30:45.219] D MercurySession.cpp:252: Executing Mercury Request, type GET [21:30:45.228] I MercurySession.cpp:42: Received packet, command: 178 [21:30:45.228] D MercurySession.cpp:174: Received mercury packet [21:30:45.228] I TrackQueue.cpp:158: Track name: The Less I Know The Better [21:30:45.228] I TrackQueue.cpp:159: Track duration: 216320 [21:30:45.228] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [21:30:45.228] D TrackQueue.cpp:212: File format: 2 [21:30:45.228] D TrackQueue.cpp:212: File format: 1 [21:30:45.240] I MercurySession.cpp:42: Received packet, command: 13 [21:30:45.240] I TrackQueue.cpp:252: Got audio key [21:30:45.240] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [21:30:45.282] I CDNAudioFile.cpp:70: Header and footer bytes received [21:30:45.283] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:45.284] shadowRequest:338 [0x128028000]: Stop [21:30:45.284] AVTStop:203 [0x128028000]: uPNP stop (cookie 0x3) [21:30:45.284] I spotify.cpp:300: new track will start at 0 [21:30:45.297] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/ca46e501c506cba037797d6f95570be14e729ffe?__token__=exp=1700166645~hmac=e234e2ae0ca3e2b033b63597ea7d369db0ab011ecc8a537fef7a938c09a0a5e4 [21:30:45.336] I HTTPstreamer.cpp:147: HTTP streamer bbbb5e01d9bd_1 deleted [21:30:45.389] I HTTPstreamer.cpp:147: HTTP streamer bbbb5e01d9bd_0 deleted [21:30:45.389] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:45.390] I spotify.cpp:322: Play [21:30:45.402] D MercurySession.cpp:252: Executing Mercury Request, type GET [21:30:45.410] I MercurySession.cpp:42: Received packet, command: 178 [21:30:45.410] D MercurySession.cpp:174: Received mercury packet [21:30:45.410] I TrackQueue.cpp:158: Track name: Baby Blue (feat. Chance the Rapper) [21:30:45.411] I TrackQueue.cpp:159: Track duration: 280160 [21:30:45.411] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [21:30:45.411] D TrackQueue.cpp:212: File format: 2 [21:30:45.411] D TrackQueue.cpp:212: File format: 1 [21:30:45.430] I MercurySession.cpp:42: Received packet, command: 13 [21:30:45.430] I TrackQueue.cpp:252: Got audio key [21:30:45.431] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [21:30:45.490] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa?__token__=exp=1700166645~hmac=2e573503fdfa9f17d706e80bcfc76ed98aa838652e9e7e94cefc496f54cd5252 [21:30:45.612] I TrackPlayer.cpp:206: Playing [21:30:45.613] I spotify.cpp:176: trackUniqueId update => e86f7cbabd916603158fabba95fdb3bcff4ada1e [21:30:45.613] I spotify.cpp:245: new track id fc0a10f961ed427bb9e2893fc290eb65 => [21:30:45.613] I HTTPstreamer.cpp:134: Bound to port 64236 [21:30:45.613] I spotify.cpp:255: loading with id bbbb5e01d9bd_2 [21:30:45.613] shadowRequest:355 [0x128028000]: spotify LOAD request [21:30:45.613] AVTSetURI:77 [0x128028000]: uPNP setURI http://192.168.1.18:64236/stream?id=bbbb5e01d9bd_2 (cookie 0x4) [21:30:45.613] shadowRequest:369 [0x128028000]: spotify play request [21:30:45.613] AVTPlay:137 [0x128028000]: uPNP play (cookie 0x5) [21:30:45.741] I HTTPstreamer.cpp:467: got HTTP connection 15 [21:30:45.741] I HTTPstreamer.cpp:210: HTTP received => GET /stream?id=bbbb5e01d9bd_2 HTTP/1.1 Host: 192.168.1.18:64236 Icy-MetaData: 1 Connection: close transferMode.dlna.org: Streaming User-Agent: WinampMPEG/2.8 Accept: */* [21:30:45.741] I HTTPstreamer.cpp:327: HTTP response => HTTP/1.1 200 OK transfermode.dlna.org: streaming Server: spot-connect Content-Type: audio/flac Connection: close [21:30:46.605] I MercurySession.cpp:42: Received packet, command: 178 [21:30:46.605] D MercurySession.cpp:174: Received mercury packet [21:30:46.736] I MercurySession.cpp:42: Received packet, command: 181 [21:30:46.736] I MercurySession.cpp:42: Received packet, command: 178 [21:30:46.736] D SpircHandler.cpp:69: Received subscription response [21:30:46.737] D MercurySession.cpp:174: Received mercury packet [21:30:50.026] ActionHandler:595 [0x128028000]: uPNP transition [21:30:50.527] I MercurySession.cpp:42: Received packet, command: 181 [21:30:50.527] D SpircHandler.cpp:69: Received subscription response [21:30:50.528] I TrackPlayer.cpp:98: Resetting state [21:30:50.528] I spotify.cpp:340: next/prev [21:30:50.528] shadowRequest:338 [0x128028000]: Stop [21:30:50.528] AVTStop:203 [0x128028000]: uPNP stop (cookie 0x9) [21:30:50.530] I TrackPlayer.cpp:255: Playing done [21:30:50.558] D MercurySession.cpp:252: Executing Mercury Request, type GET [21:30:50.568] I MercurySession.cpp:42: Received packet, command: 178 [21:30:50.568] D MercurySession.cpp:174: Received mercury packet [21:30:50.568] I TrackQueue.cpp:158: Track name: Starships [21:30:50.568] I TrackQueue.cpp:159: Track duration: 210626 [21:30:50.568] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [21:30:50.568] D TrackQueue.cpp:212: File format: 2 [21:30:50.568] D TrackQueue.cpp:212: File format: 1 [21:30:50.580] I MercurySession.cpp:42: Received packet, command: 13 [21:30:50.580] I TrackQueue.cpp:252: Got audio key [21:30:50.581] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [21:30:50.583] I TrackPlayer.cpp:171: Got track ID=ca46e501c506cba037797d6f95570be14e729ffe [21:30:50.583] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/ca46e501c506cba037797d6f95570be14e729ffe?__token__=exp=1700166645~hmac=e234e2ae0ca3e2b033b63597ea7d369db0ab011ecc8a537fef7a938c09a0a5e4 [21:30:50.624] E HTTPstreamer.cpp:427: HTTP error 32 for bbbb5e01d9bd_2 => send 0 / 32768 (15) [21:30:50.624] I HTTPstreamer.cpp:503: closing socket 15 [21:30:50.650] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/242f31c01b62fbd81819dd11679ebc11ca8eeed1?__token__=exp=1700166650~hmac=482a033a1ae3600906075c17957cbf377589ce42eb85d8f5b07402dc114a723c [21:30:50.824] I CDNAudioFile.cpp:70: Header and footer bytes received [21:30:50.824] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:50.826] shadowRequest:338 [0x128028000]: Stop [21:30:50.826] I spotify.cpp:300: new track will start at 0 [21:30:50.834] I HTTPstreamer.cpp:147: HTTP streamer bbbb5e01d9bd_2 deleted [21:30:50.835] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:50.838] I spotify.cpp:322: Play [21:30:50.870] I MercurySession.cpp:42: Received packet, command: 178 [21:30:50.870] D MercurySession.cpp:174: Received mercury packet [21:30:50.879] I MercurySession.cpp:42: Received packet, command: 178 [21:30:50.879] D MercurySession.cpp:174: Received mercury packet [21:30:50.996] I TrackPlayer.cpp:206: Playing [21:30:50.998] I spotify.cpp:176: trackUniqueId update => ca46e501c506cba037797d6f95570be14e729ffe [21:30:50.998] I spotify.cpp:245: new track id dd8e974aed8942be8cd0888a27394513 => [21:30:50.999] I HTTPstreamer.cpp:134: Bound to port 64246 [21:30:50.999] I spotify.cpp:255: loading with id bbbb5e01d9bd_3 [21:30:50.999] shadowRequest:355 [0x128028000]: spotify LOAD request [21:30:50.999] AVTSetURI:77 [0x128028000]: uPNP setURI http://192.168.1.18:64246/stream?id=bbbb5e01d9bd_3 (cookie 0xa) [21:30:50.999] shadowRequest:369 [0x128028000]: spotify play request [21:30:50.999] AVTPlay:137 [0x128028000]: uPNP play (cookie 0xb) [21:30:51.060] I HTTPstreamer.cpp:467: got HTTP connection 15 [21:30:51.061] I HTTPstreamer.cpp:210: HTTP received => GET /stream?id=bbbb5e01d9bd_3 HTTP/1.1 Host: 192.168.1.18:64246 Icy-MetaData: 1 Connection: close transferMode.dlna.org: Streaming User-Agent: WinampMPEG/2.8 Accept: */* [21:30:51.061] I HTTPstreamer.cpp:327: HTTP response => HTTP/1.1 200 OK transfermode.dlna.org: streaming Server: spot-connect Content-Type: audio/flac Connection: close [21:30:51.543] ActionHandler:595 [0x128028000]: uPNP transition [21:30:53.822] I MercurySession.cpp:42: Received packet, command: 181 [21:30:53.822] D SpircHandler.cpp:69: Received subscription response [21:30:53.822] I TrackPlayer.cpp:107: Seeking... [21:30:53.823] D MercurySession.cpp:252: Executing Mercury Request, type SEND [21:30:53.825] I spotify.cpp:362: seeking from streamer bbbb5e01d9bd_3 at 206854 [21:30:53.825] shadowRequest:338 [0x128028000]: Stop [21:30:53.825] AVTStop:203 [0x128028000]: uPNP stop (cookie 0x14) [21:30:53.825] shadowRequest:355 [0x128028000]: spotify LOAD request [21:30:53.825] AVTSetURI:77 [0x128028000]: uPNP setURI http://192.168.1.18:64246/stream?id=bbbb5e01d9bd_3 (cookie 0x15) [21:30:53.825] shadowRequest:369 [0x128028000]: spotify play request [21:30:53.825] AVTPlay:137 [0x128028000]: uPNP play (cookie 0x15) [21:30:53.872] I MercurySession.cpp:42: Received packet, command: 178 [21:30:53.875] D MercurySession.cpp:174: Received mercury packet [21:30:53.892] E HTTPstreamer.cpp:427: HTTP error 32 for bbbb5e01d9bd_3 => send 0 / 32768 (15) [21:30:53.892] I HTTPstreamer.cpp:503: closing socket 15 [21:30:53.941] I HTTPstreamer.cpp:467: got HTTP connection 15 [21:30:53.941] I HTTPstreamer.cpp:210: HTTP received => GET /stream?id=bbbb5e01d9bd_3 HTTP/1.1 Host: 192.168.1.18:64246 Icy-MetaData: 1 Connection: close transferMode.dlna.org: Streaming User-Agent: WinampMPEG/2.8 Accept: */* [21:30:53.941] I HTTPstreamer.cpp:327: HTTP response => HTTP/1.1 200 OK transfermode.dlna.org: streaming Server: spot-connect Content-Type: audio/flac Connection: close [21:30:54.064] ActionHandler:595 [0x128028000]: uPNP transition [21:30:54.123] I TrackPlayer.cpp:224: EOF [21:30:54.123] I TrackPlayer.cpp:255: Playing done [21:30:54.175] I TrackPlayer.cpp:171: Got track ID=d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa [21:30:54.175] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa?__token__=exp=1700166645~hmac=2e573503fdfa9f17d706e80bcfc76ed98aa838652e9e7e94cefc496f54cd5252 [21:30:54.316] I CDNAudioFile.cpp:70: Header and footer bytes received [21:30:54.450] I TrackPlayer.cpp:206: Playing [21:30:54.452] I spotify.cpp:176: trackUniqueId update ca46e501c506cba037797d6f95570be14e729ffe => d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa [21:30:54.452] I spotify.cpp:241: draining track bbbb5e01d9bd_3 [21:30:54.452] I spotify.cpp:245: new track id eed0a80a318941dc9d3de9e08b73c35a => [21:30:54.453] I HTTPstreamer.cpp:134: Bound to port 64263 [21:30:54.453] I spotify.cpp:255: loading with id bbbb5e01d9bd_4 [21:30:54.453] shadowRequest:355 [0x128028000]: spotify LOAD request [21:30:54.453] shadowRequest:362 [0x128028000]: Gapped next track http://192.168.1.18:64263/stream?id=bbbb5e01d9bd_4 [21:30:57.995] I HTTPstreamer.cpp:492: HTTP streaming finished for 15 (id: bbbb5e01d9bd_3) ```

I will perform some tests and provide logs, with the DLNA flags.

philippe44 commented 8 months ago

It's a very strange log... Can you do me a favor and take a fresh log? Be very strict with the following

1- starts spotupnp 2- using a spotify controller (PC or smartphone), connect to one of the created player 3- playback should start immediately 4- don't do anything, touch anything on the controller. Let the track play and wait at least 30 s after track's end before exiting spotupnp. Do **notùù stop or pause spotify, nothing. Just type "exit" at the spotupnp prompt, it will exit the program (whether the log is on the screen or in a file) 5- post that log

trilame commented 8 months ago

I did run spotupnp-macos, without taking into account any config file (I hope that's what you meant). Simply running ./spotupnp-macos

I'm sharing two outputs with you:

On the first try, I connect Spotify to the created player: on the Spotify interface, it shows it's connected and that the track plays, but no sound is coming out of the speaker. This happened multiple time during my other tests, but I also noticed it happened with a speaker I have at home, that has Spotify Connect integrated (and not using SpotConnect at all, it was before) _Edit: it seems I'm not alone_. If this happens, in both case (SpotConnect or not), I launch another track and it works immediately. Anyway, on this try, I did nothing else (so, no sound), let the track finish (as I could see on the interface), waited at least 30 seconds, and typed exit. Here is the log:

Log 1

``` [23:19:08.987] main:1546 Starting stopupnp version: v0.5.0 (Nov 10 2023 @ 17:47:26) [23:19:08.988] main:1553 no config file, using defaults [23:19:08.988] Start:1259 Binding to iface en0@192.168.1.18:0 [23:19:08.988] Start:1273 Binding to 192.168.1.18:49152 [23:19:10.335] AddMRDevice:1185 [0x148008000]: adding renderer (Cat Sound) with mac BBBBDA1ADAD2 [23:19:10.344] I BellHTTPServer.cpp:191: Server listening on port 0 [23:19:10.344] I spotify.cpp:556: ZeroConf mode (port 57366) [23:19:10.356] MasterHandler:788 [0x148008000]: subscribe success [23:19:13.272] AddMRDevice:1185 [0x14800b0f0]: adding renderer (JBL OnBeat Air01D9BD) with mac BBBBBDD9015E [23:19:13.280] I BellHTTPServer.cpp:191: Server listening on port 0 [23:19:13.280] I spotify.cpp:556: ZeroConf mode (port 57372) [23:19:13.282] MasterHandler:788 [0x14800b0f0]: subscribe success [23:19:13.303] ProcessEvent:515 [0x14800b0f0]: UPnP Volume local change 22:-1 (master) [23:19:31.345] I spotify.cpp:599: Spotify client launched for JBL OnBeat Air01D9BD+ [23:19:31.394] D Session.cpp:67: Connecting with AP [23:19:31.402] D PlainConnection.cpp:101: Connected to spotify server [23:19:31.419] I Session.cpp:43: Received APHello response [23:19:31.429] D Session.cpp:48: Received shannon keys [23:19:31.471] D Session.cpp:87: Authorization successful [23:19:31.471] I MercurySession.cpp:42: Received packet, command: 4 [23:19:31.471] D TimeProvider.cpp:15: Time synced with spotify servers [23:19:31.474] I MercurySession.cpp:42: Received packet, command: 2 [23:19:31.474] I MercurySession.cpp:42: Received packet, command: 118 [23:19:31.474] I MercurySession.cpp:42: Received packet, command: 27 [23:19:31.475] I MercurySession.cpp:42: Received packet, command: 80 [23:19:31.475] I MercurySession.cpp:42: Received packet, command: 31 [23:19:31.475] D MercurySession.cpp:252: Executing Mercury Request, type SUB [23:19:31.475] I MercurySession.cpp:42: Received packet, command: 105 [23:19:31.475] D MercurySession.cpp:153: Received country code FR [23:19:31.487] I MercurySession.cpp:42: Received packet, command: 181 [23:19:31.487] I MercurySession.cpp:42: Received packet, command: 74 [23:19:31.492] I MercurySession.cpp:42: Received packet, command: 179 [23:19:31.493] D MercurySession.cpp:174: Received mercury packet [23:19:31.493] D MercurySession.cpp:252: Executing Mercury Request, type SEND [23:19:31.493] D SpircHandler.cpp:61: Sent kMessageTypeHello! [23:19:31.531] I MercurySession.cpp:42: Received packet, command: 181 [23:19:31.531] I MercurySession.cpp:42: Received packet, command: 178 [23:19:31.531] D SpircHandler.cpp:69: Received subscription response [23:19:31.531] D SpircHandler.cpp:132: Notify frame [23:19:31.531] D MercurySession.cpp:174: Received mercury packet [23:19:31.573] I AccessKeyFetcher.cpp:100: Access token expired, fetching new one... 286 [23:19:31.607] I MercurySession.cpp:42: Received packet, command: 181 [23:19:31.607] D SpircHandler.cpp:69: Received subscription response [23:19:31.607] D SpircHandler.cpp:179: Load frame 50! [23:19:31.607] D MercurySession.cpp:252: Executing Mercury Request, type SEND [23:19:31.609] I TrackPlayer.cpp:98: Resetting state [23:19:31.647] I MercurySession.cpp:42: Received packet, command: 178 [23:19:31.647] D MercurySession.cpp:174: Received mercury packet [23:19:31.651] I AccessKeyFetcher.cpp:114: Access token sucessfully fetched [23:19:31.651] D MercurySession.cpp:252: Executing Mercury Request, type GET [23:19:31.659] I MercurySession.cpp:42: Received packet, command: 178 [23:19:31.662] D MercurySession.cpp:174: Received mercury packet [23:19:31.662] I TrackQueue.cpp:158: Track name: The Less I Know The Better [23:19:31.662] I TrackQueue.cpp:159: Track duration: 216320 [23:19:31.662] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [23:19:31.662] D TrackQueue.cpp:212: File format: 2 [23:19:31.662] D TrackQueue.cpp:212: File format: 1 [23:19:31.671] I MercurySession.cpp:42: Received packet, command: 13 [23:19:31.671] I TrackQueue.cpp:252: Got audio key [23:19:31.671] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [23:19:31.685] I MercurySession.cpp:42: Received packet, command: 181 [23:19:31.732] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/ca46e501c506cba037797d6f95570be14e729ffe?__token__=exp=1700173171~hmac=b528156a219ea2bc60daccbc03bc198630464dc9dc3e29f40dca33a7aa440292 [23:19:31.732] I TrackPlayer.cpp:171: Got track ID=ca46e501c506cba037797d6f95570be14e729ffe [23:19:31.732] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/ca46e501c506cba037797d6f95570be14e729ffe?__token__=exp=1700173171~hmac=b528156a219ea2bc60daccbc03bc198630464dc9dc3e29f40dca33a7aa440292 [23:19:31.798] I CDNAudioFile.cpp:70: Header and footer bytes received [23:19:31.798] D MercurySession.cpp:252: Executing Mercury Request, type SEND [23:19:31.800] shadowRequest:338 [0x14800b0f0]: Stop [23:19:31.800] I spotify.cpp:300: new track will start at 139515 [23:19:31.800] D MercurySession.cpp:252: Executing Mercury Request, type SEND [23:19:31.801] I spotify.cpp:322: Play [23:19:31.833] D MercurySession.cpp:252: Executing Mercury Request, type GET [23:19:31.841] I MercurySession.cpp:42: Received packet, command: 178 [23:19:31.844] D MercurySession.cpp:174: Received mercury packet [23:19:31.847] I MercurySession.cpp:42: Received packet, command: 178 [23:19:31.847] I MercurySession.cpp:42: Received packet, command: 178 [23:19:31.847] D MercurySession.cpp:174: Received mercury packet [23:19:31.847] I TrackQueue.cpp:158: Track name: Baby Blue (feat. Chance the Rapper) [23:19:31.847] I TrackQueue.cpp:159: Track duration: 280160 [23:19:31.847] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [23:19:31.847] D TrackQueue.cpp:212: File format: 2 [23:19:31.847] D TrackQueue.cpp:212: File format: 1 [23:19:31.847] D MercurySession.cpp:174: Received mercury packet [23:19:31.864] I MercurySession.cpp:42: Received packet, command: 13 [23:19:31.864] I TrackQueue.cpp:252: Got audio key [23:19:31.864] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [23:19:31.887] I TrackPlayer.cpp:206: Playing [23:19:31.887] I spotify.cpp:176: trackUniqueId update => ca46e501c506cba037797d6f95570be14e729ffe [23:19:31.887] I spotify.cpp:245: new track id dd8e974aed8942be8cd0888a27394513 => [23:19:31.888] I HTTPstreamer.cpp:134: Bound to port 57387 [23:19:31.888] I spotify.cpp:255: loading with id bbbb5e01d9bd_0 [23:19:31.888] shadowRequest:355 [0x14800b0f0]: spotify LOAD request [23:19:31.888] AVTSetURI:77 [0x14800b0f0]: uPNP setURI http://192.168.1.18:57387/stream?id=bbbb5e01d9bd_0 (cookie 0x0) [23:19:31.888] shadowRequest:369 [0x14800b0f0]: spotify play request [23:19:31.888] AVTPlay:137 [0x14800b0f0]: uPNP play (cookie 0x1) [23:19:31.913] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa?__token__=exp=1700173171~hmac=27227f773eb0bc92c940dbcf3d2a1f296c495c087daf640dc21ea07a4b106f35 [23:19:32.013] D MercurySession.cpp:252: Executing Mercury Request, type GET [23:19:32.022] I MercurySession.cpp:42: Received packet, command: 178 [23:19:32.022] D MercurySession.cpp:174: Received mercury packet [23:19:32.022] I TrackQueue.cpp:158: Track name: Starships [23:19:32.022] I TrackQueue.cpp:159: Track duration: 210626 [23:19:32.022] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [23:19:32.022] D TrackQueue.cpp:212: File format: 2 [23:19:32.022] D TrackQueue.cpp:212: File format: 1 [23:19:32.030] I MercurySession.cpp:42: Received packet, command: 13 [23:19:32.030] I TrackQueue.cpp:252: Got audio key [23:19:32.030] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [23:19:32.073] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/242f31c01b62fbd81819dd11679ebc11ca8eeed1?__token__=exp=1700173172~hmac=f19f2ac80a5e902a27eecd0e515bb6a33ae3bbf78f7a558bdf09793ac07e3af9 [23:21:31.477] I MercurySession.cpp:42: Received packet, command: 4 [23:21:31.478] D TimeProvider.cpp:15: Time synced with spotify servers [23:21:31.483] I MercurySession.cpp:42: Received packet, command: 74 exit [23:22:00.203] main:1648 stopping devices ... [23:22:00.203] Stop:1319 terminate update thread ... [23:22:00.203] Stop:1327 flush renderers ... [23:22:00.203] I spotify.cpp:146: player deletion pending [23:22:00.203] I spotify.cpp:654: terminating player [23:22:00.204] I spotify.cpp:156: done [23:22:05.576] MRThread:277 [0x148008000] player thread exited [23:22:05.576] I spotify.cpp:146: player deletion pending [23:22:05.706] I TrackPlayer.cpp:98: Resetting state [23:22:05.752] I TrackPlayer.cpp:255: Playing done [23:22:05.753] I MercurySession.cpp:128: Disconnecting mercury session [23:22:05.753] I PlainConnection.cpp:197: Closing socket... [23:22:05.753] E MercurySession.cpp:53: Error while receiving packet: Error in read [23:22:05.754] I TrackPlayer.cpp:98: Resetting state [23:22:05.754] I spotify.cpp:645: disconnecting player [23:22:05.754] I spotify.cpp:654: terminating player [23:22:05.754] I spotify.cpp:156: done [23:22:07.419] I HTTPstreamer.cpp:147: HTTP streamer bbbb5e01d9bd_0 deleted [23:22:12.425] MRThread:277 [0x14800b0f0] player thread exited [23:22:12.425] Stop:1330 terminate libupnp [23:22:12.428] Stop:1346 terminate main thread ... [23:22:12.428] main:1650 all done ```

On a second try, I did the same and the previously mentioned "bug" did not occur, the speaker was immediately playing as expected. I also waited for the end of the track, plus 30 seconds, and typed exit. Here is the log:

Log 2

``` [23:23:36.277] main:1546 Starting stopupnp version: v0.5.0 (Nov 10 2023 @ 17:47:26) [23:23:36.278] main:1553 no config file, using defaults [23:23:36.279] Start:1259 Binding to iface en0@192.168.1.18:0 [23:23:36.279] Start:1273 Binding to 192.168.1.18:49152 [23:23:37.077] AddMRDevice:1185 [0x120008000]: adding renderer (JBL OnBeat Air01D9BD) with mac BBBBBDD9015E [23:23:37.088] I BellHTTPServer.cpp:191: Server listening on port 0 [23:23:37.088] I spotify.cpp:556: ZeroConf mode (port 57504) [23:23:37.091] MasterHandler:788 [0x120008000]: subscribe success [23:23:37.144] ProcessEvent:515 [0x120008000]: UPnP Volume local change 22:-1 (master) [23:23:47.857] I spotify.cpp:599: Spotify client launched for JBL OnBeat Air01D9BD+ [23:23:47.916] D Session.cpp:67: Connecting with AP [23:23:47.933] D PlainConnection.cpp:101: Connected to spotify server [23:23:47.955] I Session.cpp:43: Received APHello response [23:23:47.962] D Session.cpp:48: Received shannon keys [23:23:48.003] D Session.cpp:87: Authorization successful [23:23:48.004] I MercurySession.cpp:42: Received packet, command: 4 [23:23:48.004] D TimeProvider.cpp:15: Time synced with spotify servers [23:23:48.005] I MercurySession.cpp:42: Received packet, command: 2 [23:23:48.005] I MercurySession.cpp:42: Received packet, command: 118 [23:23:48.005] I MercurySession.cpp:42: Received packet, command: 27 [23:23:48.005] I MercurySession.cpp:42: Received packet, command: 80 [23:23:48.005] I MercurySession.cpp:42: Received packet, command: 31 [23:23:48.005] I MercurySession.cpp:42: Received packet, command: 105 [23:23:48.005] D MercurySession.cpp:252: Executing Mercury Request, type SUB [23:23:48.006] D MercurySession.cpp:153: Received country code FR [23:23:48.009] I MercurySession.cpp:42: Received packet, command: 181 [23:23:48.015] I MercurySession.cpp:42: Received packet, command: 74 [23:23:48.015] I MercurySession.cpp:42: Received packet, command: 179 [23:23:48.015] D MercurySession.cpp:174: Received mercury packet [23:23:48.015] D MercurySession.cpp:252: Executing Mercury Request, type SEND [23:23:48.015] D SpircHandler.cpp:61: Sent kMessageTypeHello! [23:23:48.052] I MercurySession.cpp:42: Received packet, command: 181 [23:23:48.052] I MercurySession.cpp:42: Received packet, command: 178 [23:23:48.053] D SpircHandler.cpp:69: Received subscription response [23:23:48.053] D SpircHandler.cpp:132: Notify frame [23:23:48.053] D MercurySession.cpp:174: Received mercury packet [23:23:48.109] I AccessKeyFetcher.cpp:100: Access token expired, fetching new one... 286 [23:23:48.111] I MercurySession.cpp:42: Received packet, command: 181 [23:23:48.113] D SpircHandler.cpp:69: Received subscription response [23:23:48.114] D SpircHandler.cpp:179: Load frame 50! [23:23:48.114] D MercurySession.cpp:252: Executing Mercury Request, type SEND [23:23:48.117] I TrackPlayer.cpp:98: Resetting state [23:23:48.169] I MercurySession.cpp:42: Received packet, command: 178 [23:23:48.170] D MercurySession.cpp:174: Received mercury packet [23:23:48.187] I AccessKeyFetcher.cpp:114: Access token sucessfully fetched [23:23:48.188] D MercurySession.cpp:252: Executing Mercury Request, type GET [23:23:48.197] I MercurySession.cpp:42: Received packet, command: 178 [23:23:48.197] D MercurySession.cpp:174: Received mercury packet [23:23:48.197] I TrackQueue.cpp:158: Track name: The Less I Know The Better [23:23:48.197] I TrackQueue.cpp:159: Track duration: 216320 [23:23:48.197] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [23:23:48.197] D TrackQueue.cpp:212: File format: 2 [23:23:48.197] D TrackQueue.cpp:212: File format: 1 [23:23:48.206] I MercurySession.cpp:42: Received packet, command: 13 [23:23:48.207] I TrackQueue.cpp:252: Got audio key [23:23:48.215] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [23:23:48.271] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/ca46e501c506cba037797d6f95570be14e729ffe?__token__=exp=1700173428~hmac=29115ca7a07ca3978c30094f4e267646017770f3b7f3e9e013a50dcc9a3522f2 [23:23:48.272] I TrackPlayer.cpp:171: Got track ID=ca46e501c506cba037797d6f95570be14e729ffe [23:23:48.272] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/ca46e501c506cba037797d6f95570be14e729ffe?__token__=exp=1700173428~hmac=29115ca7a07ca3978c30094f4e267646017770f3b7f3e9e013a50dcc9a3522f2 [23:23:48.347] I CDNAudioFile.cpp:70: Header and footer bytes received [23:23:48.347] D MercurySession.cpp:252: Executing Mercury Request, type SEND [23:23:48.349] shadowRequest:338 [0x120008000]: Stop [23:23:48.349] I spotify.cpp:300: new track will start at 139988 [23:23:48.349] D MercurySession.cpp:252: Executing Mercury Request, type SEND [23:23:48.350] I spotify.cpp:322: Play [23:23:48.372] D MercurySession.cpp:252: Executing Mercury Request, type GET [23:23:48.384] I MercurySession.cpp:42: Received packet, command: 178 [23:23:48.385] I MercurySession.cpp:42: Received packet, command: 178 [23:23:48.385] D MercurySession.cpp:174: Received mercury packet [23:23:48.385] I TrackQueue.cpp:158: Track name: Baby Blue (feat. Chance the Rapper) [23:23:48.385] I TrackQueue.cpp:159: Track duration: 280160 [23:23:48.385] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [23:23:48.386] D TrackQueue.cpp:212: File format: 2 [23:23:48.386] D TrackQueue.cpp:212: File format: 1 [23:23:48.386] D MercurySession.cpp:174: Received mercury packet [23:23:48.394] I MercurySession.cpp:42: Received packet, command: 178 [23:23:48.394] D MercurySession.cpp:174: Received mercury packet [23:23:48.410] I MercurySession.cpp:42: Received packet, command: 13 [23:23:48.410] I TrackQueue.cpp:252: Got audio key [23:23:48.410] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [23:23:48.460] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa?__token__=exp=1700173428~hmac=aa4d1801f502dac0426576a86bec97e86e9b6671fe8940454870c848b2b9f42a [23:23:48.543] I TrackPlayer.cpp:206: Playing [23:23:48.543] I spotify.cpp:176: trackUniqueId update => ca46e501c506cba037797d6f95570be14e729ffe [23:23:48.543] I spotify.cpp:245: new track id dd8e974aed8942be8cd0888a27394513 => [23:23:48.545] I HTTPstreamer.cpp:134: Bound to port 57524 [23:23:48.545] I spotify.cpp:255: loading with id bbbb5e01d9bd_0 [23:23:48.545] shadowRequest:355 [0x120008000]: spotify LOAD request [23:23:48.545] AVTSetURI:77 [0x120008000]: uPNP setURI http://192.168.1.18:57524/stream?id=bbbb5e01d9bd_0 (cookie 0x0) [23:23:48.545] shadowRequest:369 [0x120008000]: spotify play request [23:23:48.545] AVTPlay:137 [0x120008000]: uPNP play (cookie 0x1) [23:23:48.565] D MercurySession.cpp:252: Executing Mercury Request, type GET [23:23:48.576] I MercurySession.cpp:42: Received packet, command: 178 [23:23:48.577] D MercurySession.cpp:174: Received mercury packet [23:23:48.577] I TrackQueue.cpp:158: Track name: Starships [23:23:48.577] I TrackQueue.cpp:159: Track duration: 210626 [23:23:48.577] D TrackQueue.cpp:162: trackInfo.restriction.size() = 1 [23:23:48.577] D TrackQueue.cpp:212: File format: 2 [23:23:48.577] D TrackQueue.cpp:212: File format: 1 [23:23:48.589] I MercurySession.cpp:42: Received packet, command: 13 [23:23:48.589] I TrackQueue.cpp:252: Got audio key [23:23:48.589] I TrackQueue.cpp:275: Received access key, fetching CDN URL... [23:23:48.637] I TrackQueue.cpp:301: Received CDN URL, https://audio-ak-spotify-com.akamaized.net/audio/242f31c01b62fbd81819dd11679ebc11ca8eeed1?__token__=exp=1700173428~hmac=9797f0fb5c4ce1c57e0747670e2397fab65aba465c780badcde6c26e2f143cee [23:23:48.711] I HTTPstreamer.cpp:467: got HTTP connection 15 [23:23:48.711] I HTTPstreamer.cpp:210: HTTP received => GET /stream?id=bbbb5e01d9bd_0 HTTP/1.1 Host: 192.168.1.18:57524 Icy-MetaData: 1 Connection: close transferMode.dlna.org: Streaming User-Agent: WinampMPEG/2.8 Accept: */* [23:23:48.715] I HTTPstreamer.cpp:327: HTTP response => HTTP/1.1 200 OK transfermode.dlna.org: streaming Server: spot-connect Content-Type: audio/flac Connection: close [23:23:52.126] ActionHandler:595 [0x120008000]: uPNP transition [23:23:52.709] AddMRDevice:1185 [0x12000b0f0]: adding renderer (Cat Sound) with mac BBBBDA1ADAD2 [23:23:52.722] I BellHTTPServer.cpp:191: Server listening on port 0 [23:23:52.722] I spotify.cpp:556: ZeroConf mode (port 57533) [23:23:52.731] MasterHandler:788 [0x12000b0f0]: subscribe success [23:24:18.453] I TrackPlayer.cpp:224: EOF [23:24:18.453] I TrackPlayer.cpp:255: Playing done [23:24:18.507] I TrackPlayer.cpp:171: Got track ID=d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa [23:24:18.507] I CDNAudioFile.cpp:43: Opening HTTP stream to https://audio-ak-spotify-com.akamaized.net/audio/d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa?__token__=exp=1700173428~hmac=aa4d1801f502dac0426576a86bec97e86e9b6671fe8940454870c848b2b9f42a [23:24:18.975] I CDNAudioFile.cpp:70: Header and footer bytes received [23:24:19.013] I TrackPlayer.cpp:206: Playing [23:24:19.014] I spotify.cpp:176: trackUniqueId update ca46e501c506cba037797d6f95570be14e729ffe => d4afc65c2d230dd59e4562c44e2d0a3d4ae87daa [23:24:19.014] I spotify.cpp:241: draining track bbbb5e01d9bd_0 [23:24:19.014] I spotify.cpp:245: new track id eed0a80a318941dc9d3de9e08b73c35a => [23:24:19.014] I HTTPstreamer.cpp:134: Bound to port 57615 [23:24:19.014] I spotify.cpp:255: loading with id bbbb5e01d9bd_1 [23:24:19.014] shadowRequest:355 [0x120008000]: spotify LOAD request [23:24:19.014] shadowRequest:362 [0x120008000]: Gapped next track http://192.168.1.18:57615/stream?id=bbbb5e01d9bd_1 [23:24:52.761] I HTTPstreamer.cpp:492: HTTP streaming finished for 15 (id: bbbb5e01d9bd_0) [23:25:48.010] I MercurySession.cpp:42: Received packet, command: 4 [23:25:48.010] D TimeProvider.cpp:15: Time synced with spotify servers [23:25:48.016] I MercurySession.cpp:42: Received packet, command: 74 exit [23:26:00.475] main:1648 stopping devices ... [23:26:00.475] Stop:1319 terminate update thread ... [23:26:00.475] Stop:1327 flush renderers ... [23:26:00.475] I spotify.cpp:146: player deletion pending [23:26:00.631] I TrackPlayer.cpp:98: Resetting state [23:26:00.681] I TrackPlayer.cpp:255: Playing done [23:26:00.682] I MercurySession.cpp:128: Disconnecting mercury session [23:26:00.682] I PlainConnection.cpp:197: Closing socket... [23:26:00.682] E MercurySession.cpp:53: Error while receiving packet: Error in read [23:26:00.682] I TrackPlayer.cpp:98: Resetting state [23:26:00.683] I spotify.cpp:645: disconnecting player [23:26:00.683] I spotify.cpp:654: terminating player [23:26:00.683] I spotify.cpp:156: done [23:26:01.915] I HTTPstreamer.cpp:147: HTTP streamer bbbb5e01d9bd_1 deleted [23:26:01.933] I HTTPstreamer.cpp:147: HTTP streamer bbbb5e01d9bd_0 deleted [23:26:02.439] MRThread:277 [0x120008000] player thread exited [23:26:02.440] I spotify.cpp:146: player deletion pending [23:26:02.441] I spotify.cpp:654: terminating player [23:26:02.441] I spotify.cpp:156: done [23:26:02.793] MRThread:277 [0x12000b0f0] player thread exited [23:26:02.793] Stop:1330 terminate libupnp [23:26:02.817] Stop:1346 terminate main thread ... [23:26:02.817] main:1650 all done ```

I hope it helps, let me know if I need to do other tests or differently!

philippe44 commented 8 months ago

The second log is clear, thanks. So, is the JBL device that guy https://www.pcmag.com/reviews/jbl-onbeat-air? If it is, it's funny because I have one and it has been causing me troubles forever, it was one of my first UPnP "fights".

If you look at the UPnP protocol, controller set the URI where to grab the audio, then send a "PLAY" command. Players have a status request command where they can be mainly PLAYING, PAUSED, STOPPED and ... TRANSITIONING. The last one means "I'm busy, but ask me later and I'll tell you where I am". My UPnP clients wait to detect the "PLAYING" state before moving one, and in our case, sending the next track. That JBL device enters "transitioning" state when you ask it to play and ... never exits it. I've never figured out why but I confirmed that other UPnP controller had the same issue, they are able to play one track and then stopped because that JBL never "plays".

Now, you might have some luck because I created a mode named "flow" in spotupnp where all the spotify tracks are sent as a single stream, like a webradio. There are some pros and cons and it's a pretty difficult mode to implement when the Spotify controller uses pause and seeking, and I've not run test for that mode in a long while, but that might work for you. The player will never exit the "transition" mode.

Now, this issue likely explains why it refused to pause. As it never plays, it does not pause. I'll run some tests and report because I should have that player somewhere.

philippe44 commented 8 months ago

All right, found the speaker. So, the UPnP will not work, I remember why now. Even in flow mode, staying in "transitioning" mode is not enough. Now, because that JBL does AirPlay (and better than UPnP), you can still use it with my apps, you just have to use spotraop instead of spotupnp and it will work!

Now, because it's AirPlay and if you use Spotify from an iPhone (AFAIU), then why not using AirPlay natively?

trilame commented 8 months ago

Yes, that's the one!! Thanks again for the explanations. And I'm glad you found it back, you allowed me to avoid some tests ;)

You are right, I'm surrounded by Apple devices at home, I could use the AirPlay integrated with this JBL. The reason is that I do like Spotify Connect versus Airplay: with Airplay, I always have this 2-3 seconds delay (which is really annoying when I skip tracks for example), it stops the music if accidentally I there is something else on the phone (like a video on Twitter), etc. And overall, I like the Spotify Connect way of working.

So, my initial motivation was to give a new life to this old speaker and enjoy it more with Spotify Connect.

I will give a try with spotraop anyway. For the moment I'm stuck with the error is loading libcrypto in an unsafe way but I will find out.

philippe44 commented 8 months ago

oh, yes that one issue with macOS... Use the -static version of spotraop-macos that I just added

trilame commented 8 months ago

Big thanks for the -static version. I just tried it, and so far everything works great!

There is still a little delay, but way shorter than with the regular AirPlay. So, it looks more convenient for my usage.

I will keep testing it and let you know if I find any other issue ;)

Apart from that, I noticed something else. For some reason, since I started all those tests, the highest volume of my JBL is lower than before. It's the case whether I use SpotConnect or not. Not sure why. Maybe I'll try to reset it.

Edit: not sure how I did it, but volume now came back to a normal behavior. I'm now enjoying spotraop, launched automatically, with the right config file! It's really what I was looking for in the end, so thanks a lot.

A big target for me would be to do this, but directly in the JBL... No idea how to do it, but if it supports AirPlay, why not hack it so it supports Spotify Connect...