[Announce] Community Firmware for Squeezebox Radio/Touch/Controller and LMS 8

[staresy]

That URL looks like a timestamp from yesterday.
Perhaps it stops because it has reached the end of a chunk - and it does not know which chunk to get next because it is not being fed with a playlist.

Does it play for a much longer time if you use something else - such as vlc ?

Hi Paul, yes in VLC it plays to the end (just over an hour) with no problem. On LMS is halts after 45mins. The feed is actually part of a playlist (http://streamlojik.com/playlist/?ch=...day&hh=10&ll=1). The 1st link I posted was just a single item from the playlist. Playing from the playlist shows the same problem, 45mins into the first segment it still bombs out but in this case it starts playing the next item in the list rather than stopping.

When you disable native playback do you see anything telling you the stream is being transcoded? I only ask because I don't.

Slarti, I don't, but I'm not sure where I should be looking.

[expectingtofly]

The bufferThreshold might be used to alleviate the startup problems with BBC sounds along with the current AAC decoder patch we're testing.
I can't be sure it would help as I don't have access to the 320b@48K streams to test and it would likely depend on what stream format is selected in the BBC Sounds settings too.

I've added a Buffer threshold setting to BBC sounds and amended the protocol handler. To be honest, it doesn't seem to have much impact.
In this trace I've set it to the bufferThreashold to 4 seconds of audio, which on the 320 streams is 160 kb (163840).
Here is the log trace from that, as you can see, the threshold setting that is being applied, appears in the log as expected, but I don't really understand what that means in this context as it doesn't seem to be filling up the output buffer with 4 seconds of audio before the underrun occurs. Sorry, if I misunderstood what was meant to occur.

As you can see following the underrun, both the input and output buffers fill up and it is rock solid from there onwards.

Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_start:705 decode_start
Feb 28 14:31:46 squeezeplay: INFO   audio.decode - decode_start_handler:281 init decoder aac
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:520 Track gain 65536
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:524 Track clip range 7fffffff 80000000
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_set_track_polarity_inversion:529 Polarity inversion 0
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_set_output_channels:537 Output channels left 0, right 0
Feb 28 14:31:46 squeezeplay: INFO   audio.decode - Playback.lua:477 connect 172.16.0.8:9000 GET /stream.mp3?player=00:04:20:2c:fa:10 HTTP/1.0^M
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - Playback.lua:194 source=stream
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - stream_connectL:506 streambuf connect 172.16.0.8:9000
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - Playback.lua:397 resume decoder, 32768 bytes buffered, decode threshold 2048
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:580 decode_resume_decoder
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:122 resume_decoder decode state: 1 audio state 0
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 32768 / 0 | 1.04% / 0.00%
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=48000
Feb 28 14:31:48 squeezeplay: INFO   audio.decode - Playback.lua:448 2.7%/0.5%
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=223552 outputTime=320 threshold=163840
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 178496 / 131072 | 5.67% / 3.72%
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 35)
Feb 28 14:31:49 squeezeplay: INFO   audio.decode - Playback.lua:448 14.8%/2.5%
Feb 28 14:31:50 squeezeplay: playback_callback:346 Audio underrun: used 448 frames, requested 480 frames. elapsed samples 83520
Feb 28 14:31:50 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm u
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:991 resume unpause
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 910447 / 82944 | 28.94% / 2.35%
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 14:31:51 squeezeplay: INFO   audio.decode - Playback.lua:448 33.6%/5.4%
Feb 28 14:31:52 squeezeplay: INFO   audio.decode - Playback.lua:448 42.3%/7.9%
Feb 28 14:31:53 squeezeplay: INFO   audio.decode - Playback.lua:448 50.6%/11.3%
Feb 28 14:31:54 squeezeplay: INFO   audio.decode - Playback.lua:448 63.9%/12.7%
Feb 28 14:31:55 squeezeplay: INFO   audio.decode - Playback.lua:448 78.2%/9.8%
Feb 28 14:31:56 squeezeplay: INFO   audio.decode - Playback.lua:448 85.7%/15.4%
Feb 28 14:31:57 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/17.3%
Feb 28 14:31:58 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/29.0%
Feb 28 14:31:59 squeezeplay: INFO   audio.decode - Playback.lua:448 99.6%/41.0%
Feb 28 14:32:00 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/52.0%
Feb 28 14:32:01 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/63.9%
Feb 28 14:32:03 squeezeplay: INFO   audio.decode - Playback.lua:448 99.6%/76.8%
Feb 28 14:32:04 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/88.1%
Feb 28 14:32:05 squeezeplay: INFO   audio.decode - Playback.lua:448 99.6%/99.0%
Feb 28 14:32:06 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.9%
Feb 28 14:32:07 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.6%
Feb 28 14:32:08 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/98.0%
Feb 28 14:32:09 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.4%
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm q
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - decode_stop:667 decode_stop

As far as I'm concerned the ramp up audio underruns really aren't that much of a problem, they don't always happen, and now that the output buffer is filling up correctly they don't occur again once the stream is underway.

[ralphy]

I've added a Buffer threshold setting to BBC sounds and amended the protocol handler. To be honest, it doesn't seem to have much impact.
In this trace I've set it to the bufferThreadhold to 4 seconds of audio, which on the 320 streams is 160 kb (163840).
Here is the log trace from that, as you can see, the threshold setting that is being applied, appears in the log as expected, but I don't really understand what that means in this context as it doesn't seem to be filling up the output buffer with 4 seconds of audio before the underrun occurs. Sorry, if I misunderstood what was meant to occur.

As you can see following the underrun, both the input and output buffers fill up and it is rock solid from there onwards.

Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_start:705 decode_start
Feb 28 14:31:46 squeezeplay: INFO   audio.decode - decode_start_handler:281 init decoder aac
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:520 Track gain 65536
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_output_set_track_gain:524 Track clip range 7fffffff 80000000
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_set_track_polarity_inversion:529 Polarity inversion 0
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - decode_set_output_channels:537 Output channels left 0, right 0
Feb 28 14:31:46 squeezeplay: INFO   audio.decode - Playback.lua:477 connect 172.16.0.8:9000 GET /stream.mp3?player=00:04:20:2c:fa:10 HTTP/1.0^M
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - Playback.lua:194 source=stream
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - stream_connectL:506 streambuf connect 172.16.0.8:9000
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:31:46 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - Playback.lua:397 resume decoder, 32768 bytes buffered, decode threshold 2048
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:580 decode_resume_decoder
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:122 resume_decoder decode state: 1 audio state 0
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 32768 / 0 | 1.04% / 0.00%
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=48000
Feb 28 14:31:48 squeezeplay: INFO   audio.decode - Playback.lua:448 2.7%/0.5%
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=223552 outputTime=320 threshold=163840
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 178496 / 131072 | 5.67% / 3.72%
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 14:31:48 squeezeplay: DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 35)
Feb 28 14:31:49 squeezeplay: INFO   audio.decode - Playback.lua:448 14.8%/2.5%
Feb 28 14:31:50 squeezeplay: playback_callback:346 Audio underrun: used 448 frames, requested 480 frames. elapsed samples 83520
Feb 28 14:31:50 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm u
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:991 resume unpause
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 910447 / 82944 | 28.94% / 2.35%
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:31:50 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 14:31:51 squeezeplay: INFO   audio.decode - Playback.lua:448 33.6%/5.4%
Feb 28 14:31:52 squeezeplay: INFO   audio.decode - Playback.lua:448 42.3%/7.9%
Feb 28 14:31:53 squeezeplay: INFO   audio.decode - Playback.lua:448 50.6%/11.3%
Feb 28 14:31:54 squeezeplay: INFO   audio.decode - Playback.lua:448 63.9%/12.7%
Feb 28 14:31:55 squeezeplay: INFO   audio.decode - Playback.lua:448 78.2%/9.8%
Feb 28 14:31:56 squeezeplay: INFO   audio.decode - Playback.lua:448 85.7%/15.4%
Feb 28 14:31:57 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/17.3%
Feb 28 14:31:58 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/29.0%
Feb 28 14:31:59 squeezeplay: INFO   audio.decode - Playback.lua:448 99.6%/41.0%
Feb 28 14:32:00 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/52.0%
Feb 28 14:32:01 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/63.9%
Feb 28 14:32:03 squeezeplay: INFO   audio.decode - Playback.lua:448 99.6%/76.8%
Feb 28 14:32:04 squeezeplay: INFO   audio.decode - Playback.lua:448 99.7%/88.1%
Feb 28 14:32:05 squeezeplay: INFO   audio.decode - Playback.lua:448 99.6%/99.0%
Feb 28 14:32:06 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.9%
Feb 28 14:32:07 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.6%
Feb 28 14:32:08 squeezeplay: INFO   audio.decode - Playback.lua:448 99.9%/98.0%
Feb 28 14:32:09 squeezeplay: INFO   audio.decode - Playback.lua:448 100.0%/97.4%
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm q
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 14:32:10 squeezeplay: DEBUG  audio.decode - decode_stop:667 decode_stop

