Home of the Squeezebox™ & Transporter® network music players.
Page 1 of 2 12 LastLast
Results 1 to 10 of 15
  1. #1
    Junior Member
    Join Date
    May 2016
    Posts
    6

    Unable to get players from SN: 503 Service Temporarily Unavailable

    My LMS server log has been filling up with vast numbers of these logs since sometime yesterday.

    [16-05-16 09:15:41.0262] Slim::Networking::SqueezeNetwork::_error (596) Unable to login to SN: 503 Service Temporarily Unavailable
    [16-05-16 09:15:41.1257] Slim::Networking::SqueezeNetwork::_error (596) Unable to login to SN: 503 Service Temporarily Unavailable
    [16-05-16 09:15:41.1271] Slim::Networking::SqueezeNetwork::Players::_player s_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 3136147200 seconds
    [16-05-16 09:15:41.1306] Slim::Networking::SqueezeNetwork::_error (596) Unable to login to SN: 503 Service Temporarily Unavailable
    [16-05-16 09:15:41.2289] Slim::Networking::SqueezeNetwork::_error (596) Unable to login to SN: 503 Service Temporarily Unavailable
    [16-05-16 09:15:41.2303] Slim::Networking::SqueezeNetwork::Players::_player s_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 3136233600 seconds
    The 3 or 4 lines repeat every 10 seconds or so. The "retrying in xxxx seconds" part increments by 86400 each time (ie 24 hrs).

    The only streaming service that I use is Pandora, and that is not working of course. Local media and internet radio is working just fine.

    LMS seem to be doing a lot of "chattering" to SN, presumably endlessly retrying to connect. It is consuming about 100MB/hr of bandwidth continuously.

    A restart of LMS has made no difference.

    I am able to log into mysqueezebox.com using a browser and all looks normal.

    Using LMS 7.7.3 on a Synology NAS, environment has been static for many months.

    Any suggestions?

  2. #2
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    19,685

    Unable to get players from SN:503 Service Temporarily Unavailable

    >> [16-05-16 09:15:41.0262] Slim::Networking::SqueezeNetwork::_error (596)
    >> Unable to login to SN: 503 Service Temporarily Unavailable
    >> [16-05-16 09:15:41.1257] Slim::Networking::SqueezeNetwork::_error (596)
    >> Unable to login to SN: 503 Service Temporarily Unavailable
    >> [16-05-16 09:15:41.1271]
    >> Slim::Networking::SqueezeNetwork::Players::_player s_error (334) Unable
    >> to get players from SN: 503 Service Temporarily Unavailable, retrying in
    >> 3136147200 seconds
    >> [16-05-16 09:15:41.1306] Slim::Networking::SqueezeNetwork::_error (596)
    >> Unable to login to SN: 503 Service Temporarily Unavailable
    >> [16-05-16 09:15:41.2289] Slim::Networking::SqueezeNetwork::_error (596)
    >> Unable to login to SN: 503 Service Temporarily Unavailable
    >> [16-05-16 09:15:41.2303]
    >> Slim::Networking::SqueezeNetwork::Players::_player s_error (334) Unable
    >> to get players from SN: 503 Service Temporarily Unavailable, retrying in
    >> 3136233600 seconds

    >
    > The 3 or 4 lines repeat every 10 seconds or so. The "retrying in xxxx
    > seconds" part increments by 86400 each time (ie 24 hrs).


    This most likely is caused by our hit rate limiting. mysb.com would only
    accept a limited number of requests per second on some of the API calls.
    Eg. up there you see four attempts to log in within a second. And that
    log snippet only shows 0.2 seconds worth of log entries. There could
    easily have been many more. We've seen instances which sent _millions_
    of login attempts within a single day...

    I'm pretty sure this "hammering" mysb.com is caused by some bug in LMS.
    Alas, I haven't found it yet. We've seen it with any LMS version. To
    resolve that issue, please follow these steps:

    - turn off mysb.com integration of LMS (Settings/mysqueezebox.com)
    - shut down LMS
    - wait a minute or two before restarting
    - make sure you really know the correct mysb.com username and password
    by logging in to mysqueezebox.com in your browser
    - go back to LMS, enter your mysb credentials, re-enable mysb integration

    > LMS seem to be doing a lot of "chattering" to SN, presumably endlessly
    > retrying to connect. It is consuming about 100MB/hr of bandwidth
    > continuously.


    Ugh... as I said, this is not normal behaviour. And it's a problem for
    us, too.

    > A restart of LMS has made no difference.


    The pause is crucial, otherwise you risk to refresh the temporary ban
    right away.

    > I am able to log into mysqueezebox.com using a browser and all looks
    > normal.


    Did you recently change your password? Are you using any kind of
    "special" character (in particular non-latin or accented characters)?

    --

    Michael

  3. #3
    Junior Member
    Join Date
    May 2016
    Posts
    6
    Quote Originally Posted by mherger View Post
    >>To resolve that issue, please follow these steps:

    - turn off mysb.com integration of LMS (Settings/mysqueezebox.com)
    - shut down LMS
    - wait a minute or two before restarting
    - make sure you really know the correct mysb.com username and password
    by logging in to mysqueezebox.com in your browser
    - go back to LMS, enter your mysb credentials, re-enable mysb integration
    I followed these steps leaving LMS stopped for about 10 mins. Unfortunately no improvement.

    So then I tried again and this time I checked the server log activity between each step. When LMS was stopped the logging stopped (as expected). But when LMS was restarted the logging restarted immediately. ie the log hammering started BEFORE re-enabling the mysb.com connection. It is still hammering now even though the settings->mysqueezebox.com integration is disabled.

    When LMS is restarted I get a new server log. The 1st few lines are here, does that 2nd line suggest anything?

    Code:
    16-05-16 17:09:50.3800] main::init (354) Starting Logitech Media Server (v7.7.3, 1375965195, Mon Aug 19 11:42:55 PDT 2013) perl 5.018001
    [16-05-16 17:09:53.5593] Slim::Control::Request::execute (1869) Request in error, returning
    [16-05-16 17:09:55.1145] Slim::Networking::SqueezeNetwork::Players::_players_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 86400 seconds
    [16-05-16 17:09:55.2043] Slim::Networking::SqueezeNetwork::Players::_players_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 86400 seconds
    [16-05-16 17:09:55.2827] Slim::Networking::SqueezeNetwork::Players::_players_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 172800 seconds
    [16-05-16 17:09:55.4175] Slim::Networking::SqueezeNetwork::Players::_players_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 259200 seconds
    [16-05-16 17:09:55.5023] Slim::Networking::SqueezeNetwork::Players::_players_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 345600 seconds
    [16-05-16 17:09:55.6151] Slim::Networking::SqueezeNetwork::_error (596) Unable to login to SN: 503 Service Temporarily Unavailable
    [16-05-16 17:09:55.6164] Slim::Networking::SqueezeNetwork::Players::_players_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 432000 seconds
    [16-05-16 17:09:55.7682] Slim::Networking::SqueezeNetwork::_error (596) Unable to login to SN: 503 Service Temporarily Unavailable
    [16-05-16 17:09:55.7697] Slim::Networking::SqueezeNetwork::Players::_players_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 518400 seconds
    [16-05-16 17:09:55.8187] Slim::Networking::SqueezeNetwork::_error (596) Unable to login to SN: 503 Service Temporarily Unavailable
    [16-05-16 17:09:55.8201] Slim::Networking::SqueezeNetwork::Players::_players_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 604800 seconds
    [16-05-16 17:09:56.0267] Slim::Networking::SqueezeNetwork::_error (596) Unable to login to SN: 503 Service Temporarily Unavailable

    There are lots of logging options under settings->advanced->logging Can you suggest anything I can turn on to get some idea of what is happening here (as if I really want more log data!).

    Regarding your questions on login password ... no, I have not changed it for years, and it is an embarrassingly simple alphanumeric password.

  4. #4
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    19,685

    Unable to get players from SN:503 Service Temporarily Unavailable

    > So then I tried again and this time I checked the server log activity
    > between each step. When LMS was stopped the logging stopped (as
    > expected). But when LMS was restarted the logging restarted
    > immediately. ie the log hammering started BEFORE re-enabling the
    > mysb.com connection. It is still hammering now even though the
    > settings->mysqueezebox.com integration is disabled.


    Thanks for your effort. I really appreciate it, as this is a problem I'd
    really like to understand.

    > When LMS is restarted I get a new server log. The 1st few lines are
    > here, does that 2nd line suggest anything?


    No, that second line most likely is caused by the LMS web UI still open
    somewhere, but a player not connected yet? Possible?

    > [16-05-16 17:09:55.1145] Slim::Networking::SqueezeNetwork::Players::_player s_error (334) Unable to get players from SN: 503 Service Temporarily Unavailable, retrying in 86400 seconds


    What timeszone are you in?

    Next test you could run: shut down LMS, edit server.prefs and remove
    username and password entries. Restart.

    --

    Michael

  5. #5
    Junior Member
    Join Date
    May 2016
    Posts
    6
    Quote Originally Posted by mherger View Post
    ...that second line most likely is caused by the LMS web UI still open
    somewhere, but a player not connected yet? Possible?
    ...
    What timeszone are you in?
    ...
    Next test you could run: shut down LMS, edit server.prefs and remove
    username and password entries. Restart.
    1. Yes, the web UI open is possible.
    2. Timezone = GMT+10 (Australia)
    3. Tested as below ...


    • ensure mysb.com integration setting is "disabled"
    • check logging ... it's hammering
    • shut down LMS
    • logging stops
    • edit server.prefs, deleted sn_email and sn_password lines entirely
    • wait 5 mins
    • restart LMS
    • check logging ... it's stopped !!!
    • re-enable mysb.com integration in settings gui
    • check logging ... it's hammering again


    Okay, so it seems that disabling mysb.com integration by the LMS settings gui does not work when the server is in its "messed up" state. But editing the prefs file directly when LMS is down does work.

    So I now have a way to stop the logging, but of course this does not actually fix the problem.

    What next?

  6. #6
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    19,685

    Unable to get players from SN:503 Service Temporarily Unavailable

    > So I now have a way to stop the logging, but of course this does not
    > actually fix the problem.


    What happens when you now add the credentials again?


    --

    Michael

  7. #7
    Junior Member
    Join Date
    May 2016
    Posts
    6
    Quote Originally Posted by mherger View Post
    What happens when you now add the credentials again?Michael
    The log thrashing starts as soon as I apply the user/password via the web gui.

  8. #8
    Junior Member
    Join Date
    May 2016
    Posts
    6

    Resolved

    Problem is now overcome.

    I turned on lots of debug logging options and could finally see where the issue lay. Connected to LMS I have 3 SB hardware players, plus one PC running squeezelite. I can see LMS successfully logging into SN and pulling player/plugin etc details. Except that it was continually retrying to sync the squeezelite player, about 20 times per second, so eventually the SN nging server gave up and rejected with the 503 responses.

    Then discovered that the PC was somehow running 2 copies of squeezelite with the same MAC and player name. This should have been imposssible but anyway, killed one copy and restart LMS and now all is good again.

    So apologies for wasting your time. I will sort out whatever was the problem with the init script to startup squeezelite. I've been running this way for months or maybe years now, so I've no idea how this magically started just a few days ago!

    Meanwhile, you say you have seen this with other users, so maybe this might help in future. You could put some check in Slim::Networking::SqueezeNetwork::PrefSync::syncDo wn to avoid this, but it is basically a user error (ie mine).

    Thanks again for your help.

  9. #9
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    19,685

    Unable to get players from SN:503 Service Temporarily Unavailable

    > Then discovered that the PC was somehow running 2 copies of squeezelite
    > with the same MAC and player name. This should have been imposssible
    > but anyway, killed one copy and restart LMS and now all is good again.


    Wow, that's an excellent finding! So the login calls were banned because
    of the excessive sync attempts. I might improve this by using different
    buckets to count them. Thanks a lot for the digging and sharing the results!

    > So apologies for wasting your time.


    No waste, really. I'm glad you've followed up on this.

    > Meanwhile, you say you have seen this with other users, so maybe this
    > might help in future. You could put some check in
    > Slim::Networking::SqueezeNetwork::PrefSync::syncDo wn to avoid this,
    > but it is basically a user error (ie mine).


    Even if it was a user error, I have to protect the infrastructure from
    such user errors ;-). Unfortunately changing the LMS code won't be
    effective, as this problem sometimes comes from outdated versions, too.
    Eg. the other reporter about this is running 7.7.3. Quite obviously
    people don't even always update to the latest stable releases. Even less
    then to some "unstable" nightly build.

    Thanks again! I'll look what I can do to better cover this case.

    --

    Michael

  10. #10
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    19,685

    Unable to get players from SN:503 Service Temporarily Unavailable

    > retrying to sync the squeezelite player, about 20 times per second, so

    Heh... Unless I'm wrong your system hit us about 1.1Mio times yesterday.
    But I'm sorry to say: you missed the Top 5 by only about 35k queries
    (the top by about 450k) :-).

    Thanks again for your thorough analysis and the feedback. I'll roll out
    a few changes which hopefully will no longer block the login, but only
    the offending prefs sync and/or player status calls.

    --

    Michael

Posting Permissions

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