Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

DBus Mpris Metadata crashes spotifyd #271

Closed
thexyno opened this issue Jul 7, 2019 · 13 comments
Closed

DBus Mpris Metadata crashes spotifyd #271

thexyno opened this issue Jul 7, 2019 · 13 comments
Labels
bug A functionality or parts of a program that do not work as intended reproducibility: easy An issue that is easily reproduced
Milestone
v0.2.18

Comments

@thexyno
Copy link

thexyno commented Jul 7, 2019

Hello,

when I try to get Metadata via DBus, spotifyd crashes

$ spotifyd --no-daemon
22:27:10 [INFO] Using software volume controller.
22:27:10 [INFO] No backend specified, defaulting to: alsa.
22:27:21 [INFO] Connecting to AP "gew1-accesspoint-a-lcpf.ap.spotify.com:443"
22:27:22 [INFO] Authenticated as "123456789" !
22:27:22 [INFO] Using alsa sink
22:27:22 [INFO] Country: "DE"
22:27:22 [WARN] Unhandled dbus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
22:27:22 [WARN] Unhandled dbus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
22:27:22 [INFO] Loading track "Abschaum" with Spotify URI "spotify:track:6sWCS9fLnJbTELQ0IuFHDE"
22:27:23 [INFO] Track "Abschaum" loaded
22:27:32 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: Error(Executor(EnterError { reason: "attempted to run an executor while another executor is already running" }), "https://api.spotify.com/v1/me/player/currently-playing")

DBus Command:

$ qdbus org.mpris.MediaPlayer2.spotifyd /org/mpris/MediaPlayer2 org.freedesktop.DBus.Properties.Get org.mpris.MediaPlayer2.Player Metadata
Error: org.freedesktop.DBus.Error.NoReply
Message recipient disconnected from message bus without replying

System Info:
Archlinux 5.1.14-arch1-1-ARCH
rustc 1.31.1
@TimOverboard
Copy link

I came here to file a bug report about mpris status request from playerctl crashing the daemon. This looks like the same bug so. attaching my log in case it's of any use. I'm also running arch linux (since July 1973).

I am writing a little sync daemon on my music box and thought the "playerctl -F status" might be of use to me. However, this crash occured without the --follow option.

Command:

$ playerctl -p spotifyd status
Playing
$ playerctl -p spotifyd play           ✔  10Jul19 9:01.53 
No players found

I included that splodge from my powerline cos it shows the time the status command executed.

log:

$ journalctl --user --no-hostname --user-unit=spotifyd -u systemd -r 
Jul 10 09:02:05 spotifyd[26778]: 09:02:05 [INFO] Using software volume controller.
Jul 10 09:02:05 systemd[754]: Started A spotify playing daemon.
Jul 10 09:02:05 systemd[754]: Stopped A spotify playing daemon.
Jul 10 09:02:05 systemd[754]: spotifyd.service: Scheduled restart job, restart counter is at 7.
Jul 10 09:02:05 systemd[754]: spotifyd.service: Service RestartSec=12s expired, scheduling restart.
Jul 10 09:01:53 systemd[754]: spotifyd.service: Failed with result 'exit-code'.
Jul 10 09:01:53 systemd[754]: spotifyd.service: Main process exited, code=exited, status=101/n/a
Jul 10 09:01:53 spotifyd[25554]: 09:01:53 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: Error(Executor(EnterError { reason: "attempted to run an executor while another executor is already running" }), "https://api.spotify.com/v1/me/player")
Jul 10 09:01:34 spotifyd[25554]: 09:01:34 [INFO] Running ["/home/tim/.scriptz/spotifyd-logevent"] with environment variables {"PLAYER_EVENT": "start", "TRACK_ID": "6B1Ume5T9fCaZKGfGp2UWA"}
Jul 10 09:01:31 spotifyd[25554]: 09:01:31 [INFO] Running ["/home/tim/.scriptz/spotifyd-logevent"] with environment variables {"PLAYER_EVENT": "stop", "TRACK_ID": "6B1Ume5T9fCaZKGfGp2UWA"}
Jul 10 09:01:31 spotifyd[25554]: 09:01:31 [INFO] Track "Super Shooter" loaded
Jul 10 09:01:31 spotifyd[25554]: 09:01:31 [INFO] Loading track "Super Shooter" with Spotify URI "spotify:track:6B1Ume5T9fCaZKGfGp2UWA"
Jul 10 09:01:31 spotifyd[25554]: 09:01:31 [WARN] Unhandled dbus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
Jul 10 09:01:30 spotifyd[25554]: 09:01:30 [INFO] Using alsa sink
Jul 10 09:01:30 spotifyd[25554]: 09:01:30 [INFO] Country: "GB"
Jul 10 09:01:30 spotifyd[25554]: 09:01:30 [INFO] Authenticated as "django87" !
Jul 10 09:01:30 spotifyd[25554]: 09:01:30 [INFO] Connecting to AP "gew1-accesspoint-a-0wtt.ap.spotify.com:443"
Jul 10 08:39:09 spotifyd[25554]: 08:39:09 [INFO] Using software volume controller.
Jul 10 08:39:09 systemd[754]: Started A spotify playing daemon.
Jul 10 08:39:09 systemd[754]: Stopped A spotify playing daemon.
Jul 10 08:39:09 systemd[754]: spotifyd.service: Scheduled restart job, restart counter is at 6.
Jul 10 08:39:09 systemd[754]: spotifyd.service: Service RestartSec=12s expired, scheduling restart.
Jul 10 08:38:57 systemd[754]: spotifyd.service: Failed with result 'exit-code'.
Jul 10 08:38:57 systemd[754]: spotifyd.service: Main process exited, code=exited, status=101/n/a
Jul 10 08:38:57 spotifyd[25329]: 08:38:57 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: Error(Executor(EnterError { reason: "attempted to run an executor while another executor is already running" }), "https://api.spotify.com/v1/me/player/currently-playing")
Jul 10 08:38:53 spotifyd[25329]: 08:38:53 [INFO] Running ["/home/tim/.scriptz/spotifyd-logevent"] with environment variables {"PLAYER_EVENT": "start", "TRACK_ID": "6B1Ume5T9fCaZKGfGp2UWA"}
Jul 10 08:38:51 spotifyd[25329]: 08:38:51 [INFO] Running ["/home/tim/.scriptz/spotifyd-logevent"] with environment variables {"TRACK_ID": "6B1Ume5T9fCaZKGfGp2UWA", "PLAYER_EVENT": "stop"}
Jul 10 08:38:51 spotifyd[25329]: 08:38:51 [INFO] Track "Super Shooter" loaded
Jul 10 08:38:51 spotifyd[25329]: 08:38:51 [INFO] Loading track "Super Shooter" with Spotify URI "spotify:track:6B1Ume5T9fCaZKGfGp2UWA"
Jul 10 08:38:51 spotifyd[25329]: 08:38:51 [WARN] Unhandled dbus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
Jul 10 08:38:51 spotifyd[25329]: 08:38:51 [INFO] Using alsa sink
Jul 10 08:38:51 spotifyd[25329]: 08:38:51 [INFO] Country: "GB"
Jul 10 08:38:51 spotifyd[25329]: 08:38:51 [INFO] Authenticated as "django87" !
Jul 10 08:38:51 spotifyd[25329]: 08:38:51 [INFO] Connecting to AP "gew1-accesspoint-exp-6hw4.ap.spotify.com:443"
Jul 10 08:37:14 spotifyd[25329]: 08:37:14 [INFO] Using software volume controller.
Jul 10 08:37:14 systemd[754]: Started A spotify playing daemon.
Jul 10 08:37:14 systemd[754]: Stopped A spotify playing daemon.
Jul 10 08:37:14 systemd[754]: spotifyd.service: Scheduled restart job, restart counter is at 5.
Jul 10 08:37:14 systemd[754]: spotifyd.service: Service RestartSec=12s expired, scheduling restart.
Jul 10 08:37:02 systemd[754]: spotifyd.service: Failed with result 'exit-code'.
Jul 10 08:37:02 systemd[754]: spotifyd.service: Main process exited, code=exited, status=101/n/a

Obviously did it a few times before deciding to post.
Ye gods, it's 9:45!

@TimOverboard
Copy link

a workaround for @ragon000

#258 (comment)

@thexyno
Copy link
Author

thexyno commented Jul 10, 2019

a workaround for @ragon000

#258 (comment)

Thanks for the help, but that workaround got me the exact same error

relevant logs:

