Advisory: Sophos Endpoint - "Your connection isn't private." We're aware of a certificate issue and are actively working to resolve it. Please see: KB-000045954 for the latest updates.

Update Cache failing since retirement of SDDS2

Hi all,

Our Update Cache running on Windows Server 2019 last updated successfully at 2024-01-27T22:43:38.408Z and has been failing since.

It was running LTS 2023.0.0.2 but the issue continued after upgrading to FTS 2023.1.2.10.

I installed a new UC on a test Windows Server 2019, which failed in the same manner with FTS 2023.1.2.10 and also 2023.1.3.6.0, which is the latest version available to us.

This failure coincides with the retirement of SDDS2 described in KB-000045867.

The downloader.log indicates UC is not properly using the SDDS3 update mechanism:

2024-02-10T20:18:41.991Z [<main>] Info: [Downloader::Impl::Impl:141] Downloader started
2024-02-10T20:18:42.001Z [<main>] Info: [wmain:140] Purge completed successfully
2024-02-10T20:18:42.001Z [<main>] Info: [Downloader::Impl::ConfigureSession:201] Configuring Download Session
2024-02-10T20:18:42.006Z [<main>] Info: [Downloader::Impl::ConfigureSession:212] Username: [redacted]
2024-02-10T20:18:42.006Z [<main>] Info: [Downloader::Impl::ConfigureSession:216] DCI file: 41aea06e7cf0d70e17fc260874fb911c
2024-02-10T20:18:42.006Z [<main>] Info: [Downloader::Impl::ConfigureSession:223] Ignoring bandwidth limit: 0 Kb/s
2024-02-10T20:18:42.006Z [<main>] Info: [Downloader::Impl::ConfigureSession:244] Adding Sophos Location: http://dci.sophosupd.com/cloudupdate
2024-02-10T20:18:42.006Z [<main>] Info: [Downloader::Impl::ConfigureSession:244] Adding Sophos Location: http://dci.sophosupd.net/cloudupdate
2024-02-10T20:18:42.008Z [<main>] Info: [WindowsProxyDiscoveryWrapper::GetDefaultProxyConfiguration:38] WinHttp default proxy not set
2024-02-10T20:18:42.794Z [<main>] Warning: [WindowsProxyDiscoveryWrapper::GetProxyForUrl:124] Exception during GetProxyForUrl. Failed to get the automatic proxy configuration.: Unknown error (12180)
2024-02-10T20:18:42.794Z [<main>] Info: [Downloader::Impl::ConfigureSession:280] Adding Update Source: direct
2024-02-10T20:18:42.794Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I40394] Downloading customer file from sophos:1:1
2024-02-10T20:18:44.517Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E26245] Error fetching data from http://dci.sophosupd.com/cloudupdate/4/1a/41aea06e7cf0d70e17fc260874fb911c.dat: WinHttpSendRequest (error 12007)
2024-02-10T20:18:44.517Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I26245] No proxy was used.
2024-02-10T20:18:44.517Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I40394] Downloading customer file from sophos:2:1
2024-02-10T20:18:45.945Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E26245] Error fetching data from http://dci.sophosupd.net/cloudupdate/4/1a/41aea06e7cf0d70e17fc260874fb911c.dat: WinHttpSendRequest (error 12007)
2024-02-10T20:18:45.945Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I26245] No proxy was used.
2024-02-10T20:18:45.945Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I40394] Downloading customer file from sophos:3:1
2024-02-10T20:18:45.945Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E75373] Ran out of sophos aliases for this update source
2024-02-10T20:18:45.945Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E40365] Failed to download all catalogues
2024-02-10T20:18:45.945Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E35369] Out of update sources
2024-02-10T20:18:45.945Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E99999] Out of sources
2024-02-10T20:18:45.945Z [<main>] Error: [Downloader::Impl::Synchronise:171] SULException: SU_readRemoteMetadata failed: [4] unspecifiedFailure
2024-02-10T20:18:45.945Z [<main>] Info: [Downloader::Impl::ConfigureSession:201] Configuring Download Session
2024-02-10T20:18:45.952Z [<main>] Info: [Downloader::Impl::ConfigureSession:212] Username: [redacted]
2024-02-10T20:18:45.952Z [<main>] Info: [Downloader::Impl::ConfigureSession:216] DCI file: afccfe648cfffe7c695e2fae258c7792
2024-02-10T20:18:45.952Z [<main>] Info: [Downloader::Impl::ConfigureSession:223] Ignoring bandwidth limit: 0 Kb/s
2024-02-10T20:18:45.952Z [<main>] Info: [Downloader::Impl::ConfigureSession:244] Adding Sophos Location: http://dci.sophosupd.com/cloudupdate
2024-02-10T20:18:45.952Z [<main>] Info: [Downloader::Impl::ConfigureSession:244] Adding Sophos Location: http://dci.sophosupd.net/cloudupdate
2024-02-10T20:18:45.952Z [<main>] Info: [WindowsProxyDiscoveryWrapper::GetDefaultProxyConfiguration:38] WinHttp default proxy not set
2024-02-10T20:18:46.000Z [<main>] Warning: [WindowsProxyDiscoveryWrapper::GetProxyForUrl:124] Exception during GetProxyForUrl. Failed to get the automatic proxy configuration.: Unknown error (12180)
2024-02-10T20:18:46.000Z [<main>] Info: [Downloader::Impl::ConfigureSession:280] Adding Update Source: direct
2024-02-10T20:18:46.000Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I40394] Downloading customer file from sophos:1:1
2024-02-10T20:18:47.879Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E26245] Error fetching data from http://dci.sophosupd.com/cloudupdate/a/fc/afccfe648cfffe7c695e2fae258c7792.dat: WinHttpSendRequest (error 12007)
2024-02-10T20:18:47.879Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I26245] No proxy was used.
2024-02-10T20:18:47.879Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I40394] Downloading customer file from sophos:2:1
2024-02-10T20:18:48.909Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E26245] Error fetching data from http://dci.sophosupd.net/cloudupdate/a/fc/afccfe648cfffe7c695e2fae258c7792.dat: WinHttpSendRequest (error 12007)
2024-02-10T20:18:48.909Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I26245] No proxy was used.
2024-02-10T20:18:48.909Z [<main>] Info: [Downloader::Impl::ProgressLogFunction:478] [I40394] Downloading customer file from sophos:3:1
2024-02-10T20:18:48.909Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E75373] Ran out of sophos aliases for this update source
2024-02-10T20:18:48.909Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E40365] Failed to download all catalogues
2024-02-10T20:18:48.909Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E35369] Out of update sources
2024-02-10T20:18:48.909Z [<main>] Error: [Downloader::Impl::ProgressLogFunction:481] [E99999] Out of sources
2024-02-10T20:18:48.909Z [<main>] Error: [Downloader::Impl::Synchronise:171] SULException: SU_readRemoteMetadata failed: [4] unspecifiedFailure
2024-02-10T20:18:48.909Z [<main>] Warning: [wmain:155] Download failed with error code 4
2024-02-10T20:18:48.942Z [<main>] Info: [Downloader::Impl::~Impl:147] Downloader finished


