Audio drops randomly when playing shuffled M3U music playlist with crossfade
#1
Hello,

It has been a bit since I posted here but I have had a persistent issue over several versions of Kodi and I am finally circling back to see if I can help get to the bottom of it.  I did try to search through the Music forum posts but didn't see any other posts that looked similar to my particular issue.

Several years ago, I posted about a similar issue where Kodi 17.6 would crash occasionally when playing a shuffled M3U playlist.  Back then I was running Kodi on Gentoo Linux and have since moved on to Kodi on LibreElec, first with a Raspberry Pi 3B+ and now a 4B.  Since moving to Libreelec, I have thankfully gotten rid of the crashing issue, but still have an issue playing shuffled M3U playlists.  (Also apologies for never responding in the previous thread as I didn't have an easy way to test new things out then.  Now I have a much easier setup to test on.)

Let me see if I can describe what happens and how I have Kodi set up.  First some of the system details:
  • Current system is LibreElec 10.0.1 & Kodi 19.3 on RPi 4B
  • Audio out is SPDIF Optical (JustBoom Digi HAT)
  • All music & playlists are on a NAS connected via SMB (GigE connected)
  • Playlists are auto-generated daily by a script so paths & filenames within are accurate
  • Crossfade between songs is enabled and set for 15 seconds (no crossfade for songs on same album)
  • M3U playlists range in size from ~1,000 to ~7,000

What happens is that a little bit before the crossfade is supposed to start (say, 3-5 seconds before), the audio cuts out for a second or two and then continues normally.  The song stops and then starts again and not like the Audio device drops the signal (though it is hard to tell).  And this happens very randomly.  It can go a couple of dozen songs without issue and then happen and sometimes it can happen a couple times in a row.  It doesn't appear to be particular songs or files as I have tried keeping a list of songs it happens on (both the current song and then next song), creating an m3u playlist with "problem" songs and can't replicate it.  And it has happened on all versions I have run since 17, both on an Intel platform (though that often led to crashes, thus the move to RPi) as well as the RPi's.

And what is the most baffling is that if I go to Genres menu and select something like Jazz, where I have ~3,500 songs, and play those on shuffle with the same crossfade setting, it NEVER has the issue.  I can run in this mode for hours on end and it never happens.  But if play an M3U playlist from those same ~3,500 songs in the Jazz genre, it will eventually exhibit this behavior.

Some other important items to note about this system.  I have just made the move to LibreElec 10.0.1 & Kodi 19.3 (previously running LibreElec 9.2.8 & Kodi 18.9) having started from a fresh installation and rebuilding everything from scratch (i.e. no restoring previous database).  (It's a long story but it involves tripping up on bugs with some legacy addons and skin addons causing issues.)

So I guess the questions I have are:
  1. Is there any special sauce I should be adding to my m3u playlists that would help prevent this issue?
  2. Or is there a way I can take said M3U playlists and "import" them in to Kodi to behave more like using the Genre list generation?
  3. Or is there anything I can help provide to get to the bottom of this once and for all?  Logs?  Debug code?  Donuts?
Anyway, I know this is a long shot in the dark but I would love to get this issue squashed once and for all.  Please let me know if there are any further details that can be of assistance or things you need me to try or test.

Cheers!
Reply
#2
Quote:What happens is that a little bit before the crossfade is supposed to start (say, 3-5 seconds before), the audio cuts out for a second or two and then continues normally.  The song stops and then starts again and not like the Audio device drops the signal (though it is hard to tell).
This sounds like some kind of buffering issue but no idea more than that. The route though the code for playback of m3u is significantly different from that of populating the queue via the music navigation screens, so not totally surprizing that a problem with one doesn't occur in the other. Comparing those routes could give some clues to what might be happening.

It is possible that a debug log could show something, so worth trying that. I am loth to say enable the component logging for ffmpeg because it will make for a huge log file, I'm not sure where cross-over fade is handled but think it likely it is in there. Also need to know the songs that had the drop out on that occassion. See what you can capture if you can get it to happen early on in the playlist before the log is silly size.

Are you using party mode?

It also sounds vaguely familiar, but I can't remember if that was you previously or someone else with gaps in playback sometimes or if we found a cause.
Reply
#3
Hi Dave,

Thanks for the quick response.  I see some vaguely similar issues in the forums and does make sense it could be a buffering issue. It appears most of the other posters reference the advancedsettings.xml file so I'll post that just for reference here:

xml:
<advancedsettings>
  <cache>
    <buffermode>1</buffermode>
    <memorysize>139460608</memorysize>
    <readfactor>20</readfactor>
  </cache>
</advancedsettings>

I have fired up debug logging, restarted Kodi, and started a shuffled M3U playlist so I should have some results soon enough.

Cheers!
Reply
#4
Ok, so I am starting to think that my system has had the fear of Dave put into it.  Yesterday, I had several audio dropouts and now today after running an M3U playlist for several hours, I haven't heard a single one.  (Granted I have been working and not completely focused on the music in the background, but still.)

Ugh... this is so frustrating.

Anyway, I'll keep it up and see if I can capture logs when it does drop.
Reply
#5
(2021-11-10, 00:09)verticalrock Wrote: Ok, so I am starting to think that my system has had the fear of Dave put into it. 
This happens sometimes Devil

I'm really hoping you can catch it with a debug that isn't too huge.
BTW by "playing shuffled" do you mean in party mode?
Reply
#6
Quote:BTW by "playing shuffled" do you mean in party mode?
I do not mean "party mode".  I mean the shuffle button on the Kore and the shuffle button when you view the Audio Controls in the main UI.

I have rebooted Kodi and restarted playing a playlist in hopes of catching it today.
Reply
#7
So I am now going to kick myself.  I was finally able to replicate the issue BUT in a moment of stupidity, I turned off Debug Logging.  However, I did turn up something in the logs that might be a clue.

Here is the kodi.log and the event occurred at end of the logs around 2021-11-10 14:22.  The interesting bit seems to be:

Code:
2021-11-10 14:22:42.083 T:1329     INFO <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder mp3float
2021-11-10 14:22:42.320 T:1329     INFO <general>: AudioDecoder: File is queued
2021-11-10 14:22:42.365 T:1135     INFO <general>: CActiveAESink::OpenSink - initialize sink
2021-11-10 14:22:42.565 T:1135     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "sysdefault:CARD=sndrpijustboomd"
2021-11-10 14:22:42.569 T:1135     INFO <general>: CAESinkALSA::Initialize - Opened device "sysdefault:CARD=sndrpijustboomd"
2021-11-10 14:22:42.569 T:1135     INFO <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-11-10 14:22:42.569 T:1135     INFO <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE4

(...)

2021-11-10 14:23:22.276 T:1135     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "sysdefault:CARD=sndrpijustboomd"
2021-11-10 14:23:22.279 T:1135     INFO <general>: CAESinkALSA::Initialize - Opened device "sysdefault:CARD=sndrpijustboomd"
2021-11-10 14:23:22.280 T:1135     INFO <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-11-10 14:23:22.280 T:1135     INFO <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE4

The question is, why did ALSA or something associated with ALSA need to reinitialize the hardware? 

In the meantime, I'll turn debug logging on again, reboot, and start the playlist up and hope for the best.

Cheers!
Reply
#8
Sometimes, when it rains it pours.  And I have finally made it rain.  Rebooted, Debug Logging and a very nice quick replication of the issue.  The event occurred at 2021-11-10 15:06.

Here is the log: kodi.log

Again, the interesting bits seem to be the ALSA stuff:

Code:
2021-11-10 15:06:00.506 T:1478    DEBUG <general>: ffmpeg[0xdaca8838X]: [mp3float] Could not update timestamps for skipped samples.
2021-11-10 15:06:00.591 T:1478     INFO <general>: AudioDecoder: File is queued
2021-11-10 15:06:00.593 T:1478    DEBUG <general>: AudioDecoder::GetReplayGain - Final Replaygain applied: 1.000000, Track/Album Gain 89.000000, Peak 1.000000
2021-11-10 15:06:00.642 T:1136     INFO <general>: CActiveAESink::OpenSink - initialize sink
2021-11-10 15:06:00.842 T:1136    DEBUG <general>: CActiveAESink::OpenSink - trying to open device ALSAConfusedysdefault:CARD=sndrpijustboomd
2021-11-10 15:06:00.842 T:1136     INFO <general>: CAESinkALSA::Initialize - Attempting to open device "sysdefault:CARD=sndrpijustboomd"
2021-11-10 15:06:00.847 T:1136     INFO <general>: CAESinkALSA::Initialize - Opened device "sysdefault:CARD=sndrpijustboomd"
2021-11-10 15:06:00.847 T:1136     INFO <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2021-11-10 15:06:00.848 T:1136     INFO <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE4
2021-11-10 15:06:00.848 T:1136    DEBUG <general>: CAESinkALSA::InitializeHW - Request: periodSize 2205, bufferSize 8820
2021-11-10 15:06:00.850 T:1136    DEBUG <general>: CAESinkALSA::InitializeHW - Got: periodSize 2205, bufferSize 8820
2021-11-10 15:06:00.850 T:1136    DEBUG <general>: CAESinkALSA::InitializeHW - Setting timeout to 200 ms
2021-11-10 15:06:00.850 T:1136    DEBUG <general>: CAESinkALSA::GetChannelLayout - Input Channel Count: 2 Output Channel Count: 2
2021-11-10 15:06:00.850 T:1136    DEBUG <general>: CAESinkALSA::GetChannelLayout - Requested Layout: FL, FR
2021-11-10 15:06:00.850 T:1136    DEBUG <general>: CAESinkALSA::GetChannelLayout - Got Layout: FL, FR (ALSA: none)
2021-11-10 15:06:00.850 T:1136    DEBUG <general>: CActiveAESink::OpenSink - ALSA Initialized:
2021-11-10 15:06:00.850 T:1136    DEBUG <general>:   Output Device : snd_rpi_justboom_digi
2021-11-10 15:06:00.850 T:1136    DEBUG <general>:   Sample Rate   : 44100
2021-11-10 15:06:00.850 T:1136    DEBUG <general>:   Sample Format : AE_FMT_S24NE4
2021-11-10 15:06:00.850 T:1136    DEBUG <general>:   Channel Count : 2
2021-11-10 15:06:00.851 T:1136    DEBUG <general>:   Channel Layout: FL, FR
2021-11-10 15:06:00.851 T:1136    DEBUG <general>:   Frames        : 2205
2021-11-10 15:06:00.851 T:1136    DEBUG <general>:   Frame Size    : 8
2021-11-10 15:06:00.856 T:1135    DEBUG <general>: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
2021-11-10 15:06:00.866 T:1478     INFO <general>: Skipped 3 duplicate messages..

However this time the same messages occur at least twice, once at 2021-11-10 14:57 before (or at the time) I accessed the playlist and once again at 2021-11-10 14:58 at the end of a song, though there was no noticeable audio drop then.

So now the hard work begins... what the h--- is going on?
Reply
#9
Link to debug log doesn't go to a log, try to upload and paste link again please.
Reply
#10
Hmm... that's odd.  Clicking both of the links work for me.... here is the link itself: http://ix.io/3EDm 

Try this one?
Reply
#11
So now the hard work begins indeed. I'm not so sure the ALSA log entries you highlight are "it", but then I'm a library guy not an audio one so what do I know.

Is the audio drop out at the beginning of the song, or the end of the last or both? I read your description as it being the start of the track, but just checking.
Reply
#12
The audio drop is at the end of the song right before the crossover fade starts.  With my example that I have a 15 second crossover, it happens a 2-4 seconds before the crossover begins and the next song starts fading in.
Reply
#13
I have experienced the same issue.  It began with R17.  I rolled backed to Jarvis 16 to eliminate it. Confluence Skin.  Occurs in Windows, Android - Shield and FireTV, and librelec.  Something to do with the new build >16.  Very annoying since I use it to shuffle my large music library with crossfade.
Reply
#14
Haven't seen any updates on this and I am still experiencing the issue after updating to LibreElec v10.0.2 with Kodi v19.4.  I'm still willing to help troubleshoot this further and provide what logs and/or other details needed.  Thanks!
Reply

Logout Mark Read Team Forum Stats Members Help
Audio drops randomly when playing shuffled M3U music playlist with crossfade0