search

plietar / librespot

Open Source Spotify client library
MIT License
1.13k stars 187 forks source link

thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: AudioKeyError' #206

Open dev-zero opened 7 years ago

dev-zero commented 7 years ago

I get the following error when trying to run librespot (in discovery mode) with either ALSA or Portaudio backend:

RUST_BACKTRACE=1 /opt/librespot/target/release/librespot --cache /var/lib/kodi/.cache/librespot --name Gambit -b 320
INFO:librespot: librespot 2259188 (2017-06-14). Built on 2017-06-25.
INFO:librespot::session: Connecting to AP "lon3-accesspoint-a53.ap.spotify.com:4070"
INFO:librespot::session: Authenticated as "********************************************" !
INFO:librespot::session: Country: "CH"
INFO:librespot::audio_backend::alsa: Using alsa sink
INFO:librespot::player: Loading track "Walking The Wire"
WARN:librespot::audio_key: error audio key 0 1
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: AudioKeyError', src/libcore/result.rs:868
stack backtrace:
   1:     0x55559df9f63c - std::sys::imp::backtrace::tracing::imp::write::h59f11508bbbb14ed
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:42
   2:     0x55559dfa44fe - std::panicking::default_hook::{{closure}}::h6803a4f823630483
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:351
   3:     0x55559dfa4104 - std::panicking::default_hook::h34bd173121b68cc3
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:367
   4:     0x55559dfa499b - std::panicking::rust_panic_with_hook::h9dbf610601b6a7e6
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:555
   5:     0x55559dfa4834 - std::panicking::begin_panic::hb6716f52468b0723
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:517
   6:     0x55559dfa4759 - std::panicking::begin_panic_fmt::h26c3fb5a170461f1
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:501
   7:     0x55559dfa46e7 - rust_begin_unwind
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:477
   8:     0x55559dfe395d - core::panicking::panic_fmt::hf96d4d16395a9d71
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libcore/panicking.rs:69
   9:     0x55559dcbc810 - core::result::unwrap_failed::h226c2e6c60f226c0
  10:     0x55559dd218db - librespot::player::PlayerInternal::load_track::h98655d8beb662f03
  11:     0x55559dd1b92f - librespot::player::PlayerInternal::run::hc0ab7de3d31cd36a
  12:     0x55559dc85292 - std::panicking::try::do_call::h70fe5412c2307000
  13:     0x55559dfad30a - __rust_maybe_catch_panic
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libpanic_unwind/lib.rs:98
  14:     0x55559dc89b6d - <F as alloc::boxed::FnBox<A>>::call_box::hfd6d939166bb691d
  15:     0x55559dfa37e4 - std::sys::imp::thread::Thread::new::thread_start::hb5d1d3fd59bea9f8
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/liballoc/boxed.rs:624
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/sys_common/thread.rs:21
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/sys/unix/thread.rs:84
  16:     0x7f1f436a23d3 - start_thread
  17:     0x7f1f43ba3f4e - __GI___clone
                        at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105
  18:                0x0 - <unknown>

thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: "SendError(..)"', src/libcore/result.rs:868
stack backtrace:
   1:     0x55559df9f63c - std::sys::imp::backtrace::tracing::imp::write::h59f11508bbbb14ed
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:42
   2:     0x55559dfa44fe - std::panicking::default_hook::{{closure}}::h6803a4f823630483
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:351
   3:     0x55559dfa4104 - std::panicking::default_hook::h34bd173121b68cc3
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:367
   4:     0x55559dfa499b - std::panicking::rust_panic_with_hook::h9dbf610601b6a7e6
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:555
   5:     0x55559dfa4834 - std::panicking::begin_panic::hb6716f52468b0723
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:517
   6:     0x55559dfa4759 - std::panicking::begin_panic_fmt::h26c3fb5a170461f1
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:501
   7:     0x55559dfa46e7 - rust_begin_unwind
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:477
   8:     0x55559dfe395d - core::panicking::panic_fmt::hf96d4d16395a9d71
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libcore/panicking.rs:69
   9:     0x55559dcbc8c2 - core::result::unwrap_failed::h2306691d0b458899
  10:     0x55559dd1aae7 - librespot::player::Player::command::h6e3dc113df813953
  11:     0x55559dd2b547 - <librespot::spirc::SpircTask as futures::future::Future>::poll::h7dec885b0de74afc
  12:     0x55559dc913b7 - librespot::main::hf1c3903b31a86f14
  13:     0x55559dfad30a - __rust_maybe_catch_panic
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libpanic_unwind/lib.rs:98
  14:     0x55559dfa5106 - std::rt::lang_start::h57d3f8e2f32e3c87
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panicking.rs:436
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/panic.rs:361
                        at /var/tmp/paludis/dev-lang-rust-1.16.0/work/rustc-1.16.0-src/src/libstd/rt.rs:57
  15:     0x7f1f43adb200 - __libc_start_main
                        at ../csu/libc-start.c:289
  16:     0x55559dc80359 - _start
                        at ../sysdeps/x86_64/start.S:120
  17:                0x0 - <unknown>

