Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 4 replies
  • Subscribers 13 subscribers
  • Views 5895 views
  • Users 0 members are here
Options
Suggested
This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

temporary MCS Status Code 503, connection timeout, Dropping connection after error, Live Discover issue

LHerzog

We've this occasionally on Windows hosts. No new issue, though.

I cannot run live query when the machine is in that state.

Here a Server 2019.

On XG Fw I can see it communicating:

SDU https://sdu-feedback.sophos.com/prod/f90ff178-b4db-4b1e-90b2-e63fdc78fe54_2022-01-12-17-19-21.zip

MCSClient.log

2022-01-12T17:08:54.816Z [ 2956: 3800] I POST https://mcs2-cloudstation-eu-central-1.prod.hydra.sophos.com:443/sophos/management/ep/v2/data_feed/device/f90ff178-b4db-xxxx-90b2-xxxxxxxxxxx/feed_id/scheduled_query
2022-01-12T17:08:54.832Z [ 2956: 3800] I 200 : sent=1119 rcvd=0 elapsed=15ms
2022-01-12T17:08:54.832Z [ 2956: 3800] I Feed channel scheduled_query: uploading file C:\ProgramData\Sophos\Management Communications System\Endpoint\Channels\LiveQueryScheduled\Incoming\scheduled-20220112170839584.json result 0 purge false
2022-01-12T17:08:54.832Z [ 2956: 3800] I Feed channel scheduled_query: uploaded file C:\ProgramData\Sophos\Management Communications System\Endpoint\Channels\LiveQueryScheduled\Incoming\scheduled-20220112170839584.json
2022-01-12T17:08:54.833Z [ 2956: 3800] I Establishing push connection
2022-01-12T17:08:54.838Z [ 2956: 3800] I (async) GET https://mcs-push-server-eu-central-1.prod.hydra.sophos.com:443/ps/push/endpoint/9ff01f87-4bbd-xxxx-092b-xxxxxxxxxxx
2022-01-12T17:08:55.929Z [ 2956:  704] I (async) 503 : conntime=1091ms
2022-01-12T17:08:55.929Z [ 2956: 3800] W (async) connection timeout
2022-01-12T17:08:55.931Z [ 2956: 3800] W [push]: error creating async stream: 0
2022-01-12T17:08:55.933Z [ 2956: 3800] I [push]: Dropping connection after error
2022-01-12T17:09:50.952Z [ 2956: 3800] I GET https://mcs2-cloudstation-eu-central-1.prod.hydra.sophos.com:443/sophos/management/ep/commands/applications/ALC;AMSI;CORC;CORE;EFW;FIM;HBT;HMPA;LiveQuery;LiveTerminal;MCS;MDR;NTP;SAV;SDU;SHS;SWC;UI;APPSPROXY/endpoint/9ff01f87-4bbd-xxxx-092b-xxxxxxxxxxx
2022-01-12T17:09:51.978Z [ 2956: 3800] I 503 : sent=0 rcvd=0 elapsed=1025ms
2022-01-12T17:09:51.978Z [ 2956: 3800] I Dropping connection after error
2022-01-12T17:09:51.978Z [ 2956: 3800] I [backoff] waiting 1145s (880s + 265s skew) after failures: 4
2022-01-12T17:14:52.124Z [ 2956: 3832] I service tamper protection disabled
2022-01-12T17:14:55.081Z [ 2956: 3800] I User sessions changed: +(userDomain=VILLABOSCH, userName=lherzogsrvadm, userPrincipalName=lherzogsrvadm@villa-bosch.de, userSid=S-1-5-21-1803570019-140194396-1541874228-18048, state=0, type=1)
2022-01-12T17:14:55.091Z [ 2956: 3800] I [connect] trying server https://mcs2-cloudstation-eu-central-1.prod.hydra.sophos.com/sophos/management/ep
2022-01-12T17:14:55.091Z [ 2956: 3800] I [connect] trying direct connection without a proxy
2022-01-12T17:14:55.091Z [ 2956: 3800] I GET https://mcs2-cloudstation-eu-central-1.prod.hydra.sophos.com:443/sophos/management/ep
2022-01-12T17:15:11.175Z [ 2956: 3800] I 200 : sent=0 rcvd=168 elapsed=16082ms

MCSAgent.log

2022-01-12T16:51:54.334Z [ 2924: 4236] I [UI] UI: Updating registry key SOFTWARE\Sophos\Sophos UI\AdapterNotifications\APPSPROXY
2022-01-12T16:51:54.334Z [ 2924: 4236] I [UI] UI: UpdateAdapterNotification registry updated for adapter APPSPROXY
2022-01-12T17:09:52.658Z [ 2924: 2928] I Session Change Notification: Remote session connected
2022-01-12T17:09:54.621Z [ 2924: 2928] I Session Change Notification: User logged on
2022-01-12T17:09:54.909Z [ 2924: 4236] I UserInfo has changed: saving and broadcasting to listening adapters
2022-01-12T17:09:54.921Z [ 2924: 4236] I [AMSI] Received property changed from: APPSPROXY
2022-01-12T17:09:54.921Z [ 2924: 4236] I [HBT] Heartbeat adapter: AdapterPropertiesChanged notification received from APPSPROXY, check user info
2022-01-12T17:09:54.921Z [ 2924: 4236] I [HBT] Heartbeat adapter: Set user info
2022-01-12T17:09:54.921Z [ 2924: 4236] I [UI] UI: AdapterPropertiesChanged notification received from APPSPROXY
2022-01-12T17:09:54.921Z [ 2924: 4236] I [UI] UI: Set key to SOFTWARE\Sophos\Sophos UI\AdapterNotifications\, trying to match adapter APPSPROXY
2022-01-12T17:09:54.921Z [ 2924: 4236] I [UI] UI: Updating registry key SOFTWARE\Sophos\Sophos UI\AdapterNotifications\APPSPROXY
2022-01-12T17:09:54.922Z [ 2924: 4236] I [UI] UI: UpdateAdapterNotification registry updated for adapter APPSPROXY
2022-01-12T17:10:25.198Z [ 2924:  112] I [UI] UI: Received request from UI: {"get":["CORE.tamperProtectionEnabled"]}
2022-01-12T17:10:25.198Z [ 2924:  112] I [UI] UI: Processing get request from UI: CORE.tamperProtectionEnabled
2022-01-12T17:10:25.199Z [ 2924:  112] I [UI] UI: Get request CORE.tamperProtectionEnabled returned value true and result 0
2022-01-12T17:10:25.261Z [ 2924: 4740] I [UI] UI: Received request from UI: {"authorisation":{"UI.token": "xxxx"},"action":{"SAV.requeststate":"[EXTRAINFO]"}}
2022-01-12T17:10:25.261Z [ 2924: 4740] I [UI] UI: SAV requeststate action does not require authentication
2022-01-12T17:10:25.261Z [ 2924: 4740] I [UI] UI: Processing action request from UI: SAV.requeststate
2022-01-12T17:10:25.261Z [ 2924: 4740] I [UI] UI: AdapterActionProgress notification received from SAV for action scanStatus :: SAV scan is not in progress
2022-01-12T17:10:25.261Z [ 2924: 4740] I [UI] UI: Set key to SOFTWARE\Sophos\Sophos UI\AdapterNotifications\, trying to match adapter SAV
2022-01-12T17:10:25.325Z [ 2924: 4184] I [UI] UI: Received request from UI: {"get":["NTP.isolated"]}
2022-01-12T17:10:25.325Z [ 2924: 4184] I [UI] UI: Processing get request from UI: NTP.isolated
2022-01-12T17:10:25.326Z [ 2924: 4184] I [NTP] NTP adapter [StatusReporter::CalculateStatus]: Returning newly calculated status of revId: xxxxxxxxxxxxxxxxx res: Same
2022-01-12T17:10:25.327Z [ 2924: 4184] I [NTP] NTP adapter [NTPAdapter::GetAdapterProperty]: Got property 'isolated': false
2022-01-12T17:10:25.327Z [ 2924: 4184] I [UI] UI: Get request NTP.isolated returned value false and result 0
2022-01-12T17:10:25.386Z [ 2924: 7880] I [UI] UI: Received request from UI: {"get":["NTP.isolated"]}
2022-01-12T17:10:25.386Z [ 2924: 7880] I [UI] UI: Processing get request from UI: NTP.isolated
2022-01-12T17:10:25.387Z [ 2924: 7880] I [NTP] NTP adapter [StatusReporter::CalculateStatus]: Returning newly calculated status of revId: xxxxxxxxxxxxxxxxx res: Same
2022-01-12T17:10:25.387Z [ 2924: 7880] I [NTP] NTP adapter [NTPAdapter::GetAdapterProperty]: Got property 'isolated': false
2022-01-12T17:10:25.387Z [ 2924: 7880] I [UI] UI: Get request NTP.isolated returned value false and result 0
2022-01-12T17:10:29.013Z [ 2924: 7860] I [UI] UI: Received request from UI: {"get":["CORE.tamperProtectionEnabled"]}
2022-01-12T17:10:29.013Z [ 2924: 7860] I [UI] UI: Processing get request from UI: CORE.tamperProtectionEnabled
2022-01-12T17:10:29.013Z [ 2924: 7860] I [UI] UI: Get request CORE.tamperProtectionEnabled returned value true and result 0
2022-01-12T17:10:29.186Z [ 2924:  756] I [UI] UI: Received request from UI: {"get":["APPSPROXY.suspended"]}
2022-01-12T17:10:29.186Z [ 2924:  756] I [UI] UI: Processing get request from UI: APPSPROXY.suspended
2022-01-12T17:10:29.197Z [ 2924:  756] I [UI] UI: Get request APPSPROXY.suspended returned value false and result 0
2022-01-12T17:14:48.985Z [ 2924: 8376] I [UI] UI: Received request from UI: {"get":["UI.tokenFor.xxxx","CORE.tamperProtectionEnabled"]}
2022-01-12T17:14:48.985Z [ 2924: 8376] I [UI] UI: Processing get request from UI: CORE.tamperProtectionEnabled

The Sophos Management Communications System client service has received an HTTP status 503 from the server. This might indicate that action is necessary.

The issue just started after I logged on to the Server via RDP Remote Desktop.

Can be seen here 17:49 logon, at 17:50 MCS communication issue.



This thread was automatically locked due to age.
Parents
  • FormerMember
    0 FormerMember

    The 503 errors are the backend telling the clients it can't process the request. These sometimes happen if the connection attempts saturate the servers. Our product automatically backs off for a random time and then reattempts the connection. You can see the successful 200 return later in the log - this means the issue is not persistent and nothing to worry about.

    It won't have anything to do with actions you are taking on the endpoint/server and because it is a 500 level error it is coming from the destination - so the issue isn't in your network unless you have a forwarding proxy - which I doubt.

    I hope that answers your questions.

  • 0 in reply to FormerMember

    Thanks for your reply

    I worry about that issue because it seems to be reproducable and as soon as an Admin logs on to the machine via RDP, I can see the 8001 MCS Error in Eventlog.

    Then, before the admin logs on, the machine is selectable in Central for Live Discover, after the logon, the Server disappears from the list here:

Reply
  • 0 in reply to FormerMember

    Thanks for your reply

    I worry about that issue because it seems to be reproducable and as soon as an Admin logs on to the machine via RDP, I can see the 8001 MCS Error in Eventlog.

    Then, before the admin logs on, the machine is selectable in Central for Live Discover, after the logon, the Server disappears from the list here:

Children
Unfiltered HTML