[GH-ISSUE #301] Playing songs not in the cache broken #219

Closed
opened 2026-02-28 14:31:26 +03:00 by kerem · 16 comments
Owner

Originally created by @omartijn on GitHub (May 20, 2022).
Original GitHub issue: https://github.com/jpochyla/psst/issues/301

Describe the bug
Playing any song that isn't already in the cache no longer works

To Reproduce
Play a song that isn't already cached.

Expected behavior
The sons plays

Screenshots
image

Environment

  • OS: Debian stable
  • Version: 11

Additional context
It looks strongly related to authentication. Of particular interest is the psst_core::session::access_token] access token expired, requesting message, which pops by regularly. I've tried going back two commits (to before the change masquerading as librespot) and that version tells me I need a premium account (which I have). The latest master tells me "success" when logging in, but then doesn't play.

Originally created by @omartijn on GitHub (May 20, 2022). Original GitHub issue: https://github.com/jpochyla/psst/issues/301 **Describe the bug** Playing any song that isn't already in the cache no longer works **To Reproduce** Play a song that isn't already cached. **Expected behavior** The sons plays **Screenshots** ![image](https://user-images.githubusercontent.com/44672243/169475933-79c75fe5-fdd1-488f-ba80-0b33f665761e.png) **Environment** - OS: Debian stable - Version: 11 **Additional context** It looks strongly related to authentication. Of particular interest is the `psst_core::session::access_token] access token expired, requesting` message, which pops by regularly. I've tried going back two commits (to before the change masquerading as librespot) and that version tells me I need a premium account (which I have). The latest master tells me "success" when logging in, but then doesn't play.
kerem 2026-02-28 14:31:26 +03:00
  • closed this issue
  • added the
    bug
    label
Author
Owner

@luukvanderduim commented on GitHub (May 20, 2022):

I encounter the same problem. Songs I have in cache play, new songs elicit:


luuk@kubus:~/code/dlock$ psst-gui 
[2022-05-20T12:18:52Z INFO  psst_gui::data::config] loading config: "/home/luuk/.config/Psst/config.json"
[2022-05-20T12:18:52Z ERROR psst_gui::webapi::client] failed to read local tracks: No such file or directory (os error 2)
[2022-05-20T12:18:52Z INFO  psst_core::audio::output] using audio device: "default"
[2022-05-20T12:18:52Z INFO  psst_core::cache] using cache: "/home/luuk/.cache/Psst"
[2022-05-20T12:18:52Z INFO  psst_core::audio::output] opening output stream: StreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Default }
[2022-05-20T12:18:52Z INFO  psst_gui::data::config] saved config: "/home/luuk/.config/Psst/config.json"
[2022-05-20T12:18:52Z INFO  psst_core::session::access_token] access token expired, requesting
[2022-05-20T12:19:05Z INFO  psst_gui::data::config] saved config: "/home/luuk/.config/Psst/config.json"
[2022-05-20T12:19:09Z INFO  psst_core::session::access_token] access token expired, requesting
[2022-05-20T12:19:11Z INFO  symphonia_format_ogg::demuxer] starting new physical stream
[2022-05-20T12:19:11Z INFO  symphonia_format_ogg::demuxer] selected vorbis mapper for stream with serial=0x0
[2022-05-20T12:19:11Z INFO  psst_core::player::file] blocked at 10799857
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10801227
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10802598
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10805811
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10807182
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10808553
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10809924
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10812666
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10815408
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10818150
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10819521
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10822195
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10823566
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10826308
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10827679
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10829050
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10831792
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10834534
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10837276
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10839950
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10842692
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10845434
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10848176
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10849547
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10852289
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10853660
[2022-05-20T12:19:12Z INFO  psst_core::player::file] blocked at 10854963
[2022-05-20T12:19:12Z INFO  psst_core::player] starting playback
thread 'audio_decoding' panicked at 'assertion failed: range.start < range.end', /home/luuk/.cargo/registry/src/github.com-1ecc6299db9ec823/rangemap-1.0.2/src/map.rs:109:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace


Ubuntu 22.04
FWIW, here is the backtrace:

m-1ecc6299db9ec823/rangemap-1.0.2/src/map.rs:109:9
stack backtrace:
   0: rust_begin_unwind
             at /rustc/cd282d7f75da9080fda0f1740a729516e7fbec68/library/std/src/panicking.rs:584:5
   1: core::panicking::panic_fmt
             at /rustc/cd282d7f75da9080fda0f1740a729516e7fbec68/library/core/src/panicking.rs:142:14
   2: core::panicking::panic
             at /rustc/cd282d7f75da9080fda0f1740a729516e7fbec68/library/core/src/panicking.rs:48:5
   3: rangemap::map::RangeMap<K,V>::insert
   4: <psst_core::player::storage::StreamReader as std::io::Read>::read
   5: <psst_core::audio::decrypt::AudioDecrypt<T> as std::io::Read>::read
   6: <psst_core::util::FileWithConstSize<T> as std::io::Read>::read
   7: symphonia_core::io::media_source_stream::MediaSourceStream::fetch
   8: <symphonia_core::io::media_source_stream::MediaSourceStream as symphonia_core::io::ReadBytes>::read_quad_bytes
   9: symphonia_format_ogg::page::PageReader::try_next_page
  10: symphonia_format_ogg::demuxer::OggReader::read_page
  11: <symphonia_format_ogg::demuxer::OggReader as symphonia_core::formats::FormatReader>::next_packet
  12: psst_core::audio::decode::AudioDecoder::read_packet
  13: <psst_core::player::worker::Worker as psst_core::actor::Actor>::handle
  14: psst_core::actor::Actor::process
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
<!-- gh-comment-id:1132844101 --> @luukvanderduim commented on GitHub (May 20, 2022): I encounter the same problem. Songs I have in cache play, new songs elicit: ``` luuk@kubus:~/code/dlock$ psst-gui [2022-05-20T12:18:52Z INFO psst_gui::data::config] loading config: "/home/luuk/.config/Psst/config.json" [2022-05-20T12:18:52Z ERROR psst_gui::webapi::client] failed to read local tracks: No such file or directory (os error 2) [2022-05-20T12:18:52Z INFO psst_core::audio::output] using audio device: "default" [2022-05-20T12:18:52Z INFO psst_core::cache] using cache: "/home/luuk/.cache/Psst" [2022-05-20T12:18:52Z INFO psst_core::audio::output] opening output stream: StreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Default } [2022-05-20T12:18:52Z INFO psst_gui::data::config] saved config: "/home/luuk/.config/Psst/config.json" [2022-05-20T12:18:52Z INFO psst_core::session::access_token] access token expired, requesting [2022-05-20T12:19:05Z INFO psst_gui::data::config] saved config: "/home/luuk/.config/Psst/config.json" [2022-05-20T12:19:09Z INFO psst_core::session::access_token] access token expired, requesting [2022-05-20T12:19:11Z INFO symphonia_format_ogg::demuxer] starting new physical stream [2022-05-20T12:19:11Z INFO symphonia_format_ogg::demuxer] selected vorbis mapper for stream with serial=0x0 [2022-05-20T12:19:11Z INFO psst_core::player::file] blocked at 10799857 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10801227 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10802598 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10805811 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10807182 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10808553 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10809924 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10812666 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10815408 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10818150 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10819521 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10822195 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10823566 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10826308 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10827679 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10829050 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10831792 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10834534 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10837276 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10839950 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10842692 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10845434 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10848176 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10849547 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10852289 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10853660 [2022-05-20T12:19:12Z INFO psst_core::player::file] blocked at 10854963 [2022-05-20T12:19:12Z INFO psst_core::player] starting playback thread 'audio_decoding' panicked at 'assertion failed: range.start < range.end', /home/luuk/.cargo/registry/src/github.com-1ecc6299db9ec823/rangemap-1.0.2/src/map.rs:109:9 note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace ``` Ubuntu 22.04 FWIW, here is the backtrace: ``` m-1ecc6299db9ec823/rangemap-1.0.2/src/map.rs:109:9 stack backtrace: 0: rust_begin_unwind at /rustc/cd282d7f75da9080fda0f1740a729516e7fbec68/library/std/src/panicking.rs:584:5 1: core::panicking::panic_fmt at /rustc/cd282d7f75da9080fda0f1740a729516e7fbec68/library/core/src/panicking.rs:142:14 2: core::panicking::panic at /rustc/cd282d7f75da9080fda0f1740a729516e7fbec68/library/core/src/panicking.rs:48:5 3: rangemap::map::RangeMap<K,V>::insert 4: <psst_core::player::storage::StreamReader as std::io::Read>::read 5: <psst_core::audio::decrypt::AudioDecrypt<T> as std::io::Read>::read 6: <psst_core::util::FileWithConstSize<T> as std::io::Read>::read 7: symphonia_core::io::media_source_stream::MediaSourceStream::fetch 8: <symphonia_core::io::media_source_stream::MediaSourceStream as symphonia_core::io::ReadBytes>::read_quad_bytes 9: symphonia_format_ogg::page::PageReader::try_next_page 10: symphonia_format_ogg::demuxer::OggReader::read_page 11: <symphonia_format_ogg::demuxer::OggReader as symphonia_core::formats::FormatReader>::next_packet 12: psst_core::audio::decode::AudioDecoder::read_packet 13: <psst_core::player::worker::Worker as psst_core::actor::Actor>::handle 14: psst_core::actor::Actor::process note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. ```
Author
Owner

