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

Collapse
X
 
  • Time
  • Show
Clear All
new posts
  • foopydog
    Junior Member
    • Dec 2020
    • 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.
  • ralphy
    Senior Member
    • Jan 2006
    • 3298

    #2
    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.

    Comment

    • d6jg
      Senior Member
      • Feb 2011
      • 8953

      #3
      Originally posted by ralphy
      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?
      Jim



      pCP9.0 / LMS 9.x storage QNAP TS419p (NFS)
      Living Room Joggler & Pi4/Khadas -> Onkyo TXNR686 -> Celestion F20s
      Office Joggler & Pi3 -> Onkyo CRN775 -> Wharfedale Modus Cubes
      Kitchen WiiM Pro -> Topping MX3 - B&W In Ceiling speakers
      Bedroom (Bedside) Pi Zero+DAC ->ToppingTP21 ->AKG Headphones
      Bedroom (TV) & Bathroom SB Touch ->Denon AVR ->Mordaunt Short M10s + Kef ceiling speakers
      Guest Room Joggler > Denon RCFN8 -> Celestions F10s

      Comment

      • foopydog
        Junior Member
        • Dec 2020
        • 15

        #4
        Originally posted by ralphy
        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-31, 03:23.

        Comment

        • ralphy
          Senior Member
          • Jan 2006
          • 3298

          #5
          Originally posted by d6jg
          @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.

          Comment

          • ralphy
            Senior Member
            • Jan 2006
            • 3298

            #6
            Originally posted by foopydog
            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.

            Comment

            • foopydog
              Junior Member
              • Dec 2020
              • 15

              #7
              Originally posted by ralphy
              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

              Comment

              • ralphy
                Senior Member
                • Jan 2006
                • 3298

                #8
                Originally posted by foopydog
                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.

                Comment

                • foopydog
                  Junior Member
                  • Dec 2020
                  • 15

                  #9
                  Originally posted by ralphy
                  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-03, 03:50. Reason: fix typo

                  Comment

                  • gordonb3
                    Senior Member
                    • Dec 2020
                    • 489

                    #10
                    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.

                    Comment

                    • ralphy
                      Senior Member
                      • Jan 2006
                      • 3298

                      #11
                      Thanks for the explaination around the unknown error strings. I'll look into that for the 64bit build. For this session, I'm building 32bit only and squeezelite still can't resolve the error code to a string.

                      In an effort to determine what the unknown socket errors are, I've uploaded an r1318-test2 build which prints the hex error value instead of trying to convert it to a string.

                      Would you try this build in debug mode?

                      Thanks,
                      Last edited by ralphy; 2021-01-03, 13:50.
                      Ralphy

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

                      Comment

                      • foopydog
                        Junior Member
                        • Dec 2020
                        • 15

                        #12
                        Originally posted by gordonb3
                        Is SqueezeLite a 64-bit app?
                        No, this is the 32-bit build 1313 which ralphy put up to help troubleshoot this issue.

                        >> it possible that your hard drives are set to park when they are not in use?

                        Yes. here is how they are set up:
                        Click image for larger version