15:18:34 [DEBUG] tokio_core::reactor: loop process, 27.057µs
15:18:34 [DEBUG] dbus_tokio::adriver: Polling message stream
15:18:34 [DEBUG] dbus_tokio::adriver: msgstream found Ok(Ready(Some((MethodCall, Some("/org/mpris/MediaPlayer2"), Some("org.freedesktop.DBus.Introspectable"), Some("Introspect")))))
15:18:34 [DEBUG] dbus_tokio::adriver: Polling message stream
15:18:34 [DEBUG] dbus_tokio::adriver: msgstream found Ok(NotReady)
15:18:34 [DEBUG] dbus_tokio::adriver: D-Bus i/o poll ready: 47 is Ready(Readable)
15:18:34 [DEBUG] dbus_tokio::adriver: D-Bus i/o unix ready: 47 is Readable | Aio
15:18:34 [DEBUG] tokio_reactor::registration: scheduling Read for: 4
15:18:34 [DEBUG] tokio_core::reactor: loop poll - 52.877µs
15:18:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 153147, tv_nsec: 628285639 }
15:18:34 [DEBUG] tokio_core::reactor: loop process, 37.774µs
15:18:34 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(50331652)
15:18:34 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
15:18:34 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(50331652)
15:18:34 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
15:18:34 [DEBUG] dbus_tokio::adriver: D-Bus i/o poll ready: 47 is Ready(Readable)
15:18:34 [DEBUG] dbus_tokio::adriver: D-Bus i/o unix ready: 47 is Readable | Aio
15:18:34 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(50331652)
15:18:34 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
15:18:34 [DEBUG] dbus_tokio::adriver: handle_msgs: (MethodCall, Some("/org/mpris/MediaPlayer2"), Some("org.freedesktop.DBus.Properties"), Some("Get"))
15:18:34 [DEBUG] tokio_core::reactor: loop poll - 1.615886ms
15:18:34 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 153147, tv_nsec: 629951659 }
15:18:34 [DEBUG] tokio_core::reactor: loop process, 28.194µs
15:18:34 [DEBUG] dbus_tokio::adriver: Polling message stream
15:18:34 [DEBUG] dbus_tokio::adriver: msgstream found Ok(Ready(Some((MethodCall, Some("/org/mpris/MediaPlayer2"), Some("org.freedesktop.DBus.Properties"), Some("Get")))))
15:18:34 [TRACE] mio::poll: [<unknown>:787] registering with poller
1515:18:34 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(4194303)
:18:3415:18:34 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: Error(Executor(EnterError { reason: "attempted to run an executor while another executor is already running" }), "https://api.spotify.com/v1/me/player/currently-playing")
15:18:34 [TRACE] reqwest::client: [<unknown>:578] response receiver is canceled
15:18:34 [TRACE] tokio_reactor: [<unknown>:390] loop process - 0 events, 0.000s
15:18:34 [DEBUG] librespot_connect::spirc: drop Spirc[0]
15:18:34 [DEBUG] librespot_playback::player: Shutting down player thread ...
15:18:34 [DEBUG] librespot_playback::player: drop Player[0]
15:18:34 [DEBUG] dbus_tokio::adriver: Dropping AMessageStream
15:18:34 [DEBUG] dbus_tokio::adriver: AMessageStream telling ADriver to quit
15:18:34 [TRACE] tokio_threadpool::pool: [<unknown>:138] shutdown; state=pool::State { lifecycle: Running, num_futures: 0 }
15:18:34 [TRACE] tokio_threadpool::pool: [<unknown>:186]   -> transitioned to shutdown
15:18:34 [TRACE] tokio_threadpool::pool: [<unknown>:207]   -> shutting down workers
15:18:34 [DEBUG] tokio_reactor: dropping I/O source: 3
15:18:34 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
15:18:34 [DEBUG] tokio_reactor: dropping I/O source: 0
15:18:34 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
15:18:34 [DEBUG] tokio_reactor: dropping I/O source: 1
15:18:34 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
15:18:34 [DEBUG] tokio_reactor: dropping I/O source: 2
15:18:34 [DEBUG] librespot_core::session: drop Session[0]
15:18:34 [DEBUG] librespot::component: drop AudioKeyManager
15:18:34 [DEBUG] librespot::component: drop ChannelManager
15:18:34 [DEBUG] librespot::component: drop MercuryManager
15:18:34 [DEBUG] librespot_core::session: drop Dispatch
15:18:34 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
15:18:34 [DEBUG] tokio_reactor: dropping I/O source: 5
15:18:34 [DEBUG] tokio_reactor: dropping I/O source: 4

@Liriel
Copy link

Liriel commented Aug 12, 2019