The first backtrace is generated when a client connects, the second one when the client tries to play. It's independent of the bitrate.

plietar commented 7 years ago

This generally happens when a track is not available in your country. librespot should be able to deal with this however in https://github.com/plietar/librespot/blob/c070f6b0dbe695241671dc6ffc64895f69848479/src/player.rs#L328 .

Also, from the looks of it this track should be available in CH. If you can still reproduce this could you run it with --verbose

dev-zero commented 7 years ago

ok, I retried it with and without --verbose and I can't reproduce it anymore, even with the same track which I was able to play on my mobile device also at the time when I reported the bug.

nbonamy commented 7 years ago

Hello. I am seeing the same problem.

For instance on "Dealing on the Boulevard" from Lou Reed (spotify:album:3502jry0dmHTGRMuEj0gMp, https://open.spotify.com/embed/album/3502jry0dmHTGRMuEj0gMp), 1st song plays OK but 2nd song crashes.

Note that I am able to play this song in the Spotify client so this is not a matter of availability.

Thanks for the great stuff Nicolas

balbuze commented 7 years ago

Something has changed in Spotify, because I now have the problem with tracks I used to listen. No link I think with the country as I'm FR and this a french artist.

maxx commented 7 years ago

For the record, I've been trying to use Spotify on my amazon echo today and have been having a ton of problems too (discovery not working, music not playing).

markubiak commented 7 years ago

I am able to replicate this issue with verbose mode on.

librespot -b 320 --name "MiniDSPi Test 2" --backend alsa --device plughw:v10 --verbose
INFO:librespot: librespot 6f24e3b (2017-05-15). Built on 2017-05-16.
WARN:mdns: Failed to register IPv6 receiver: Error { repr: Os { code: 19, message: "No such device" } }
DEBUG:librespot::authentication::discovery: Post "/" {}
INFO:librespot::session: Connecting to AP "ash2-accesspoint-a104.ap.spotify.com:4070"
INFO:librespot::session: Authenticated as "<user>" !
DEBUG:librespot::session: new Session[0]
DEBUG:librespot::spirc: new Spirc[0]
DEBUG:librespot::mercury: new MercuryManager
DEBUG:librespot::player: new Player[0]
DEBUG:librespot::session: Session[0] strong=3 weak=2
INFO:librespot::session: Country: "US"
INFO:librespot::audio_backend::alsa: Using alsa sink
DEBUG:librespot::mercury: unknown subscription uri=hm://remote/3/user/<redacted>/fbacf7bfc10829c2dca369b13189005fdd06d38f
DEBUG:librespot::mercury: subscribed uri=hm://remote/3/user/<redacted>/ count=0
DEBUG:librespot::spirc: kMessageTypeNotify "MiniDSPi" 8e0cd3a7f3edf5c280614bfa445b3815e089ed97 19 1499646420260
DEBUG:librespot::spirc: kMessageTypeNotify "HTC One M9" b77109aee360a48c244fede85a057bf6b7a33607 1 1499646418474
DEBUG:librespot::spirc: kMessageTypeNotify "C368 - 067F" 34963f5d31c4460581c6dbd13c07a9b4657ca380 381 1499646419719
DEBUG:librespot::spirc: kMessageTypeNotify "Living Room" 2358af27640aeafd5485bbcbd84586d60c92cafc 678 1499646419912
DEBUG:librespot::spirc: kMessageTypeNotify "MB50" 27188a27abd5946da12a8df77b3108cebfe17f69 303 1499646420001
DEBUG:librespot::spirc: kMessageTypeLoad "HTC One M9" b77109aee360a48c244fede85a057bf6b7a33607 2 0
DEBUG:librespot::player: command=Load(SpotifyId(u128 { high: 17094772842723757106, low: 10433356220603861092 }), false, 96315)
DEBUG:librespot::metadata: new MetadataManager
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: WireError("invalid value for enum: 13")', /checkout/src/libcore/result.rs:859
note: Run with `RUST_BACKTRACE=1` for a backtrace.
DEBUG:librespot::player: drop Player[0]
DEBUG:librespot::spirc: kMessageTypeNotify "MiniDSPi Test 2" fbacf7bfc10829c2dca369b13189005fdd06d38f 2 1499646420437
DEBUG:librespot::spirc: kMessageTypeNotify "HTC One M9" b77109aee360a48c244fede85a057bf6b7a33607 51 1499646420001
DEBUG:librespot::spirc: kMessageTypePlay "HTC One M9" b77109aee360a48c244fede85a057bf6b7a33607 3 0
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: "SendError(..)"', /checkout/src/libcore/result.rs:859
DEBUG:librespot::spirc: drop Spirc[0]
DEBUG:librespot::session: drop Session[0]
DEBUG:librespot::mercury: drop MercuryManager
DEBUG:librespot::metadata: drop MetadataManager
DEBUG:librespot::session: drop Dispatch
swilalaa commented 7 years ago

Same issue here - two days ago everything was working fine, looks like spotify has chanegd something.

pi@raspberrypi:~ $ librespot --backend pipe --device /home/pi/srv/music/spotify -n spotifyConnect1 --disable-audio-cache --verbose
INFO:librespot: librespot 67deb07 (2017-06-30). Built on 2017-07-05.
WARN:mdns::fsm: error sending packet Error { repr: Os { code: 99, message: "Cannot assign requested address" } }
WARN:mdns::fsm: error sending packet Error { repr: Os { code: 99, message: "Cannot assign requested address" } }
WARN:mdns::fsm: error sending packet Error { repr: Os { code: 99, message: "Cannot assign requested address" } }
WARN:mdns::fsm: error sending packet Error { repr: Os { code: 99, message: "Cannot assign requested address" } }
DEBUG:librespot::authentication::discovery: Post "/" {}
INFO:librespot::session: Connecting to AP "lon3-accesspoint-a19.ap.spotify.com:4070"
INFO:librespot::session: Authenticated as "<USERID" !
DEBUG:librespot::session: new Session[0]
DEBUG:librespot::spirc: new Spirc[0]
DEBUG:librespot::player: new Player[0]
DEBUG:librespot::mercury: new MercuryManager
DEBUG:librespot::session: Session[0] strong=3 weak=2
INFO:librespot::session: Country: "DE"
DEBUG:librespot::mercury: unknown subscription uri=hm://remote/3/user/<USERID>/d75a8ac5db9f85ea8085e18ed2e64858e3ee4a90
DEBUG:librespot::mercury: unknown subscription uri=hm://remote/3/user/<USERID>/webapi
DEBUG:librespot::mercury: subscribed uri=hm://remote/3/user/<USERID>/ count=0
DEBUG:librespot::spirc: kMessageTypeNotify "KS-Air" 9dee012d570190747c69847a20876c23ee648b14 1 1499726184538
DEBUG:librespot::spirc: kMessageTypeLoad "KS-Air" 9dee012d570190747c69847a20876c23ee648b14 2 0
DEBUG:librespot::player: command=Load(SpotifyId(u128 { high: 12266110232946624619, low: 9811057198462756229 }), false, 132926)
DEBUG:librespot::metadata: new MetadataManager
DEBUG:librespot::spirc: kMessageTypeNotify "KS-Air" 9dee012d570190747c69847a20876c23ee648b14 56 1499726184538
DEBUG:librespot::spirc: kMessageTypeNotify "KS-Air" 9dee012d570190747c69847a20876c23ee648b14 94 1499726184538
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: WireError("invalid value for enum: 12")', /checkout/src/libcore/result.rs:859
note: Run with `RUST_BACKTRACE=1` for a backtrace.
DEBUG:librespot::player: drop Player[0]
DEBUG:librespot::spirc: kMessageTypeNotify "spotifyConnect1" d75a8ac5db9f85ea8085e18ed2e64858e3ee4a90 2 1499726191742
DEBUG:librespot::spirc: kMessageTypeNotify "iPlay" 1cd0503f525433314064b05660a99acd27b3a3b7 4 1499726184538
DEBUG:librespot::spirc: kMessageTypeNotify "iPlay" 1cd0503f525433314064b05660a99acd27b3a3b7 110 1499726184538
DEBUG:librespot::spirc: kMessageTypeNotify "KS-Air" 9dee012d570190747c69847a20876c23ee648b14 95 1499726191742
WARN:mdns::fsm: error sending packet Error { repr: Os { code: 99, message: "Cannot assign requested address" } }
WARN:mdns::fsm: error sending packet Error { repr: Os { code: 99, message: "Cannot assign requested address" } }
DEBUG:librespot::spirc: kMessageTypePlay "KS-Air" 9dee012d570190747c69847a20876c23ee648b14 3 0
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: "SendError(..)"', /checkout/src/libcore/result.rs:859
DEBUG:librespot::spirc: drop Spirc[0]
DEBUG:librespot::session: drop Session[0]
DEBUG:librespot::mercury: drop MercuryManager
DEBUG:librespot::metadata: drop MetadataManager
DEBUG:librespot::session: drop Dispatch
swilalaa commented 7 years ago

updating to the latest release fixes the issue.

markubiak commented 7 years ago

I updated to the latest release and the issue was fixed for me as well.