GStreamer 1.20 regression causes Pithos to stop playing after 1 or 2 songs about pithos HOT 46 CLOSED

I've started trying to debug this.
What I've seen is that query_position() suddently returns 0 after the song has started.
For example, at the start of the song, after 1 second it is 399000 and after 34 seconds it is 34595250000, but on second 35, it returns 0 - and at the end of the song there is no EOS.

A very quick fix has been to save the position, and if it goes from +ve to a zero mid song, I trigger a next(). So i miss out on half a song, but it doesn't die. Obviously this isn't a fix for everyone, but at least I've found a telltale, and am now narrowing down on finding where it's being set to 0 (in gstreamer? In a buffer overflow in pithos?)

So maybe it's gstreamer, or maybe it's always been there in pithos and it's jjst appearing now because of a race condition or unhandled buffer overflow. Getting there...

from pithos.

This is a bug tracker for this application. It is not a forum thread. Please keep the comments on topic to debugging and solving the issue.

from pithos.

Some findings from the last research, just in case anyone wants to discount any avenues:

• The issue is caused when gstreamer returns a stream position of 0 in the middle of a song. The song plays out to the end (from the buffer) but there is no EOS sent so it just sits there,
• It isn't reliably reproduceable, but it is reliably UNREPRODUCEABLE by running gstreamer debug of 4 - definitely 5
• If you leave pithos in the locked up condition, gstreamer sends an EOS after a few hours and pithos will recover and move on by itself. Seen this three times now, after I forgot about it and let it sit there
• It's not tied to ads - it happens in the middle of songs, sometimes multiple times in the same song (I have my pithos set to restart the current song when it sees a 0 stream position; usually it makes it through, sometimes it restarts multiple times)

Unfortunately gstreamer won't compile at the moment (see https://gitlab.freedesktop.org/rayrapetyan/gstreamer/-/pipelines/1024979) but soon as they fix that rebasing issue, that's where the investigation should go next.

from pithos.

Hi fellow sufferers of this bug!
I've picked this up again because lately I'm getting the issue pretty much every song. What I've discovered is, as expected, it's a buffering race condition.

Pithos has an event trigger set (using native gstreamer) to update the screen every second, inside which it does a Query to get the current position in the stream. It also has an event callback set to handle a buffering event, where it hits pause, lets the buffer fill, then hits play (usually within microseconds). It appears that when a timer trigger and a buffer trigger happen in a certain order, the Query from then on returns 0 because it's now looking at the wrong segment, and it would appear the EOS (end-of-stream) triggger never fires either because it's looking at the old, abandoned fragment because the Query made it look at the old, now abandoned stream segment. Result: Pithos points to the wrong segment (but the stream itself continues to play), song ends, but Pithos doesn't get informed because it's looking at the wrong variable, never triggers a play.next, we see it as pPithos having died.

If I disable the every-second screen update, so far I've not had the issue - so there's that workaround. Whether this is a bug deep in GStreamer or just Pithos' logic that variables don't change, I haven't quite worked out yet - but the cause is (I'm 99% sure) a race condition between query.song.position and song.buffering

Anyone else who wants to jump in to the code, this is a fight between song_text() and on_gst_buffering(). Commenting out song.position = self.query_position() in song_text() stops the time appearing in the GUI but lets everything else carry on as normal,

from pithos.

Well! That wasn't scary at all.
GstPlay is a drop-in replacement for GstPlayer if you are using it for audio only (GstPlay supports video as well). Changing over to the new library internally is a one-line change that has Pithos not display this bug, without any fancy hacks to avoid updating the GUI.

As a bonus, it means Pithos won't suddenly die when upgrading gstreamer to 1.24 in the future.

from pithos.

After reading through the thread I just created a super quick 'workaround' based on the GST_DEBUG=5.

Created the file '/usr/local/bin/pithos':

#!/bin/sh

exec env GST_DEBUG=5 /usr/bin/pithos

Super easy and so far so good! With all the debug info in the background not sure how this will impact PC performance but I haven't noticed any noticeable performance hit on my average spec'd PC.

from pithos.

Awesome, thanks! I can confirm that Pithos has been playing for 6 songs so far and no problems, whereas before it would stop after 2 or 3.

from pithos.

The Pithos flatpak works fine here. Based on comments here the problem is introduced in some update as part of Ubuntu 22.04 (and Arch which is always up to date of course).

from pithos.

Here is the last little bit of a debug log when Pithos runs into this issue. Doesn't seem like Pithos is waiting on anything.

...
02","artistExplorerUrl":"http://www.pandora.com/xml/music/artist/fine-frenzy?explicit=false"},{"adToken":"334061779151755777-none"}]}}
INFO - pithos:art_callback:898 - Downloaded album art for 21
INFO - pithos:art_callback:898 - Downloaded album art for 20
INFO - pithos:art_callback:898 - Downloaded album art for 22
INFO - pithos:art_callback:898 - Downloaded album art for 23
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
DEBUG - pithos:react_to_buffering_mesage:1159 - Buffer underrun
DEBUG - pithos:react_to_buffering_mesage:1161 - Pausing pipeline
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1169 - Restarting pipeline
DEBUG - pithos:react_to_buffering_mesage:1159 - Buffer underrun
DEBUG - pithos:react_to_buffering_mesage:1161 - Pausing pipeline
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1169 - Restarting pipeline
INFO - pithos:on_gst_eos:1085 - EOS
INFO - pithos:start_song:748 - Starting song: index = 20
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pithos:check_if_song_is_ad:1127 - Not an Ad..
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1166 - Song starting
DEBUG - pithos:react_to_buffering_mesage:1159 - Buffer underrun
DEBUG - pithos:react_to_buffering_mesage:1161 - Pausing pipeline
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1169 - Restarting pipeline
DEBUG - pithos:react_to_buffering_mesage:1159 - Buffer underrun
DEBUG - pithos:react_to_buffering_mesage:1161 - Pausing pipeline
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1169 - Restarting pipeline
INFO - pithos:on_gst_eos:1085 - EOS
INFO - pithos:start_song:748 - Starting song: index = 21
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pithos:check_if_song_is_ad:1127 - Not an Ad..
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1166 - Song starting
INFO - pithos:on_gst_eos:1085 - EOS
INFO - pithos:start_song:748 - Starting song: index = 22
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pandora:audioUrl:525 - Using audio quality mediumQuality: 64 aacplus
INFO - pithos:check_if_song_is_ad:1127 - Not an Ad..
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1166 - Song starting
DEBUG - pithos:react_to_buffering_mesage:1159 - Buffer underrun
DEBUG - pithos:react_to_buffering_mesage:1161 - Pausing pipeline
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1169 - Restarting pipeline
DEBUG - pithos:react_to_buffering_mesage:1159 - Buffer underrun
DEBUG - pithos:react_to_buffering_mesage:1161 - Pausing pipeline
DEBUG - pithos:react_to_buffering_mesage:1163 - Buffer overrun
DEBUG - pithos:react_to_buffering_mesage:1169 - Restarting pipeline

from pithos.

@TingPing So I tried GST_DEBUG=5 pithos. Tons of debug info. Ran it pretty much all day for 2 days like this, not a single unexpected freeze. So I tried running it normally through the terminal via pithos & and it freezes after the first song. Can't really explain it. Gonna try more with GST_DEBUG=5. Will report back if I get it to freeze with debug on.

from pithos.

I have this too. Have had for many weeks. I don't use it every day so I can't pinpoint a particular day or update or other event. It's just been doing it for some time for me.

No problem with pianobar using the same paid account.

from pithos.

I usually run with GST_DEBUG=4 because that doesn't produce the issue, but after about an hour of streaming I ended up with a paused stream, so I got a little bit more than you get with GST_DEBUG=3.

INFO basesrc gstbasesrc.c:2918:gst_base_Src_loop:<source> pausing after gst_base_src_get_range() = eos
INFO tast gsttask.c:368:gst_task_func:<source:src> Task going to paused

So yeah it seems that GST is getting some kind of end-of-stream thing and causing it to pause.

from pithos.

At first I thought this as well, so did some testing a few months back, and saw the problem even if I leave focus on Pithos the entire time, not minimizing it or switching windows. This is running Xfce, not GNOME.

from pithos.

I run Pithos on an older machine, using MX Linux. I have encountered this problem with higher debug values, including GST_DEBUG=5 Here is a pastebin of the last portion of the log: https://pastebin.com/Z8EUdXzA

I hope this helps.

from pithos.

I took @user4815162342 idea (nice!) and wrapped song_text() in a check for self.buffering_timer_id == 0 (initally tried self._current_state==BUFFERING but it ends up being PLAYING, even when buffering_timer_id is not zero, so another race condition there). I've been running pithos for the last 10+ hours and unless you look really closely and see the time info line valish for up to 2 seconds in the GUI, you'd never know Pithos isn't behaving exactly like it used to.

I can write this as a patch in github, but since it is an ugly hack rather than solving the actual race condition, @TingPing what do you think of this as a solution? Broadly:

in song_text()

    ...
    title = html.escape(song.title)                          
    artist = html.escape(song.artist)                        
    album = html.escape(song.album)                          
    description = "<b><big>%s</big></b>\nby <b>%s</b>\n<small>from <i>%s</i></small>" % (title, artist, album)
    msg = []
    if song is self.current_song:                            
        if self.buffering_timer_id != 0:
	    return description
        song.position = self.query_position()
         if not song.bitrate is None:
         ...

Added filling in the variable description early, and then inserted that if test to simply skip anything else if it's BUFFERING (using the timer rather than the status because _self.current_state is not reliably PseudoGst.BUFFERING when tested - but this is the condition I want to test for...), and this skips responding to those occasional async (or async-ish) calls that song_text() gets.

Also, I found that it's not just running the Gst.Query.new_position that breaks things, I had some other queries in there for debugging and if I ran any query on the stream at all, context was lost and Pithos broke. Just skipping touching the stream altogether does seem workable.

from pithos.

I withdrew my fix because whilst it more or less works, I wasn't entirely sure where the race was happening and if i caught it. And I didn't because it still broke once or twice in some of my testers. So I thought, time to learn gstreamer properly. And - bad news - Pithos uses a GstPlayer object, which was deprecated in gstreamer 1.20, and will be removed altogether in 1.24. Worse, apparently that's a superset of a playbin object - not supported anymore, and playbin2 is deprecated, and playbin3 is the new standard.

So my quick patch is now become an attempt to migrate to a GstPlay object, and then seeing if the issue still happens.

Not a small step. But - hey, I love open source.

from pithos.

I'm having the same problem on Arch (kernel 5.18.1-arch1-1, XFCE). Pithos 1.5. I discovered it on 6/13 after running an update. Pianobar works though.

from pithos.

I've been having the same problem too, recently (pithos 1.5.1, Arch 5.18.7-arch1-1, openbox). The one thing I have to add is that pithos will start playing again if you skip the song it's stuck on.

from pithos.

Correct.
I was witnessing the issue for a few weeks on and off (it seemed) but I was by the computer or a tethered device and could easily click next. Its when I started to spend days with it playing and able to hear but not close so I would have to walk over. I dealt with it for awhile as it wasn't that big of a deal.....but then I really started to wonder if it was just me and it was starting to reliably stop play after each track and thats when I sat and tested it before opening this issue.

from pithos.

I am having the same problem with 22.04 Kubuntu. I thought it was the power saving on the cheap laptop i am running it on, but I noticed other people are having the same issue.

from pithos.

This is most likely a change in gstreamer, considering Pithos hasn't changed in those years.

Somebody will need to spend a good amount of time looking into it.

from pithos.

Is there any way to put a temporary workaround in Pithos?

The behavior I've seen is consistent: the elapsed time of the song continues incrementing as the song plays, but when this issue happens, the elapsed time shows as 0:00.

Is there some way to capture when that happens and tell it to skip to the next song? Perhaps after a few seconds have passed?

Apologies if this is a bad idea, I know nothing about GTK or Gstreamer API's.

from pithos.

Thats a great idea that would seem to work, altho, same as you, no idea how code-able it would be.
When time allows, probably by 8-18-22, ill check out the gits for gstreamer and see if there are open issues that would seem relevant to the pithos issue. Ill comment if I find anything as well as report it back here.
Anyone else feel free to do the same as im not super technical so totally possible id overlook something that is actually relevant.

...do most people just stop using stuff when it stops working, or are we most of the only people exp'ing this issue with pithos??

from pithos.

The flatpak version does not successfully login with arch manjaro 21.3.6 ... for me anyway. It hangs upon entry and clicking apply. When I click back into preferences it gives an error window saying, "Failed to store your Pandora credentials please re-enter your email and password"

from pithos.

I did not get around to searching thru gstreamer for related issues. ... Due to the technical ignorance I mentioned prior, I vastly underestimated how large of a task to JUST go thru the open issues would be.

from pithos.

Pianobar works flawlessly for me....if that maybe makes the Pithos issue easier to diagnose shrug
I found my solution.
Best of luck to rest yall.

from pithos.

The Pithos flatpak works fine here. Based on comments here the problem is introduced in some update as part of Ubuntu 22.04 (and Arch which is always up to date of course).

Unfortunately this solution doesn't work for Linux Mint (there are two versions of Ptihos 4.0 and 4.1 in flatpak via Software Manager). Both have the same problem. This is strange since 4.0 packages it's own gstreamer libraries. I'm using LM 21 Vanessa. There were recently a bunch of updates to gstream.

from pithos.

I have personally seen this occur on a consistent basis in arch, debian and rpm distributions on separate devices. GNOME environment on all. Anxiously awaiting a solution.

from pithos.

I have personally seen this occur on a consistent basis in arch, debian and rpm distributions on separate devices. GNOME environment on all. Anxiously awaiting a solution.

Have you tried pianobar? ...i see my comment was marked "off-topic" where i mentioned pianobar may be a solution for others, as it was for me. Fix the issue or let comments that OFFER SOLUTIONS stay LOL

from pithos.

This may be some kind of idle/timeout issue that's built into newer DEs. It could have been a coincidence, but it seems to have paused for a few seconds before resuming after reengaging the mouse/keyboard a couple times. Idk, but I would really hate to replace this app; it's one of my favorites and one of the few I keep in my dock. Running a testing distro, I hope to see something role out soon!

from pithos.

Same. It was the only was I used Pandora for years.
But with how TingPing has been responding here (assuming that is the account hiding comments) I'm glad to replace it with the solution I've found.

from pithos.

I think it has nothing to do with Pithos.

You can debug GStreamer by setting GST_DEBUG=5 (You can try higher or lower numbers if its overly verbose or not enough).

from pithos.

Another app has some gstreamer command options that could be a good reference for this issue or might be a good idea to include them as options in pithos . App is goodvibes -- it does not perform the same function of pithos.

from pithos.

@TingPing I'm another one with this issue, after years of using Pithos issue-free.
I get the issue every single song - the counter stutters and doesn't increase a second every second - and then, when the song ends, if it's not at max, Pithos just sits there.

Like @FallingSnow I ran for days using GST_DEBUG=5 without issue, but if I drop it to GST_DEBUG=3 I get the hang every song or two. So it feels like a race condition in GS

When it hangs, GS emits this (DEBUG=3):
0x7f70e0013a40 WARN pulse pulsesink.c:703:gst_pulsering_stream_underflow_cb: Got underflow

I have a stupidly overspec'd laptop, running XFCE, not exceeding 7% CPU - so unlikely load-induced. Debian Sid, latest version of everything.

from pithos.

Glad to hear there is another partial patch for the issue.
...Pianobar works flawlessly too.
Pianobar is an alternative to pithos and is a >>SOLUTION<< to the open issue here, for anyone not able to get Pithos running with any of the workarounds outlined here.
All solutions are solutions even if it means migrating to an alternative service/application/company.

from pithos.

I notice this as well, with gstreamer 1.22.0 on Debian Bookworm. Is this a regression in GStreamer, or is it an oddity in GStreamer that Pithos didn't need to handle until now?

from pithos.

pithos usage of GStreamer is pretty basic, it largely relies on the playbin element from them, which is designed to "just work" and do the right things by default. We don't do a ton on top of that.

I won't remove the possibility it is a Pithos bug but its also been stable for many GStreamer releases.

Anyway the situation is nobody is looking into this AFAIK. So help diagnosing it and debugging it appreciated.