I have a very similar issue here. Steps to reproduce:

  • start spotify
  • start spotifyd
  • quit spotify
  • spotifyd dies and cannot be restartet
14:48:36 [INFO] Using alsa volume controller.
14:48:36 [INFO] Connecting to AP "gew1-accesspoint-a-7x53.ap.spotify.com:443"
14:48:36 [INFO] Authenticated as "USER" !
14:48:36 [INFO] Country: "DE"
14:48:37 [WARN] Unhandled dbus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
14:48:37 [WARN] Unhandled dbus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
14:48:37 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: Error(Executor(EnterError { reason: "attempted to run an executor while another executor is already running" }), "https://api.spotify.com/v1/me/player")

@jonaslb
Copy link

jonaslb commented Aug 17, 2019

This bug was introduced in "v0.2.11" // commit 62552d6, where the Cargo.lock file was updated.
I don't have a fix, but a workaround is to checkout the Cargo.lock from before this commit, ie. from fae5042. This works even for latest commit on master branch.

@mainrs
Copy link
Member

mainrs commented Aug 18, 2019 •
edited
Loading

Well, we didn't change any direct dependencies ourselves so a package updated its dependencies or a patch version screwed something up. I checked to see if dbus got updated but only its libc dependency got updated from 0.2.51 to 0.2.58.

I am currently busy with my bachelor's thesis but after I'm done with that I can take a closer look.

@Liriel
Copy link

Liriel commented Aug 20, 2019

@jonaslb reverting to the mentioned commit did the trick for me and also fixed the metadata returned by playerctl

@mainrs
Copy link
Member

mainrs commented Aug 20, 2019

Super weird. I'm probably missing something. Not sure which crate is actually responsible for the dbus functionality dbus or dbus-tokio, but both of them are only pinned on their minor version. Cargo would therefore download the newest patch version. The lock file might circumvent this but I am actually not sure. Maybe @simonpersson has more insights on this one....

@mainrs mainrs mentioned this issue Aug 21, 2019
Closed
@hifiberry
Copy link

Any idea how to proceed here? Bug still seems to be active in 0.2.13

@mainrs
Copy link
Member

mainrs commented Sep 17, 2019

Does a cargo build --release --locked work for you? So to reproduce it you guys connect to the daemon and play some music but kill the app that actually controls the daemon? I can't really test it out for some days as I have to do some work related stuff first.

@Felixoid
Copy link

Felixoid commented Sep 18, 2019 •
edited
Loading

Hey @sirwindfield
By following the #294 I've faced the issue as well.

The binary is built as cargo build --release --locked --features pulseaudio_backend,dbus_mpris,dbus_keyring

Here's a log output with verbose.

The application crashes immidiately after the start 

>±> RUST_BACKTRACE=full spotifyd --verbose --no-daemon
12:01:49 [TRACE] spotifyd: [<unknown>:56] CliConfig { config_path: None, no_daemon: true, verbose: true, pid: None, shared_config: SharedConfigValues { username: Some("username"), password: None, password_cmd: None, use_keyring: true, on_song_change_hook: None, cache_path: None, backend: Some(PulseAudio), volume_controller: Some(SoftVolume), device: None, control: None, mixer: None, device_name: Some("ig-fel-spotifyd"), bitrate: Some(Bitrate320), volume_normalisation: false, normalisation_pregain: None, zeroconf_port: None } }
12:01:49 [TRACE] spotifyd::utils: [<unknown>:30] Found shell "/bin/zsh" using SHELL environment variable.
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [TRACE] tokio_threadpool::builder: [<unknown>:430] build; num-workers=4
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [INFO] Using software volume controller.
12:01:49 [DEBUG] tokio_reactor::background: starting background reactor
12:01:49 [DEBUG] tokio_reactor: adding I/O source: 0
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [DEBUG] librespot_connect::discovery: Zeroconf server listening on 0.0.0.0:45817
12:01:49 [DEBUG] tokio_reactor: adding I/O source: 4194305
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Writable Token(4194305)
12:01:49 [DEBUG] tokio_reactor: adding I/O source: 8388610
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Writable Token(8388610)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [INFO] Checking keyring for password
12:01:49 [DEBUG] tokio_reactor: adding I/O source: 12582915
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [TRACE] hyper::client::pool: [<unknown>:125] park; waiting for idle connection: "http://apresolve.spotify.com"
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Writable Token(12582915)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [TRACE] hyper::client::connect: [<unknown>:118] Http::connect("http://apresolve.spotify.com/")
12:01:49 [DEBUG] tokio_core::reactor: consuming notification queue
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 0
12:01:49 [DEBUG] hyper::client::dns: resolving host="apresolve.spotify.com", port=80
----- IP ADRESSES -----
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 1
12:01:49 [TRACE] mdns::fsm: [<unknown>:247] sending packet to V4(224.0.0.251:5353)
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(4194305)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(4194305)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
----- IP ADRESSES -----
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 2
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(8388610)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 3
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 1.14347ms
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 262252082 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 12.197µs
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 1
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 1
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 2
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 2
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 66.712µs
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 262338589 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 9.065µs
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Writable Token(8388610)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 2.602385ms
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 264955008 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 25.498µs
12:01:49 [DEBUG] hyper::client::connect: connecting to 104.199.64.136:80
12:01:49 [DEBUG] tokio_reactor: adding I/O source: 16777220
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Write for: 4
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Writable Token(16777220)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 23.707938ms
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 288855125 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 29.806µs
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=false
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 4
12:01:49 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=None) = true
12:01:49 [TRACE] hyper::proto::h1::role: [<unknown>:349] Client::encode has_body=false, method=None
12:01:49 [TRACE] hyper::proto::h1::io: [<unknown>:546] reclaiming write buf Vec
12:01:49 [DEBUG] hyper::proto::h1::io: flushed 47 bytes
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: KeepAlive, keep_alive: Busy, error: None }
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 157.442µs
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 289105211 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 20.059µs
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(8388610)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 1
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 2
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 2
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 22.170503ms
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 311307604 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 35.556µs
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(16777220)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:193] Conn::read_head
12:01:49 [DEBUG] hyper::proto::h1::io: read 685 bytes
12:01:49 [TRACE] hyper::proto::h1::role: [<unknown>:254] Response.parse([Header; 100], [u8; 685])
12:01:49 [TRACE] hyper::proto::h1::role: [<unknown>:259] Response.parse Complete(267)
12:01:49 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Keep-Alive"
12:01:49 [TRACE] hyper::header: [<unknown>:355] maybe_literal not found, copying "Vary"
12:01:49 [DEBUG] hyper::proto::h1::io: parsed 9 headers (267 bytes)
12:01:49 [DEBUG] hyper::proto::h1::conn: incoming body is content-length (418 bytes)
12:01:49 [TRACE] hyper::proto: [<unknown>:133] expecting_continue(version=Http11, header=None) = false
12:01:49 [TRACE] hyper::proto: [<unknown>:122] should_keep_alive(version=Http11, header=Some(Connection([KeepAlive]))) = true
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:279] Conn::read_body
12:01:49 [TRACE] hyper::proto::h1::decode: [<unknown>:88] decode; state=Length(418)
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Body(Length(0)), writing: KeepAlive, keep_alive: Busy, error: None }
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 3.89449ms
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 315264915 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 37.375µs
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:279] Conn::read_body
12:01:49 [TRACE] hyper::proto::h1::decode: [<unknown>:88] decode; state=Length(0)
12:01:49 [DEBUG] hyper::proto::h1::conn: incoming body completed
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 4
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:460] maybe_notify; read_from_io blocked
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=false
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 4
12:01:49 [TRACE] want: [<unknown>:268] signal: Want
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Init, writing: Init, keep_alive: Idle, error: None }
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
12:01:49 [TRACE] want: [<unknown>:132] poll_want: taker wants!
12:01:49 [TRACE] hyper::client::pool: [<unknown>:306] pool dropped, dropping pooled ("http://apresolve.spotify.com")
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 382.936µs
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 315789133 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 40.518µs
12:01:49 [INFO] Connecting to AP "gew1-accesspoint-a-6htn.ap.spotify.com:443"
12:01:49 [DEBUG] tokio_reactor: adding I/O source: 20971525
12:01:49 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Write for: 5
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:317] read_keep_alive; is_mid_message=false
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 4
12:01:49 [TRACE] hyper::proto::h1::dispatch: [<unknown>:414] client tx closed
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:904] State::close_read()
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:914] State::close_write()
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:654] flushed State { reading: Closed, writing: Closed, keep_alive: Disabled, error: None }
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:337] wants_read_again? false
12:01:49 [TRACE] hyper::proto::h1::conn: [<unknown>:662] shut down IO
12:01:49 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
12:01:49 [DEBUG] tokio_reactor: dropping I/O source: 4
12:01:49 [TRACE] want: [<unknown>:261] signal: Closed
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 225.629µs
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 335180659 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 37.551µs
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Writable Token(20971525)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 24.450545ms
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 359683294 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 54.481µs
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 5
12:01:49 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(20971525)
12:01:49 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:49 [DEBUG] tokio_core::reactor: loop poll - 25.103765ms
12:01:49 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 401512863 }
12:01:49 [DEBUG] tokio_core::reactor: loop process, 20.146µs
12:01:49 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:189] flushing framed transport
12:01:49 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:192] writing; remaining=155
12:01:49 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:213] framed transport flushed
12:01:49 [DEBUG] tokio_reactor::registration: scheduling Read for: 5
12:01:50 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(20971525)
12:01:50 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:50 [DEBUG] tokio_core::reactor: loop poll - 131.652031ms
12:01:50 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 540416839 }
12:01:50 [DEBUG] tokio_core::reactor: loop process, 94.986µs
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [INFO] Authenticated as "username" !
12:01:50 [DEBUG] librespot_core::session: new Session[0]
12:01:50 [DEBUG] librespot_connect::spirc: new Spirc[0]
12:01:50 [DEBUG] librespot::component: new MercuryManager
12:01:50 [DEBUG] librespot_connect::spirc: input volume:65535 to mixer: 65535
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [DEBUG] librespot_core::session: Session[0] strong=4 weak=2
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [INFO] Country: "DE"
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [DEBUG] tokio_reactor::registration: scheduling Read for: 5
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:189] flushing framed transport
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:192] writing; remaining=872
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:213] framed transport flushed
12:01:50 [DEBUG] tokio_core::reactor: loop poll - 752.127µs
12:01:50 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 542016871 }
12:01:50 [DEBUG] tokio_core::reactor: loop process, 67.721µs
12:01:50 [DEBUG] librespot_playback::player: new Player[0]
12:01:50 [DEBUG] librespot_playback::audio_backend::pulseaudio: Using PulseAudio sink
12:01:50 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(20971525)
12:01:50 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [DEBUG] tokio_reactor::registration: scheduling Read for: 5
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:189] flushing framed transport
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:213] framed transport flushed
12:01:50 [DEBUG] tokio_core::reactor: loop poll - 22.442743ms
12:01:50 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 564561404 }
12:01:50 [DEBUG] tokio_core::reactor: loop process, 17.952µs
12:01:50 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(20971525)
12:01:50 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [DEBUG] tokio_reactor::registration: scheduling Read for: 5
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:189] flushing framed transport
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:213] framed transport flushed
12:01:50 [DEBUG] tokio_core::reactor: loop poll - 6.976129ms
12:01:50 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 571565625 }
12:01:50 [DEBUG] tokio_core::reactor: loop process, 108.191µs
12:01:50 [DEBUG] librespot_core::mercury: subscribed uri=hm://remote/user/username/ count=0
12:01:50 [DEBUG] tokio_core::reactor: loop poll - 9.462µs
12:01:50 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 571857029 }
12:01:50 [DEBUG] tokio_core::reactor: loop process, 78.478µs
12:01:50 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(20971525)
12:01:50 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [DEBUG] tokio_reactor::registration: scheduling Read for: 5
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:189] flushing framed transport
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:213] framed transport flushed
12:01:50 [DEBUG] tokio_core::reactor: loop poll - 17.484615ms
12:01:50 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 589450924 }
12:01:50 [DEBUG] tokio_core::reactor: loop process, 47.216µs
12:01:50 [DEBUG] dbus_tokio::adriver: Modify_watch: Watch { fd: 23, read: true, write: false }, poll_now: false
12:01:50 [DEBUG] tokio_reactor: adding I/O source: 25165828
12:01:50 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:50 [DEBUG] dbus_tokio::adriver: Dropping AConnection
12:01:50 [DEBUG] tokio_reactor::registration: scheduling Read for: 4
12:01:50 [DEBUG] tokio_reactor::registration: scheduling Read for: 4
12:01:50 [DEBUG] dbus_tokio::adriver: D-Bus i/o poll ready: 23 is NotReady
12:01:50 [DEBUG] dbus_tokio::adriver: handle_msgs: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
12:01:50 [DEBUG] dbus_tokio::adriver: handle_msgs: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
12:01:50 [DEBUG] dbus_tokio::adriver: handle_msgs: (MethodCall, Some("/org/mpris/MediaPlayer2"), Some("org.freedesktop.DBus.Properties"), Some("GetAll"))
12:01:50 [DEBUG] tokio_core::reactor: loop poll - 79.425µs
12:01:50 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 591188778 }
12:01:50 [DEBUG] tokio_core::reactor: loop process, 18.488µs
12:01:50 [TRACE] tokio_reactor: [<unknown>:376] event Readable | Writable Token(20971525)
12:01:50 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:196] frame decoded from buffer
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_read: [<unknown>:193] attempting to decode a frame
12:01:50 [DEBUG] tokio_reactor::registration: scheduling Read for: 5
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:189] flushing framed transport
12:01:50 [TRACE] tokio_io::_tokio_codec::framed_write: [<unknown>:213] framed transport flushed
12:01:50 [DEBUG] tokio_core::reactor: loop poll - 36.538943ms
12:01:50 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 1039786, tv_nsec: 627754920 }
12:01:50 [DEBUG] tokio_core::reactor: loop process, 26.507µs
12:01:50 [DEBUG] dbus_tokio::adriver: Polling message stream
12:01:50 [DEBUG] dbus_tokio::adriver: msgstream found Ok(Ready(Some((Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired")))))
12:01:50 [WARN] Unhandled dbus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
12:01:50 [DEBUG] dbus_tokio::adriver: Polling message stream
12:01:50 [DEBUG] dbus_tokio::adriver: msgstream found Ok(Ready(Some((Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired")))))
12:01:50 [WARN] Unhandled dbus message: (Signal, Some("/org/freedesktop/DBus"), Some("org.freedesktop.DBus"), Some("NameAcquired"))
12:01:50 [DEBUG] dbus_tokio::adriver: Polling message stream
12:01:50 [DEBUG] dbus_tokio::adriver: msgstream found Ok(Ready(Some((MethodCall, Some("/org/mpris/MediaPlayer2"), Some("org.freedesktop.DBus.Properties"), Some("GetAll")))))
12:01:50 [TRACE] mio::poll: [<unknown>:787] registering with poller
12:01:50 [ERROR] Caught panic with message: called `Result::unwrap()` on an `Err` value: Error(BlockingClientInFutureContext, "https://api.spotify.com/v1/me/player")
12:01:50 [TRACE] reqwest::client: [<unknown>:588] response receiver is canceled
12:01:50 [DEBUG] librespot_connect::spirc: drop Spirc[0]
12:01:50 [DEBUG] librespot_playback::player: Shutting down player thread ...
12:01:50 [DEBUG] librespot_playback::player: drop Player[0]
12:01:50 [DEBUG] librespot_core::session: drop Session[0]
12:01:50 [DEBUG] librespot::component: drop MercuryManager
12:01:50 [DEBUG] dbus_tokio::adriver: Dropping AMessageStream
12:01:50 [DEBUG] dbus_tokio::adriver: AMessageStream telling ADriver to quit
12:01:50 [TRACE] tokio_threadpool::pool: [<unknown>:138] shutdown; state=pool::State { lifecycle: Running, num_futures: 0 }
12:01:50 [TRACE] tokio_threadpool::pool: [<unknown>:186]   -> transitioned to shutdown
12:01:50 [TRACE] tokio_threadpool::pool: [<unknown>:207]   -> shutting down workers
12:01:50 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
12:01:50 [DEBUG] tokio_reactor: dropping I/O source: 0
12:01:50 [DEBUG] tokio_reactor: dropping I/O source: 3
12:01:50 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
12:01:50 [DEBUG] tokio_reactor: dropping I/O source: 1
12:01:50 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
12:01:50 [DEBUG] tokio_reactor: dropping I/O source: 2
12:01:50 [DEBUG] tokio_reactor: dropping I/O source: 4
12:01:50 [DEBUG] librespot_core::session: drop Dispatch
12:01:50 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
12:01:50 [DEBUG] tokio_reactor: dropping I/O source: 5

exited with code 101

@hifiberry
Copy link

hifiberry commented Sep 18, 2019 •
edited by mainrs
Loading

Same here, compiled with

cargo build --release --features="dbus_mpris" --locked

dbus-send --system --print-reply --dest=org.mpris.MediaPlayer2.spotifyd /org/mpris/MediaPlayer2 org.freedesktop.DBus.Properties.Get string:'org.mpris.MediaPlayer2.Player' string:'PlaybackStatus'
Here's a log output with verbose.

(I'm using the system dbus, not a session instance) 

13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [DEBUG] dbus_tokio::adriver: D-Bus i/o poll ready: 23 is Ready(Readable)
13:57:54 [DEBUG] dbus_tokio::adriver: D-Bus i/o unix ready: 23 is Readable | Aio
13:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(33554438)
13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
13:57:54 [DEBUG] dbus_tokio::adriver: handle_msgs: (MethodCall, Some("/org/mpris/MediaPlayer2"), Some("org.freedesktop.DBus.Properties"), Some("Get"))
13:57:54 [DEBUG] tokio_core::reactor: loop poll - 9.666267097s
13:57:54 [DEBUG] tokio_core::reactor: loop time - Instant { tv_sec: 518, tv_nsec: 523579399 }
13:57:54 [DEBUG] tokio_core::reactor: loop process, 79.22µs
13:57:54 [DEBUG] dbus_tokio::adriver: Polling message stream
13:57:54 [DEBUG] dbus_tokio::adriver: msgstream found Ok(Ready(Some((MethodCall, Some("/org/mpris/MediaPlayer2"), Some("org.freedesktop.DBus.Properties"), Some("Get")))))
13:57:54 [TRACE] mio::poll: [<unknown>:787] registering with poller
1313:57:54 [TRACE] tokio_reactor: [<unknown>:376] event Readable Token(4194303)
:5713:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 1 events, 0.000s
:54 [ERROR13:57:54 [TRACE] reqwest::client: [<unknown>:588] response receiver is canceled
] 13:57:54 [TRACE] tokio_reactor: [<unknown>:390] loop process - 0 events, 0.000s
Caught panic with message: called `Result::unwrap()` on an `Err` value: Error(BlockingClientInFutureContext, "https://api.spotify.com/v1/me/player")
13:57:54 [DEBUG] librespot_connect::spirc: drop Spirc[0]
13:57:54 [DEBUG] librespot_playback::player: Shutting down player thread ...
13:57:54 [DEBUG] librespot_playback::player: drop Player[0]
13:57:54 [DEBUG] librespot_core::session: drop Session[0]
13:57:54 [DEBUG] librespot::component: drop MercuryManager
13:57:54 [DEBUG] dbus_tokio::adriver: Dropping AMessageStream
13:57:54 [DEBUG] dbus_tokio::adriver: AMessageStream telling ADriver to quit
13:57:54 [TRACE] tokio_threadpool::pool: [<unknown>:138] shutdown; state=pool::State { lifecycle: Running, num_futures: 0 }
13:57:54 [TRACE] tokio_threadpool::pool: [<unknown>:186]   -> transitioned to shutdown
13:57:54 [TRACE] tokio_threadpool::pool: [<unknown>:207]   -> shutting down workers
13:57:54 [DEBUG] tokio_reactor: dropping I/O source: 3
13:57:54 [DEBUG] librespot_core::session: drop Dispatch
13:57:54 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
13:57:54 [DEBUG] tokio_reactor: dropping I/O source: 5
13:57:54 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
13:57:54 [DEBUG] tokio_reactor: dropping I/O source: 1
13:57:54 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
13:57:54 [DEBUG] tokio_reactor: dropping I/O source: 2
13:57:54 [TRACE] mio::poll: [<unknown>:907] deregistering handle with poller
13:57:54 [DEBUG] tokio_reactor: dropping I/O source: 0
13:57:54 [DEBUG] tokio_reactor: dropping I/O source: 6

@mainrs mainrs added bug A functionality or parts of a program that do not work as intended reproducibility: easy An issue that is easily reproduced labels Sep 18, 2019
@mainrs mainrs mentioned this issue Sep 23, 2019
Closed
@mainrs mainrs added this to the v0.2.18 milestone Oct 1, 2019
@taigrr
Copy link

taigrr commented Oct 3, 2019

@sirwindfield can confirm works now after #346

@taigrr taigrr mentioned this issue Oct 3, 2019
Merged
@mainrs mainrs closed this as completed Oct 3, 2019
@wazabees wazabees mentioned this issue Apr 1, 2021
Open
@busti busti mentioned this issue Jan 23, 2022
Open
6 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug A functionality or parts of a program that do not work as intended reproducibility: easy An issue that is easily reproduced
Projects
None yet
Milestone
v0.2.18
Development

No branches or pull requests
8 participants
@Liriel @Felixoid @mainrs @hifiberry @taigrr @jonaslb @TimOverboard @thexyno