PDA

View Full Version : Softsqueeze sync problems with 1.13 (long, includes log)



Russell Mulcahy
2004-12-12, 07:18
Richard,

I have tried falling back to 1.12 and back up to 1.14. No change. I did
notice that that the sync is nearly right immediately after unsyncing and
then resyncing the players. It goes off again very quickly to about a fixed
1-2 secs and then stays like that. It is certainly doing some serious damage
to my listening pleasures as I get "audio leaks" from the room next door!
OTOH, just one or two tracks mix up nicely with a 1 sec delayed echo ;-)

I have a sync debug log but I am too ignorant to make much sense of it. The
only items that look odd to me are the underruns and the "No chunks". My
first version of this post included the log but it has been moderated (over
the limited). I have attached some excerpts.

Is there an accepted way to post logs? If not, what should I look for?

Thanks!

Russell.

Excerpts from log ...

2004-12-11 17:22:00.8809 00:04:20:05:60:72: No filehandle to read from,
returning no chunk.
2004-12-11 17:22:00.8953 Negative position calculated, we are still playing
out the previous song.
2004-12-11 17:22:00.8956 realpos -5087450 calcuated from bytes received:
3361597 minus buffer fullness: 53303
2004-12-11 17:22:00.8960 Negative position calculated, we are still playing
out the previous song.
2004-12-11 17:22:00.8962 realpos -5087450 calcuated from bytes received:
3361597 minus buffer fullness: 53303
2004-12-11 17:22:00.9423 00:04:20:05:60:72: No filehandle to read from,
returning no chunk.
<Cut>
2004-12-11 17:22:00.6151 00:04:20:05:60:72: No filehandle to read from,
returning no chunk.
2004-12-11 17:22:00.6616 Negative position calculated, we are still playing
out the previous song.
2004-12-11 17:22:00.6619 realpos -5071380 calcuated from bytes received:
3361597 minus buffer fullness: 37233
2004-12-11 17:22:00.6622 Negative position calculated, we are still playing
out the previous song.
2004-12-11 17:22:00.6625 realpos -5071380 calcuated from bytes received:
3361597 minus buffer fullness: 37233
2004-12-11 17:22:00.6682 00:04:20:05:60:72: No filehandle to read from,
returning no chunk.
2004-12-11 17:22:00.6702 00:04:20:05:60:72: No filehandle to read from,
returning no chunk.
<Cut>
2004-12-11 17:22:02.7517 realpos -5039732 calcuated from bytes received:
3361597 minus buffer fullness: 5585
2004-12-11 17:22:02.7583 00:04:20:05:60:72: Underrun while this mode:
playout-play
2004-12-11 17:22:03.7894 00:04:20:05:60:72 has run out of data, checking to
see if we can push on...
2004-12-11 17:22:03.7896 everybody's run out of data. Let's start them
up...
2004-12-11 17:22:03.7897 **skipahead: stopping
2004-12-11 17:22:03.7899 Backtrace:

frame 0: Slim::Player::Source::playmode (/PerlApp/Slim/Player/Source.pm
line 482)
frame 1: Slim::Player::Source::skipahead (/PerlApp/Slim/Player/Sync.pm
line 341)
frame 2: Slim::Player::Sync::checkSync
(/PerlApp/Slim/Networking/Slimproto.pm line 459)
frame 3: Slim::Networking::Slimproto::process_slimproto_fra me
(/PerlApp/Slim/Networking/Slimproto.pm line 233)
frame 4: Slim::Networking::Slimproto::client_readable
(/PerlApp/Slim/Networking/Select.pm line 116)
frame 5: Slim::Networking::Select::select (slimserver.pl line 453)
frame 6: main::idle (slimserver.pl line 40)
frame 7: PerlSvc::Startup (perlsvc line 1201)
frame 8: PerlSvc::_startup (slimserver.pl line 0)
frame 9: (eval) (slimserver.pl line 0)

2004-12-11 17:22:03.7901 00:04:20:05:60:72: Switching to mode stop from
playout-play
2004-12-11 17:22:03.7903 00:04:20:05:60:72 New play mode: stop
2004-12-11 17:22:03.7909 Stopping and clearing out old chunks for client
00:04:20:05:60:72
2004-12-11 17:22:03.7918 d5:08:24:9c:46:1f New play mode: stop
2004-12-11 17:22:03.7920 Stopping and clearing out old chunks for client
d5:08:24:9c:46:1f
2004-12-11 17:22:03.7931 00:04:20:05:60:72: Current playmode: stop
2004-12-11 17:22:03.7933 **skipahead: opening next song
2004-12-11 17:22:03.7934 opening next song...
2004-12-11 17:22:03.7937 the next song is number 62, was 61
2004-12-11 17:22:03.8266 undermax = 1, type = mp3, squeezebox =
00:04:20:05:60:72, lame =
2004-12-11 17:22:03.8268 checking formats for:
mp3-aif-squeezebox-00:04:20:05:60:72
2004-12-11 17:22:03.8269 Checking to see if
mp3-aif-squeezebox-00:04:20:05:60:72 is enabled
<Cut>
2004-12-11 17:22:03.9091 Streaming with format: mp3
2004-12-11 17:22:03.1640 **skipahead: restarting after underrun
2004-12-11 17:22:03.1643 Backtrace:

frame 0: Slim::Player::Source::playmode (/PerlApp/Slim/Player/Source.pm
line 488)
frame 1: Slim::Player::Source::skipahead (/PerlApp/Slim/Player/Sync.pm
line 341)
frame 2: Slim::Player::Sync::checkSync
(/PerlApp/Slim/Networking/Slimproto.pm line 459)
frame 3: Slim::Networking::Slimproto::process_slimproto_fra me
(/PerlApp/Slim/Networking/Slimproto.pm line 233)
frame 4: Slim::Networking::Slimproto::client_readable
(/PerlApp/Slim/Networking/Select.pm line 116)
frame 5: Slim::Networking::Select::select (slimserver.pl line 453)
frame 6: main::idle (slimserver.pl line 40)
frame 7: PerlSvc::Startup (perlsvc line 1201)
frame 8: PerlSvc::_startup (slimserver.pl line 0)
frame 9: (eval) (slimserver.pl line 0)

2004-12-11 17:22:03.1645 00:04:20:05:60:72: Switching to mode play from stop
2004-12-11 17:22:03.1652 openSong on:
file:///C:/Russell/My%20Music/Will%20Young/Friday's%20Child/Going%20My%20Way
-Will%20Young.mp3
2004-12-11 17:22:03.1662 openSong: getting duration 221, size 3543343,
endian and offset 0 for
file:///C:/Russell/My%20Music/Will%20Young/Friday's%20Child/Going%20My%20Way
-Will%20Young.mp3
2004-12-11 17:22:03.1963 undermax = 1, type = mp3, squeezebox =
00:04:20:05:60:72, lame =
<Cut>
2004-12-11 17:25:26.9413 Matched Format: mp3 Type: mp3 Command: -
2004-12-11 17:25:26.9417 playing out before starting next song. (old format:
mp3, new: mp3)
2004-12-11 17:25:26.9422 Backtrace:

frame 0: Slim::Player::Source::playmode (/PerlApp/Slim/Player/Source.pm
line 723)
frame 1: Slim::Player::Source::openNext (/PerlApp/Slim/Player/Source.pm
line 1504)
frame 2: Slim::Player::Source::readNextChunk
(/PerlApp/Slim/Player/Source.pm line 506)
frame 3: Slim::Player::Source::nextChunk (/PerlApp/Slim/Web/HTTP.pm line
1122)
frame 4: Slim::Web::HTTP::sendStreamingResponse
(/PerlApp/Slim/Networking/Select.pm line 124)
frame 5: Slim::Networking::Select::select (slimserver.pl line 453)
frame 6: main::idle (slimserver.pl line 40)
frame 7: PerlSvc::Startup (perlsvc line 1201)
frame 8: PerlSvc::_startup (slimserver.pl line 0)
frame 9: (eval) (slimserver.pl line 0)

2004-12-11 17:25:26.9425 00:04:20:05:60:72: Switching to mode playout-play
from play
2004-12-11 17:25:26.9427 00:04:20:05:60:72 New play mode: playout-play
2004-12-11 17:25:26.9441 d5:08:24:9c:46:1f New play mode: playout-play
2004-12-11 17:25:26.9455 00:04:20:05:60:72: Current playmode: playout-play
2004-12-11 17:25:26.9467 00:04:20:05:60:72: Can't opennext, returning no
chunk.
2004-12-11 17:25:26.0580 00:04:20:05:60:72: No filehandle to read from,
returning no chunk.
<Cut>

