Continuous Buffering

sam_adams

Still doing the buffering thing. Sometimes it stops several times a day.

I can understand your frustration with this issue and you have my sympathies as I understand how maddening it can be when your favorite software refuses to co-operate. However . . . without providing more information beyond "it's stuck buffering", makes it very difficult for @jonas to figure out what is actually happening.

Without being too pretentious, it may be helpful to know what your hardware setup is, i.e., computer make/model, processor type, installed RAM etc., sound output device (internal soundcard, external DAC with connection type like USB, SPDIF, HDMI out to an AVR, etc.), where the file library is located; network share and filesharing protocol like SMB or NFS, local internal storage, USB or Thunderbolt connected external storage, etc.

In order to provide Jonas with more information as to what exactly Strawberry is doing when it throws its buffering message, you may have to run Strawberry with the Linux debugger, gdb, in order to get some usable information for Jonas to act on. You may even have to resort to installing a debug version from RPM to really drill down to what the root cause is. (Debug RPMs are available on the Github release page.)

I really can't provide much help with installing and using debug versions of Strawberry on Linux and how you would configure gdb to gather the necessary info because I'm just a dabbler in Linux with Raspberry Pi devices—I was able to get Strawberry installed and running on the PI, but other aspects of the OS made it unsuitable for my needs. Jonas would be the expert source on how to do this, but I don't want to make more work for him than he already has.

Maybe there are some members here that have the requisite Linux experience to help get you started in setting up a debug installation that will help you and Jonas get to the bottom of this vexing issue. We'd all like to see it solved as it would benefit everyone who loves Strawberry and appreciates Jonas' herculean effort in making this software available to all of us.

rlkeeney

@sam_adams

I know you are trying to be helpful, and I thank you for that. However, I am only posting here to keep the thread alive.

As a retired Linux/Unix Systems Programmer, I have extensive experience with Linux. I have been using Linux since shortly after Slackware was released. If there were an error, I would have found it. I am not your typical user, and my system is not typical. I can provide any info Jonas might need. However, I doubt Jonas could duplicate my system. For example, I have 48GB of RAM, 19 TB of active storage, 28 TB of offline storage for backups, and a few TB of network-shared storage.

BTW, my music is on a local attached (SATA) hard drive.

Strawberry worked fine for years, and then the buffering thing started while I was using Fedora. I later switched to Linux Mint LMDE 22.1 because I support people who have Linux Mint and only support one Fedora system.

ben2talk

@rlkeeney said in Continuous Buffering:

I have extensive experience with Linux. If there were an error, I would have found it. I am not your typical user

That solves it, then.

If you have enough space, then try copying a large portion of your collection (if not all) to your system drive and see if that fixes the issue... but remember to exclude that from backups if you already have it stored elsewhere...

You say you saw this issue in Fedora, and are now running Mint - so the issue is not the installation, though obviously $USER data is always suspect... but this doesn't sound like a Strawberry issue to me; not that it has none, just none like this.

I recently had issues with Plex, buffering and messing around... wasted a lot of time troubleshooting, why wouldn't movies play on the TV downstairs? Then it started local playback issues and I started playing files manually; but the final straw came with this:

sudo smartctl -a /dev/sdX

I am experienced. I had not found any errors for 2 weeks, and in the next few days the drive failed to the extent that I replaced it after only extracting about 25% of the data (i.e. the important data - the rest is very easily replaced).

Just doing an rsync backup of my collection took about 3-4 hours in total. Actually, 20 minutes for the copy and the rest for getting past bad sectors.

I now have qDiskInfo installed too - a nice front end for smartctl, so I'd recommend you add that to your ToDo list

Now I'm watching this old dog (I think from 2013):

It's been on the 'failing' list now for over a year - let's see. I hate to replace stuff prematurely.

rlkeeney

@ben2talk
I'm running smartd continuously and have manually run the long diagnostic. I also monitor drive health daily via an automatically generated report that is emailed to me.

I have run extensive tests on this drive with nothing found. It has zero bad sectors, and none of the replacement sectors have been used. Despite its age, this drive tests completely clean. The only thing I have not done is a destructive read-write test.

Jellby

@rlkeeney said in Continuous Buffering:

As a retired Linux/Unix Systems Programmer, I have extensive experience with Linux.

Perhaps at this point what remains in biting the bullet, compiling your own Strawberry build and trying to debug with it.

Speckie

Got the same buffering issue.

Linux Mint 22.2 Zara base: Ubuntu 24.04 noble
Strawberry 1.2.14 but had the same problem in 1.2.13

rlkeeney

@Jellby said in Continuous Buffering:

@rlkeeney said in Continuous Buffering:

As a retired Linux/Unix Systems Programmer, I have extensive experience with Linux.

Perhaps at this point what remains in biting the bullet, compiling your own Strawberry build and trying to debug with it.

It might be a good idea if there were time available. However, it only takes two mouse clicks to restart, so it is not worth the effort at this time.

jonas

@rlkeeney

It could be bug that only appears on certain harddrives, ie.: if the harddrive is a slower mechanical HDD.
You can set the GST_DEBUG environment variable to get more debug output.
Something like:

GST_DEBUG=*:5 GST_DEBUG_FILE=/tmp/gstreamer-debug.log strawberry

However, the file will grow huge, so make sure you have enough space on /tmp, or change the path to somewhere else.

rlkeeney

I upgraded my Linux Mint a couple of weeks ago, including the kernel. Since then, the buffering issue appears every few days. I have it running 24/7 most days to see if it will stop.

rlkeeney

@jonas said in Continuous Buffering:

@rlkeeney

It could be bug that only appears on certain harddrives, ie.: if the harddrive is a slower mechanical HDD.
You can set the GST_DEBUG environment variable to get more debug output.
Something like:
GST_DEBUG=*:5 GST_DEBUG_FILE=/tmp/gstreamer-debug.log strawberry
However, the file will grow huge, so make sure you have enough space on /tmp, or change the path to somewhere else.

Thanks, I will try that.

rlkeeney

@jonas That did not take long.

I don't see anything obvious. What am I looking for.

