Thread Info
  • State Verified Answer
  • Locked Locked
  • Replies 7 replies
  • Subscribers 16 subscribers
  • Views 11700 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

Update Cache failing since retirement of SDDS2

stoomart

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



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

    I know the next version of UC which comes with 2023.2 (1.12.0.386) doesn't event have: "C:\Program Files\Sophos\UpdateCache\UpdateCacheDownloader.exe" and therefore downloader.log.  I think the errors in downloader.log can be ignored.  That's not to say something else isn't working but they are perhaps not the issue.

  • 0 in reply to Sophos User930

    Interesting...this may very well be the case as I see my original and test UCs show Active in Central for the cache status and the last cache update is within an hour.

    I will review logs from some endpoints that use the UC and look into modifying my log monitoring script to see about ignoring the downloader elements.

      Can you enable to the 2023.2 version in our tenant or does this require a support ticket?

  • 0 in reply to stoomart

    Hello  ,

    I just want to add a few points here for your information. 

    Devices on a version prior to Core Agent 2023.2 will not display a recent Last Cache Update timestamp when viewed in the Sophos Central Dashboard. This is caused due to the retirement of our SDDS2 updating mechanism, which an Update Cache on a previous Core Agent version would still have access to download data from.

    For affected devices, a recent Last Active timestamp and a Cache Status of 'Active' can be used to confirm an Update Cache is working as expected.

    Locally on a device, opening Endpoint Self Help (ESH), accessing the Server page, and confirming the Sophos Update Cache Status displays 'Good' can also confirm the Update Cache is working as expected.

    Yogalakshmi
    Sophos Digital Support
    Are you a Sophos Partner? | Product Documentation | @SophosSupport | Sign up for SMS Alerts
    If a post solves your question, please use the "Verify Answer" button.
    The New Home of Sophos Support Videos!  - Visit Sophos Techvids
  • 0 in reply to Yogalakshmi

    Thanks ,

    I see our 2023.1 servers showing fine in Sophos Central:


    However they both report Unknown and Never in the ESH:



    I've opened a case to get 2023.2 enabled since I'm not convinced they are working properly.

    Regards,
    Stuart

  • +1 in reply to stoomart

    Hi ,

    Good day.

    For that issue, you could try the below steps and check if the update cache status changes to good.

    Through File Explorer,

    1. Browse to C:\Program Files\Sophos\Endpoint Self Help.
    2. Right-click on SophosDiag.exe and select Run as administrator
    3. Then, restart the device.
    4. Open the endpoint agent and check the update cache status and the timestamp of the last successful update. 
    Yogalakshmi
    Sophos Digital Support
    Are you a Sophos Partner? | Product Documentation | @SophosSupport | Sign up for SMS Alerts
    If a post solves your question, please use the "Verify Answer" button.
    The New Home of Sophos Support Videos!  - Visit Sophos Techvids
  • 0 in reply to Yogalakshmi

    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

Reply
  • 0 in reply to Yogalakshmi

    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
Unfiltered HTML