Name:	synology-hibernation.JPG
Views:	1
Size:	59.6 KB
ID:	1570859

                        Hibernation happens after 20 minutes, and I have also set up logging for this. Looking at the logs, I see the last hibernation activity was 8 months ago. That makes sense, because this page: https://www.synology.com/en-global/k...re_hibernation
                        explains that certain services, such as the Logitech Media Server need constant access to disk, so if they are running, hibernation usually doesn't happen, and that is the case with me.

                        >>applications report 8-byte length winsock errors that need to be masked 0x0000FFFF to resolve to a usable 10xxx decimal error code.

                        In that case, it would be helpful to use a #computer-directive to check for 32/64 bitness, and use the suggested logic to resolve the error-code. I hope ralphy can easily make the change, and I'll rerun my test to see if I can get that error code.

                        >> if you have installed `green` drives they will actually do that themselves without the OS telling them.
                        I am aware that these desktop-type drives have this power-saving 'feature' which causes problems for NAS. I have Toshiba NAS drives, and these are not the 'green' type drives.

                        Looking at the hard drives:
                        admin@nas:~$ sudo smartctl -a /dev/sda
                        smartctl 6.5 (build date May 7 2020) [x86_64-linux-4.4.59+] (local build)
                        Copyright (C) 2002-16, Bruce Allen, Christian Franke, www.smartmontools.org

                        === START OF INFORMATION SECTION ===
                        Vendor: TOSHIBA
                        Product: HDWN160
                        Revision: FS1M
                        User Capacity: 6,001,175,126,016 bytes [6.00 TB]
                        Logical block size: 512 bytes
                        Physical block size: 4096 bytes
                        LU is fully provisioned
                        Rotation Rate: 7200 rpm
                        Form Factor: 3.5 inches
                        Logical Unit id: 0x50000398ac581f2a
                        Serial number: 78NUK021FAXG
                        Device type: disk
                        Local Time is: Mon Jan 4 09:47:49 2021 PST
                        SMART support is: Unavailable - device lacks SMART capability.

                        === START OF READ SMART DATA SECTION ===
                        Current Drive Temperature: 0 C
                        Drive Trip Temperature: 0 C

                        Error Counter logging not supported

                        [GLTSD (Global Logging Target Save Disable) set. Enable Save with '-S on']
                        Device does not support Self Test logging

                        Here we don't see all the information, but with the Synology Storage Manager I can see SMART and other info about my 4 disks in raid-5.
                        Click image for larger version