from pithos.

When using the Last.fm scrobbling plugin, songs that are stopped like this at 0:00 are at no point scrobbled to last.fm.
Not sure how helpful that is, or how consistent this behaviour is, (or if someone else has already pointed it out) but thought it might be worth noting.

from pithos.

Is it possible we are all seeing this when we use the Notification Icon plugin and have Pithos minimized to the system tray, or when Pithos is minimized to the task bar even without the plugin active?

I think the only time I can reproduce the issue is when I minimize to the tray or have the window minimized in the task bar. Both of these are "unsupported" states in GNOME which I have enabled with extensions. I haven't thoroughly tested having the window on a secondary display or workspace yet, those are other possible theories I have right now.

from pithos.

Is it possible we are all seeing this when we use the Notification Icon plugin and have Pithos minimized to the system tray, or when Pithos is minimized to the task bar even without the plugin active?

I think the only time I can reproduce the issue is when I minimize to the tray or have the window minimized in the task bar. Both of these are "unsupported" states in GNOME which I have enabled with extensions. I haven't thoroughly tested having the window on a secondary display or workspace yet, those are other possible theories I have right now.

Im going to test this also. I have zero recollection of those details as far as when I was using Pithos. It would be so wonderful if it stayed working properly if I simply keep it open on a 2nd display (or 2nd virtual desktop)

*EDIT:: um, nvm. The keyring is being an issue so cant test right now. No time to figure out how to make it use the keyrings I have installed. Altho, doesnt look like it would matter after seeing the comment left by chmeeedalf

from pithos.

I cannot help but to think that the stops are where the commercials are supposed to be. I have never had any commercials on Pithos where the commercials are prevalent on the same subscription level on the iOS and Windows. Anyone know why?

from pithos.

I cannot help but to think that the stops are where the commercials are supposed to be. I have never had any commercials on Pithos where the commercials are prevalent on the same subscription level on the iOS and Windows. Anyone know why?

From what I can tell it's a quirk in the XML parsing. I didn't get commercials using Pithos so ended up getting a Plus subscription (or whatever it's called now) (call it easing my conscience, or whatnot), so I shouldn't be getting commercials in my feed, yet still hit this.

from pithos.

I know almost nothing about Python programming. Is the query_position function an asynchronous call, in that it might be called before the buffering event, but return after? Does python even have functions that look blocking but are actually async?

Otherwise, it looks like there's a timer being set in on_gst_buffering. Would it fix the problem to check if self.buffering_timer_id is 0 before calling query_position in song_text? Should this be checked for all other queries as well?

from pithos.

Callbacks happen on the main thread. However everything GStreamer is doing internally is a mixture of async things so it may trigger those callbacks out of order.

from pithos.

There is definitely an async call going on in Pithos, and it sometimes coincides with the issue.
Depending on timing, song_text() gets executed between the inital call and return of the event handler on_gst_buffering().

I see the sequence when the issue happens being

  song_text() fires, position > 0, song_text() returns

  on_gst_buffering() fires
    react_to_buffering_message() called
      self._current_state is PLAYING
      Buffer underrun reported
      ** song_text() fires, position > 0, song_text() returns **
      react_to_buffering_message() continues, reports "Pausing pipeline"
    react_to_buffering_message() returns
  on_get_buffering() returns

  on_gst_buffering() fires
    react_to_buffering_message() called
      self._current_state is BUFFERING
      Buffer overrun reported
      ** song_text() fires, position == 0, song_text() returns **
      react_to_buffering_message() continues, reports "Restarting pipeline"
    react_to_buffering_message() returns
  on_gst_buffering() returns

  react_to_buffering_message() fires
    self._current_state is PLAYING
  react_to_buffering_message() returns
  ...
  song_text() fires after 1 sec, position == 0 from then on

But sometimes that sequence happens and the position is > 0 after that 'overrun' report (and EOS happens), and other times song_text() is not called at all during the on_gst_buffering() sequence (and, thus, position stays > 0)

from pithos.

@fenugeek I don't really have time to spend on debugging this, so go ahead and open a PR. Just leave some comments, point to this discussion, etc.

from pithos.