Skip to content

spotify: Forward librespot log messages to Gstreamer logging (Fixes #613).

Nick Steel requested to merge kingosticks/gst-plugins-rs:spotify-logging into main

Librespot trace (and above) logging is forwarded to new "librespot" gst::DebugCategoryLogger.

An example of what you now get when running with GST_DEBUG=librespot:4:

0:00:09.727911037 3123225 0x7ff260022510 INFO               librespot session.rs:201:librespot_core::session: Connecting to AP "ap-gew1.spotify.com:4070"
0:00:15.729543122 3123225 0x7ff260022510 WARN               librespot session.rs:220:librespot_core::session: Try another access point...
0:00:15.729587422 3123225 0x7ff260022510 INFO               librespot session.rs:201:librespot_core::session: Connecting to AP "ap-gew1.spotify.com:443"
0:00:15.851529049 3123225 0x7ff260022510 INFO               librespot session.rs:231:librespot_core::session: Authenticated as 'XXXXX' !
0:00:15.852100056 3123225 0x7ff25c001b40 INFO               librespot session.rs:635:librespot_core::session: Country: "XX"
0:00:15.853814076 3123225 0x7ff244000f00 INFO               librespot convert.rs:29:librespot_playback::convert: Converting with ditherer: tpdf
0:00:15.857266617 3123225 0x7ff21c002f20 INFO               librespot spclient.rs:96:librespot_core::spclient: Resolved "gew1-spclient.spotify.com:443" as spclient access point
0:00:16.028998827 3123225 0x7ff21c002f20 INFO               librespot player.rs:951:librespot_playback::player: Loading <Come out to La> with Spotify URI <spotify:track:1ffgkx3sYnqMhtu0fmYZ7q>
0:00:16.049287264 3123225 0x7ff21c002f20 INFO               librespot passthrough_decoder.rs:62:librespot_playback::decoder::passthrough_decoder: Starting passthrough track with serial 3120995202
0:00:16.049498367 3123225 0x7ff21c002f20 INFO               librespot player.rs:1144:librespot_playback::player: <Come out to La> (209480 ms) loaded

Unfortunately, cranking it up to DEBUG level (GST_DEBUG=librespot:5) where all the action happens, also includes the extremely noisy (and uninteresting) rustls logging:

0:03:05.310118282 3123267 0x7fe314000cd0 DEBUG              librespot session.rs:125:librespot_core::session: new Session
0:03:05.310180382 3123267 0x7fe314000cd0 DEBUG              librespot apresolve.rs:44:librespot_core::apresolve: new ApResolver
0:03:05.310235883 3123267 0x7fe314000cd0 DEBUG              librespot http_client.rs:176:librespot_core::http_client: Requesting https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient
0:03:05.316754259 3123267 0x7fe314000cd0 DEBUG              librespot config.rs:81:hyper_rustls::config: with_native_roots processed 147 valid and 0 invalid certs
0:03:05.322055121 3123267 0x7fe314000cd0 DEBUG              librespot config.rs:42:hyper_rustls::config: with_native_roots processed 147 valid and 0 invalid certs
0:03:05.329065702 3123267 0x7fe314000cd0 DEBUG              librespot hs.rs:79:rustls::client::hs: No cached session for DnsName("apresolve.spotify.com")
0:03:05.329180504 3123267 0x7fe314000cd0 DEBUG              librespot hs.rs:137:rustls::client::hs: Not resuming any session
0:03:05.338308910 3123267 0x7fe314000cd0 DEBUG              librespot hs.rs:786:rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384
0:03:05.338365911 3123267 0x7fe314000cd0 DEBUG              librespot tls13.rs:143:rustls::client::tls13: Not resuming
0:03:05.338451312 3123267 0x7fe314000cd0 DEBUG              librespot tls13.rs:425:rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(6832)])]
0:03:05.338479412 3123267 0x7fe314000cd0 DEBUG              librespot hs.rs:643:rustls::client::hs: ALPN protocol is Some(b"h2")
0:03:05.361032275 3123267 0x7fe314000cd0 INFO               librespot session.rs:201:librespot_core::session: Connecting to AP "ap-gew1.spotify.com:4070"
0:03:08.362772035 3123267 0x7fe314000cd0 DEBUG              librespot mod.rs:83:librespot_core::connection: Connection failed: timed out
0:03:08.362933337 3123267 0x7fe314000cd0 DEBUG              librespot mod.rs:86:librespot_core::connection: Retry access point...
0:03:11.364287991 3123267 0x7fe314000cd0 DEBUG              librespot mod.rs:83:librespot_core::connection: Connection failed: timed out
0:03:11.364350392 3123267 0x7fe314000cd0 WARN               librespot session.rs:220:librespot_core::session: Try another access point...
0:03:11.364364592 3123267 0x7fe314000cd0 INFO               librespot session.rs:201:librespot_core::session: Connecting to AP "ap-gew1.spotify.com:443"
0:03:11.408936111 3123267 0x7fe314000cd0 DEBUG              librespot mod.rs:162:librespot_core::connection: Authenticating with AP using AUTHENTICATION_STORED_SPOTIFY_CREDENTIALS
0:03:11.499732568 3123267 0x7fe314000cd0 INFO               librespot session.rs:231:librespot_core::session: Authenticated as 'XXXXX' !
0:03:11.500289275 3123267 0x7fe328001af0 DEBUG              librespot session.rs:326:librespot_core::session: Session strong=2 weak=3
0:03:11.500469077 3123267 0x7fe328001af0 INFO               librespot session.rs:635:librespot_core::session: Country: "XX"
0:03:11.500618078 3123267 0x7fe32403fdc0 DEBUG              librespot player.rs:454:librespot_playback::player: new Player [1]
0:03:11.500813281 3123267 0x7fe32403fdc0 INFO               librespot convert.rs:29:librespot_playback::convert: Converting with ditherer: tpdf
0:03:11.504825527 3123267 0x7fe32403fdc0 DEBUG              librespot player.rs:2079:librespot_playback::player: command=AddEventSender
0:03:11.504985729 3123267 0x7fe32403fdc0 DEBUG              librespot player.rs:2079:librespot_playback::player: command=Load(SpotifyId("spotify:track:1ffgkx3sYnqMhtu0fmYZ7q"), true, 0)
0:03:11.505524736 3123267 0x7fe340011540 DEBUG              librespot spclient.rs:42:librespot_core::spclient: new SpClient
0:03:11.505712938 3123267 0x7fe340011540 INFO               librespot spclient.rs:96:librespot_core::spclient: Resolved "gew1-spclient.spotify.com:443" as spclient access point
0:03:11.505781839 3123267 0x7fe340011540 DEBUG              librespot token.rs:18:librespot_core::token: new TokenProvider
0:03:11.505794439 3123267 0x7fe340011540 DEBUG              librespot mod.rs:22:librespot_core::mercury: new MercuryManager
0:03:11.526803183 3123267 0x7fe340011540 DEBUG              librespot spclient.rs:178:librespot_core::spclient: Client token unavailable or expired, requesting new token.
0:03:11.527127187 3123267 0x7fe340011540 DEBUG              librespot http_client.rs:176:librespot_core::http_client: Requesting https://clienttoken.spotify.com/v1/clienttoken
0:03:11.549092143 3123267 0x7fe340011540 DEBUG              librespot hs.rs:79:rustls::client::hs: No cached session for DnsName("clienttoken.spotify.com")
0:03:11.549452047 3123267 0x7fe340011540 DEBUG              librespot hs.rs:137:rustls::client::hs: Not resuming any session
0:03:11.559219361 3123267 0x7fe340011540 DEBUG              librespot hs.rs:786:rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384
0:03:11.559321762 3123267 0x7fe340011540 DEBUG              librespot tls13.rs:143:rustls::client::tls13: Not resuming
0:03:11.559486864 3123267 0x7fe340011540 DEBUG              librespot tls13.rs:425:rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(6832)])]
0:03:11.559555165 3123267 0x7fe340011540 DEBUG              librespot hs.rs:643:rustls::client::hs: ALPN protocol is Some(b"h2")
0:03:11.582390031 3123267 0x7fe328001af0 DEBUG              librespot mod.rs:280:librespot_core::mercury: unknown subscription uri=hm://pusher/v1/connections/NThlN2E2NTAtNTVjNy00MmEwLWI3ZmMtZGZiZjQ5MzY5YWQwK0FQK3RjcDovL2FwLTQzLXN3aW0uc2VydmljZXMuZ2V3MS5zcG90aWZ5Lm5ldDo1MDI2K0Q4MUYzNTVBRjg4RTZFMkFBODMyNjlBRjE0MkRGREVCM0NBQzg3QTkxRkVDRjRGM0I2Qzc5QzY0MzNCNEVEQTA%3D
0:03:11.582490432 3123267 0x7fe328001af0 DEBUG              librespot session.rs:715:librespot_core::session: could not dispatch command: Service unavailable { error handling Mercury response: MercuryResponse { uri: "hm://pusher/v1/connections/NThlN2E2NTAtNTVjNy00MmEwLWI3ZmMtZGZiZjQ5MzY5YWQwK0FQK3RjcDovL2FwLTQzLXN3aW0uc2VydmljZXMuZ2V3MS5zcG90aWZ5Lm5ldDo1MDI2K0Q4MUYzNTVBRjg4RTZFMkFBODMyNjlBRjE0MkRGREVCM0NBQzg3QTkxRkVDRjRGM0I2Qzc5QzY0MzNCNEVEQTA%3D", status_code: 200, payload: [] } }
0:03:11.582930537 3123267 0x7fe340011540 DEBUG              librespot spclient.rs:274:librespot_core::spclient: Received a granted token
0:03:11.583008238 3123267 0x7fe340011540 DEBUG              librespot http_client.rs:176:librespot_core::http_client: Requesting https://gew1-spclient.spotify.com:443/metadata/4/track/28efc26466134a6aa6b762bca9a4ef60?product=0&country=GB&salt=1402535511
0:03:11.591365235 3123267 0x7fe340011540 DEBUG              librespot hs.rs:79:rustls::client::hs: No cached session for DnsName("gew1-spclient.spotify.com")
0:03:11.591506737 3123267 0x7fe340011540 DEBUG              librespot hs.rs:137:rustls::client::hs: Not resuming any session
0:03:11.601896058 3123267 0x7fe340011540 DEBUG              librespot hs.rs:786:rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384
0:03:11.601984059 3123267 0x7fe340011540 DEBUG              librespot tls13.rs:143:rustls::client::tls13: Not resuming
0:03:11.602124961 3123267 0x7fe340011540 DEBUG              librespot tls13.rs:425:rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(6832)])]
0:03:11.602182661 3123267 0x7fe340011540 DEBUG              librespot hs.rs:643:rustls::client::hs: ALPN protocol is Some(b"h2")
0:03:11.633803630 3123267 0x7fe340011540 INFO               librespot player.rs:951:librespot_playback::player: Loading <Come out to La> with Spotify URI <spotify:track:1ffgkx3sYnqMhtu0fmYZ7q>
0:03:11.634074133 3123267 0x7fe340011540 DEBUG              librespot mod.rs:369:librespot_audio::fetch: File 653d73ec4cfb8d3d1188c26717f4f3e183cd2f04 already in cache
0:03:11.634269735 3123267 0x7fe340011540 DEBUG              librespot audio_key.rs:39:librespot_core::audio_key: new AudioKeyManager
0:03:11.648768104 3123267 0x7fe340011540 INFO               librespot passthrough_decoder.rs:62:librespot_playback::decoder::passthrough_decoder: Starting passthrough track with serial 3121207043
0:03:11.648888905 3123267 0x7fe340011540 DEBUG              librespot passthrough_decoder.rs:26:librespot_playback::decoder::passthrough_decoder: Vorbis header type 1
0:03:11.649013007 3123267 0x7fe340011540 DEBUG              librespot passthrough_decoder.rs:26:librespot_playback::decoder::passthrough_decoder: Vorbis header type 3
0:03:11.649070107 3123267 0x7fe340011540 DEBUG              librespot passthrough_decoder.rs:26:librespot_playback::decoder::passthrough_decoder: Vorbis header type 5
0:03:11.649122008 3123267 0x7fe340011540 DEBUG              librespot passthrough_decoder.rs:128:librespot_playback::decoder::passthrough_decoder: Seek to offset page 0
0:03:11.649179409 3123267 0x7fe340011540 INFO               librespot player.rs:1144:librespot_playback::player: <Come out to La> (209480 ms) loaded
0:03:11.649461312 3123267 0x7fe32403fdc0 DEBUG              librespot passthrough_decoder.rs:167:librespot_playback::decoder::passthrough_decoder: Wrote Ogg headers

I think this is because librespot uses rustls default features, and for some odd reason that includes logging. I'm not aware of any way to filter off this junk, like we'd normally do with something like env_logger. If anyone has a solution (other than trying to fix librespot, which I intend to try), I'd love to hear it.

Merge request reports