Home of the Squeezebox™ & Transporter® network music players.
Page 1 of 6 123 ... LastLast
Results 1 to 10 of 51
  1. #1
    Junior Member
    Join Date
    Dec 2020
    Posts
    15

    SqueezeLite on Windows pausing, interruption, dropout of audio every 5 minutes

    I really need help to solve my problem. Hopefully someone out there can provide some insight.

    I've been running Squeezebox for years, and my server is a Synology DS918+ running DSM 6.x.
    I was running LMS 7.9.1 and recently upgraded to 8.0.1. My issue exists on either version of LMS.
    I have used Squeezebox Duet without any issues, but now I no longer use the Squeezebox unit, and I listen on a couple of clients: SqueezeLite on Windows, and also piCorePlayer on Raspberry Pi. My issue is that when running a windows client (SqueezeLite-X and also SqueezeLite command line) the audio will stop for about a minute, and then resume.

    Here is what I observe: (client side)
    * SqueezeLite version 1.9.8 is run like this:
    squeezelite-win.exe -d all=debug -s 192.168.0.60 -o 0
    * With the 'debug' level, you see some activity in the console, which doesn't show much, but is helpful.

    * I see some activity like this:
    [18:59:29.781] connect_socket:158 connecting to 192.168.0.60:9002
    [18:59:29.811] stream_sock:591 header: GET /stream.mp3?player=70:85:c2:a8:ce:68 HTTP/1.0
    * This shows that it is getting an mp3 stream from the NAS server.

    * I see activity about every 5 minutes:
    [18:40:36.290] mad_decode:247 setting track_start
    [18:40:36.290] _checkfade:287 fade mode: 1 duration: 3 track-start
    [18:40:36.292] _checkfade:327 CROSSFADE: 132300 frames
    [18:40:44.375] _output_frames:152 track start sample rate: 44100 replay_gain: 0
    [18:40:44.375] _output_frames:180 fade start reached
    [18:40:47.365] _output_frames:203 crossfade complete
    [18:40:47.365] _output_frames:206 skipped crossfaded start
    [18:45:38.698] decode_flush:236 decode flush
    [18:45:38.698] output_flush:438 flush output buffer
    [18:45:38.783] codec_open:264 codec open: 'm'
    [18:45:38.783] connect_socket:158 connecting to 192.168.0.60:9002
    [18:45:38.823] stream_sock:591 header: GET /stream.mp3?player=70:85:c2:a8:ce:68 HTTP/1.0
    [18:45:38.908] stream_thread:325 headers: len: 116
    HTTP/1.1 200 OK
    Server: Logitech Media Server (7.9.1 - 1504317335)
    Connection: close
    Content-Type: audio/mpeg
    [18:45:38.973] mad_decode:247 setting track_start
    [18:45:38.973] _checkfade:287 fade mode: 1 duration: 3 track-start
    [18:45:38.983] _output_frames:64 start buffer frames: 13295
    [18:45:38.983] _output_frames:152 track start sample rate: 44100 replay_gain: 0
    [18:45:39.324] stream_thread:398 end of stream

    * From this we see that it is buffering the stream, and it appears that the client is getting music in chunks every 5 minutes.

    * When the music stops, it is usually 5 minutes after the last logging activity seen. Then the music stops for about 1 minute, and the music resumes, and I immediately see some logging activity, similar to above. The activity is normal, and there are no errors, it just STOPs, and resumes again after 1 minutes.

    * During this stoppage, I see on the browser-based page, the playback counter is looping. Let's say playback is at the 2:15 mark. The sound stops, and I see it count forward 5 seconds: 2:15, 2:16, 2:17, 2:18, 2:19, 2:20 then back to 2:15 again. It always goes forward 4 or 5 seconds, before looping back, and it always resumes at the place it stopped. This suggests it's some kind of 'buffering' issue. Due to some network-related delay, it just stops, but can resume when it is able to buffer more audio and continue.

    * Looking around for some clues about what went wrong - first I look at the windows client machine - CPU, memory, disk, network - everything normal.
    * Looking at the LMS running on Synology - CPU, memory, disk, network - everything normal.
    * Looking at the Log files for LMS in /volume1/@appstore/SqueezeCenter/Logs but there is no server-side logging activity when this issue comes up.

    * It only happens with the Windows client. It happens the same on 2 different windows computers. But I could not find any clues about why it is pausing, either on client-side or server-side. Everything seems 'normal' but of course, it's far from normal. This started happening more recently, like the last 1 year, but no issues before that.
    * The Windows computer and Synology NAS are physically connected with wired ethernet via a router. I have not observed any network-related issues.

    * I searched the web for some forum postings and discussions, but I could not find any discussion about this particular issue.

    * I'm a technical user, I'm very familiar with administrator-level stuff on windows, and I can get around linux too. With all the technical knowledge I could muster, I simply cannot figure out what is going on with this Squeezebox. I realize all the tech is very old, and some is now end-of-life - Synology is no longer offering LMS, and I need to download it from Sourceforge, and even that is now no longer supported since 2015. The windows client is also old, and not updated since 2014. I get it. There might be no 'fix' and it might be time to retire the Squeezebox altogether.

    Best wishes to all for a safe and happy new year.

  2. #2
    Senior Member ralphy's Avatar
    Join Date
    Jan 2006
    Location
    Canada
    Posts
    2,837
    Please try the 1.9.8-1313 win32 build.
    Ralphy

    1-Touch, 5-Classics, 3-Booms, 2-UE Radio
    Squeezebox client builds donations always appreciated.

  3. #3
    Senior Member
    Join Date
    Feb 2011
    Location
    Cheshire, UK
    Posts
    5,720
    Quote Originally Posted by ralphy View Post
    Please try the 1.9.8-1313 win32 build.
    @ralphy
    Is there a W64bit version and is this likely to fix what I can only describe as an occasional burping noise which I think occurs when cross fading across different sample rates and sometimes kills the instance of Squeezelite?

  4. #4
    Junior Member
    Join Date
    Dec 2020
    Posts
    15
    Quote Originally Posted by ralphy View Post
    Please try the 1.9.8-1313 win32 build.
    Per your suggestion, i've taken the 1.9.8-1313 build of the 32-bit SqueezeLite.
    After running smoothly for 9 minutes, the first dropout was heard. The sound resumed about 1 minute later.
    The behavior seems to be the same as before.

    I'm curious to know if there was anything in this build to address this particular issue?

    I should add: this issue has existed for me for over a year. I just haven't used squeezebox for a while, and only this week I made a determined effort to get it working. It's not clear whether an older version of SqueezeLite would behave any differently. From my troubleshooting so far, it appears the issue is on the client-side, and windows in particular.

    I will keep monitoring the behavior.
    Last edited by foopydog; 2020-12-30 at 20:23.

  5. #5
    Senior Member ralphy's Avatar
    Join Date
    Jan 2006
    Location
    Canada
    Posts
    2,837
    Quote Originally Posted by d6jg View Post
    @ralphy
    Is there a W64bit version and is this likely to fix what I can only describe as an occasional burping noise which I think occurs when cross fading across different sample rates and sometimes kills the instance of Squeezelite?
    No. r1313 is only a test build to try and help isolate the problem foopydog described.
    Ralphy

    1-Touch, 5-Classics, 3-Booms, 2-UE Radio
    Squeezebox client builds donations always appreciated.

  6. #6
    Senior Member ralphy's Avatar
    Join Date
    Jan 2006
    Location
    Canada
    Posts
    2,837
    Quote Originally Posted by foopydog View Post
    Per your suggestion, i've taken the 1.9.8-1313 build of the 32-bit SqueezeLite.
    After running smoothly for 9 minutes, the first dropout was heard. The sound resumed about 1 minute later.
    The behavior seems to be the same as before.

    I'm curious to know if there was anything in this build to address this particular issue?

    I should add: this issue has existed for me for over a year. I just haven't used squeezebox for a while, and only this week I made a determined effort to get it working. It's not clear whether an older version of SqueezeLite would behave any differently. From my troubleshooting so far, it appears the issue is on the client-side, and windows in particular.

    I will keep monitoring the behavior.
    Thanks for trying it. I wouldn't have asked you to test if I hadn't made a change that I thought would address your issue.

    I've had a few similiar reports recently, however, I'm unable to reproduce it on either of the 3 flavours of windows I have available.

    For the number of downloads of squeezelite for windows, I'd expect a plethora of reports if this issue was in squeezelite as opposed to some other piece of software running on the windows os causing the problem.
    Ralphy

    1-Touch, 5-Classics, 3-Booms, 2-UE Radio
    Squeezebox client builds donations always appreciated.

  7. #7
    Junior Member
    Join Date
    Dec 2020
    Posts
    15
    Quote Originally Posted by ralphy View Post
    Thanks for trying it. I wouldn't have asked you to test if I hadn't made a change that I thought would address your issue.

    I've had a few similiar reports recently, however, I'm unable to reproduce it on either of the 3 flavours of windows I have available.

    For the number of downloads of squeezelite for windows, I'd expect a plethora of reports if this issue was in squeezelite as opposed to some other piece of software running on the windows os causing the problem.
    Ok, i'm with you, thank you. The build 1313 definitely DID help. After a few hours of listening, I got fewer interruptions. It paused twice in the first 15 minutes, but after that, it only paused once or twice over a few hours.

    What was the change you made?

    One suggestion: better logging. Usually the "info" loggers should show what's happening, but the SqueezeLite info logs are not helpful at all. A few strategic info() messages might help shine some light on what's happening during the interruption. Also, is there any suitable error() logging? (that is, if an error or timeout occurred, would we see it in the logs?) Hopefully, all code has a try/catch and all caught exceptions should log to the error logger. If error logs are missing, then it would be helpful to add at least a few handlers, in strategic locations. In particular, any external requests that might time-out after 1 minute, should have an exception handler for the time-out, and to log a warning.

    Also, if you can suggest any further troubleshooting or debugging steps, I can easily try stuff on my side.

    >> I'd expect a plethora of reports if this issue was in squeezelite as opposed to some other piece of software running on the windows os causing the problem.
    I totally agree, and so far, evidence only suggests it's a Windows problem, but I don't know for sure. I have two windows machines that both have this problem.
    With some effort, I could stand-up an Ubuntu VM, and try on that platform. But I already have a piCorePlayer running on Pi3, so I'll test that again on this network with piCorePlayer, and report back.

    John

  8. #8
    Senior Member ralphy's Avatar
    Join Date
    Jan 2006
    Location
    Canada
    Posts
    2,837
    Quote Originally Posted by foopydog View Post
    Ok, i'm with you, thank you. The build 1313 definitely DID help. After a few hours of listening, I got fewer interruptions. It paused twice in the first 15 minutes, but after that, it only paused once or twice over a few hours.

    What was the change you made?
    Well that's more encouraging than your initial test results. This is the change.

    I'd already pulled the r1313 test build before seeing your post.

    Thanks for the suggestion. I will likely need to add more logging to figure out what's happening.
    Ralphy

    1-Touch, 5-Classics, 3-Booms, 2-UE Radio
    Squeezebox client builds donations always appreciated.

  9. #9
    Junior Member
    Join Date
    Dec 2020
    Posts
    15
    Quote Originally Posted by ralphy View Post
    Well that's more encouraging than your initial test results. This is the change.

    I'd already pulled the r1313 test build before seeing your post.

    Thanks for the suggestion. I will likely need to add more logging to figure out what's happening.
    UPDATE: I reran the test again, and now I see the error, so I had to rewrite the post.

    Ah, I see it's written in C, so obviously no try/catch is possible.
    Looking at the code, I see that if send() failed (because it's blocked or lost the connection) it will retry 10 times, pausing for 1 second, and if it can't write, log a warning "failed writing to socket".
    I agree that this code might result in the "pause" observed, but so far, I didn't see anything in the logs to indicate it failed to send_packet().

    Armed with this knowledge, I reran my tests, with debug logs. While streaming normally, I see this:

    [20:02:06.590] sendSTAT:195 STAT: STMs
    [20:02:07.600] sendSTAT:195 STAT: STMt
    [20:02:09.319] sendSTAT:195 STAT: STMt
    [20:02:09.320] process:527 strm
    [20:02:09.337] process_strm:280 strm command t
    [20:02:09.343] sendSTAT:195 STAT: STMt
    [20:02:10.353] sendSTAT:195 STAT: STMt
    [20:02:12.377] sendSTAT:195 STAT: STMt
    [20:02:13.389] sendSTAT:195 STAT: STMt
    ...
    [20:02:23.318] process:527 strm
    [20:02:23.324] process_strm:280 strm command t
    [20:02:23.330] sendSTAT:195 STAT: STMt
    [20:02:24.340] sendSTAT:195 STAT: STMt
    [20:02:26.363] sendSTAT:195 STAT: STMt
    [20:02:27.319] process:527 strm
    [20:02:27.319] process_strm:280 strm command t
    ...

    It was showing these messages continuously.
    Then, after the first 6 minutes of streaming, the audio stopped, and the logs continued like this:

    [20:08:41.318] sendSTAT:195 STAT: STMt
    [20:08:41.318] sendSTAT:195 STAT: STMo
    [20:08:41.319] process:527 strm
    [20:08:41.324] process_strm:280 strm command t
    [20:08:41.325] sendSTAT:195 STAT: STMt
    [20:08:41.325] process:527 strm
    [20:08:41.326] process_strm:280 strm command p
    [20:08:41.326] sendSTAT:195 STAT: STMp
    [20:08:41.327] process_strm:316 pause interval: 0
    [20:08:41.447] process:527 strm
    [20:08:41.447] process_strm:280 strm command t
    [20:08:41.450] sendSTAT:195 STAT: STMt
    [20:08:41.748] process:527 strm
    [20:08:41.748] process_strm:280 strm command t
    [20:08:41.749] sendSTAT:195 STAT: STMt
    [20:08:42.048] process:527 strm
    [20:08:42.049] process_strm:280 strm command t
    [20:08:42.050] sendSTAT:195 STAT: STMt
    [20:08:42.349] process:527 strm
    [20:08:42.349] process_strm:280 strm command t

    It continued for exactly 30 seconds with these sendSTAT for stream command "t" (I think this means 'track' latency)
    And as soon as the audio resumed, I saw this:

    [20:09:11.814] process_strm:280 strm command t
    [20:09:11.815] sendSTAT:195 STAT: STMt
    [20:09:12.114] process:527 strm
    [20:09:12.114] process_strm:280 strm command t
    [20:09:12.116] sendSTAT:195 STAT: STMt
    [20:09:12.415] process:527 strm
    [20:09:12.415] process_strm:280 strm command q
    [20:09:12.419] decode_flush:236 decode flush
    [20:09:12.425] output_flush:438 flush output buffer
    [20:09:12.427] sendSTAT:195 STAT: STMf
    [20:09:12.643] process:527 audg
    [20:09:12.643] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1
    [20:09:12.651] set_volume:111 setting internal gain left: 20992 right: 20992
    [20:09:12.654] process:527 strm
    [20:09:12.656] process_strm:280 strm command s
    [20:09:12.661] process_strm:350 strm s autostart: 1 transition period: 3 transition type: 0 codec: m
    [20:09:12.668] sendSTAT:195 STAT: STMf
    [20:09:12.670] codec_open:264 codec open: 'm'
    [20:09:12.676] connect_socket:158 connecting to 192.168.0.60:9002
    [20:09:12.679] stream_sock:591 header: GET /stream.mp3?player=70:85:c2:a8:ce:68 HTTP/1.0


    [20:09:12.685] sendSTAT:195 STAT: STMc
    [20:09:12.688] process_strm:383 set fade mode: 0
    [20:09:12.694] process:527 audg
    [20:09:12.701] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1
    [20:09:12.707] set_volume:111 setting internal gain left: 20992 right: 20992
    [20:09:12.767] stream_thread:325 headers: len: 491
    HTTP/1.1 200 OK
    Server: Logitech Media Server (8.0.1 - 1607087403)
    Connection: close
    Content-Type: audio/mpeg
    Set-Cookie: Squeezebox-albumView=; path=/
    Set-Cookie: Squeezebox-expandPlayerControl=true; path=/
    Set-Cookie: Squeezebox-expanded-MY_MUSIC=1; path=/
    Set-Cookie: Squeezebox-expanded-FAVORITES=0; path=/
    Set-Cookie: Squeezebox-expanded-PLUGINS=0; path=/
    Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=0; path=/
    Set-Cookie: Squeezebox-expanded-RADIO=0; path=/


    [20:09:12.769] sendRESP:226 RESP
    [20:09:12.780] mad_decode:247 setting track_start
    [20:09:12.782] mad_decode:276 gapless: skipping 529 frames at start
    [20:09:12.784] mad_decode:235 mad_frame_decode error: bad main_data_begin pointer
    [20:09:12.800] _output_frames:64 start buffer frames: 32879
    [20:09:12.801] _output_frames:152 track start sample rate: 44100 replay_gain: 0
    [20:09:12.803] pa_callback:525 pad with silence
    [20:09:12.809] sendSTAT:195 STAT: STMs
    [20:09:12.814] sendSTAT:195 STAT: STMt
    [20:09:13.164] stream_thread:398 end of stream
    [20:09:13.165] sendDSCO:214 DSCO: 0
    [20:09:13.318] process:527 strm
    [20:09:13.318] process_strm:280 strm command t
    [20:09:13.325] sendSTAT:195 STAT: STMt

    The first error we see is "mad_frame_decode error: bad main_data_begin pointer"
    Playback continued for another 15 seconds, before I saw some socket errors:

    [20:09:16.354] sendSTAT:195 STAT: STMt
    [20:09:30.921] sendSTAT:195 STAT: STMt
    [20:09:30.932] send_packet:114 failed writing to socket: Unknown error
    [20:09:30.932] slimproto_run:563 error reading from socket: Unknown error
    [20:09:31.059] slimproto:932 connected
    [20:09:31.059] sendHELO:148 mac: 70:85:c2:a8:ce:68
    [20:09:31.065] sendHELO:150 cap: CanHTTPS=1,Model=squeezelite,AccuratePlayPoints=1, HasDigitalOut=1,HasPolarityInversion=1,Firmware=v1 .9.8-1313,ModelName=SqueezeLite,MaxSampleRate=768000,ds f,dff,alc,aac,ogg,ops,ogf,flc,aif,pcm,mp3
    [20:09:31.068] process:527 setd
    [20:09:31.068] sendSETDName:254 set playername: SqueezeLite-bogan-admin
    [20:09:31.070] process:527 setd
    [20:09:31.072] process:527 aude
    [20:09:31.073] process_aude:421 enable spdif: 1 dac: 1
    [20:09:31.075] process:527 audg
    [20:09:31.083] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1
    [20:09:31.085] set_volume:111 setting internal gain left: 20992 right: 20992
    [20:09:32.090] sendSTAT:195 STAT: STMt
    [20:09:33.105] sendSTAT:195 STAT: STMt
    [20:09:35.124] sendSTAT:195 STAT: STMt
    [20:09:35.318] process:527 strm
    [20:09:35.318] process_strm:280 strm command t

    So playback continued for another 1.5 minutes:

    [20:09:35.322] sendSTAT:195 STAT: STMt
    [20:09:36.342] sendSTAT:195 STAT: STMt
    [20:09:38.351] sendSTAT:195 STAT: STMt
    [20:09:39.317] process:527 strm
    [20:09:39.318] process_strm:280 strm command t
    ...
    [20:09:49.396] sendSTAT:195 STAT: STMt
    [20:09:50.405] sendSTAT:195 STAT: STMt
    [20:09:51.415] sendSTAT:195 STAT: STMt
    [20:09:53.434] sendSTAT:195 STAT: STMt

    Then the error came up again:

    [20:10:11.995] mad_decode:207 end of stream
    [20:11:00.038] decode_thread:100 decode complete
    [20:11:00.038] sendSTAT:195 STAT: STMd
    [20:11:00.039] send_packet:114 failed writing to socket: Unknown error
    [20:11:00.039] sendSTAT:195 STAT: STMt
    [20:11:00.045] send_packet:114 failed writing to socket: Unknown error
    [20:11:00.047] slimproto_run:563 error reading from socket: Unknown error
    [20:11:00.171] slimproto:932 connected
    [20:11:00.171] sendHELO:148 mac: 70:85:c2:a8:ce:68
    [20:11:00.177] sendHELO:150 cap: CanHTTPS=1,Model=squeezelite,AccuratePlayPoints=1, HasDigitalOut=1,HasPolarityInversion=1,Firmware=v1 .9.8-1313,ModelName=SqueezeLite,MaxSampleRate=768000,ds f,dff,alc,aac,ogg,ops,ogf,flc,aif,pcm,mp3
    [20:11:00.183] slimproto_run:715 output underrun
    [20:11:00.185] sendSTAT:195 STAT: STMu
    [20:11:00.192] process:527 setd
    [20:11:00.194] sendSETDName:254 set playername: SqueezeLite-bogan-admin
    [20:11:00.200] process:527 setd
    [20:11:00.206] process:527 aude
    [20:11:00.207] process_aude:421 enable spdif: 1 dac: 1
    [20:11:00.213] process:527 audg
    [20:11:00.215] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1
    [20:11:00.216] set_volume:111 setting internal gain left: 20992 right: 20992
    [20:11:00.327] process:527 strm
    [20:11:00.327] process_strm:280 strm command t
    [20:11:00.332] sendSTAT:195 STAT: STMt
    [20:11:05.318] process:527 strm
    [20:11:05.318] process_strm:280 strm command t
    [20:11:05.319] sendSTAT:195 STAT: STMt
    [20:11:09.768] slimproto_stop:972 slimproto stop
    [20:11:10.428] decode_close:221 close decode
    [20:11:10.428] stream_close:502 close stream
    [20:11:10.430] output_close_pa:613 close output

    These socket errors were appearing while playback was going on. They appeared AFTER playback had stopped and already resumed, thus we can say that the errors were a symptom of the failure, but the failure happened somewhere else. I hope your knowledge of the code will point you towards the real cause of the problem.

    John
    Last edited by foopydog; 2021-01-02 at 20:50. Reason: fix typo

  10. #10
    Senior Member
    Join Date
    Dec 2020
    Posts
    124
    Would have been nice if the log had displayed the winsock error code rather than print `unknown` trying to be more verbose about it. Is SqueezeLite a 64-bit app? I've seen applications report 8-byte length winsock errors that need to be masked 0x0000FFFF to resolve to a usable 10xxx decimal error code. The `sendHELO`entries in the log do give some indication though that these will likely be 10053 (Abort) and/or 10060 (Timeout). You could probably trace this with wireshark or a similar TCP dumping tool.

    I'm not real sure how Synology handles things internally, but is it possible that your hard drives are set to park when they are not in use? Note that if you have installed `green` drives they will actually do that themselves without the OS telling them. Run `smartctl -a /dev/sda` on the Synology (... sdb, sdc - however many drives you have installed and which ones contain any music files) and check the `Load_Cycle_Count`- if that's a really high number you are in trouble and the disk may in fact be near to EOL. If you configured RAID you may also want to run `btrfs device stats` to see if it reports any errors.

Tags for this Thread

Posting Permissions

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