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
Added tags
[edited by: Gladys at 10:20 AM (GMT -8) on 5 Mar 2024]
