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.

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

Playing songs not in the cache broken #301

Closed
omartijn opened this issue May 20, 2022 · 16 comments
Closed

Playing songs not in the cache broken #301

omartijn opened this issue May 20, 2022 · 16 comments
Labels
bug Something isn't working

Comments

@omartijn
Copy link

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.

@omartijn omartijn added the bug Something isn't working label May 20, 2022
@luukvanderduim
Copy link
Contributor

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.

@omartijn
Copy link
Author

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

@omartijn
Copy link
Author

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?

@omartijn
Copy link
Author

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.

@luukvanderduim
Copy link
Contributor

luukvanderduim commented 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.

@luukvanderduim
Copy link
Contributor

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'.

@luukvanderduim
Copy link
Contributor

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?

@luukvanderduim
Copy link
Contributor

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.

@omartijn
Copy link
Author

@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.

@jpochyla
Copy link
Owner

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

@luukvanderduim
Copy link
Contributor

luukvanderduim commented 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.

@luukvanderduim
Copy link
Contributor

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

@jeffparsons
Copy link
Contributor

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

jeffparsons added a commit to jeffparsons/psst that referenced this issue Jun 11, 2022
This contains a fix that will hopefully solve jpochyla#301.
@luukvanderduim
Copy link
Contributor

luukvanderduim commented 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?

jpochyla pushed a commit that referenced this issue Jun 13, 2022
This contains a fix that will hopefully solve #301.
@jpochyla
Copy link
Owner

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

@omartijn
Copy link
Author

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.

ZachNation added a commit to ZachNation/psst that referenced this issue Oct 11, 2022
This contains a fix that will hopefully solve jpochyla/psst#301.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants