Advisory: Sophos Endpoint "Your connection isn't private" after reboot. Policy settings can be returned to normal. See: KB-000045954 for the latest updates.

IPS/NTP HTTPS Decryption - ERR_EMPTY_RESPONSE issues since latest upgrade to NTP64 2023.2.573

Hey Sophos,

you managed to bring one of our websites out of production with your new NTP64 component.

Since installed, endpoints will not load it or only parts of it. Intercept-X kills the connection during TLS handshake.

HTTPS Decryption enabled.

Working NTP version yesterday:

2023-11-30T08:37:39.828Z [ 6960:16792] I Successfully installed product NTP64.
2023-11-30T08:37:39.838Z [ 9172: 6492] I [SAU] Successfully installed product NTP64 (NTP64) 1.17.3508

Not working NTP version today:

2023-12-01T08:23:52.249Z [16248:16324] I Successfully installed product NTP64.
2023-12-01T08:23:52.261Z [12576: 9776] I [SAU] Successfully installed product NTP64 (NTP64) 2023.2.573

Loading the site yesterday was fine:

2023-11-30T09:42:32.544Z [ 8244: 8324] I [webengine] New connection 0x262427ae5e0
2023-11-30T09:42:32.545Z [ 8244: 8324] I Connection from '\Device\HarddiskVolume3\Program Files\Mozilla Firefox\firefox.exe' with Spid: (5344,133458102324959521) and flowId:15186
2023-11-30T09:42:32.546Z [ 8244: 8280] I [clienthello] connection:0x262427ae5e0 sni:website.load.me ip:123.123.123.123 flowId:15186 decision:nodecrypt source:sxl4_cache
2023-11-30T09:42:32.548Z [ 8244:16656] I [request] connection: 0x262427ae5e0 url:https://website.load.me ip:123.123.123.123 flowId:15186 decision:allowed riskLevel:2 universalCategory:6
2023-11-30T09:42:32.548Z [ 8244:16656] I page allowed: https://website.load.me
2023-11-30T09:42:32.587Z [ 8244: 8324] I [webengine] New connection 0x262427af9c0

Today it's messed up with logs like this:

2023-12-01T17:04:50.037Z [ 7748: 8016] I [webengine] New connection 0x27eabc4e7c0
2023-12-01T17:04:50.037Z [ 7748: 8016] I Connection from '\Device\HarddiskVolume3\Program Files (x86)\Google\Chrome\Application\chrome.exe' with Spid: (16052,133459235343051278) and flowId:3210
2023-12-01T17:04:50.037Z [ 7748: 8016] I [clienthello] connection:0x27eabc4e7c0 sni:website.load.me ip:123.123.123.123 flowId:3210 decision:nodecrypt source:snf_cache webControl:[ decision:allow reason:category policyName:[Base Policy] version:1 ]
2023-12-01T17:04:50.058Z [ 7748: 8004] I Completing offload for flowId 3210
2023-12-01T17:04:50.058Z [ 7748: 8004] I [webengine] Closing connection 0x27eabc4e7c0 for '': request=669B, response=0B, lifetime=21ms, businessLogicDelay=0ms, timeInCache=0ms, in=0ms, out=0ms
2023-12-01T17:04:51.064Z [ 7748: 8000] I [webengine] New connection 0x27eac0c0dc0

Todays Debug Log.

2023-12-01T17:25:59.778Z [18120:15632] A Log level changed from Info to Debug. Source: SOFTWARE\Sophos\Logging\NTP
2023-12-01T17:26:04.046Z [18120: 4264] D [SED:COMMS]: Sending 541 bytes
2023-12-01T17:26:04.046Z [18120: 4264] D [SED:COMMS]: Sending 524 bytes
2023-12-01T17:26:04.047Z [18120:18836] D [SED:COMMS]: [0] Received 76 bytes
2023-12-01T17:26:04.047Z [18120:18836] D [SED:COMMS]: Received command reply
2023-12-01T17:26:04.047Z [18120:18836] D [SED:COMMS]: [0] Received 76 bytes
2023-12-01T17:26:04.047Z [18120:18836] D [SED:COMMS]: Received command reply
2023-12-01T17:26:06.184Z [18120:12360] D Didn't find a context with flowId=7941
2023-12-01T17:26:06.184Z [18120:12360] I [webengine] New connection 0x2493c5ac840
2023-12-01T17:26:06.184Z [18120:12360] D Created context for flowId=7941
2023-12-01T17:26:06.184Z [18120:12360] I Connection from '\Device\HarddiskVolume3\Program Files (x86)\Google\Chrome\Application\chrome.exe' with Spid: (6572,133459239622300236) and flowId:7941
2023-12-01T17:26:06.184Z [18120:12360] I [clienthello] connection:0x2493c5ac840 sni:website.load.me ip:123.123.123.123 flowId:7941 decision:nodecrypt source:snf_cache webControl:[ decision:allow reason:category policyName:[Base Policy] version:1 ]
2023-12-01T17:26:06.184Z [18120:12360] D Client Hello SNI lookup: website.load.me - allow=true, offload=false, nodecrypt=1
2023-12-01T17:26:06.184Z [18120:12360] D Client Hello - Processing WebControl policy
2023-12-01T17:26:06.184Z [18120:12360] D Lookup URL https://website.load.me
2023-12-01T17:26:06.184Z [18120:12360] D [SED:COMMS]: Sending 842 bytes
2023-12-01T17:26:06.186Z [18120: 5528] D [SED:COMMS]: [0] Received 512 bytes
2023-12-01T17:26:06.186Z [18120: 5528] D [SED:COMMS]: Received command reply
2023-12-01T17:26:06.186Z [18120:18824] I [request] connection: 0x2493c5ac840 url:https://website.load.me ip:123.123.123.123 flowId:7941 decision:allowed riskLevel:2 universalCategory:6 webControl:[ decision:allow reason:category policyName:[Base Policy] version:1 ]
2023-12-01T17:26:06.186Z [18120:18824] D NetFilter is using WebControl result from webrule
2023-12-01T17:26:06.186Z [18120:18824] I page allowed: https://website.load.me
2023-12-01T17:26:06.267Z [18120:12360] D Erasing context for flowId=7941
2023-12-01T17:26:06.267Z [18120:12360] D Storing web flow journal event for 13345925166-7941. Number of certs stored: 0
2023-12-01T17:26:06.267Z [18120:12360] I [webengine] Closing connection 0x2493c5ac840 for 'https://website.load.me': request=2176B, response=5467B, lifetime=83ms, firstResponse=30ms, businessLogicDelay=0ms, timeInCache=0ms, in=30ms, out=67ms, l.eos=82ms, r.eos=82ms
2023-12-01T17:26:08.317Z [18120:18448] D Didn't find a context with flowId=7947
2023-12-01T17:26:08.318Z [18120:18448] I [webengine] New connection 0x2493c64f540
2023-12-01T17:26:08.318Z [18120:18448] D Created context for flowId=7947
2023-12-01T17:26:08.318Z [18120:18448] I Connection from '\Device\HarddiskVolume3\Program Files (x86)\Google\Chrome\Application\chrome.exe' with Spid: (6572,133459239622300236) and flowId:7947
2023-12-01T17:26:08.318Z [18120:18448] I [clienthello] connection:0x2493c64f540 sni:website.load.me ip:123.123.123.123 flowId:7947 decision:nodecrypt source:snf_cache webControl:[ decision:allow reason:category policyName:[Base Policy] version:1 ]
2023-12-01T17:26:08.318Z [18120:18448] D Client Hello SNI lookup: website.load.me - allow=true, offload=false, nodecrypt=1
2023-12-01T17:26:08.318Z [18120:18448] D Client Hello - Processing WebControl policy
2023-12-01T17:26:08.318Z [18120:18448] D Lookup URL https://website.load.me
2023-12-01T17:26:08.318Z [18120:18448] D [SED:COMMS]: Sending 842 bytes
2023-12-01T17:26:08.319Z [18120: 5528] D [SED:COMMS]: [0] Received 512 bytes
2023-12-01T17:26:08.319Z [18120: 5528] D [SED:COMMS]: Received command reply
2023-12-01T17:26:08.319Z [18120:18824] I [request] connection: 0x2493c64f540 url:https://website.load.me ip:123.123.123.123 flowId:7947 decision:allowed riskLevel:2 universalCategory:6 webControl:[ decision:allow reason:category policyName:[Base Policy] version:1 ]
2023-12-01T17:26:08.319Z [18120:18824] D NetFilter is using WebControl result from webrule
2023-12-01T17:26:08.319Z [18120:18824] I page allowed: https://website.load.me
2023-12-01T17:26:08.494Z [18120:18780] D Erasing context for flowId=7947
2023-12-01T17:26:08.494Z [18120:18780] D Storing web flow journal event for 13345925168-7947. Number of certs stored: 0
2023-12-01T17:26:08.494Z [18120:18780] I [webengine] Closing connection 0x2493c64f540 for 'https://website.load.me': request=2112B, response=5467B, lifetime=176ms, firstResponse=108ms, businessLogicDelay=0ms, timeInCache=0ms, in=108ms, out=144ms, l.eos=176ms, r.eos=176ms
2023-12-01T17:26:09.653Z [18120:12360] D Didn't find a context with flowId=7952
2023-12-01T17:26:09.653Z [18120:12360] I [webengine] New connection 0x2493c5ac540

Must I say, it works, when disabling Sophos modules?

I'm a bit tired.



Updated the tags
[edited by: Gladys at 11:16 AM (GMT -8) on 2 Jan 2024]