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 7 months ago

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.

Top Replies

LHerzog 7 months ago in reply to RichardP +1

Thanks for your reply RichardP

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…

0 RichardP 7 months ago

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.

RichardP

Program Manager, Support Readiness | CISSP | Sophos Technical Support
Support Videos | Product Documentation | @SophosSupport | Sign up for SMS Alerts
If a post solves your question use the 'Verify Answer' link.
Cancel
Vote Up 0 Vote Down

Cancel
0 LHerzog 7 months ago in reply to RichardP

Thanks for your reply RichardP

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:
Cancel
Vote Up +1 Vote Down

Cancel
0 LHerzog 7 months ago in reply to LHerzog

new SDU with

sdu-feedback.sophos.com/.../f90ff178-b4db-4b1e-90b2-e63fdc78fe54_2022-01-13-08-49-30.zip
Cancel
Vote Up 0 Vote Down

Cancel
0 LHerzog 7 months ago in reply to LHerzog

The last days I monitored this on multiple machines. Today I tried to reproduce and could'nt. As written initially: "We've this occasionally on Windows hosts". Will see, what next week brings.
Cancel
Vote Up 0 Vote Down

Cancel