-----Original Message-----
From: discuss-bounces (AT) lists (DOT) slimdevices.com
[mailto:discuss-bounces (AT) lists (DOT) slimdevices.com] On Behalf Of Richard Titmuss
Sent: 09 December 2004 20:53
To: Slim Devices Discussion
Subject: [slim] Softsqueeze sync problems with 1.13

Russell,

You could try enabling d_sync or d_source in the slimserver debugging
options. The best diagnostic is an ethereal trace captured on the server
that includes the packets to both Softsqueeze and the squeezebox - but I
don't think that will work on XP with slimserver and softsqueeze on the same
machine.

If you use an older version of softsqueeze does it work correctly?

Regards,
Richard


Russell Mulcahy wrote:

>I just checked - the hardware box definitely lags! I am playing 128 and
>192 MP3s over an 11b wireless network. I do get the occasional
>squeezebox reboot (after several hours) that some others have reported
>but otherwise the network seems fine. Signal strength is reported (from
>the server page for the hardware box) as 43% at the moment. The
>softsqueeze is running on the same machine as slimserver.
>
>This used to work fine! What's the best diagnostic here?
>
>Russell.
>

rtitmuss
2004-12-13, 15:06
Russell,

I think it would be best if you post me the log off list, and I will
look at it later in the week. A test you could make is to enable the
buffer fullness display (in the slimserver player settings). When
playing in sync you should see the buffers on both players at (or near)
100%, but as you reach the end of each track the buffers will reduce to
zero. At the start of the next track the players should start playing
when both buffers are at 70% or greater. From what you have said it
sounds like Softsqueeze might be starting before the Squeezebox buffer
is filled? Or the Squeezebox is buffer is emptying during the track?

You could also check to make sure that bitrate limiting is not enabled
for either player. Also try swapping the order that the players are
sync'd (so if you normally select sync from the Softsqueeze player, try
selecting it from the Squeezebox or vica versa). I would not expect
either of these settings to make a difference, but it will be worth just
checking!

Regards,
Richard



Russell Mulcahy wrote:

>Richard,
>
>I have tried falling back to 1.12 and back up to 1.14. No change. I did
>notice that that the sync is nearly right immediately after unsyncing and
>then resyncing the players. It goes off again very quickly to about a fixed
>1-2 secs and then stays like that. It is certainly doing some serious damage
>to my listening pleasures as I get "audio leaks" from the room next door!
>OTOH, just one or two tracks mix up nicely with a 1 sec delayed echo ;-)
>
>I have a sync debug log but I am too ignorant to make much sense of it. The
>only items that look odd to me are the underruns and the "No chunks". My
>first version of this post included the log but it has been moderated (over
>the limited). I have attached some excerpts.
>
>Is there an accepted way to post logs? If not, what should I look for?
>
>Thanks!
>
>Russell.
>
>Excerpts from log ...
>
>
<Cut>

>-----Original Message-----
>From: discuss-bounces (AT) lists (DOT) slimdevices.com
>[mailto:discuss-bounces (AT) lists (DOT) slimdevices.com] On Behalf Of Richard Titmuss
>Sent: 09 December 2004 20:53
>To: Slim Devices Discussion
>Subject: [slim] Softsqueeze sync problems with 1.13
>
>Russell,
>
>You could try enabling d_sync or d_source in the slimserver debugging
>options. The best diagnostic is an ethereal trace captured on the server
>that includes the packets to both Softsqueeze and the squeezebox - but I
>don't think that will work on XP with slimserver and softsqueeze on the same
>machine.
>
>If you use an older version of softsqueeze does it work correctly?
>
>Regards,
>Richard
>
>
>Russell Mulcahy wrote:
>
>
>
>>I just checked - the hardware box definitely lags! I am playing 128 and
>>192 MP3s over an 11b wireless network. I do get the occasional
>>squeezebox reboot (after several hours) that some others have reported
>>but otherwise the network seems fine. Signal strength is reported (from
>>the server page for the hardware box) as 43% at the moment. The
>>softsqueeze is running on the same machine as slimserver.
>>
>>This used to work fine! What's the best diagnostic here?
>>
>>Russell.
>>
>>
>>
>
>