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

Bug: panic on playerctl previous with Chromium MPRIS client #3

Closed
hcwesson opened this issue Jan 16, 2023 · 5 comments · Fixed by #4
Closed

Bug: panic on playerctl previous with Chromium MPRIS client #3

hcwesson opened this issue Jan 16, 2023 · 5 comments · Fixed by #4

Comments

@hcwesson
Copy link
Contributor

hcwesson commented Jan 16, 2023 •
edited
Loading

First off, thank you for making this tool! It's been really useful to me.

Issue Description

I'm currently encountering a bug that occurs when I use playerctl previous in conjunction with the Spotify web app (controlled via the Chromium MPRIS client), which reliably causes mpris-notifier to panic/crash.

System details:

$ uname -srvmo 
Linux 6.1.5-arch2-1 #1 SMP PREEMPT_DYNAMIC Thu, 12 Jan 2023 22:42:33 +0000 x86_64 GNU/Linux

$ cargo version 
cargo 1.68.0-nightly (2381cbdb4 2022-12-23)

$ cargo install --list | rg 'mpris-notifier'
mpris-notifier v0.1.4:
    mpris-notifier

I was able to grab the following backtrace:

$ RUST_BACKTRACE=full mpris-notifier

thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', /home/hcw/.cargo/registry/src/github.com-1ecc6299db9ec823/mpris-notifier-0.1.4/src/signal_handler.rs:128:23
stack backtrace:
   0:     0x55ce4512468a - std::backtrace_rs::backtrace::libunwind::trace::h27f73006c00d225f
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x55ce4512468a - std::backtrace_rs::backtrace::trace_unsynchronized::h5b1e3ed7625da978
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x55ce4512468a - std::sys_common::backtrace::_print_fmt::h2a671809f517f2b1
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/sys_common/backtrace.rs:65:5
   3:     0x55ce4512468a - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h6d0ea0aaa57736e8
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x55ce45146f5e - core::fmt::write::h6e5c49f92ea0e272
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/core/src/fmt/mod.rs:1208:17
   5:     0x55ce4511ee95 - std::io::Write::write_fmt::h6842012d97fc496b
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/io/mod.rs:1682:15
   6:     0x55ce45124455 - std::sys_common::backtrace::_print::h1ab4c02867e328ec
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/sys_common/backtrace.rs:47:5
   7:     0x55ce45124455 - std::sys_common::backtrace::print::h32598b3616e9614b
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/sys_common/backtrace.rs:34:9
   8:     0x55ce45125c3f - std::panicking::default_hook::{{closure}}::h3d50ddf8e1e49d82
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:267:22
   9:     0x55ce4512597b - std::panicking::default_hook::h4ce33dc8fd186ef2
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:286:9
  10:     0x55ce4512634c - std::panicking::rust_panic_with_hook::h2a4fa5f415ff0032
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:688:13
  11:     0x55ce451260a2 - std::panicking::begin_panic_handler::{{closure}}::h713c2df68306363e
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:577:13
  12:     0x55ce45124b3c - std::sys_common::backtrace::__rust_end_short_backtrace::h2b698c64fdb8b17b
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/sys_common/backtrace.rs:137:18
  13:     0x55ce45125df2 - rust_begin_unwind
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:575:5
  14:     0x55ce44e61423 - core::panicking::panic_fmt::hc36243dbd0d8aecb
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/core/src/panicking.rs:64:14
  15:     0x55ce44e614fd - core::panicking::panic::he5fb07ffbf75baf5
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/core/src/panicking.rs:112:5
  16:     0x55ce44f0339d - mpris_notifier::signal_handler::SignalHandler::handle_signal::h47f8758adca546bf
  17:     0x55ce44e8950b - mpris_notifier::main::h6c3e5a0b57ece164
  18:     0x55ce44e709b6 - std::sys_common::backtrace::__rust_begin_short_backtrace::h8e24cefcafd87243
  19:     0x55ce44e7fce5 - std::rt::lang_start::{{closure}}::h321a8788984b762e
  20:     0x55ce4511a55c - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::ha9cf51e0ef3558b3
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/core/src/ops/function.rs:606:13
  21:     0x55ce4511a55c - std::panicking::try::do_call::h9c7493d8ac276d80
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:483:40
  22:     0x55ce4511a55c - std::panicking::try::h2bfb1f90507a2474
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:447:19
  23:     0x55ce4511a55c - std::panic::catch_unwind::h7be130a8f9b4b90b
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panic.rs:137:14
  24:     0x55ce4511a55c - std::rt::lang_start_internal::{{closure}}::h8c58adba4c26b7c4
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/rt.rs:148:48
  25:     0x55ce4511a55c - std::panicking::try::do_call::h03c15e8a349a4d2f
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:483:40
  26:     0x55ce4511a55c - std::panicking::try::h27f9d1287663c803
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panicking.rs:447:19
  27:     0x55ce4511a55c - std::panic::catch_unwind::h2e76d10aa2609bfc
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/panic.rs:137:14
  28:     0x55ce4511a55c - std::rt::lang_start_internal::heabf64234330f612
                               at /rustc/8dfb3395411555e93399671d0c41a4ac9ed62b95/library/std/src/rt.rs:148:20
  29:     0x55ce44e896e5 - main
  30:     0x7f1715be8290 - <unknown>
  31:     0x7f1715be834a - __libc_start_main
  32:     0x55ce44e61a45 - _start
                               at /build/glibc/src/glibc/csu/../sysdeps/x86_64/start.S:115
  33:                0x0 - <unknown>
@hcwesson hcwesson mentioned this issue Jan 17, 2023
Merged
@hcwesson hcwesson changed the title Bug: mpris-notifier panics on playerctl previous command with Chromium MPRIS client Bug: panic on playerctl previous with Chromium MPRIS client Jan 17, 2023
@l1na-forever l1na-forever reopened this Jan 18, 2023
@l1na-forever
Copy link
Owner

Hi! Merged the patch and left a comment on how I think that bug might get triggered. If you happen to have a moment to grab the dbus-monitor output, I can confirm, but otherwise feel free to close. Thanks again for the report!

@hcwesson
Copy link
Contributor Author

hcwesson commented Jan 21, 2023 •
edited
Loading

Hi! Merged the patch and left a comment on how I think that bug might get triggered.

Cool, thank you!

If you happen to have a moment to grab the dbus-monitor output, I can confirm

Sure thing - I ran the dev build of commit 7bedc9e and cross-ref'd dbus-notifier messages with the time of panic, and I found that just skipping to the beginning of a (Spotify web) track triggered one.

Here's the output I grabbed after restarting a track with playerctl previous at the time the panic occurred:

$ dbus-monitor --session "path=/org/mpris/MediaPlayer2,member=PropertiesChanged"

signal time=1674342186.288579 sender=:1.1694 -> destination=(null destination) serial=1896 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.mpris.MediaPlayer2.Player"
   array [
      dict entry(
         string "Rate"
         variant             double 0
      )
   ]
   array [
   ]
signal time=1674342186.297540 sender=:1.1694 -> destination=(null destination) serial=1899 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.mpris.MediaPlayer2.Player"
   array [
      dict entry(
         string "Rate"
         variant             double 1
      )
   ]
   array [
   ]

I also noticed I could reproduce the crash without any additional (inactive) media players open in Chromium, putting my armchair theory to bed. 😅

Just for completeness, I'm attaching additional output logs I got when skipping to the next/previous track:

Next track/playerctl next
dbus_mpris_chromium_skipToNext.log

Previous song/playerctl previous x2
dbus_mpris_chromium_skipToPrevious.log

Hope that helps!

@hcwesson
Copy link
Contributor Author

hcwesson commented Jan 21, 2023 •
edited
Loading

Ah! Just saw you asked for dbus-monitor | grep PlaybackStatus which I totally missed.

I just did that while triggering the crash, but I couldn't really discern much from it:

$ dbus-monitor | rg -A2 -B1 '"PlaybackStatus"'

      dict entry(
         string "PlaybackStatus"
         variant             string "Playing"
      )

In the "PropertiesChanged" logs I posted above, it seemed like the "Rate" property was the only one that turned up consistently when using playerctl previous, so here's one that also includes those:

$ dbus-monitor | rg -A2 -B1 '"PlaybackStatus"|"Rate"'

      dict entry(
         string "PlaybackStatus"
         variant             string "Playing"
      )
--
      dict entry(
         string "Rate"
         variant             double 1
      )
--
      dict entry(
         string "Rate"
         variant             double 0
      )
--
      dict entry(
         string "Rate"
         variant             double 1
      )

@hcwesson
Copy link
Contributor Author

hcwesson commented Jan 22, 2023 •
edited
Loading

From my read of handle_signal, the pending_notification field will be populated from empty if the MPRIS message contains either player metadata or a status change. If the message contains either of those elements, pending_notification will either be set, updated, or cleared with a proper early return. Therefore, I'm wondering if Chromium can send a message that contains neither of those elements

@l1na-forever good call - I think that's definitely the case here!

After digging through the raw dbus-notifier output, it seems like Chromium sends a message with both "Metadata" and "PlaybackStatus" entries, but does so using member=GetAll instead of member=PropertiesChanged (see end of the first line):

method call time=1674346097.113628 sender=:1.5544 -> destination=:1.1694 serial=17 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=GetAll
   string "org.mpris.MediaPlayer2.Player"
method return time=1674346097.113865 sender=:1.1694 -> destination=:1.5544 serial=3345 reply_serial=17
   array [
### (truncated) ###
      dict entry(
         string "Metadata"
         variant             array [
               dict entry(
                  string "mpris:length"
                  variant                      int64 216023219
               )
               dict entry(
                  string "mpris:trackid"
                  variant                      object path "/org/chromium/MediaPlayer2/TrackList/TrackE07F19AD82AD0B729427060004BBB49E"
               )
### (truncated) ###
            ]
      )
### (truncated) ###
      dict entry(
         string "PlaybackStatus"
         variant             string "Playing"
      )
### (truncated) ###
      dict entry(
         string "Rate"
         variant             double 1
      )
### (truncated) ###
   ]

On the other hand, the "Rate" changes are sent using member=PropertiesChanged, so I'm betting they're the only ones that would be picked up by handle_signal:

signal time=1674346097.114710 sender=:1.1694 -> destination=(null destination) serial=3347 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.mpris.MediaPlayer2.Player"
   array [
      dict entry(
         string "Rate"
         variant             double 0
      )
   ]
   array [
   ]
signal time=1674346097.114719 sender=:1.1694 -> destination=(null destination) serial=3348 path=/org/mpris/MediaPlayer2; interface=org.mpris.MediaPlayer2.Player; member=Seeked
   int64 122475596
signal time=1674346097.114728 sender=:1.1694 -> destination=(null destination) serial=3349 path=/org/mpris/MediaPlayer2; interface=org.mpris.MediaPlayer2.Player; member=Seeked
   int64 0
signal time=1674346097.132564 sender=:1.1694 -> destination=(null destination) serial=3350 path=/org/mpris/MediaPlayer2; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.mpris.MediaPlayer2.Player"
   array [
      dict entry(
         string "Rate"
         variant             double 1
      )
   ]
   array [
   ]

@l1na-forever
Copy link
Owner

Awesome - thanks for the logs and confirming! Resolving 🎆

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

bugfix: Check if mutable reference to pending_notification is None hcwesson/mpris-notifier
2 participants
@hcwesson @l1na-forever