1:45:03.121612943 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<abin>.[00m query 0x5f72f7680500 result 1
1:45:03.121620130 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<abin>.[00m got position 237718139826
1:45:03.121636731 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<playsink>.[00m child audiotee is not sink
1:45:03.121645550 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<playsink>.[00m child streamsynchronizer1 is not sink
1:45:03.121653469 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<playsink>.[00m max position 237718139826
1:45:03.121661692 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<playsink>.[00m query 0x5f72f7680500 result 1
1:45:03.121669127 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<playsink>.[00m got position 237718139826
1:45:03.121678322 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<pipeline-2-pipeline>.[00m child uridecodebin3 is not sink
1:45:03.121686180 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<pipeline-2-pipeline>.[00m max position 237718139826
1:45:03.121694065 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<pipeline-2-pipeline>.[00m query 0x5f72f7680500 result 1
1:45:03.321152494 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m               query gstquery.c:680:gst_query_new_custom:.[00m creating new query 0x5f72f5609880 position
1:45:03.321195304 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element pipeline-2-pipeline
1:45:03.321228002 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<pipeline-2-pipeline>.[00m Sending query 0x5f72f5609880 (type position) to sink children
1:45:03.321242323 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<pipeline-2-pipeline>.[00m child playsink is sink
1:45:03.321254302 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element playsink
1:45:03.321264259 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<playsink>.[00m Sending query 0x5f72f5609880 (type position) to sink children
1:45:03.321273865 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<playsink>.[00m child abin is sink
1:45:03.321319023 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element abin
1:45:03.321329866 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<abin>.[00m Sending query 0x5f72f5609880 (type position) to sink children
1:45:03.321341723 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<abin>.[00m child aconv is not sink
1:45:03.321353307 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<abin>.[00m child aqueue is not sink
1:45:03.321362720 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<abin>.[00m child audiobin is sink
1:45:03.321371183 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element audiobin
1:45:03.321380760 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<audiobin>.[00m Sending query 0x5f72f5609880 (type position) to sink children
1:45:03.321390886 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child capsfilter31 is not sink
1:45:03.321400579 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child capsfilter30 is not sink
1:45:03.321410283 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-ebur128_volume is not sink
1:45:03.321419240 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-volume_sw is not sink
1:45:03.321429244 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-audiosinkconverter is not sink
1:45:03.321438310 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-audioqueueconverter is not sink
1:45:03.321447751 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-audioqueue is not sink
1:45:03.321457063 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-autoaudiosink is sink
1:45:03.321466099 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element pipeline-2-autoaudiosink
1:45:03.321475888 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<pipeline-2-autoaudiosink>.[00m Sending query 0x5f72f5609880 (type position) to sink children
1:45:03.321489434 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<pipeline-2-autoaudiosink>.[00m child pipeline-2-autoaudiosink-actual-sink-pulse is sink
1:45:03.321498120 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element pipeline-2-autoaudiosink-actual-sink-pulse
1:45:03.321516107 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5447:default_element_query:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m position query in format time
1:45:03.321528441 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5225:gst_base_sink_get_position:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m in paused, using start time 0:37:23.033983000
1:45:03.321546443 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5265:gst_base_sink_get_position:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m in PLAYING using last 0:03:57.897133937
1:45:03.321565287 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5344:gst_base_sink_get_position:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m now 0:37:23.033983000 - base_time 0:33:25.315843174 - base 0:33:25.315843174 + time 0:00:00.000000000  last 0:03:57.897133937
1:45:03.321580216 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5360:gst_base_sink_get_position:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m res: 1, POSITION: 0:03:57.718139826
1:45:03.321590845 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5566:default_element_query:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m query position returns 1
1:45:03.321600164 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m got position 237718139826
1:45:03.321609573 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<pipeline-2-autoaudiosink>.[00m max position 237718139826
1:45:03.321618796 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<pipeline-2-autoaudiosink>.[00m query 0x5f72f5609880 result 1
1:45:03.321626921 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<pipeline-2-autoaudiosink>.[00m got position 237718139826
1:45:03.321635790 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<audiobin>.[00m max position 237718139826
1:45:03.321644423 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<audiobin>.[00m query 0x5f72f5609880 result 1
1:45:03.321652394 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<audiobin>.[00m got position 237718139826
1:45:03.321661042 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<abin>.[00m max position 237718139826
1:45:03.321670294 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<abin>.[00m query 0x5f72f5609880 result 1
1:45:03.321678255 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<abin>.[00m got position 237718139826
1:45:03.321692267 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<playsink>.[00m child audiotee is not sink
1:45:03.321701991 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<playsink>.[00m child streamsynchronizer1 is not sink
1:45:03.321710877 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<playsink>.[00m max position 237718139826
1:45:03.321719636 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<playsink>.[00m query 0x5f72f5609880 result 1
1:45:03.321727665 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<playsink>.[00m got position 237718139826
1:45:03.321737553 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<pipeline-2-pipeline>.[00m child uridecodebin3 is not sink
1:45:03.321746067 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<pipeline-2-pipeline>.[00m max position 237718139826
1:45:03.321763334 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<pipeline-2-pipeline>.[00m query 0x5f72f5609880 result 1
1:45:03.520461539 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m               query gstquery.c:680:gst_query_new_custom:.[00m creating new query 0x5f72f66a8720 position
1:45:03.520528731 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element pipeline-2-pipeline
1:45:03.520546349 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<pipeline-2-pipeline>.[00m Sending query 0x5f72f66a8720 (type position) to sink children
1:45:03.520560477 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<pipeline-2-pipeline>.[00m child playsink is sink
1:45:03.520577184 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element playsink
1:45:03.520588278 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<playsink>.[00m Sending query 0x5f72f66a8720 (type position) to sink children
1:45:03.520604360 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<playsink>.[00m child abin is sink
1:45:03.520613052 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element abin
1:45:03.520622252 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<abin>.[00m Sending query 0x5f72f66a8720 (type position) to sink children
1:45:03.520632395 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<abin>.[00m child aconv is not sink
1:45:03.520643739 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<abin>.[00m child aqueue is not sink
1:45:03.520652638 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<abin>.[00m child audiobin is sink
1:45:03.520661363 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element audiobin
1:45:03.520673954 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<audiobin>.[00m Sending query 0x5f72f66a8720 (type position) to sink children
1:45:03.520691404 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child capsfilter31 is not sink
1:45:03.520699752 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child capsfilter30 is not sink
1:45:03.520709020 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-ebur128_volume is not sink
1:45:03.520717612 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-volume_sw is not sink
1:45:03.520726837 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-audiosinkconverter is not sink
1:45:03.520735494 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-audioqueueconverter is not sink
1:45:03.520744392 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-audioqueue is not sink
1:45:03.520760301 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<audiobin>.[00m child pipeline-2-autoaudiosink is sink
1:45:03.520807979 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element pipeline-2-autoaudiosink
1:45:03.520818388 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4311:gst_bin_query:<pipeline-2-autoaudiosink>.[00m Sending query 0x5f72f66a8720 (type position) to sink children
1:45:03.520827844 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<pipeline-2-autoaudiosink>.[00m child pipeline-2-autoaudiosink-actual-sink-pulse is sink
1:45:03.520836256 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;37;41m    GST_ELEMENT_PADS gstelement.c:2098:gst_element_query:.[00m send query on element pipeline-2-autoaudiosink-actual-sink-pulse
1:45:03.520852652 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5447:default_element_query:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m position query in format time
1:45:03.520869444 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5225:gst_base_sink_get_position:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m in paused, using start time 0:37:23.033983000
1:45:03.520878555 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5265:gst_base_sink_get_position:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m in PLAYING using last 0:03:57.897133937
1:45:03.520895980 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5344:gst_base_sink_get_position:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m now 0:37:23.033983000 - base_time 0:33:25.315843174 - base 0:33:25.315843174 + time 0:00:00.000000000  last 0:03:57.897133937
1:45:03.520905733 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5360:gst_base_sink_get_position:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m res: 1, POSITION: 0:03:57.718139826
1:45:03.520915547 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00m            basesink gstbasesink.c:5566:default_element_query:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m query position returns 1
1:45:03.520923916 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<pipeline-2-autoaudiosink-actual-sink-pulse>.[00m got position 237718139826
1:45:03.520933755 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<pipeline-2-autoaudiosink>.[00m max position 237718139826
1:45:03.520943657 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<pipeline-2-autoaudiosink>.[00m query 0x5f72f66a8720 result 1
1:45:03.520951953 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<pipeline-2-autoaudiosink>.[00m got position 237718139826
1:45:03.520960430 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<audiobin>.[00m max position 237718139826
1:45:03.520968509 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<audiobin>.[00m query 0x5f72f66a8720 result 1
1:45:03.520975800 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<audiobin>.[00m got position 237718139826
1:45:03.520983759 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<abin>.[00m max position 237718139826
1:45:03.520991625 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<abin>.[00m query 0x5f72f66a8720 result 1
1:45:03.520999009 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<abin>.[00m got position 237718139826
1:45:03.521016741 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<playsink>.[00m child audiotee is not sink
1:45:03.521028890 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<playsink>.[00m child streamsynchronizer1 is not sink
1:45:03.521039239 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<playsink>.[00m max position 237718139826
1:45:03.521047445 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<playsink>.[00m query 0x5f72f66a8720 result 1
1:45:03.521054864 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4134:bin_query_position_fold:<playsink>.[00m got position 237718139826
1:45:03.521063998 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01;31m          GST_STATES gstbin.c:1957:bin_element_is_sink:<pipeline-2-pipeline>.[00m child uridecodebin3 is not sink
1:45:03.521072163 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4152:bin_query_position_done:<pipeline-2-pipeline>.[00m max position 237718139826
1:45:03.521080294 .[33m    2.[00m 0x5f72f54778a0 .[37mDEBUG  .[00m .[00;01m                 bin gstbin.c:4334:gst_bin_query:<pipeline-2-pipeline>.[00m query 0x5f72f66a8720 result 1