As far as I'm concerned the ramp up audio underruns really aren't that much of a problem, they don't always happen, and now that the output buffer is filling up correctly they don't occur again once the stream is underway.

Thank you for trying this. I'll have a closer look at your log later on today.

I agree that just with the higher buffer fill rate after the initial pause, it is much better than the r16835 release.

Do you see the same issue with either the hide audio sample rate from LMS or Force http streaming options enabled?

[slartibartfast]

Slarti, I don't, but I'm not sure where I should be looking.

In "More info" you normally see it but not with your stream

Sent from my Pixel 3a using Tapatalk

[slartibartfast]

Hi Paul, yes in VLC it plays to the end (just over an hour) with no problem. On LMS is halts after 45mins. The feed is actually part of a playlist (http://streamlojik.com/playlist/?ch=...day&hh=10&ll=1). The 1st link I posted was just a single item from the playlist. Playing from the playlist shows the same problem, 45mins into the first segment it still bombs out but in this case it starts playing the next item in the list rather than stopping.

It plays to the end for me. Do you have the reliable plugin installed?

Sent from my Pixel 3a using Tapatalk

[expectingtofly]

Do you see the same issue with either the hide audio sample rate from LMS or Force http streaming options enabled?

"Force HTTP streaming" relates to the protocol used to get the chunked audio from the BBC. So shouldn't relate to this issue.
"hide audio sample rate" relates to not setting the sample rate on the track. That the trascode picker uses, Which also I don't expect to have any impact (I have tried and it doesn't impact)

To give you more info. I've captured a log with 2 extremes of bufferThreshold set. Which is quite interesting.

This is a log for a buffer of 1 second (40k) :

Feb 28 16:49:58 squeezeplay: INFO   audio.decode - Playback.lua:477 connect 172.16.0.8:9000 GET /stream.mp3?player=00:04:20:2c:fa:10 HTTP/1.0^M
Feb 28 16:49:58 squeezeplay: DEBUG  audio.decode - Playback.lua:194 source=stream
Feb 28 16:49:58 squeezeplay: DEBUG  audio.decode - stream_connectL:506 streambuf connect 172.16.0.8:9000
Feb 28 16:49:58 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:49:58 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - Playback.lua:397 resume decoder, 98304 bytes buffered, decode threshold 2048
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:580 decode_resume_decoder
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:122 resume_decoder decode state: 1 audio state 0
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 98304 / 0 | 3.12% / 0.00%
Feb 28 16:50:00 squeezeplay: INFO   audio.decode - Playback.lua:448 3.0%/0.0%
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=48000
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=131072 outputTime=128 threshold=40960
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 162224 / 65536 | 5.16% / 1.86%
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 42)
Feb 28 16:50:01 squeezeplay: INFO   audio.decode - Playback.lua:448 15.5%/3.3%
Feb 28 16:50:02 squeezeplay: playback_callback:346 Audio underrun: used 160 frames, requested 480 frames. elapsed samples 86880
Feb 28 16:50:02 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm u
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:991 resume unpause
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 917712 / 94464 | 29.17% / 2.68%
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 16:50:03 squeezeplay: INFO   audio.decode - Playback.lua:448 35.8%/5.3%

Here's a log for the threshold set to 5 seconds (200k) :

Feb 28 16:52:12 squeezeplay: INFO   audio.decode - Playback.lua:477 connect 172.16.0.8:9000 GET /stream.mp3?player=00:04:20:2c:fa:10 HTTP/1.0^M
Feb 28 16:52:12 squeezeplay: DEBUG  audio.decode - Playback.lua:194 source=stream
Feb 28 16:52:12 squeezeplay: DEBUG  audio.decode - stream_connectL:506 streambuf connect 172.16.0.8:9000
Feb 28 16:52:12 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:52:12 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - Playback.lua:397 resume decoder, 65536 bytes buffered, decode threshold 2048
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:580 decode_resume_decoder
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:122 resume_decoder decode state: 1 audio state 0
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 65536 / 0 | 2.08% / 0.00%
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=48000
Feb 28 16:52:14 squeezeplay: INFO   audio.decode - Playback.lua:448 1.6%/0.7%
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=256440 outputTime=874 threshold=204800
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 186808 / 352256 | 5.94% / 9.98%
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 175)
Feb 28 16:52:16 squeezeplay: INFO   audio.decode - Playback.lua:448 15.9%/7.7%
Feb 28 16:52:17 squeezeplay: INFO   audio.decode - Playback.lua:448 26.7%/5.4%
Feb 28 16:52:18 squeezeplay: INFO   audio.decode - Playback.lua:448 32.9%/4.5%
Feb 28 16:52:19 squeezeplay: INFO   audio.decode - Playback.lua:448 42.1%/2.8%
Feb 28 16:52:20 squeezeplay: playback_callback:346 Audio underrun: used 192 frames, requested 480 frames. elapsed samples 248640
Feb 28 16:52:20 squeezeplay: playback_callback:346 Audio underrun: used 384 frames, requested 480 frames. elapsed samples 254592
Feb 28 16:52:20 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm u
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:991 resume unpause
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 1806764 / 86272 | 57.44% / 2.45%
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 16:52:21 squeezeplay: INFO   audio.decode - Playback.lua:448 64.4%/2.4%

The underrun happens at the point of end of the Bufferthreshold time that the buffer represents (1 second and 5 Second respectively) after the track started . I guess that must mean something! But beats me what that is

[ralphy]

"Force HTTP streaming" relates to the protocol used to get the chunked audio from the BBC. So shouldn't relate to this issue.
"hide audio sample rate" relates to not setting the sample rate on the track. That the trascode picker uses, Which also I don't expect to have any impact (I have tried and it doesn't impact)

To give you more info. I've captured a log with 2 extremes of bufferThreshold set. Which is quite interesting.

This is a log for a buffer of 1 second (40k) :

Feb 28 16:49:58 squeezeplay: INFO   audio.decode - Playback.lua:477 connect 172.16.0.8:9000 GET /stream.mp3?player=00:04:20:2c:fa:10 HTTP/1.0^M
Feb 28 16:49:58 squeezeplay: DEBUG  audio.decode - Playback.lua:194 source=stream
Feb 28 16:49:58 squeezeplay: DEBUG  audio.decode - stream_connectL:506 streambuf connect 172.16.0.8:9000
Feb 28 16:49:58 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:49:58 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - Playback.lua:397 resume decoder, 98304 bytes buffered, decode threshold 2048
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:580 decode_resume_decoder
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:122 resume_decoder decode state: 1 audio state 0
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 98304 / 0 | 3.12% / 0.00%
Feb 28 16:50:00 squeezeplay: INFO   audio.decode - Playback.lua:448 3.0%/0.0%
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=48000
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=131072 outputTime=128 threshold=40960
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 162224 / 65536 | 5.16% / 1.86%
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 16:50:00 squeezeplay: DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 42)
Feb 28 16:50:01 squeezeplay: INFO   audio.decode - Playback.lua:448 15.5%/3.3%
Feb 28 16:50:02 squeezeplay: playback_callback:346 Audio underrun: used 160 frames, requested 480 frames. elapsed samples 86880
Feb 28 16:50:02 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm u
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:991 resume unpause
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 917712 / 94464 | 29.17% / 2.68%
Feb 28 16:50:02 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 16:50:03 squeezeplay: INFO   audio.decode - Playback.lua:448 35.8%/5.3%

Here's a log for the threshold set to 5 seconds (200k) :

Feb 28 16:52:12 squeezeplay: INFO   audio.decode - Playback.lua:477 connect 172.16.0.8:9000 GET /stream.mp3?player=00:04:20:2c:fa:10 HTTP/1.0^M
Feb 28 16:52:12 squeezeplay: DEBUG  audio.decode - Playback.lua:194 source=stream
Feb 28 16:52:12 squeezeplay: DEBUG  audio.decode - stream_connectL:506 streambuf connect 172.16.0.8:9000
Feb 28 16:52:12 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:52:12 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - Playback.lua:397 resume decoder, 65536 bytes buffered, decode threshold 2048
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:580 decode_resume_decoder
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:122 resume_decoder decode state: 1 audio state 0
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 65536 / 0 | 2.08% / 0.00%
Feb 28 16:52:14 squeezeplay: DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=48000
Feb 28 16:52:14 squeezeplay: INFO   audio.decode - Playback.lua:448 1.6%/0.7%
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=256440 outputTime=874 threshold=204800
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 186808 / 352256 | 5.94% / 9.98%
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 16:52:15 squeezeplay: DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 175)
Feb 28 16:52:16 squeezeplay: INFO   audio.decode - Playback.lua:448 15.9%/7.7%
Feb 28 16:52:17 squeezeplay: INFO   audio.decode - Playback.lua:448 26.7%/5.4%
Feb 28 16:52:18 squeezeplay: INFO   audio.decode - Playback.lua:448 32.9%/4.5%
Feb 28 16:52:19 squeezeplay: INFO   audio.decode - Playback.lua:448 42.1%/2.8%
Feb 28 16:52:20 squeezeplay: playback_callback:346 Audio underrun: used 192 frames, requested 480 frames. elapsed samples 248640
Feb 28 16:52:20 squeezeplay: playback_callback:346 Audio underrun: used 384 frames, requested 480 frames. elapsed samples 254592
Feb 28 16:52:20 squeezeplay: INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm p
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio:624 decode_pause_audio interval_ms=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:156 decode_pause_handler interval=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_pause_audio_handler:171 pause_audio decode state: 1 audio state 0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 0 0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:855 strm u
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:991 resume unpause
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 1806764 / 86272 | 57.44% / 2.45%
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 555 555
Feb 28 16:52:20 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Feb 28 16:52:21 squeezeplay: INFO   audio.decode - Playback.lua:448 64.4%/2.4%

The underrun happens at the point of end of the Bufferthreshold time that the buffer represents (1 second and 5 Second respectively) after the track started . I guess that must mean something! But beats me what that is

That's what I noticed in the first log as well. To me, that means it's not making a difference and you can probably just remove setting the bufferThreshold.

It appears that at startup the player just can't fill the output buffer fast enough. Thanks for testing the different options. I now have a lot more info to go through.

[staresy]

Hi,
Thanks for your efforts in investigating the AAC stream issue. I've noticed another anomaly when playing the outreach radio stream. I'm not sure if the post is relevant to the Community Firmware thread, but it maybe, but I imagine you guys would be able to advise either way.

I currently have my LMS set to decode AAC streams locally (rather than natively in the player) to allow me to listen to the affected stream. I've noticed that when playing the stream, it gets to 45 minutes into the stream and then bombs out (ie. just stops playing mid-stream). This is 100% repeatable, try the stream below, at around 44:50 it stops playing every time.

Any chance you guys could take a look? Here's a link to the stream:

https://live.streamlojik.com:17070/20210227_1004.aac

Thanks

Hi,
Since posting this, I've done a bit further investigation and have concluded that this is NOT related to the community firmware. If I play the feed on a Win10 machine via squeezelite-x it still crashes out at 45mins but ONLY if decoding locally on LMS (ie. by disabling native decode for AAC).

So, no further discussion required about this on this thread, I'll open up a separate thread in the LMS category.

Thanks

[expectingtofly]

That's what I noticed in the first log as well. To me, that means it's not making a difference and you can probably just remove setting the bufferThreshold.

Ok, thanks, I think I understand this now. On BBC Sounds Live Radio, this underrun problem never occurs now. This is because the protocol handler is operating on the live edge, and as a maximum, only has up to 12 seconds (2 dash chunks) of audio available to the radio. So the aac decoder can never prioritise filling up the input buffer over populating the output buffer. so you get a very different log profile for live radio:

Mar  1 07:59:02 squeezeplay: INFO   audio.decode - Playback.lua:477 connect 172.16.0.8:9000 GET /stream.mp3?player=00:04:20:2c:fa:10 HTTP/1.0^M
Mar  1 07:59:02 squeezeplay: DEBUG  audio.decode - Playback.lua:194 source=stream
Mar  1 07:59:02 squeezeplay: DEBUG  audio.decode - stream_connectL:506 streambuf connect 172.16.0.8:9000
Mar  1 07:59:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1262 stopping local pause timer
Mar  1 07:59:02 squeezeplay: DEBUG  audio.decode - Playback.lua:1192 gainL, gainR: 200 200
Mar  1 07:59:03 squeezeplay: DEBUG  audio.decode - Playback.lua:397 resume decoder, 32768 bytes buffered, decode threshold 2048
Mar  1 07:59:03 squeezeplay: DEBUG  audio.decode - decode_resume_decoder:580 decode_resume_decoder
Mar  1 07:59:03 squeezeplay: DEBUG  audio.decode - decode_resume_decoder_handler:122 resume_decoder decode state: 1 audio state 0
Mar  1 07:59:03 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 32768 / 0 | 1.04% / 0.00%
Mar  1 07:59:04 squeezeplay: DEBUG  audio.decode - decode_output_samples:280 first buffer sample_rate=48000
Mar  1 07:59:04 squeezeplay: DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=95944 outputTime=149 threshold=40960
Mar  1 07:59:04 squeezeplay: DEBUG  audio.decode - decode_resume_audio:601 decode_resume_audio start_jiffies=0
Mar  1 07:59:04 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:133 decode_resume_audio_handler start_jiffies=0
Mar  1 07:59:04 squeezeplay: DEBUG  audio.decode - debug_fullness:112 fullness: 63176 / 65536 | 2.01% / 1.86%
Mar  1 07:59:04 squeezeplay: DEBUG  audio.decode - decode_resume_audio_handler:146 resume_audio decode state: 1 audio state 40
Mar  1 07:59:04 squeezeplay: INFO   audio.decode - Playback.lua:448 2.0%/1.6%
Mar  1 07:59:04 squeezeplay: DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 528)
Mar  1 07:59:05 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
Mar  1 07:59:06 squeezeplay: INFO   audio.decode - Playback.lua:448 8.0%/3.6%
Mar  1 07:59:07 squeezeplay: INFO   audio.decode - Playback.lua:448 10.4%/6.3%
Mar  1 07:59:08 squeezeplay: INFO   audio.decode - Playback.lua:448 7.9%/15.3%
Mar  1 07:59:09 squeezeplay: INFO   audio.decode - Playback.lua:448 12.6%/16.6%
Mar  1 07:59:10 squeezeplay: INFO   audio.decode - Playback.lua:448 12.5%/21.5%
Mar  1 07:59:11 squeezeplay: INFO   audio.decode - Playback.lua:448 10.5%/26.4%
Mar  1 07:59:13 squeezeplay: INFO   audio.decode - Playback.lua:448 8.5%/32.0%
Mar  1 07:59:14 squeezeplay: INFO   audio.decode - Playback.lua:448 6.5%/36.9%
Mar  1 07:59:15 squeezeplay: INFO   audio.decode - Playback.lua:448 4.6%/41.4%
Mar  1 07:59:16 squeezeplay: INFO   audio.decode - Playback.lua:448 11.1%/41.0%
Mar  1 07:59:17 squeezeplay: INFO   audio.decode - Playback.lua:448 9.5%/45.2%
Mar  1 07:59:18 squeezeplay: INFO   audio.decode - Playback.lua:448 7.7%/49.4%
Mar  1 07:59:19 squeezeplay: INFO   audio.decode - Playback.lua:448 5.9%/54.1%
Mar  1 07:59:20 squeezeplay: INFO   audio.decode - Playback.lua:448 3.9%/58.7%
Mar  1 07:59:21 squeezeplay: INFO   audio.decode - Playback.lua:448 2.0%/63.1%
Mar  1 07:59:22 squeezeplay: INFO   audio.decode - Playback.lua:448 8.5%/62.7%
Mar  1 07:59:23 squeezeplay: INFO   audio.decode - Playback.lua:448 6.9%/67.9%
Mar  1 07:59:24 squeezeplay: INFO   audio.decode - Playback.lua:448 4.8%/73.2%
Mar  1 07:59:25 squeezeplay: INFO   audio.decode - Playback.lua:448 3.0%/77.6%
Mar  1 07:59:26 squeezeplay: INFO   audio.decode - Playback.lua:448 1.2%/81.6%
Mar  1 07:59:27 squeezeplay: INFO   audio.decode - Playback.lua:448 0.0%/80.7%
Mar  1 07:59:28 squeezeplay: INFO   audio.decode - Playback.lua:448 5.7%/72.2%
Mar  1 07:59:30 squeezeplay: INFO   audio.decode - Playback.lua:448 6.0%/76.6%
Mar  1 07:59:31 squeezeplay: INFO   audio.decode - Playback.lua:448 3.9%/81.4%
Mar  1 07:59:32 squeezeplay: INFO   audio.decode - Playback.lua:448 2.1%/85.8%
Mar  1 07:59:33 squeezeplay: INFO   audio.decode - Playback.lua:448 0.0%/91.1%
Mar  1 07:59:34 squeezeplay: INFO   audio.decode - Playback.lua:448 0.0%/79.6%
Mar  1 07:59:34 dropbear[8653]: Child connection from 172.16.0.70:39826
Mar  1 07:59:35 squeezeplay: INFO   audio.decode - Playback.lua:448 7.6%/73.7%
Mar  1 07:59:36 squeezeplay: INFO   audio.decode - Playback.lua:448 6.1%/73.9%
Mar  1 07:59:37 squeezeplay: INFO   audio.decode - Playback.lua:448 4.3%/77.4%
Mar  1 07:59:38 dropbear[8653]: Password auth succeeded for 'root' from 172.16.0.70:39826

So actually, for the non-live audio-on-demand radio streams, I can actually eliminate the buffer underruns by throttling the amount of data available to the radio. Which is all a bit counter intuitive! So I'm not sure I want to do that in a release version.

As you eluded to earlier in the thread, it looks like the outputThreshold setting is probably the right one which (from what I understand from your comments) delays the playback until a threshold is reached in the decoded output buffer. But I don't believe I can set that in the protocol handler?

[expectingtofly]

[EDIT Removed this post, incorrect log.]