Here's a snippet from uc.log for the same update attempt following a reboot:

2024-02-10T20:18:27.575Z [<main>] Info: [wWinMain:108] ~~~~~~~~~~~~~~~~~~~
2024-02-10T20:18:27.575Z [<main>] Info: [wWinMain:109] Service is starting
2024-02-10T20:18:27.575Z [<main>] Info: [wWinMain:110] Update Cache 1.11.0.307
2024-02-10T20:18:27.575Z [<main>] Info: [wWinMain:111] ~~~~~~~~~~~~~~~~~~~
2024-02-10T20:18:27.683Z [<main>] Info: [wWinMain:116] UC component tamper protection registration exists
2024-02-10T20:18:28.750Z [eb8] Info: [TamperProtectionMonitor::Start:27] Starting: TamperProtectionMonitor, Spawning the thread...
2024-02-10T20:18:28.750Z [eb8] Info: [TamperProtectionMonitor::Start:36] TamperProtectionMonitor is now running...
2024-02-10T20:18:28.752Z [eb8] Info: [SvcInit:221] Service has started
2024-02-10T20:18:29.102Z [f68] Info: [TamperProtectionUpdater::UpdateTamperProtection:77] The service is currently stoppable
2024-02-10T20:18:29.106Z [f64] Info: [Status::SaveToStateStore:127] Persisting to state store. State is load_policy, legacy state is load_policy
2024-02-10T20:18:29.107Z [f64] Info: [LoadPolicyStateHandler::Run:47] Load Policy state handler running
2024-02-10T20:18:29.109Z [f64] Info: [LoadPolicyStateHandler::LoadPolicy:170] Loaded new Policy from UEP storage
2024-02-10T20:18:29.109Z [f64] Info: [StateMachine::Run:53] State changing load_policy -> register
2024-02-10T20:18:29.110Z [f64] Info: [Status::SaveToStateStore:127] Persisting to state store. State is register, legacy state is register
2024-02-10T20:18:29.111Z [f64] Info: [RegisterStateHandler::Run:32] Register State Handler Running
2024-02-10T20:18:29.131Z [f68] Info: [TamperProtectionUpdater::UpdateTamperProtection:81] The service is now not stoppable
2024-02-10T20:18:29.136Z [f64] Info: [StateMachine::Run:53] State changing register -> install_certificate
2024-02-10T20:18:29.137Z [f64] Info: [Status::SaveToStateStore:127] Persisting to state store. State is install_certificate, legacy state is install_certificate
2024-02-10T20:18:29.139Z [f64] Info: [InstallCertificateStateHandler::Run:19] Install certificate state handler running
2024-02-10T20:18:29.140Z [f64] Info: [StateMachine::Run:53] State changing install_certificate -> initial_download
2024-02-10T20:18:29.140Z [f64] Info: [Status::SaveToStateStore:127] Persisting to state store. State is active, legacy state is initial_download
2024-02-10T20:18:29.142Z [f64] Info: [ActiveStateHandler::Run:75] Active State Handler Running. Current state is initial_download
2024-02-10T20:18:29.142Z [f64] Info: [SystemHealth::EvaluateCacheHealth:55] Catalogues timestamp file does not exist
2024-02-10T20:18:29.142Z [f64] Info: [ActiveStateHandler::Run:86] Active state: start monitoring for Central commands in C:\ProgramData\Sophos\Management Communications System\Endpoint\Messages\FromManagementServer
2024-02-10T20:18:29.267Z [1014] Info: [DirectoryChangeMonitor::Monitor:83] Starting directory change monitor for C:\ProgramData\Sophos\Management Communications System\Endpoint\Messages\FromManagementServer
2024-02-10T20:18:29.268Z [f64] Info: [ActiveStateHandler::Run:100] Active state: start monitoring the Unified Endpoint Policy Store for changes
2024-02-10T20:18:29.615Z [1080] Info: [RegistryChangeMonitor::Run:76] Starting registry change monitoring of key SOFTWARE\Sophos\Management\Policy
2024-02-10T20:18:29.615Z [f64] Info: [HTTPServer::ConfigureSSL:171] Checking HTTP service configuration (port=8191)
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:202] Starting HTTPServer...
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:203] Host: [redacted]
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:204] Port: 8191
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:205] Data root path: C:\ProgramData\Sophos\UpdateCache\www
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:206] SDDS2 URL root: sophos
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:207] SDDS3 URL root: v3
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:208] Queue length: 10000
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:209] Primary source URL: https://sdds3.sophosupd.com
2024-02-10T20:18:29.616Z [f64] Info: [HTTPServer::Start:210] Certificate folder path: C:\ProgramData\Sophos\Certificates\UpdateCache\Manifest
2024-02-10T20:18:29.634Z [f64] Info: [ResourceCoordinator::RefreshSourceSelection:259] ResourceCoordinator: refreshing source selection...
2024-02-10T20:18:29.928Z [10dc] Info: [WindowsProxyDiscoveryWrapper::GetDefaultProxyConfiguration:38] WinHttp default proxy not set
2024-02-10T20:18:33.228Z [10dc] Warning: [WindowsProxyDiscoveryWrapper::GetProxyForUrl:124] Exception during GetProxyForUrl. Failed to get the automatic proxy configuration.: Unknown error (12180)
2024-02-10T20:18:33.228Z [10dc] Info: [FileDownloader::SelectSource:235] Evaluating 1 proxy candidates with source https://sdds3.sophosupd.com
2024-02-10T20:18:36.417Z [10dc] Info: [FileDownloader::SelectSource:244] Selected proxy <none>
2024-02-10T20:18:36.417Z [10dc] Info: [ResourceCoordinator::SourceSelectionThreadFun:240] Updating the current source configuration: url: https://sdds3.sophosupd.com, proxy: 
2024-02-10T20:18:36.785Z [f64] Info: [ResourceCoordinator::Start:125] ResourceCoordinator: starting...
2024-02-10T20:18:36.787Z [f64] Info: [ResourceCoordinator::ChangeDownloadThreadCount:169] Starting 10 new download threads...
2024-02-10T20:18:36.790Z [f64] Info: [HTTPServer::Start:263] Starting the maintenance worker...
2024-02-10T20:18:36.854Z [f64] Info: [HTTPServer::Start:269] HTTP client is running
2024-02-10T20:18:37.036Z [1538] Info: [RegistryChangeMonitor::Run:76] Starting registry change monitoring of key SOFTWARE\Sophos\UpdateCache\SDDS2
2024-02-10T20:18:37.036Z [f64] Info: [HTTPServer::Start:312] Setting the HTTP queue length to 10000
2024-02-10T20:18:39.509Z [f64] Info: [HTTPServer::Start:333] HTTPServer is running
2024-02-10T20:18:39.511Z [f64] Info: [ActiveStateHandler::CheckCertExpiryThrottled:198] Checking if certificate is to expire soon.
2024-02-10T20:18:39.514Z [f64] Info: [ActiveStateHandler::LaunchDownloaderProcess:388] Starting downloader from C:\Program Files\Sophos\UpdateCache\UpdateCacheDownloader.exe
2024-02-10T20:18:48.974Z [f64] Info: [ActiveStateHandler::WaitForDownloaderProcessToEnd:492] Downloader run completed (exit code=4)
2024-02-10T20:18:48.983Z [f64] Info: [FileSystem::AtomicWriteFile:263] Wrote 237 bytes to file C:\ProgramData\Sophos\UpdateCache\Status\downloader_history.xml
2024-02-10T20:18:48.984Z [f64] Info: [SystemHealth::EvaluateCacheHealth:55] Catalogues timestamp file does not exist


Regards,
Stuart

Parents Reply
  • Thanks ,

    I tried these steps and the status did show properly after running as admin, but reverted to Unknown/Never after the reboot.

    The Unknown/Never status issue appears to be cosmetic due to opening the client as a standard user...the status shows properly if I simply click Tools > Elevate > Status > Server:

    I'm marking your response as the answer, though I'm still curious if 2023.2 addresses the issues in the logs, which the support engineer said has a tentative rollout completion date in April 2024.

    Regards,
    Stuart

Children
No Data