Log filling up with connection errors

[justifiably]

My LMS instance is being swamped by enormous numbers of connection errors logged from BBC Sounds - see two messages alternating below which grew log file to over 650M and LMS became increasingly laggy/unresponsive. I have several squeezebox radios used to listen to Radio 4/Sounds, perhaps the errors are caused by one or two radios failing to resume their streams?

(I think this was on BBC Sounds v2.25.3 running on the current/last-but-one release of the official LMS docker container but I have seen a lot of messages like this for a while. I've upgraded and turned off logging for BBC Sounds now in the hope this may fix the log overflow problem.)

logitechmediaserver  | [22-09-11 19:15:09.1867] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831251.m4s
logitechmediaserver  | [22-09-11 19:15:09.1872] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831252.m4s
logitechmediaserver  | [22-09-11 19:15:09.1877] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831251.m4s
logitechmediaserver  | [22-09-11 19:15:09.1882] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831252.m4s
logitechmediaserver  | [22-09-11 19:15:09.1886] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831251.m4s
logitechmediaserver  | [22-09-11 19:15:09.1892] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831252.m4s

[expectingtofly]

Hmmm, that's odd. The plugin retries a few times if the chunk of audio is not reachable, then as soon as you get that failure error, then streaming should just stop. I'm not sure how that has occurred that you are getting those errors continually being logged.

What players are you using is it a standard Squeezebox Radio, and what error is appearing on the actual radio? Presumably the streaming stopped on the radios?

[justifiably]

Thanks for speedy follow-up. Yes, I have 4 standard Squeezebox Radios with similar configuration. Unfortunately I'm not sure whether any error is shown on the radio when this happened, perhaps the radio showed "Connecting" or "Rebuffering" but I'm not sure. Could it happen while the stream/play is paused? Or if the internet connection is interrupted?

I think the connection was interrupted around the time the messages started yesterday although at least one of the players resumed playing fine a few minutes later.

At most two of the radios were playing Radio 4 at the time but probably only one. These log messages seem to be repeated thousands of times every second, I guess there must be an unexpected tight loop somewhere!?

logitechmediaserver  | [22-09-11 19:30:00.0000] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831251.m4s
logitechmediaserver  | [22-09-11 19:30:00.0002] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831252.m4s
logitechmediaserver  | [22-09-11 19:30:00.0003] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_four
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831251.m4s
...
fm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831252.m4s
logitechmediaserver  | [22-09-11 20:30:00.9995] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831251.m4s
logitechmediaserver  | [22-09-11 20:30:00.9997] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831252.m4s
logitechmediaserver  | [22-09-11 20:30:00.9998] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831251.m4s
logitechmediaserver  | [22-09-11 20:30:00.9999] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1036) Failed to get https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831252.m4s

[justifiably]

Quick look at ProtocolHandler.pm, is your comparison here the wrong way around?

if ($v->{'retryCount'} > CHUNK_RETRYCOUNT) {

[justifiably]

Or perhaps failing to clear the error? I haven't tried to understand the code.

[justifiably]

Maybe it helps to see corresponding "Retrying" messages, here is what I got

# zcat crash.txt.gz | grep Retrying
logitechmediaserver  | [22-09-11 17:58:18.3075] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1042) Retrying of https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_two/bbc_radio_two.isml/dash/bbc_radio_two-audio=320000-259830546.m4s
logitechmediaserver  | [22-09-11 19:09:46.8887] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1042) Retrying of https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831216.m4s
logitechmediaserver  | [22-09-11 19:10:02.9072] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1042) Retrying of https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831216.m4s
logitechmediaserver  | [22-09-11 19:10:39.3471] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1042) Retrying of https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831214.m4s
logitechmediaserver  | [22-09-11 19:10:59.3784] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1042) Retrying of https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831214.m4s
logitechmediaserver  | [22-09-11 19:14:34.6491] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1042) Retrying of https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831234.m4s
logitechmediaserver  | [22-09-11 19:14:35.6871] Plugins::BBCSounds::ProtocolHandler::__ANON__ (1042) Retrying of https://as-dash-uk-live.akamaized.net/pool_904/live/uk/bbc_radio_fourfm/bbc_radio_fourfm.isml/dash/bbc_radio_fourfm-audio=320000-259831234.m4s

The failure at 19:14 seems to be the one that started the logging loop.

[justifiably]

Anyway sorry for random guesses I will stop now! It seems there is a path through the code where retryCount has exceeded the limit but not been reset so the error keeps occurring and giving a message every time. In case it helps further (I see a comment further up in the code), my radios have been updated with the community firmware. Thanks for looking.

[expectingtofly]

Ah! I think I can see how it occurred. The player must have restarted the stream, and I think there is a scenario if it fails to get any audio right at the start of streaming it will fail to set the stream to end and the player will keep asking. If the audio stream is never reachable it will log forever. Thanks for the report, I'll get that fixed.

$v->{'streaming'} = 0 if ($v->{'endOffset'} > 0) && ($v->{'offset'} > $v->{'endOffset'});

Anyway, to stop the infinite logging in the meantime, play another station on your player and switch back again and it will stop asking for the audio on that stream and all should be well again.

[expectingtofly]

OK, the fix works, but it is too brutal, we do want it to carry on on the next chunk of audio if possible. So I'll add some more code so that it only forces end if multiple failures.

[expectingtofly]

This has now been fixed in version 2.25.4. Thanks for reporting.

[justifiably]

Not at all -- thank you for the quick fix and making this wonderful plugin available to us all! :star2: