The longer trackma & mpv run, the more signals I get

[FichteFoll]

The longer I have mpv and trackma running together (in debug mode), the more mpris signals I get (that are then also ignored). Or at least that's what it appears to be because when I restart trackma, I'm back to one extra signal instead. I don't have a reliable way of reproducing it yet.

It doesn't seem to affect any functionality either, since this is just debug output, but trackma has been missing episodes more frequently in the past despite no other media being played and the episode was already detected but the tracker somehow lost track of the episode before it updated. No idea if those are related, though.

Log after mpv and trackma have been running for a while and toggling the playing state of my player twice.

[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): New playback status: Paused

The same after restarting trackma (still one extra signal, curiously):

[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.

I haven't had the time to debug this yet, but this way it's at least not forgotten for the time being.

[z411]

Thank you for the report. Even though it is "just" debug output, it still means there's something wrong going on internally. It's worth looking into.

[FichteFoll]

Here's an example of the event somehow not getting through.

[D] Tracker (MPRIS): Show guess: Bastard!! Ankoku no Hakaishin (2022): {'id': 144677, 'title': 'BASTARD!! -Heavy Metal, Dark Fantasy-', 'my_progress': 1, 'total': 24, 'type': None, 'titles': ['BASTARD!! -Heavy Metal, Dark Fantasy-', 'BASTARD!!: Ankoku no Hakaishin', 'BASTARD!! -Heavy Metal, Dark Fantasy-', 'BASTARD!! －暗黒の破壊神－', 'Bastard!! อสูรร้ายจอมราชัน']} (2)
Tracker (MPRIS): Will update BASTARD!! -Heavy Metal, Dark Fantasy- - 2
[D] Tracker (MPRIS): New tracker status: Tracker.PLAYING (previously: Tracker.PLAYING)
[D] Tracker (MPRIS): (Tracker.PLAYING) Setting active player: :1.356
[D] Tracker (MPRIS): Starting MPRIS timer.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): Got signal from an inactive player, ignoring.
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New video: watch?v=TZqM8-m64tw
[D] Tracker (MPRIS): Guessing filename: watch?v=TZqM8-m64tw
[D] Tracker (MPRIS): Show guess: watch?v=TZqM8 m64tw: None (1)
Tracker (MPRIS) warning: Found player but show not in list.

Unfortunately, there are no timestamps here (I'll get to changing that once we/I switch to the logging module), but I have indeed properly completed watching the episode. However, I am not sure if I started watching the video before or after the episode was completed. I believe that the tracker state was incorrectly reset, as indicated by the following lines:

[D] Tracker (MPRIS): New tracker status: Tracker.NOT_FOUND (previously: Tracker.NOT_FOUND)
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): Clearing active player: :1.356
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Tracker (MPRIS): New playback status: Stopped
[D] Data: No items in queue.
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Data: No items in queue.
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Paused
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New playback status: Playing
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Data: No items in queue.
[D] Tracker (MPRIS): New playback status: Playing
[D] Tracker (MPRIS): New video: Overlord IV E02 […]
[D] Tracker (MPRIS): Guessing filename: Overlord IV E02 […]
[D] Tracker (MPRIS): Show guess: Overlord IV: {'id': 133844, 'title': 'Overlord IV', 'my_progress': 1, 'total': 13, 'type': None, 'titles': ['Overlord IV', 'Overlord IV', 'Overlord IV', 'オーバーロードⅣ', 'Overlord 4', 'โอเวอร์ลอร์ด ภาค 4', 'โอเวอร์ ลอร์ด จอมมารพิชิตโลก ภาค 4']} (2)
Tracker (MPRIS): Will update Overlord IV - 2

(I have shortened the file names.)

[FichteFoll]

So, I've rewritten most of the mpris tricker by now but I wasn't able to get rid of this problem. I've been able to track it down to the _on_update handler being called with the same event for each connected player, which makes it basically impossible to associate the event with the correct player since they all receive an identical message. This behavior is not observable with dbus-monitor or Qt DBusViewer, where the printed events/signals look as expected. Thus, I can only presume that it must be something with pydbus, which could also explain why this didn't happen before because pydbus was only used after #529. The switch happened because python-dbus was deprecated but I can't exactly say that pydbus is any more active considering the last activity on Github (commit or comment) was over 4 years ago.

As such, I'm looking for alternative dbus libraries and I gotta say there are a couple choices (with varying degrees of asyncio-ness, gobject-ness, maintained-ness, usage & availability on package managers) and I haven't decided on one yet, but I'd like to collect some suggestions if anyone knows some.

I should probably also try to build a minimal reproduction case for the problem to be absolutely sure the issue is with pydbus.

Edit: It does reproduce in a single file.

Edit2: The jeepney documentation has a small section on alternative dbus client libraries that provides a good summary of the candidates I was considering, namely jeepney itself, dasbus, dbussy. Currently, I'm favoring jeepney because of its design philosophy, no dependencies and availability on several package managers (Arch, Debian, Fedora).