@omartijn commented on GitHub (May 23, 2022):

I just noticed something strange while debugging. This error occurs when I run the release-build of psst-gui, but not when I run the debug build.

What i normally do is cargo install --path psst-gui --profile release after pulling the latest changes, I then have a psst.desktop file so that I can easily start it (or start it from the terminal, as I have added the rust bin folder to my PATH).

When instead I do cargo run --bin psst-gui, it actually works as expected. Strangely enough, though it uses the same config file, it showed me as logged out when I started it the first time. After logging in it worked. So there is something different in the way it loads credentials.

To show, first output is from cargo run --bin psst-gui (I've omitted the compilation steps here), second is psst-gui from my PATH (which is the release build.

warning: `psst-gui` (bin "psst-gui") generated 10 warnings
    Finished dev [unoptimized + debuginfo] target(s) in 0.09s
     Running `target/debug/psst-gui`
[2022-05-23T07:08:37Z INFO  psst_gui::data::config] loading config: "/home/martijn/.config/Psst/config.json"
[2022-05-23T07:08:37Z ERROR psst_gui::webapi::client] failed to read local tracks: No such file or directory (os error 2)
[2022-05-23T07:08:37Z INFO  psst_core::audio::output] using audio device: "default"
[2022-05-23T07:08:37Z INFO  psst_core::cache] using cache: "/home/martijn/.cache/Psst"
[2022-05-23T07:08:37Z INFO  psst_core::audio::output] opening output stream: StreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Default }
[2022-05-23T07:08:37Z INFO  psst_gui::data::config] saved config: "/home/martijn/.config/Psst/config.json"
[2022-05-23T07:08:37Z INFO  psst_core::session::access_token] access token expired, requesting
[2022-05-23T07:08:37Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:37Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:37Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:37Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:37Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:37Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:37Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
[2022-05-23T07:08:38Z WARN  rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest]
martijn@xps15 ~/g/psst (master)> psst-gui
[2022-05-23T07:08:46Z INFO  psst_gui::data::config] loading config: "/home/martijn/.config/Psst/config.json"
[2022-05-23T07:08:46Z ERROR psst_gui::webapi::client] failed to read local tracks: No such file or directory (os error 2)
[2022-05-23T07:08:46Z INFO  psst_core::audio::output] using audio device: "default"
[2022-05-23T07:08:46Z INFO  psst_core::cache] using cache: "/home/martijn/.cache/Psst"
[2022-05-23T07:08:46Z INFO  psst_core::audio::output] opening output stream: StreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Default }
[2022-05-23T07:08:46Z INFO  psst_gui::data::config] saved config: "/home/martijn/.config/Psst/config.json"
[2022-05-23T07:08:46Z INFO  psst_core::session::access_token] access token expired, requesting
[2022-05-23T07:08:49Z INFO  psst_gui::data::config] saved config: "/home/martijn/.config/Psst/config.json"
[2022-05-23T07:08:51Z INFO  psst_core::session::access_token] access token expired, requesting
[2022-05-23T07:08:51Z INFO  symphonia_format_ogg::demuxer] starting new physical stream
[2022-05-23T07:08:51Z INFO  symphonia_format_ogg::demuxer] selected vorbis mapper for stream with serial=0x0
[2022-05-23T07:08:51Z INFO  psst_core::player::file] blocked at 6506377
[2022-05-23T07:08:51Z INFO  psst_core::player::file] blocked at 6522760
[2022-05-23T07:08:51Z INFO  psst_core::player::file] blocked at 6539144
[2022-05-23T07:08:51Z INFO  psst_core::player::file] blocked at 6545228
[2022-05-23T07:08:51Z INFO  psst_core::player::file] blocked at 6561612
[2022-05-23T07:08:51Z INFO  psst_core::player] starting playback
thread 'audio_decoding' panicked at 'assertion failed: range.start < range.end', /home/martijn/.cargo/registry/src/github.com-1ecc6299db9ec823/rangemap-1.0.2/src/map.rs:109:9
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
<!-- gh-comment-id:1134273533 --> @omartijn commented on GitHub (May 23, 2022): I just noticed something strange while debugging. This error occurs when I run the release-build of `psst-gui`, but not when I run the debug build. What i normally do is `cargo install --path psst-gui --profile release` after pulling the latest changes, I then have a `psst.desktop` file so that I can easily start it (or start it from the terminal, as I have added the rust bin folder to my PATH). When instead I do `cargo run --bin psst-gui`, it actually works as expected. Strangely enough, though it uses the same config file, it showed me as logged out when I started it the first time. After logging in it worked. So there is something different in the way it loads credentials. To show, first output is from `cargo run --bin psst-gui` (I've omitted the compilation steps here), second is `psst-gui` from my `PATH` (which is the release build. ``` warning: `psst-gui` (bin "psst-gui") generated 10 warnings Finished dev [unoptimized + debuginfo] target(s) in 0.09s Running `target/debug/psst-gui` [2022-05-23T07:08:37Z INFO psst_gui::data::config] loading config: "/home/martijn/.config/Psst/config.json" [2022-05-23T07:08:37Z ERROR psst_gui::webapi::client] failed to read local tracks: No such file or directory (os error 2) [2022-05-23T07:08:37Z INFO psst_core::audio::output] using audio device: "default" [2022-05-23T07:08:37Z INFO psst_core::cache] using cache: "/home/martijn/.cache/Psst" [2022-05-23T07:08:37Z INFO psst_core::audio::output] opening output stream: StreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Default } [2022-05-23T07:08:37Z INFO psst_gui::data::config] saved config: "/home/martijn/.config/Psst/config.json" [2022-05-23T07:08:37Z INFO psst_core::session::access_token] access token expired, requesting [2022-05-23T07:08:37Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:37Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:37Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:37Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:37Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:37Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:37Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] [2022-05-23T07:08:38Z WARN rustls::check] Received a ServerHelloDone handshake message while expecting [CertificateRequest] martijn@xps15 ~/g/psst (master)> psst-gui [2022-05-23T07:08:46Z INFO psst_gui::data::config] loading config: "/home/martijn/.config/Psst/config.json" [2022-05-23T07:08:46Z ERROR psst_gui::webapi::client] failed to read local tracks: No such file or directory (os error 2) [2022-05-23T07:08:46Z INFO psst_core::audio::output] using audio device: "default" [2022-05-23T07:08:46Z INFO psst_core::cache] using cache: "/home/martijn/.cache/Psst" [2022-05-23T07:08:46Z INFO psst_core::audio::output] opening output stream: StreamConfig { channels: 2, sample_rate: SampleRate(44100), buffer_size: Default } [2022-05-23T07:08:46Z INFO psst_gui::data::config] saved config: "/home/martijn/.config/Psst/config.json" [2022-05-23T07:08:46Z INFO psst_core::session::access_token] access token expired, requesting [2022-05-23T07:08:49Z INFO psst_gui::data::config] saved config: "/home/martijn/.config/Psst/config.json" [2022-05-23T07:08:51Z INFO psst_core::session::access_token] access token expired, requesting [2022-05-23T07:08:51Z INFO symphonia_format_ogg::demuxer] starting new physical stream [2022-05-23T07:08:51Z INFO symphonia_format_ogg::demuxer] selected vorbis mapper for stream with serial=0x0 [2022-05-23T07:08:51Z INFO psst_core::player::file] blocked at 6506377 [2022-05-23T07:08:51Z INFO psst_core::player::file] blocked at 6522760 [2022-05-23T07:08:51Z INFO psst_core::player::file] blocked at 6539144 [2022-05-23T07:08:51Z INFO psst_core::player::file] blocked at 6545228 [2022-05-23T07:08:51Z INFO psst_core::player::file] blocked at 6561612 [2022-05-23T07:08:51Z INFO psst_core::player] starting playback thread 'audio_decoding' panicked at 'assertion failed: range.start < range.end', /home/martijn/.cargo/registry/src/github.com-1ecc6299db9ec823/rangemap-1.0.2/src/map.rs:109:9 note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace ```
Author
Owner

@omartijn commented on GitHub (May 23, 2022):

It doesn't seem to have anything to do with release/debug specifically. Running cargo run --bin psst-gui --profile release runs the optimized build, which then also seems to work just fine. It's just the installed version that seems to be broken.

@luukvanderduim How are you running psst-gui? Do you get the same behaviour?

<!-- gh-comment-id:1134279031 --> @omartijn commented on GitHub (May 23, 2022): It doesn't seem to have anything to do with release/debug specifically. Running `cargo run --bin psst-gui --profile release` runs the optimized build, which then also seems to work just fine. It's just the _installed_ version that seems to be broken. @luukvanderduim How are you running `psst-gui`? Do you get the same behaviour?
Author
Owner

@omartijn commented on GitHub (May 23, 2022):

OK, I think I'm onto something. It seems something goes wrong when you do multiple builds without cleaning the repo in-between. That's why doing the cargo run commands initially worked. Strangely enough, doing that command again and running another build broke it again like before.

What worked for me is to do git clean -ffxd and then doing a cargo run --bin psst-gui --profile release. This gave me a functioning executable again. I then manually copied this executable to my ~/.cargo/bin folder - since doing another cargo install ... would do another build which would be broken.

<!-- gh-comment-id:1134294800 --> @omartijn commented on GitHub (May 23, 2022): OK, I think I'm onto something. It seems something goes wrong when you do multiple builds without cleaning the repo in-between. That's why doing the `cargo run` commands initially worked. Strangely enough, doing that command again and running another build broke it again like before. What worked for me is to do `git clean -ffxd` and then doing a `cargo run --bin psst-gui --profile release`. This gave me a functioning executable again. I then _manually_ copied this executable to my `~/.cargo/bin` folder - since doing another `cargo install ...` would do another build _which would be broken_.
Author
Owner

@luukvanderduim commented on GitHub (May 23, 2022):

@omartijn
Sharp observations!
I do cargo install --path=. in psst/psst-gui and then just run by psst-gui.

cargo clean and cargo install --path=. leads to a broken broken install.
git clean -ffxd and cargo install --path=. also led to a broken install.
cargo clean and cargo rr --bin=psst-gui leads to a working instance.

The working builds have the rustls warnings whereas the broken builds do not.

<!-- gh-comment-id:1134479130 --> @luukvanderduim commented on GitHub (May 23, 2022): @omartijn Sharp observations! I do `cargo install --path=.` in `psst/psst-gui` and then just run by `psst-gui`. `cargo clean` and `cargo install --path=.` leads to a broken broken install. `git clean -ffxd` and `cargo install --path=.` also led to a broken install. `cargo clean` and `cargo rr --bin=psst-gui` leads to a working instance. The working builds have the `rustls` warnings whereas the broken builds do not.
Author
Owner

@luukvanderduim commented on GitHub (May 23, 2022):

When stracing (strace --status=failure target/release/psst-gui ) both binaries, the first differing syscall (in the failing binary) is:
prctl(PR_CAPBSET_READ, 0x30 /* CAP_??? */) = -1 EINVAL (Invalid argument)

So it fails to read its 'thread capability bound set'.

<!-- gh-comment-id:1134769555 --> @luukvanderduim commented on GitHub (May 23, 2022): When stracing (`strace --status=failure target/release/psst-gui` ) both binaries, the first differing syscall (in the failing binary) is: `prctl(PR_CAPBSET_READ, 0x30 /* CAP_??? */) = -1 EINVAL (Invalid argument)` So it fails to read its 'thread capability bound set'.
Author
Owner

@luukvanderduim commented on GitHub (May 23, 2022):

cargo install --path=psst-gui --locked results in a working build for me.
It seems cargp build (or run) do honor Cargo.lock whereas cargo install ignores it.

@omartijn Does this fix your build too?

<!-- gh-comment-id:1135057659 --> @luukvanderduim commented on GitHub (May 23, 2022): `cargo install --path=psst-gui --locked` results in a working build for me. It seems `cargp build` (or run) do honor Cargo.lock whereas `cargo install` ignores it. @omartijn Does this fix your build too?
Author
Owner

@luukvanderduim commented on GitHub (May 25, 2022):

It appears that sometimes start is greater than end and this makes the u64::sub panic in psst-core/src/player/storage.rs

This is the 'fix' to avoid the panic. This works fine(tm) up-until-now.

fn range_to_offset_and_length(range: &Range<u64>) -> (u64, u64) {
-    (range.start, range.end - range.start)
+    (range.start, range.end.saturating_sub(range.start))
}

But note that I have no clue how start ends up being greater than end and how this problem is introduced by newer dependencies as we have seen earlier in the thread.

<!-- gh-comment-id:1137122388 --> @luukvanderduim commented on GitHub (May 25, 2022): It appears that sometimes `start` is greater than `end` and this makes the `u64::sub` panic in psst-core/src/player/storage.rs This is the 'fix' to avoid the panic. This works fine(tm) up-until-now. ```Rust fn range_to_offset_and_length(range: &Range<u64>) -> (u64, u64) { - (range.start, range.end - range.start) + (range.start, range.end.saturating_sub(range.start)) } ``` But note that I have no clue how `start` ends up being greater than `end` _and_ how this problem is introduced by newer dependencies as we have seen earlier in the thread.
Author
Owner

@omartijn commented on GitHub (May 26, 2022):

@luukvanderduim --locked option produces a working build for me as well. I think we can conclude this has something to do with cargo pulling in updated dependencies without this flag.

<!-- gh-comment-id:1138836084 --> @omartijn commented on GitHub (May 26, 2022): @luukvanderduim ` --locked` option produces a working build for me as well. I think we can conclude this has something to do with cargo pulling in updated dependencies without this flag.
Author
Owner

@jpochyla commented on GitHub (May 30, 2022):

Fuuu, what a strange bug! Thanks for the extensive detective work, but so far I have no idea what's going on.

<!-- gh-comment-id:1141200021 --> @jpochyla commented on GitHub (May 30, 2022): Fuuu, what a strange bug! Thanks for the extensive detective work, but so far I have no idea what's going on.
Author
Owner

@luukvanderduim commented on GitHub (Jun 5, 2022):

I think I narrowed it down to the rangemap versionbump from v1.0.1 to v1.0.2. To be specific, commit 9d0b12572278ee94e78ecabfccc43e6edd3b96ba seems to first introduces the bug.

  1. cargo update && cargo upgrade --workspace // update all dependencies in the workspace
  2. cargo clean && cargo run --bin psst-gui --locked // to confirm updated dependencies introduces the problem
  3. In vscode edit psst/Cargo.lock, only revert the rangemap change.
  4. cargo clean && cargo run --bin psst-gui --locked // to confirm updated rangemap crate introduces the bug
  5. 'git reset --hard'
  6. edit psst-core/Cargo.toml the rangemap dependency to point ot a local cloned repository rangemap = { path = "../../rangemap/" }
  7. Then git bisect until the culprit is found.
<!-- gh-comment-id:1146843205 --> @luukvanderduim commented on GitHub (Jun 5, 2022): I think I narrowed it down to the `rangemap` versionbump from v1.0.1 to v1.0.2. To be specific, commit [9d0b12572278ee94e78ecabfccc43e6edd3b96ba](https://github.com/jeffparsons/rangemap/commit/9d0b12572278ee94e78ecabfccc43e6edd3b96ba) seems to first introduces the bug. 1. `cargo update` && `cargo upgrade --workspace` // update all dependencies in the workspace 2. `cargo clean` && `cargo run --bin psst-gui --locked` // to confirm updated dependencies introduces the problem 3. In vscode edit psst/Cargo.lock, only revert the rangemap change. 4. `cargo clean` && `cargo run --bin psst-gui --locked` // to confirm updated `rangemap` crate introduces the bug 5. 'git reset --hard' 6. edit `psst-core/Cargo.toml` the `rangemap` dependency to point ot a local cloned repository `rangemap = { path = "../../rangemap/" }` 7. Then git bisect until the culprit is found.
Author
Owner

@luukvanderduim commented on GitHub (Jun 10, 2022):

In order to see what behavior changed in jeffparsons/rangemap I copied (~30) tests from rangemap::map to rangemap::set as we are most interested in RangeSet.
Then I copied all set tests to the v1.0.1 commit too and found one test that fails in v1.0.1, but passes in v1.0.2:

    #[test]
    fn empty_outer_range_with_items_away_from_both_sides() {
        let mut range_set: RangeSet<u32> = RangeSet::new();
        // 0 1 2 3 4 5 6 7 8 9
        // ◌ ◆---◇ ◌ ◌ ◌ ◌ ◌ ◌
        range_set.insert(1..3);
        // 0 1 2 3 4 5 6 7 8 9
        // ◌ ◌ ◌ ◌ ◌ ◆---◇ ◌ ◌
        range_set.insert(5..7);
        // 0 1 2 3 4 5 6 7 8 9
        // ◌ ◌ ◌ ◌ ◆ ◌ ◌ ◌ ◌ ◌
        let outer_range = 4..4;
        let mut gaps = range_set.gaps(&outer_range);
        // Should yield a gap covering the zero-width outer range.
        assert_eq!(gaps.next(), Some(4..4));
        // Gaps iterator should be fused.
        assert_eq!(gaps.next(), None);
        assert_eq!(gaps.next(), None);
    }

Which fails like so:

    ---- set::tests::empty_outer_range_with_items_away_from_both_sides stdout ----
    thread 'set::tests::empty_outer_range_with_items_away_from_both_sides' panicked at 'assertion failed: `(left == right)`
      left: `None`,
     right: `Some(4..4)`', src/set.rs:789:9
    note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Considering the definition of what is contained in a range, this may be a bug, and may have introduced our bug here (but may even be unrelated still).
Filed an issue for this: jeffparsons/rangemap#47

<!-- gh-comment-id:1152361970 --> @luukvanderduim commented on GitHub (Jun 10, 2022): In order to see what behavior changed in jeffparsons/rangemap I copied (~30) tests from rangemap::map to rangemap::set as we are most interested in `RangeSet`. Then I copied all `set` tests to the v1.0.1 commit too and found one test that fails in v1.0.1, but passes in v1.0.2: ```Rust #[test] fn empty_outer_range_with_items_away_from_both_sides() { let mut range_set: RangeSet<u32> = RangeSet::new(); // 0 1 2 3 4 5 6 7 8 9 // ◌ ◆---◇ ◌ ◌ ◌ ◌ ◌ ◌ range_set.insert(1..3); // 0 1 2 3 4 5 6 7 8 9 // ◌ ◌ ◌ ◌ ◌ ◆---◇ ◌ ◌ range_set.insert(5..7); // 0 1 2 3 4 5 6 7 8 9 // ◌ ◌ ◌ ◌ ◆ ◌ ◌ ◌ ◌ ◌ let outer_range = 4..4; let mut gaps = range_set.gaps(&outer_range); // Should yield a gap covering the zero-width outer range. assert_eq!(gaps.next(), Some(4..4)); // Gaps iterator should be fused. assert_eq!(gaps.next(), None); assert_eq!(gaps.next(), None); } ``` Which fails like so: ```Bash ---- set::tests::empty_outer_range_with_items_away_from_both_sides stdout ---- thread 'set::tests::empty_outer_range_with_items_away_from_both_sides' panicked at 'assertion failed: `(left == right)` left: `None`, right: `Some(4..4)`', src/set.rs:789:9 note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace ``` Considering the definition of what is contained in a range, this may be a bug, and may have introduced our bug here (but may even be unrelated still). Filed an issue for this: jeffparsons/rangemap#47
Author
Owner

@jeffparsons commented on GitHub (Jun 11, 2022):

I've just released version 1.0.3 of rangemap with this issue fixed.

<!-- gh-comment-id:1152923415 --> @jeffparsons commented on GitHub (Jun 11, 2022): I've just released version 1.0.3 of rangemap with this issue fixed.
Author
Owner

@luukvanderduim commented on GitHub (Jun 12, 2022):

@jeffparsons fixed this bug with jeffparsons/rangemap v1.0.3.

I found a case that has v1.0.2 rangeset..gaps() return a range where start > end where it should return None (see: jeffparsons/rangemap#47 )

Found it like this:
In psst-core/src/playter/storage.rs

    fn not_yet_requested(&self, offset: u64, length: u64) -> Vec<(u64, u64)> {
        #[cfg(debug_assertions)]
        let backup = self.requested.lock().clone();

        self.requested
            .lock()
            .gaps(&(offset..offset + length))
            .into_iter()
            .map(|r| {
                if r.start > r.end {
                    println!("Outer range: offset ({0}) .. offset ({0}) + length ({1})", &offset, &length);
                    println!("Method gaps returns start>end ranges is called on RangeSet: {:?}", backup); 
                    std::process::exit(1);
                }
                range_to_offset_and_length(&r)
            })
            //.map(|r| range_to_offset_and_length(&r))
            .collect()
    }

(note that I am not suggesting to use this code in psst, just for obtaining a test case)

I think this bug can be closed when we set the dependency >1.0.2 in psst-core/Cargo.toml?

<!-- gh-comment-id:1153166319 --> @luukvanderduim commented on GitHub (Jun 12, 2022): @jeffparsons fixed this bug with jeffparsons/rangemap v1.0.3. I found a case that has v1.0.2 `rangeset..gaps()` return a range where start > end where it should return `None` (see: jeffparsons/rangemap#47 ) Found it like this: In `psst-core/src/playter/storage.rs` ```Rust fn not_yet_requested(&self, offset: u64, length: u64) -> Vec<(u64, u64)> { #[cfg(debug_assertions)] let backup = self.requested.lock().clone(); self.requested .lock() .gaps(&(offset..offset + length)) .into_iter() .map(|r| { if r.start > r.end { println!("Outer range: offset ({0}) .. offset ({0}) + length ({1})", &offset, &length); println!("Method gaps returns start>end ranges is called on RangeSet: {:?}", backup); std::process::exit(1); } range_to_offset_and_length(&r) }) //.map(|r| range_to_offset_and_length(&r)) .collect() } ``` (note that I am not suggesting to use this code in psst, just for obtaining a test case) I think this bug can be closed when we set the dependency >1.0.2 in `psst-core/Cargo.toml`?
Author
Owner

@jpochyla commented on GitHub (Jun 13, 2022):

Big thanks, everybody! ❤️ I've merged #304, can you confirm it fixes the bug?

<!-- gh-comment-id:1154060086 --> @jpochyla commented on GitHub (Jun 13, 2022): Big thanks, everybody! ❤️ I've merged #304, can you confirm it fixes the bug?
Author
Owner

@omartijn commented on GitHub (Jun 13, 2022):

Seems to work fine here. I've built the latest master, removed ~/.cache/Psst and started psst-gui. It plays tracks fine.

One little thing I noticed is that the first time I started it it wouldn't play tracks. Then I started it fresh and it worked. No idea what was going on there.

<!-- gh-comment-id:1154085459 --> @omartijn commented on GitHub (Jun 13, 2022): Seems to work fine here. I've built the latest master, removed `~/.cache/Psst` and started `psst-gui`. It plays tracks fine. One little thing I noticed is that the _first_ time I started it it wouldn't play tracks. Then I started it fresh and it worked. No idea what was going on there.
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/psst#219
No description provided.