Home of the Squeezebox™ & Transporter® network music players.
Page 2 of 2 FirstFirst 12
Results 11 to 16 of 16
  1. #11
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    17,984
    Quote Originally Posted by Mastropietro View Post
    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.

  2. #12
    Junior Member
    Join Date
    Apr 2009
    Posts
    29
    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.
    Running Squeezecenter 7.9 on MariaDB 10.1.38
    Ubuntu 18.04.01 LTS Server
    SqueezeBox Boom (x2) - SqueezeBox Classic - Squeezebox Radio

  3. #13
    Junior Member
    Join Date
    Nov 2019
    Posts
    3
    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.

  4. #14
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    17,984
    Quote Originally Posted by biomass View Post
    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.

  5. #15
    Junior Member
    Join Date
    Nov 2019
    Posts
    3
    @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:

    Code:
    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
    Code:
    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??))
    Code:
    [19-12-08 12:54:31.7901] Slim::Player::StreamingController::playerTrackStarted (2180) 00:00:00:00:00:00 squeezeplay
    Last edited by biomass; 2019-12-08 at 12:06. Reason: math and moderator approval

  6. #16
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    17,984
    Quote Originally Posted by biomass View Post
    @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.
    Code:
    [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

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •