pithos icon indicating copy to clipboard operation
pithos copied to clipboard
verified publisher icon pithos

Strange issue with playback stoppage and audio quality

Open jkugler opened this issue 10 years ago • 72 comments

I apologize in advance because this bug report is going to be very nebulous. I don't have much (really, any) data at this point, but would like to work with you to debug this problem.

Fairly often it seems, Pithos will finish a song, and then stop playing. It could have been running for a ong time, or for just a few songs. The next song will be buffered, but it won't start, and oddly enough, the play/pause button still shows the pause bars (so there hasn't been a state toggle to paused).

When the pause button is pressed, it stays in the "play state" (showing double bars) and the song starts, but there is a clicking every second or two. Think "radio too close to a spark source" type of clicking. The only way to fix it I've found so far is restarting Pithos.

Very little network traffic at the time, so I don't think that's it. Very low CPU activity too I'm pretty sure, but could be wrong (maybe it spikes so briefly I don't notice it).

This is Ubuntu (Kubuntu) 14.04. The audio is going through a USB headset. Have not tried to see if this happens with just the system analog speakers.

What can I do to help you debug this?

lspci output, for the fun of it

00:00.0 Host bridge: Intel Corporation Xeon E3-1200 v3/4th Gen Core Processor DRAM Controller (rev 06)
00:01.0 PCI bridge: Intel Corporation Xeon E3-1200 v3/4th Gen Core Processor PCI Express x16 Controller (rev 06)
00:02.0 VGA compatible controller: Intel Corporation 4th Gen Core Processor Integrated Graphics Controller (rev 06)
00:03.0 Audio device: Intel Corporation Xeon E3-1200 v3/4th Gen Core Processor HD Audio Controller (rev 06)
00:14.0 USB controller: Intel Corporation 8 Series/C220 Series Chipset Family USB xHCI (rev 05)
00:16.0 Communication controller: Intel Corporation 8 Series/C220 Series Chipset Family MEI Controller #1 (rev 04)
00:1a.0 USB controller: Intel Corporation 8 Series/C220 Series Chipset Family USB EHCI #2 (rev 05)
00:1b.0 Audio device: Intel Corporation 8 Series/C220 Series Chipset High Definition Audio Controller (rev 05)
00:1c.0 PCI bridge: Intel Corporation 8 Series/C220 Series Chipset Family PCI Express Root Port #1 (rev d5)
00:1c.1 PCI bridge: Intel Corporation 8 Series/C220 Series Chipset Family PCI Express Root Port #2 (rev d5)
00:1c.2 PCI bridge: Intel Corporation 8 Series/C220 Series Chipset Family PCI Express Root Port #3 (rev d5)
00:1c.3 PCI bridge: Intel Corporation 8 Series/C220 Series Chipset Family PCI Express Root Port #4 (rev d5)
00:1d.0 USB controller: Intel Corporation 8 Series/C220 Series Chipset Family USB EHCI #1 (rev 05)
00:1f.0 ISA bridge: Intel Corporation HM86 Express LPC Controller (rev 05)
00:1f.2 SATA controller: Intel Corporation 8 Series/C220 Series Chipset Family 6-port SATA Controller 1 [AHCI mode] (rev 05)
00:1f.3 SMBus: Intel Corporation 8 Series/C220 Series Chipset Family SMBus Controller (rev 05)
03:00.0 Unassigned class [ff00]: Realtek Semiconductor Co., Ltd. RTS5229 PCI Express Card Reader (rev 01)
04:00.0 Network controller: Intel Corporation Wireless 3160 (rev 83)
05:00.0 Unassigned class [ff00]: Realtek Semiconductor Co., Ltd. Device 5289 (rev 01)
05:00.2 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller (rev 0a)

jkugler avatar Jun 30 '15 17:06 jkugler

What version of pithos?

gregsheremeta avatar Jun 30 '15 21:06 gregsheremeta

Ah, sorry. The latest available on 14.04: 1.0.3-1ppa1

jkugler avatar Jun 30 '15 22:06 jkugler

It's an old bug, and should have been fixed in 1.0.2. Specifically, this commit: https://github.com/pithos/pithos/commit/1e9824b178605698d98afccc3ff4faef67e25b60

Can you please locate pithos.py |grep python and then grep that file for the string self.player.props.flags and paste here?

gregsheremeta avatar Jul 02 '15 18:07 gregsheremeta 

jkugler@hosanna:~$ locate pithos.py |grep python
/usr/lib/python3/dist-packages/pithos/pithos.py
jkugler@hosanna:~$ grep self.player.props.flags /usr/lib/python3/dist-packages/pithos/pithos.py
jkugler@hosanna:~$

Seem that string is not in that file. I'm pretty sure I'm not using an old version, because:

jkugler@hosanna:~$ dpkg -S /usr/lib/python3/dist-packages/pithos/pithos.py
pithos: /usr/lib/python3/dist-packages/pithos/pithos.py

I even uninstalled pithos and reinstalled 1.0.3. String is still not there.

jkugler avatar Jul 02 '15 19:07 jkugler

Ok. Next, I'll need a debug log when it hangs.

python3 -m pithos -vv

gregsheremeta avatar Jul 02 '15 19:07 gregsheremeta

Sure thing. Restarted with -vv. I'll see if I can get any useful output. It's not reliably reproducible.

jkugler avatar Jul 02 '15 19:07 jkugler

OK, I finally got it to do it!

At this point it stopped, but was not paused. The double bars were there, but the song's status said paused. The log looked like this:

INFO - pithos:art_callback:551 - Downloaded album art for 86
INFO - pithos:art_callback:551 - Downloaded album art for 87
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "50301" (type: <class 'int'>)
INFO - pithos:on_gst_eos:638 - EOS
INFO - pithos:start_song:463 - Starting song: index = 85
INFO - pandora:audioUrl:370 - Using audio quality mediumQuality: 64 aacplus
DEBUG - pithos:on_gst_buffering:728 - Buffering (4%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (4%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (4%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (4%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (4%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (4%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (3%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (2%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (25%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (25%)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:handler:685 - Found tag "datetime" in stream: "2012-12-05T11:43:45Z" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "container-format" in stream: "ISO MP4/M4A" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
INFO - pithos:check_if_song_is_ad:711 - Not an Ad..
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)

After I hit the pause button to start it again, the log had this:

DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "73212" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "70284" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "67528" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "66839" (type: <class 'int'>)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "63738" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "62360" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "60465" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "58570" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "56503" (type: <class 'int'>)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "56330" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "audio-codec" in stream: "MPEG-4 AAC audio" (type: <class 'str'>)
DEBUG - pithos:handler:685 - Found tag "maximum-bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "bitrate" in stream: "64000" (type: <class 'int'>)
DEBUG - pithos:handler:685 - Found tag "minimum-bitrate" in stream: "53057" (type: <class 'int'>)
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline

DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline


DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (0%)
DEBUG - pithos:on_gst_buffering:734 - Buffer underrun. Pausing pipeline
DEBUG - pithos:on_gst_buffering:728 - Buffering (100%)
DEBUG - pithos:on_gst_buffering:742 - Buffer recovery. Restarting pipeline

And it kept printing a LOT of those. Skipping to the next song "fixed" it.

Here is the screen shot when it pauses on its own. image

jkugler avatar Jul 14 '15 22:07 jkugler

Perfect, thanks for the detail.

This is a known issue that @JasonLG1979 has mentioned before. I never use AAC because I have Pandora One, but @JasonLG1979 has seen this behavior while testing.

I don't think we know the root cause yet, but it's probably an issue in gstreamer's AAC support, or something wrong with the way we're using gstreamer.

gregsheremeta avatar Jul 15 '15 12:07 gregsheremeta

It's nothing we're doing wrong it's a bug in GStreamer. There are multiple bug reports filed about it already that go back a couple years but no one seems to be doing anything about it. From what I understand AAC streams are allocated basically what amounts to almost infinite and/or unnecessarily HUGE buffers. That's why we see the buffer bounce from 0 to 100% several times. MP3 streams behave well enough because they have sensible buffer values. I'm not even sure a custom pipeline would help as it seems to be built into the base plugin? I think someone with some coding skills would have to try to get a patch accepted in Gstreamer itself to fix the problem.

JasonLG1979 avatar Jul 15 '15 22:07 JasonLG1979

The only thing that kinda sort works is an ugly hack that I threw together that relies on ignoring the 0% buffer message and using a time based polling method to check the buffer level instead of listening on the bus. But like I said it's ugly and really wouldn't be necessary if ACC's worked properly.

JasonLG1979 avatar Jul 15 '15 22:07 JasonLG1979

This post was originally a bug report that mirrored the issues experienced by jkugler, but now I'd like to point out that as strange as it sounds, re-adding line number 198:

self.player.props.flags |= (1 << 7) # enable progressive download (GST_PLAY_FLAG_DOWNLOAD)

removed in commit 1e9824b back to pithos.py appears to have eliminated this issue for me.

I'm on Ubuntu 14.04, Pithos 1.0.3, non-Subscriber. I've been a Pithos user for over a year or so now (I love the program, my thanks!) and sure enough I started noticing this problem about the time that commit was made. It's very strange that a fix (which appears to have eliminated an identical sounding buffer issue for many) was what caused it for me (and potentially jkugler).

If any help is wanted in determining an underlying cause then I'd be happy to help.

Thanks!

Rondo5000 avatar Sep 16 '15 07:09 Rondo5000

re-adding line number 198 removed in commit 1e9824b back to pithos.py appears to have eliminated this issue for me.

What the hell?? ><

gregsheremeta avatar Sep 16 '15 11:09 gregsheremeta

Haha. I hope you hadn't lost much sleep over the glitch. I've pulled a near 12 hour programming binge while listening since making the change and it hasn't hitched up a single time, and it had previously affected me at LEAST once per an 8 song set (I wonder now why on Earth I put off checking into it so long!?). If nobody else chimes in to confirm I'll report back after a few days usage, but I'm convinced it's fixed.

Rondo5000 avatar Sep 16 '15 11:09 Rondo5000

It's because of the way Gstreamer handles buffering with AAC's. For some unknown(to me at least) reason Gstreamer uses WAY too many buffers with AAC's. The end result is that sometimes randomly it gets stupid. The buffer for Mp3's is a little more sensible but download buffering is broken(self.player.props.flags |= (1 << 7)) they are 2 separate but related issues. It's kinda a catch 22 of sorts. The solution that has worked for me for several months with MP3's anyway is to use a loop to detect buffer % and not rely on the bus message except for the initial message. It also has the side effect of reducing CPU usage during buffering. Normally on my system anyway during buffering of mp3's the bus will send about 30 messages per sec. On AAC's on the other hand the number goes up to around 1000 bus messages per second. With my method once the 1st buffering bus message is received it sets a loop that polls the buffer % 10 times a sec. A much more reasonable number.

JasonLG1979 avatar Sep 17 '15 01:09 JasonLG1979

From very limited testing with Download Buffering re-enabled with the AAC stream with my personal fork I am noticing that AAC's take A LOT longer to buffer than Mp3's not sure if this is a Gstreamer problem or just Pandora throttling me on AAC. I'm getting anywhere from 5 to 20 sec for initial buffering to complete for AAC's and around 0.5 to 1 sec for MP3's to complete initial buffering. I'll test with the main official branch on my next day off.

screenshot_2015-09-17_11-08-14

JasonLG1979 avatar Sep 17 '15 16:09 JasonLG1979

self.player.props.flags |= (1 << 7) is still a no go with MP3's. I went months without any issues and it took a grand total of 12 hours before I got a deadlock.

JasonLG1979 avatar Sep 19 '15 21:09 JasonLG1979

Let's use one mode for AAC and another for MP3. Easy right?

gregsheremeta avatar Sep 19 '15 21:09 gregsheremeta

Basically reverting back to pre-Gstreamer 1.4 behaviour. I'll have to see if that can be turned on and off. Right now that flag is set when gstreamer is initialized, before we know what the stream is.

JasonLG1979 avatar Sep 19 '15 21:09 JasonLG1979

It would basically have to be tied to the Audio quality dropdown and Pandora One checkbox. It would only need to be disabled if you're using the High Quality setting with a Pandora One account. Even then I think it's more trouble than it's worth. I don't think that enabling download buffering helps the buffering behavior with AAC's. In any and all the testing I've done it makes no difference.

JasonLG1979 avatar Sep 19 '15 21:09 JasonLG1979

An easier option would be to make it a user option. Put a checkbox in the options(defaulting to off) and let the user decide.

JasonLG1979 avatar Sep 19 '15 21:09 JasonLG1979

Whatever lets people use the program. Settings are fine. Automatic is fine. Don't care :)

gregsheremeta avatar Sep 19 '15 22:09 gregsheremeta

I honestly don't think download buffering is the issue and I also don't think it offers much value. The purpose of download buffering is to keep it from buffering mid song and that doesn't seem to be much of a problem once the initial buffering completes. The initial buffering is the problem and download buffer doesn't help that. If anything it adds another buffering layer to an already screwed up buffering system.

JasonLG1979 avatar Sep 20 '15 02:09 JasonLG1979

I can supply any logs or diagnostics necessary to back up the fact that it's cleared up the issue for me. I had hoped that Jkugler, the original reporter of the issue, would return to see what may make our particular hardware/software/network scenario different enough from yours that you aren't able to replicate it.

I have yet to experience the deadlock you spoke of, but I'm more than happy to take the tradeoff of having a lock every twelve hours as opposed to experiencing the current glitch about once per every four to eight tracks.

Rondo5000 avatar Sep 20 '15 02:09 Rondo5000

@Rondo5000 no need for logs. I believe you. That flag may not be the "root" of the problem, but if it lets people use the app, we'll add automatic toggling / a setting.

gregsheremeta avatar Sep 20 '15 02:09 gregsheremeta

My thanks to you both for looking into it. If I do indeed prove to be an isolated case and the fix becomes more trouble than it's worth then I'll voice no complaints about removing it (given I can still just stick this particular fix in myself as I've done). Just whatever is best FOR THE MASSES (as well as the programmers), obviously.

Rondo5000 avatar Sep 20 '15 03:09 Rondo5000

I'm not sure what details you need; let me know.

As for the "fix," I did re-add

self.player.props.flags |= (1 << 7) # enable progressive download (GST_PLAY_FLAG_DOWNLOAD)

at line 198, and in the few hours I listened, it fixed it, when it had been doing it several times a day. I'll listen longer come Monday. We'll see what it does then.

jkugler avatar Sep 20 '15 03:09 jkugler

I have yet to experience the deadlock you spoke of

The deadlock effects the MP3 stream mostly AFAIK. That's why I said it's kinda a catch 22. Either enable it and break MP3's or keep it disabled and break AAC's.

but if it lets people use the app, we'll add automatic toggling / a setting.

I can pretty easily make Pithos automatically decide whether or not to turn on download buffering in the start_song function but there are 2 issues.

  1. It depends on my pull request to get codec info from Pandora.(we would need to know the codec before we start buffering)
  2. I can't figure out how to turn it off once it's enabled. So basically once the flag is set when an AAC is played I can't figure out how to disable it for MP3's.

JasonLG1979 avatar Sep 20 '15 06:09 JasonLG1979

Well I still can't figure out how to turn it off once it's enabled but I have come up with kinda a work around. The working code I have still depends on my pull request for getting codec info from Pandora but it now automatically uses download buffering or not based on if the AAC or MP3 stream is played. Basically I use 2 playbins one with the flag set for AAC's and one without the flag set for MP3's and switch back and forth as needed.

JasonLG1979 avatar Sep 20 '15 07:09 JasonLG1979

Yeah, that's what I want.

Can you push this into a branch somewhere so people can test it?

gregsheremeta avatar Sep 20 '15 13:09 gregsheremeta

Putting in a lot of overtime at work. I'll do something with it this coming weekend when I get some time. That will also give me a chance to test it further myself, before I punish anyone else with my ugly hack,lol!!!

I would also be nice if you could review/accept that merge request for the whole getting the codec info from Pandora.

EDIT: There, that was easier than I thought. Test away!!! https://github.com/JasonLG1979/pithos/tree/JasonLG1979-2playbins

JasonLG1979 avatar Sep 20 '15 18:09 JasonLG1979