Name:	Drive-health.JPG
Views:	1
Size:	65.1 KB
ID:	1570861

                        Also:
                        admin@nas:~$ sudo btrfs device stats .
                        [/dev/mapper/cachedev_0].write_io_errs 0
                        [/dev/mapper/cachedev_0].read_io_errs 0
                        [/dev/mapper/cachedev_0].flush_io_errs 0
                        [/dev/mapper/cachedev_0].corruption_errs 0
                        [/dev/mapper/cachedev_0].generation_errs 0
                        We can see that the Synology reports good health, and this is good for all drives. With 15,000 hours on the drives, they have had about 2 years of operation. I run a monthly health report on the drives, and they have always reported good health. There is no reason to think that these issues are related to drive health.

                        I'm going to play with Wireshark to see if I can gain some insight into the TCP activity surrounding this outage issue.

                        Thanks

                        Comment

                        • gordonb3
                          Senior Member
                          • Dec 2020
                          • 489

                          #13
                          Oh... That's pretty interesting. Apparently the Synology shell is something of a virtualization layer on top of the actual OS. Shame that the SSM tool does not display vital drive information like LCC, but with a 20 minute sleep setting I would not expect issues with park/unpark. Should this be the case anyway you should definitely be able to identify it by a ticking sound coming from the unit. Do note that RAID 5 is a three disk configuration, so one of your disks must function as a spare. Does SSM tell you which one is which, i.e. which one is the spare? Two types of logic might apply here, just follow the numerical order or skip one of the centre two disks to reduce heat exchange between the disks, so drawing any conclusions from it will most likely prove wrong, but I would be very suspicious if the spare happened to be sda.

                          That said, I think we may have gotten off-track here a bit as I was wondering if you could verify this behaviour with the Duet you own and then noticed that you had mentioned to run piCorePlayer as well and not seeing the issue there. That implies that the problem is on the client side, not the server. It may be interesting to verify TCP connectivity on other protocols, in particular SMB. Do you have active drive mappings to the Synology on the Windows client? If not, create one and keep an Explorer window with folder listing open without clicking the mapped drive. If after some time (probably about 5 minutes or so) you see a red X appear over the mapped drive this means that the TCP connection has actively been disconnected, which should not happen.
                          Last edited by gordonb3; 2021-01-04, 19:44.

                          Comment

                          • ralphy
                            Senior Member
                            • Jan 2006
                            • 3298

                            #14
                            Originally posted by foopydog
                            No, this is the 32-bit build 1313 which ralphy put up to help troubleshoot this issue.

                            >>applications report 8-byte length winsock errors that need to be masked 0x0000FFFF to resolve to a usable 10xxx decimal error code.

                            In that case, it would be helpful to use a #computer-directive to check for 32/64 bitness, and use the suggested logic to resolve the error-code. I hope ralphy can easily make the change, and I'll rerun my test to see if I can get that error code.
                            Have you had a chance to try this?
                            Ralphy

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

                            Comment

                            • foopydog
                              Junior Member
                              • Dec 2020
                              • 15

                              #15
                              >> Apparently the Synology shell is something of a virtualization layer on top of the actual OS.

                              Yes, sort of. The user-interface for Synology DSM runs on linux. It's not a virtualization layer as such, but just a user-interface on top of regular linux. In the case of my Storage Manager, it does provide a bit more insight than smartctl, but that's probably because Synology developed other tools to manage the raid array. They call it "SHR - Synology Hybrid Raid", which is like regular RAID, but allows different types of disk, and volumes can grow/shrink.

                              >> Do note that RAID 5 is a three disk configuration, so one of your disks must function as a spare. Does SSM tell you which one is which, i.e. which one is the spare?

                              Actually that's not correct. Raid-5 has one-disk redundancy, but there is no concept of a "spare". Think of it like this: There are 4 disks in the array, all are equal to each other, and when a file is written to the array, the parity is calculated, and stored alongside the file, and it's distributed across disks. Then, if any one of the four disks fails, a new disk is inserted, and all the missing files are reconstructed, one by one, based on the parity.

                              >>verify this behaviour with the Duet

                              Now I can't because I no longer have a Duet. I had one for years, but recently sold both on ebay. I have replaced the Duet with my Raspberry Pi.
                              I can say for sure that this issue does NOT exist with the SqueezeLite running on piCorePlayer on the Raspberry Pi 3B+. I tested it again yesterday, and it ran all day with not a single hiccup.

                              >>That implies that the problem is on the client side, not the server.

                              Yes I agree. I also used the Synology LMS for years with the Duet, and also never saw an issue like this. That's why I presumed that this is a windows-specific client-side issue.
                              I also re-ran tests on BOTH my windows machines separately, and both have the same problem with audio dropouts, and the exact same behavior too.
                              1. Dell XPS-13, Core i7 6th gen, 16GB memory, windows home.
                              2. Asrock Mini ITX, Core i7-8700K, 16GB memory, windows pro.
                              For both machines, the behavior is the same:
                              * Interruptions happen every 5, 10, 15 or 20 minutes, almost exactly these time-intervals
                              * The interruption always lasts for 30 seconds, and then resumes.

                              >>Do you have active drive mappings to the Synology on the Windows client?

                              Yes, the Synology is running Samba, and both windows systems have drive-mappings to the Synology over Samba. I don't see how this could affect the behavior of the SqueezeLite, because it doesn't talk to the Synology over Samba.

                              >> If after some time (probably about 5 minutes or so) you see a red X appear over the mapped drive

                              Good suggestion, but I confirmed that there is no network outage. I know that when you unplug the ethernet cable, or reboot the NAS, I would see those "red X" showing that the drive-mapping had become disconnected, and when the connection is restored, you only need to click on the drive-mapping, to reactivate it. That feature works as expected, but in this case, there is no network outage. That is, when SqueezeLite loses audio, I can immediately navigate to samba shares, and the network connectivity continues normally. I have examined both windows and synology systems during the outage, but everything is normal. Thus we can say that the SqueezeLite client is the only cause of the outage.

                              But since it's hard to reproduce on another Windows system, we still don't know that for sure. There could be some weird routing issue with my LAN on which these 2 machines sit, but I don't know what that could be. It could be some weird Windows thing but what? The right way to fix this, is to debug it on my machine. I'm not set up with Visual Studio, but I could set it up and do a debug session, if we exhaust the basic options.

                              Separately, I'll reply to ralphy and test the new build he put up.
                              John

                              Comment

                              Working...