PDA

View Full Version : Squeezeplay skipping to next track randomly



itm
2019-02-03, 06:16
When I'm playing random song mixes on Squeezeplay 7.8.0 (on Windows 10) I frequently get songs skipping to the next track before completion. I'm running LMS 7.9.1 on Linux.
When I tried to download logs to investigate (from the LMS web GUI) I got an empty server log.
My logging settings on the LMS web interface are set to "Error" for all log types (which presumably tells me that the skipping is not caused by errors, as the server log was empty?). Which log setting(s) do I need to change to get more info on what's causing the random skipping?

EDIT: I should add that there is no wireless in the equation - both the LMS server and the Windows 10 renderer machine are connected to the same switch via Ethernet

itm
2019-02-04, 09:25
OK I managed to get some logging info....the skip occurred at about 16:17 today (4/2/19). It was playing Tom Waits "Mr Siegal" (on player 0a:00:27:00:00:02), then skipped before the end and started playing the Stereophonics "Don't Let Me Down". I don't see anything obvious in here. Can anyone else spot anything?

d6jg
2019-02-04, 09:47
Is your PC wired or wireless ? Network interruption can cause skipping

itm
2019-02-04, 09:58
Is your PC wired or wireless ? Network interruption can cause skipping

The PC renderer and LMS Server are both wired into the same switch

d6jg
2019-02-04, 10:14
The PC renderer and LMS Server are both wired into the same switch

Your log shows PAUSE a couple of times at 16:17.

itm
2019-02-04, 10:32
Your log shows PAUSE a couple of times at 16:17.

That's not something that I initiated - I left it playing when I downloaded the logs
???

biomass
2019-11-18, 04:46
I noticed the same behaviour. A large portion of my collection is encoded as Variable Bit Rate MP3. Nothing visible in the logs.. Albums play fine on Touch and Radios's but SqueezePlay skips randomly, usually near the end of a track.

sle118
2019-11-19, 21:27
OK I managed to get some logging info....the skip occurred at about 16:17 today (4/2/19). It was playing Tom Waits "Mr Siegal" (on player 0a:00:27:00:00:02), then skipped before the end and started playing the Stereophonics "Don't Let Me Down". I don't see anything obvious in here. Can anyone else spot anything?

I can't tell for sure if this is related, but I did troubleshoot a similar problem which occurred while streaming Spotify. If you are comfortable with compiling a C program using visual studio, you could try my fix:

https://github.com/Logitech/slimserver-tools/pull/3

Otherwise, I could make my compiled binary available for you to test.

bpa
2019-11-20, 02:38
I can't tell for sure if this is related, but I did troubleshoot a similar problem which occurred while streaming Spotify. If you are comfortable with compiling a C program using visual studio, you could try my fix:

https://github.com/Logitech/slimserver-tools/pull/3

Otherwise, I could make my compiled binary available for you to test.

The OP log shows direct MP3 streaming - so I don't think socketwrapper is the issue.

That said OP should post player.source INFO logging to confirm no trasncoding is taking place - never sure of Squeezeplay capabiltiies as it depends on the build.

Mastropietro
2019-11-22, 07:01
Are you sure transcoding could create issues like this?

bpa
2019-11-22, 07:04
Are you sure transcoding could create issues like this?
sle118 has found some instances where transcoding on Windows only can cut off last few second of some services.

fizze
2019-11-25, 12:46
I'm experiencing similar issues, mostly notable when listening to longer songs using SqueezePlay.
This does not happen on any of my SqueezeBoxes.
It is more noticeable for longer tracks, but no transcoding is taking place, and the (windows 10) client where SqueezePlay runs is wired to the LMS instance, as are all other SqueezeBoxes.

biomass
2019-12-07, 09:46
I used to use LMS 7.7.6-116 from the Synology package, and after posting here, I am now using LMS 7.9.1-168 from the beta packages list. My Squeezeplay.exe is 7.6.2 built October 18, 2012. The skipping of tracks is still there. So I'm suspecting it may be a Squeezeplay issue, or at least I would like to see the Squeezeplay logs.

Looking at the source code there is a possibililty to log, but that seems to be disabled on the Windows build. I got the source from Github, but getting that to build with VS 2019 needs work.

bpa
2019-12-07, 16:52
I used to use LMS 7.7.6-116 from the Synology package, and after posting here, I am now using LMS 7.9.1-168 from the beta packages list. My Squeezeplay.exe is 7.6.2 built October 18, 2012. The skipping of tracks is still there. So I'm suspecting it may be a Squeezeplay issue, or at least I would like to see the Squeezeplay logs.

Looking at the source code there is a possibililty to log, but that seems to be disabled on the Windows build. I got the source from Github, but getting that to build with VS 2019 needs work.

Start with the LMS logs first - they'll be more informative.

biomass
2019-12-08, 08:55
@bpa: I started humming 'I've got a feeling' by the Black Eyed Peas when I read your comment ;)

So I went looking in the Server Settings and set the (player.source) - Player Source Audio & Conversion Logging to 'Debug' and I created a playlist starting with 1 CBR mp3, and then followed by an album of VBR mp3 files. The skipping happened on the second track of the VBR tracks, it stopped around 19 seconds early.
It appears to be initiated by Squeezeplay:


Line 7831: [19-12-08 12:41:09.3947] Slim::Player::Protocols::File::open (81) duration: [325] size: [5204428] endian [] offset: [1470] for tmp:///volume2/music/Jimi%20Hendrix/1Track%20No01.mp3
Line 8865: [19-12-08 12:46:24.8872] Slim::Player::Protocols::File::open (81) duration: [248.933] size: [6622031] endian [] offset: [1083] for file:///volume2/music/Lana%20Del%20Rey/NFR/001%20Track001.mp3
Line 9710: [19-12-08 12:50:33.8492] Slim::Player::Protocols::File::open (81) duration: [247.146] size: [7244677] endian [] offset: [1029] for file:///volume2/music/Lana%20Del%20Rey/NFR/002%20Track002.mp3
Line 10491: [19-12-08 12:54:21.8143] Slim::Player::Protocols::File::open (81) duration: [577.2] size: [16197534] endian [] offset: [2028] for file:///volume2/music/Lana%20Del%20Rey/NFR/003%20Track003.mp3


Line 7857: [19-12-08 12:41:09.6395] Slim::Player::StreamingController::_Playing (361) Song 0 has now started playing
Line 8919: [19-12-08 12:46:34.8244] Slim::Player::StreamingController::_Playing (361) Song 1 has now started playing (326.849 s later than song 0)
Line 9756: [19-12-08 12:50:43.7873] Slim::Player::StreamingController::_Playing (361) Song 2 has now started playing (248.629 s later than song 1)
Line 10542: [19-12-08 12:54:31.7937] Slim::Player::StreamingController::_Playing (361) Song 3 has now started playing (228.064 s later than song 2?? (19 seconds early??))

[19-12-08 12:54:31.7901] Slim::Player::StreamingController::playerTrackStar ted (2180) 00:00:00:00:00:00 squeezeplay

bpa
2019-12-08, 14:38
@bpa: I started humming 'I've got a feeling' by the Black Eyed Peas when I read your comment ;)

So I went looking in the Server Settings and set the (player.source) - Player Source Audio & Conversion Logging to 'Debug' and I created a playlist starting with 1 CBR mp3, and then followed by an album of VBR mp3 files. The skipping happened on the second track of the VBR tracks, it stopped around 19 seconds early.

Editing logs is never a good idea as sometimes it is what is missing or the order of message that indicates what is happening. If you make a log - give the complete and unedited log from start of test to end of test - copied into a text file, zipped and attach to a post.

Skipping at end of a song usually means either LMS has not sent all the data usually becuase player has told LMS to give it the next song. So player.source is not a great choice for "end of song" issues unless there is transcoding.

File will be streamed using http to player so enable network.http to INFO to see the chunks of audio sent to the player. To minimise log message do not use WebUI or have other player active at the same time. YOu can see if the LMS does not send while file to player or if player disconnected the stream.

network.protocol.slimproto to INFO will show player control messages and buffer fullness. The end fo a song will indicate what si happening.

The log will be something like the following "fullness" is the undecoded data sent by LMS and output_fullness is the decoded PCM data. So fullness will go to zero when no more data from LMS. Then output_fullness will go to zero.


[19-12-08 21:31:59.0111] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=2318, output_fullness=3516408, elapsed=25.884
[19-12-08 21:31:59.0118] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-strm: fullness=2318, output_fullness=3516280, elapsed=25.884
[19-12-08 21:31:59.0163] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:22:00:d9: STAT-STMt: fullness=0, output_fullness=-1, elapsed=0.000
[19-12-08 21:31:59.4651] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=3521656, elapsed=26.339
[19-12-08 21:31:59.5600] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMd: fullness=0, output_fullness=3516152, elapsed=26.433
[19-12-08 21:32:00.4654] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=3197792, elapsed=27.339
[19-12-08 21:32:01.4644] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=2845024, elapsed=28.339
[19-12-08 21:32:02.4641] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=2492128, elapsed=29.339
[19-12-08 21:32:03.0066] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=2300768, elapsed=29.881
[19-12-08 21:32:03.0135] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:22:00:d9: STAT-STMt: fullness=0, output_fullness=-1, elapsed=0.000
[19-12-08 21:32:03.0137] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-strm: fullness=0, output_fullness=2300640, elapsed=29.882
[19-12-08 21:32:03.4658] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=2139424, elapsed=30.339
[19-12-08 21:32:04.4655] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=1786528, elapsed=31.339
[19-12-08 21:32:05.4651] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=1433760, elapsed=32.339
[19-12-08 21:32:06.4657] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=1080992, elapsed=33.339
[19-12-08 21:32:07.0069] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=889888, elapsed=33.880
[19-12-08 21:32:07.0090] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-strm: fullness=0, output_fullness=889760, elapsed=33.881
[19-12-08 21:32:07.0101] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:22:00:d9: STAT-STMt: fullness=0, output_fullness=-1, elapsed=0.000
[19-12-08 21:32:07.4644] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=728224, elapsed=34.339
[19-12-08 21:32:08.4656] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=375328, elapsed=35.339
[19-12-08 21:32:09.4654] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=22560, elapsed=36.339
[19-12-08 21:32:09.5293] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMu: fullness=0, output_fullness=-1, elapsed=36.403
[19-12-08 21:32:10.4650] Slim::Networking::Slimproto::_stat_handler (785) 00:04:20:16:07:0e: STAT-STMt: fullness=0, output_fullness=-1, elapsed=36.403