I'm at a loss to understand what the issue is here with the evidence so far. It does indeed sound as if something odd is happening. The log (see next comment) does show some suspicious output from the code related to the referenced change but it is not at all clear what is really happening. It could be that something else is going wrong and the referenced change is simply stopping the server from exploding (as designed).

I should point out that We make extensive use of the iPlayer plugin in our household, mostly for live streams but quite often for listen-gain as well (although rarely for programs longer than 30 minutes). A large part of that listening is synchronized across 2 players (mainly SB2 and SB3).

I would encourage others to post careful and detailed descriptions of the symptoms they are seeing. If anyone can come up with a reproducible scenario then that would be great.

[12-01-23 20:04:08.3952] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.3990] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4026] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4061] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4098] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4135] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4170] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4206] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4237] Slim::Player::Pipeline::sysread (304) Attempting to write to pipeline writer
[12-01-23 20:04:08.4258] Slim::Player::Pipeline::sysread (310) Wrote 2807 bytes to pipeline writer
[12-01-23 20:04:08.4279] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4308] Slim::Player::Pipeline::sysread (304) Attempting to write to pipeline writer
[12-01-23 20:04:08.4338] Slim::Player::Pipeline::sysread (310) Wrote 936 bytes to pipeline writer
[12-01-23 20:04:08.4359] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4394] Slim::Player::Pipeline::sysread (304) Attempting to write to pipeline writer
[12-01-23 20:04:08.4417] Slim::Player::Pipeline::sysread (310) Wrote 2807 bytes to pipeline writer
[12-01-23 20:04:08.4436] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4482] Slim::Player::Pipeline::sysread (282) Pipeline doesn't have pending bytes - trying to get some from source
[12-01-23 20:04:08.4517] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.4548] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.4578] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.4607] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.4637] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.4668] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.4698] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.4727] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.4757] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.5311] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e
[12-01-23 20:04:08.5616] Slim::Player::Source::nextChunk (134) Waiting for queue to drain for 00:04:20:1e:97:3e

you say:
'I'm at a loss to understand what the issue is here with the evidence so far'

how do you think contributing that actually helps towards a resolution? 

I'm really not clear...

Have you spoken to Triode? 

what happens in your organisation in this situation? 

Is there no-one you 
can escalate this problem to? 

Or discuss it with? 

Remember that I'm just a consumer who has bought your product on the assumption that it worked in a certain way, a way in which it did work for several years, until a software change casued it to stop working. You need to find that software gremlin and punish him. 

If you can't resolve it, maybe you can tell me who to talk to about getting my money back? 

Or who I can complain to who may be able to fix this? 

 Or suggest a work around.

Your post is unhelpful. 

You probably think this post is too - but if it stimulates you to some kind of resolution, or gets someone else to look at this who may be able to offer a resolution then it will have served its purpose.

Created attachment 7616 [details]
Logs of iPlayer listen again during fault

Logs taken with:

plugin.bbciplayer.rtmp logging set to info 
player.source logging at debug level

I am one of the original reporters of this bug on the iPlayer forum. The bug states this is iPlayer only but I have seen it with Classic FM. The streams I have seen this with are:

Classic FM 128kbps MP3 live stream (only observed once)
iPlayer Radio 3 live http AAC (only occasionally)
iPlayer Radio 3 listen again AAC (several times in most 1 hour shows)

The observed symptoms are that music stops ie. silence from my Duet Reciever and Boom but the play time on the Controller keeps counting up. When I press Pause on the Controller the play time jumps back to approximately where the sound stopped. Pressing Pause again causes music to continue from where it stopped, usually (maybe always) after a Rebuffering... displayed on the Controller.

I listen with a Receiver and Boom sync'd, using LMS 7.7.1 running on WHS v1. Both players are on wifi but the server is cabled. MP3 streaming is configured to always be proxied even if not sync'd. AAC for iPlayer is being transcoded to FLAC, MP3 is playing native on the boxes.

Created attachment 7617 [details]
Server logs of Classic FM problem a

Listening to Classic FM live 128kbps MP3, sycn'd Duet and Boom playing. Sound stopped, looked at Controller and it was doing a re-buffering. This finished and the play time continued counting up but no sound. Pressed Pause and the play time jumped back to the rebuffer point, pressed Pause again and music started again (with no re-buffer). Not quite identical to the iPlayer symptoms but close, and I only spotted the rebuffer before thhe failure because I was quick getting to the Controller. The fault is pretty near the end of the log, search from the end backwards for Pause.

Logging set to:

player.source at Debug
player.streaming at Debug
player.sync at Debug
plugin.bbciplayer.rtmp at Info (not relevant for this)

Created attachment 7618 [details]
Logs of Classic FM problem b

Listening to Classic FM live 128kbps MP3, sycn'd Duet and Boom playing. Still playing from after problem a. Sound stopped, looked at Controller and it was doing a re-buffering. This never completed and eventually I pressed Pause. I can't recall exactly how many times I pressed Pause, but at some point it reconnected the stream and started playing again. May or may not be related to the problem this issue is discussing with iPlayer, but it's all evidence. The fault is pretty near the end of the log, search from the end backwards for Pause.

Logging set to:

player.source at Debug
player.streaming at Debug
player.sync at Debug
plugin.bbciplayer.rtmp at Info (not relevant for this)

Created attachment 7619 [details]
Logs of Classic FM problem c

Listening to Classic FM live 128kbps MP3, sycn'd Duet and Boom playing. Continuation of playing after problem b above. I was upstairs reporting a and b so did not see what the Controller said at the time. All I know is the sound stopped for some time, then when I went downstairs the play time on the Controller was still counting up but no sound was playing (very much like the iPlayer problem). I pressed Pause and the stream reconnected and started from scratch, I can't quite remember if I pressed Pause once or twice (should be in the logs). The common thread seems to be play time counting up but no sound during sync'd playing, and no automatic recovery from whatever the problem may be. The fault is pretty near the end of the log, search from the end backwards for Pause.

Logging set to:

player.source at Debug
player.streaming at Debug
player.sync at Debug
plugin.bbciplayer.rtmp at Info (not relevant for this)

Created attachment 7620 [details]
Logs of Classic FM problem d - MUCH CLOSE TO IPLAYER

OK the observed symptoms on this one are EXACTLY what happens with iPlayer.

Listening to Classic FM live 128kbps MP3, sycn'd Duet and Boom playing.
Continuation of playing after problem c above. I was upstairs reporting c so did not see what the Controller said at the time. Sound stopped, and after a while I went downstairs. Play time on Controller still counting up but still no sound. I pressed Pause and the play time jumped back. I pessed Pause again and the music started playing again and the play time started counting up, this time with no rebuffering or anything. The fault is pretty near the end of the log, search from the end backwards
for Pause.

Logging set to:

player.source at Debug
player.streaming at Debug
player.sync at Debug
plugin.bbciplayer.rtmp at Info (not relevant for this) 

I can't see any value in uploading any more logs from Classic FM unless someone advises me to change logging levels. If I can get an occurence on iPlayer with these logging levels then I will add that logfile.

Thank you for the logs. I have been trying to recreate the problem here (with Classic FM) but so far without success.

It seems that you are able to reproduce it petty readily. IN that case one further logging level, in addition to what you have also set, would be useful:

network.protocol.slimproto at Info

I have enabled the following as requested:

network.protocol.slimproto at Info 

Note I can sometimes easily reproduce this, and then it goes away for days at a time. After the 4 instances in quick succession this morning, it then played Classic FM for over 3 hours with no problems.

The nice thing about it happening on Classic FM using MP3 is it rules out transcoding and FLAC as parts of the problem.

Personally I suspect network issues (maybe on my broadband) which LMS then doesn't cope well with. This would explain why many people never see it. Also I never have this problem playing FLACs or MP3s locally from my server, it's only internet based stuff that I have trouble with.

This is almost certainly a consequence of the changes for bug 13814, not bug 14117.

What is happening in Owen's logs is that the player is (or the players are) suffering an underrun. As he suggests, this is probably because of poor Internet bandwidth issues for the remote stream. What is happeneing is that, after the consequent rebuffering has buffered sufficient data, the resume process calculates when each player should resume, so that they should be synchronized immediately upon resuming. It is possible that they may each have played a different amount of the stream prior to the underrun, especially if the issue is something that causes only one of the players to suffer an underrun. It appears that this start-at time is being calculated incorrectly (several minutes in the future).

One can tell from the logs that players have not actually resumed because they are not sending status heartbeat packets every second, which would cause CheckSync to be invoked. CheckSync is only being invoked every 5s due to the active polling from the server.

One of Owen's logs, would appear to indicate a problem with the data connection between the server and one of the players, not the remote connection. The consequence are the same. However, in this case the logging contains entries that appear to implicate bug 14117, probably erroneously.

This is not specific to iplayer.

It affects player models prior to Radio and Touch. Earlier players will honour a start-at time an arbitrary time in the future whereas SP-based players put an upper limit of 5s on this interval.

I am pretty certain that bug 14117 is not at issue. In the circumstances that lead to this bug then it is indeed protecting the server against memory overuse.

 == Auto-comment from SVN commit #33809 to the slim repo by ayoung ==
 == http://svn.slimdevices.com/slim?view=revision&revision=33809 ==

Fixed bug 17877: Resume after underrun broken for synchronized (ip3k) players 
Record resumeTime when starting a rebuffer so that the synchronized resume does not attempt to delay start by the period already played.

 == Auto-comment from SVN commit #33810 to the slim repo by ayoung ==
 == http://svn.slimdevices.com/slim?view=revision&revision=33810 ==

bug 17877: Resume after underrun broken for synchronized (ip3k) players

As part of investigating this bug I may have stumbled across another bug. I'm really not sure because the evidence was confusing.

I think that it is possible than an ip3k player may fail to start playing at all when synchronized under some circumstances. My guess is that this would occur in a window between 24 and 48 days since the player was booted. However, I suspect I may be wrong in this as such a scenario is common in my house and I do not see this problem. If I can reproduce it then I'll open a new bug.