locked
Windows Server 2016 WSUS Clients Downloading Unapproved Updates RRS feed

  • Question

  • I have been having issues recently within WSUS.  Here are the specifics of my environment:

    WSUS server is Windows Server 2016 Standard

    All clients come to a singular WSUS server for approvals, but request the files from Microsoft Update.

    This was all working fine with the exception that recently in February, the Server 2016 WSUS clients started downloading whatever they felt like as soon as updates were available.  No other clients are doing this, including Windows 10 1511, 1607, and 1703 clients.  Only the 2016 servers (including the WSUS server itself). 

    Things I have looked at already:

    All servers receive the same GPO for WSUS configuration so it is not a group policy issue, and I have verified through GPResult that the GPO is applied correctly and not conflicting with others.

    I have deleted the SusClientId and SusClientValidation reg settings and let it recreate in WSUS.

    I ran a cleanup script on the WSUS server I found online here:  https://community.spiceworks.com/scripts/show/2998-wsus-automated-maintenance-formerly-adamj-clean-wsus

    I have re-registered the dlls necessary for a windows update client to function.

    I have manually hit the URL for WSUS to verify it is functional (which is should be, as only Server 2016 is having issues).

    I generated the log files on the server as well, which I will share relevant portions of below.

    I see these logs over and over again:

    2018/03/14 13:02:16.8670026 1468  3852  WebServices     WS Error code: Server
    2018/03/14 13:02:16.8670165 1468  3852  WebServices     WS error: <detail/>
    2018/03/14 13:02:18.8796048 1468  3852  WebServices     Auto proxy settings for this web service call.
    2018/03/14 13:02:18.8834171 1468  3852  WebServices     WS error: The body of the received message contained a fault.
    2018/03/14 13:02:18.8834185 1468  3852  WebServices     WS error: The body of the received message contained a fault.
    2018/03/14 13:02:18.8834193 1468  3852  WebServices     WS error: The body of the received message contained a fault.
    2018/03/14 13:02:18.8834201 1468  3852  WebServices     WS error: The body of the received message contained a fault.
    2018/03/14 13:02:18.8834210 1468  3852  WebServices     WS error: The body of the received message contained a fault.
    2018/03/14 13:02:18.8834218 1468  3852  WebServices     WS error: The body of the received message contained a fault.
    2018/03/14 13:02:18.8834226 1468  3852  WebServices     WS error: The body of the received message contained a fault.
    2018/03/14 13:02:18.8834235 1468  3852  WebServices     WS error: The body of the received message contained a fault.
    2018/03/14 13:02:18.8834309 1468  3852  WebServices     WS error: System.Web.Services.Protocols.SoapException: Server was unable to process request. ---> System.TypeInitializationException: The type initializer for 'Microsoft.UpdateServices.Internal.Reporting.WebService' threw an exception. ---> System.Data.SqlClient.SqlException: Login failed for user 'NT AUTHORITY\NETWORK SERVICE'. Reason: Server is in script upgrade mode. Only administrator can connect at this time.    at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)    at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)    at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionIn

    And eventually, the server appears to turn to Microsoft Update and grab everything, even the stuff that was not approved on my WSUS server.

    2018/03/14 13:02:18.8834336 1468  3852  WebServices     WS Error code: Server
    2018/03/14 13:02:18.8834493 1468  3852  WebServices     WS error: <detail/>
    2018/03/14 13:09:44.4468091 1468  3588  Agent           Earliest future timer found:
    2018/03/14 13:09:44.4468206 1468  3588  Agent               Timer: 29A863E7-8609-4D1E-B7CD-5668F857F1DB, Expires 2018-03-15 14:35:03, not idle-only, not network-only
    2018/03/14 13:09:44.4488773 1468  3588  Misc            CreateSessionStateChangeTrigger, TYPE:2, Enable:No
    2018/03/14 13:09:44.4488799 1468  3588  Misc            CreateSessionStateChangeTrigger, TYPE:4, Enable:No
    2018/03/14 13:09:44.4843954 1468  3588  Handler         CUHCbsHandler::CancelDownloadRequest called
    2018/03/14 13:09:44.4847742 1468  3588  Agent           Sending shutdown notification to client
    2018/03/14 13:09:44.4847937 1468  3588  Agent           Sending shutdown notification to client
    2018/03/14 13:09:44.4848087 1468  3588  Agent           Sending shutdown notification to client
    2018/03/14 13:09:44.4855201 1468  3588  Agent               Timer: 9482F4B4-E343-43B6-B170-9A65BC822C77, Expires 2018-03-14 16:49:24, not idle-only, <NULL>network-only
    2018/03/14 13:09:44.7397156 1468  3588  Shared          * END * Service exit Exit code = 0x240001
    2018/03/14 13:09:47.8536179 1468  1704  Shared          * START * Service startup
    2018/03/14 13:09:47.8843192 1468  1704  Agent           WU client version 10.0.14393.2097
    2018/03/14 13:09:47.8844897 1468  1704  Agent           SleepStudyTracker: Machine is non-AOAC. Sleep study tracker disabled.
    2018/03/14 13:09:47.8845447 1468  1704  Agent           Base directory: C:\Windows\SoftwareDistribution
    2018/03/14 13:09:47.8853330 1468  1704  Agent           Datastore directory: C:\Windows\SoftwareDistribution\DataStore\DataStore.edb
    2018/03/14 13:09:48.9273833 1468  1704  DataStore       Service 3DA21691-E39D-4DA6-8A4B-B43877BCB1B7 added
    2018/03/14 13:09:48.9583280 1468  1704  DataStore       Service 9482F4B4-E343-43B6-B170-9A65BC822C77 added
    2018/03/14 13:09:48.9600603 1468  1704  DataStore       Data store successfully created
    2018/03/14 13:09:48.9602691 1468  1704  Shared          UpdateNetworkState Ipv6, cNetworkInterfaces = 1.
    2018/03/14 13:09:48.9602860 1468  1704  Shared          UpdateNetworkState Ipv4, cNetworkInterfaces = 1.
    2018/03/14 13:09:48.9606658 1468  1704  Shared          Network state: Connected
    2018/03/14 13:09:49.0323374 1468  1704  Misc            LoadHistoryEventFromRegistry completed, hr = 8024000C
    2018/03/14 13:09:49.0468937 1468  1704  Shared          UpdateNetworkState Ipv6, cNetworkInterfaces = 1.
    2018/03/14 13:09:49.0468990 1468  1704  Shared          UpdateNetworkState Ipv4, cNetworkInterfaces = 1.
    2018/03/14 13:09:49.0469043 1468  1704  Shared          Power status changed
    2018/03/14 13:09:49.0522430 1468  1704  Agent           Initializing global settings cache
    2018/03/14 13:09:49.0522436 1468  1704  Agent           WSUS server: http://<MYWSUSSERVER>.domain.com:8530/
    2018/03/14 13:09:49.0522441 1468  1704  Agent           WSUS status server: http://<MYWSUSSERVER>.domain.com:8530/
    2018/03/14 13:09:49.0522444 1468  1704  Agent           Alternate Download Server: NULL
    2018/03/14 13:09:49.0522448 1468  1704  Agent           Fill Empty Content Urls: No
    2018/03/14 13:09:49.0522451 1468  1704  Agent           Target group: Datacenter
    2018/03/14 13:09:49.0522455 1468  1704  Agent           Windows Update access disabled: No
    2018/03/14 13:09:49.3066203 1468  1704  Agent           Initializing Windows Update Agent
    2018/03/14 13:09:49.3067279 1468  1704  DownloadManager Download manager restoring 0 downloads
    2018/03/14 13:09:49.3068042 1468  1704  Agent           CPersistentTimeoutScheduler | GetTimer, returned hr = 0x80248007
    2018/03/14 13:09:49.3068119 1468  1704  Agent           CPersistentTimeoutEvent | Resubscribe, no existing/cached timer for Id=29A863E7-8609-4D1E-B7CD-5668F857F1DB.
    2018/03/14 13:09:49.3068133 1468  1704  Agent           Adding timer:
    2018/03/14 13:09:49.3068216 1468  1704  Agent               Timer: 29A863E7-8609-4D1E-B7CD-5668F857F1DB, Expires 2018-03-15 17:09:49, not idle-only, not network-only
    2018/03/14 13:09:49.3104577 1468  6692  Shared          Effective power state: AC
    2018/03/14 13:09:49.3104584 1468  6692  DownloadManager Power state change detected. Source now: AC
    1600/12/31 19:00:00.0000000 3340  2224                  Unknown( 10): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 3340  2224                  Unknown( 11): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:09:58.4064618 1468  1344  Agent           * START * Queueing Finding updates [CallerId = <<PROCESS>>: powershell.exe  Id = 1]
    2018/03/14 13:09:58.4064669 1468  1344  Agent           Added service 00000000-0000-0000-0000-000000000000 to sequential scan list
    1600/12/31 19:00:00.0000000 3340  2224                  Unknown( 12): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:09:58.4107507 1468  4552  Agent           * END * Queueing Finding updates [CallerId = <<PROCESS>>: powershell.exe  Id = 1]
    2018/03/14 13:09:58.4146318 1468  4552  Agent           * START * Finding updates CallerId = <<PROCESS>>: powershell.exe  Id = 1
    2018/03/14 13:09:58.4146327 1468  4552  Agent           Online = Yes; AllowCachedResults = No; Ignore download priority = No
    2018/03/14 13:09:58.4146332 1468  4552  Agent           Criteria = Type='Software'""
    2018/03/14 13:09:58.4146359 1468  4552  Agent           ServiceID = {00000000-0000-0000-0000-000000000000} Third party service
    2018/03/14 13:09:58.4146364 1468  4552  Agent           Search Scope = {Machine}
    2018/03/14 13:09:58.4146383 1468  4552  Agent           Caller SID for Applicability: S-1-5-18
    2018/03/14 13:09:58.4146387 1468  4552  Agent           RegisterService is set
    1600/12/31 19:00:00.0000000 1468  4552                  Unknown( 38): GUID=adf11b8c-baac-3d44-1059-4f8c843b025a (No Format Information found).
    2018/03/14 13:09:58.4203952 1468  4552  SLS             Retrieving SLS response from server...
    2018/03/14 13:09:58.4208756 1468  4552  SLS             Making request with URL HTTPS://sls.update.microsoft.com/SLS/{9482F4B4-E343-43B6-B170-9A65BC822C77}/x64/10.0.14393.0/0?CH=636&L=en-US&P=&PT=0x7&WUA=10.0.14393.2097
    2018/03/14 13:09:58.7560537 1468  4552  Misc            Validating signature for C:\Windows\SoftwareDistribution\SLS\9482F4B4-E343-43B6-B170-9A65BC822C77\sls.cab with dwProvFlags 0x00000080:
    2018/03/14 13:09:58.7630975 1468  4552  Misc             Microsoft signed: NA
    2018/03/14 13:09:58.7631521 1468  4552  Misc             Infrastructure signed: Yes
    2018/03/14 13:09:58.7674291 1468  4552  Misc            Validating signature for C:\Windows\SoftwareDistribution\SLS\9482F4B4-E343-43B6-B170-9A65BC822C77\TMP2A74.tmp with dwProvFlags 0x00000080:
    2018/03/14 13:09:58.7711139 1468  4552  Misc             Microsoft signed: NA
    2018/03/14 13:09:58.7711629 1468  4552  Misc             Infrastructure signed: Yes
    2018/03/14 13:09:58.7730995 1468  4552  Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir SecondaryServiceAuth URL: 117cab2d-82b1-4b5a-a08c-4d62dbee7782""
    2018/03/14 13:09:58.7741064 1468  4552  SLS             CoCreateInstance Failed: hr = 0x80040154
    2018/03/14 13:09:58.7741084 1468  4552  Agent           Failed to retrieve SLS response data for service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, error = 0x80040154
    2018/03/14 13:09:58.7741104 1468  4552  Agent           Caller Service Recovery failed to opt in to service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, hr=0X80040154
    2018/03/14 13:09:58.7748751 1468  4552  Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir Client/Server URL: https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx""
    2018/03/14 13:09:59.2850847 1468  4552  ProtocolTalker  ServiceId = {9482F4B4-E343-43B6-B170-9A65BC822C77}, Server URL = https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx
    2018/03/14 13:09:59.2850934 1468  4552  ProtocolTalker  PT: Calling GetConfig on server
    2018/03/14 13:09:59.2851094 1468  4552  WebServices     Auto proxy settings for this web service call.
    2018/03/14 13:09:59.4685604 1468  4552  ProtocolTalker  PT: Service supports GetConfig2, Calling GetConfig2 on server
    2018/03/14 13:09:59.5163604 1468  4552  ProtocolTalker  Cached cookie has expired or new PID is available
    2018/03/14 13:09:59.5163722 1468  4552  ProtocolTalker  PTWarn: Anonymous plug-in skipped for WU
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=fe1b6309-dedb-392e-308c-ec757efded1a (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=fe1b6309-dedb-392e-308c-ec757efded1a (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 11): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:10:12.8764837 1468  6500  Agent           * START * Queueing Finding updates [CallerId = UpdateOrchestrator  Id = 2]
    2018/03/14 13:10:12.8764960 1468  6500  Agent           Service 3DA21691-E39D-4DA6-8A4B-B43877BCB1B7 is not in sequential scan list
    2018/03/14 13:10:12.8765014 1468  6500  Agent           Added service 3DA21691-E39D-4DA6-8A4B-B43877BCB1B7 to sequential scan list
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 12): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:31.5713303 1468  4552  ProtocolTalker  PTInfo: syncing with server using normal query
    2018/03/14 13:13:31.6190906 1468  4552  ProtocolTalker  SyncUpdates round trips: 19
    2018/03/14 13:13:42.3310220 1468  4552  ProtocolTalker  ServiceId = {9482F4B4-E343-43B6-B170-9A65BC822C77}, Server URL = https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx
    2018/03/14 13:13:42.3310239 1468  4552  ProtocolTalker  OK to reuse existing configuration
    2018/03/14 13:13:42.3310270 1468  4552  ProtocolTalker  Existing cookie is valid, just use it
    2018/03/14 13:13:44.9003256 1468  4552  Agent           Added update 17170AE7-705A-4073-8DCE-375BD8D61864.201 to search result
    2018/03/14 13:13:44.9003291 1468  4552  Agent           Added update 4064FC9E-46F4-4E2D-9A65-E67479754CD0.200 to search result
    2018/03/14 13:13:44.9003323 1468  4552  Agent           Added update 17557D88-C388-40FE-9AD7-0E3B357F727B.200 to search result
    2018/03/14 13:13:44.9003355 1468  4552  Agent           Added update A873372B-7A5C-443C-8022-CD59A550BEF4.201 to search result
    2018/03/14 13:13:44.9003403 1468  4552  Agent           Added update A0F997B1-1ABE-4A46-941F-B37F732F9FBD.201 to search result
    2018/03/14 13:13:44.9003433 1468  4552  Agent           Added update 685F03C4-8329-4A6E-BB32-9558ABCA8906.201 to search result
    2018/03/14 13:13:44.9003455 1468  4552  Agent           Update 3E4E12B4-7338-4825-9D05-34863B24B570.201 is pruned out due to potential supersedence
    2018/03/14 13:13:44.9003483 1468  4552  Agent           Added update 9651955D-C815-4CAD-BCBD-90EEF858E67B.200 to search result
    2018/03/14 13:13:44.9003513 1468  4552  Agent           Added update 9DCB114A-30A2-4455-96C0-EE3057CBCA8A.201 to search result
    2018/03/14 13:13:44.9003569 1468  4552  Agent           Added update 5DC25E3E-31B9-4AC7-B1B7-A62A9821390D.202 to search result
    2018/03/14 13:13:44.9003765 1468  4552  Agent           Added update 35B857F9-0C05-43BF-85C4-CE4D75E7947C.200 to search result
    2018/03/14 13:13:44.9003986 1468  4552  Agent           Found 10 updates and 20 categories in search; evaluated appl. rules of 663 out of 1003 deployed entities
    2018/03/14 13:13:44.9192083 1468  4552  Agent           * END * Finding updates CallerId = <<PROCESS>>: powershell.exe  Id = 1
    2018/03/14 13:13:44.9668650 1468  3644  Agent           Service 3DA21691-E39D-4DA6-8A4B-B43877BCB1B7 is in sequential scan list
    2018/03/14 13:13:44.9709049 1468  200   Agent           * END * Queueing Finding updates [CallerId = UpdateOrchestrator  Id = 2]

    I'm at a loss on this one and I can't seem to find anywhere else on the net that a similar situation to this has been answered, so I am posting.

    Wednesday, March 14, 2018 6:56 PM

All replies

  • Here are some further logs showing that the update client proceeded to download an unapproved update and download it.

    2018/03/14 13:13:44.9747952 1468  200   Agent           * START * Finding updates CallerId = UpdateOrchestrator  Id = 2
    2018/03/14 13:13:44.9747961 1468  200   Agent           Online = Yes; AllowCachedResults = No; Ignore download priority = No
    2018/03/14 13:13:44.9747971 1468  200   Agent           Criteria = IsInstalled=0 and DeploymentAction='Installation' or IsPresent=1 and DeploymentAction='Uninstallation' or IsInstalled=1 and DeploymentAction='Installation' and RebootRequired=1 or IsInstalled=0 and DeploymentAction='Uninstallation' and RebootRequired=1""
    2018/03/14 13:13:44.9748005 1468  200   Agent           ServiceID = {3DA21691-E39D-4DA6-8A4B-B43877BCB1B7} Managed
    2018/03/14 13:13:44.9748010 1468  200   Agent           Search Scope = {Machine}
    2018/03/14 13:13:44.9748036 1468  200   Agent           Caller SID for Applicability: S-1-5-21-787576246-839995514-475923621-56991
    2018/03/14 13:13:44.9748042 1468  200   Agent           ProcessDriverDeferrals is set
    2018/03/14 13:13:44.9748046 1468  200   Agent           RegisterService is set
    2018/03/14 13:13:44.9757700 1468  200   Agent           Unable to query IsInventoryRequired service property, hr=0x8024043D
    2018/03/14 13:13:44.9769305 1468  200   Agent           Blocking Windows content for WUfB
    2018/03/14 13:13:44.9881091 1468  200   Misc            Got WSUS Client/Server URL: http://<MYWSUSSERVER>.domain.com:8530/ClientWebService/client.asmx""
    2018/03/14 13:13:45.3496942 1468  200   ProtocolTalker  ServiceId = {3DA21691-E39D-4DA6-8A4B-B43877BCB1B7}, Server URL = http://<MYWSUSSERVER>.domain.com:8530/ClientWebService/client.asmx
    2018/03/14 13:13:45.3498057 1468  200   ProtocolTalker  PT: Calling GetConfig on server
    2018/03/14 13:13:45.3498278 1468  200   WebServices     Auto proxy settings for this web service call.
    2018/03/14 13:13:45.3536121 1468  200   ProtocolTalker  Cached cookie has expired or new PID is available
    2018/03/14 13:13:45.3536199 1468  200   Misc            Got WSUS SimpleTargeting URL: http://<MYWSUSSERVER>.domain.com:8530/""
    2018/03/14 13:13:45.3538007 1468  200   ProtocolTalker  Initializing simple targeting cookie, clientId = d4bc00fd-0dde-4cb0-8c4f-0c9b13567b70, target group = Datacenter, DNS name = <MYWSUSSERVER>.domain.com
    2018/03/14 13:13:45.3538015 1468  200   ProtocolTalker    Server URL = http://<MYWSUSSERVER>.domain.com:8530/SimpleAuthWebService/SimpleAuth.asmx
    2018/03/14 13:13:45.3653313 1468  200   WebServices     Auto proxy settings for this web service call.
    2018/03/14 13:13:45.4112519 1468  200   ProtocolTalker  PTInfo: Server requested registration
    2018/03/14 13:13:45.4187191 1468  200   ProtocolTalker  PTInfo: Calling RegisterComputer
    1600/12/31 19:00:00.0000000 3340  1920                  Unknown( 16): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 3340  1920                  Unknown( 17): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 3340  1920                  Unknown( 20): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:45.9674444 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    1600/12/31 19:00:00.0000000 3340  2224                  Unknown( 10): GUID=fe1b6309-dedb-392e-308c-ec757efded1a (No Format Information found).
    2018/03/14 13:13:46.4298539 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:46.6613437 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:46.7467502 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:46.8527616 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.0215918 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.0796338 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.1298118 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.1563887 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.1815806 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.2120465 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.2670172 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.3162717 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.3518571 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.3787705 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.7557543 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.7910004 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.8227209 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.9605590 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:47.9901363 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:48.0156660 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:48.0224125 1468  200   ProtocolTalker  PTInfo: syncing with server using normal query
    2018/03/14 13:13:48.0259752 1468  200   ProtocolTalker  SyncUpdates round trips: 25
    2018/03/14 13:13:48.0349981 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:48.0490484 1468  200   Agent           Update filtered by policy: 6964AAB4-C5B5-43BD-A17D-FFB4346A8E1D.100
    2018/03/14 13:13:48.0569197 1468  200   ProtocolTalker  ServiceId = {3DA21691-E39D-4DA6-8A4B-B43877BCB1B7}, Server URL = http://<MYWSUSSERVER>.domain.com:8530/ClientWebService/client.asmx
    2018/03/14 13:13:48.0569211 1468  200   ProtocolTalker  OK to reuse existing configuration
    2018/03/14 13:13:48.0569238 1468  200   ProtocolTalker  Existing cookie is valid, just use it
    2018/03/14 13:13:48.0569246 1468  200   ProtocolTalker  PTInfo: Server requested registration
    2018/03/14 13:13:48.1100370 1468  200   Agent           Found 0 updates and 81 categories in search; evaluated appl. rules of 296 out of 666 deployed entities
    2018/03/14 13:13:48.1307646 1468  200   Agent           * END * Finding updates CallerId = UpdateOrchestrator  Id = 2
    1600/12/31 19:00:00.0000000 1468  2000                  Unknown( 16): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  2000                  Unknown( 17): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  2000                  Unknown( 20): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=fe1b6309-dedb-392e-308c-ec757efded1a (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 11): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:48.1835358 1468  6500  Agent           * START * Queueing Finding updates [CallerId = UpdateOrchestrator  Id = 3]
    2018/03/14 13:13:48.1835414 1468  6500  Agent           Service 9482F4B4-E343-43B6-B170-9A65BC822C77 is not in sequential scan list
    2018/03/14 13:13:48.1835452 1468  6500  Agent           Added service 9482F4B4-E343-43B6-B170-9A65BC822C77 to sequential scan list
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 12): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:48.1836334 1468  3644  Agent           Service 9482F4B4-E343-43B6-B170-9A65BC822C77 is in sequential scan list
    2018/03/14 13:13:48.1882761 1468  5172  Agent           * END * Queueing Finding updates [CallerId = UpdateOrchestrator  Id = 3]
    2018/03/14 13:13:48.1927846 1468  5172  Agent           * START * Finding updates CallerId = UpdateOrchestrator  Id = 3
    2018/03/14 13:13:48.1927855 1468  5172  Agent           Online = Yes; AllowCachedResults = No; Ignore download priority = No
    2018/03/14 13:13:48.1927865 1468  5172  Agent           Criteria = IsInstalled=0 and DeploymentAction='Installation' or IsPresent=1 and DeploymentAction='Uninstallation' or IsInstalled=1 and DeploymentAction='Installation' and RebootRequired=1 or IsInstalled=0 and DeploymentAction='Uninstallation' and RebootRequired=1""
    2018/03/14 13:13:48.1927898 1468  5172  Agent           ServiceID = {9482F4B4-E343-43B6-B170-9A65BC822C77} Windows Update
    2018/03/14 13:13:48.1927902 1468  5172  Agent           Search Scope = {Machine}
    2018/03/14 13:13:48.1927925 1468  5172  Agent           Caller SID for Applicability: S-1-5-21-787576246-839995514-475923621-56991
    2018/03/14 13:13:48.1927930 1468  5172  Agent           ProcessDriverDeferrals is set
    2018/03/14 13:13:48.1927933 1468  5172  Agent           RegisterService is set
    2018/03/14 13:13:48.1963651 1468  5172  Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir SecondaryServiceAuth URL: 117cab2d-82b1-4b5a-a08c-4d62dbee7782""
    2018/03/14 13:13:48.1973573 1468  5172  SLS             CoCreateInstance Failed: hr = 0x80040154
    2018/03/14 13:13:48.1973594 1468  5172  Agent           Failed to retrieve SLS response data for service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, error = 0x80040154
    2018/03/14 13:13:48.1973616 1468  5172  Agent           Caller Service Recovery failed to opt in to service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, hr=0X80040154
    2018/03/14 13:13:48.1980569 1468  5172  Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir Client/Server URL: https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx""
    2018/03/14 13:13:48.2848310 1468  5172  ProtocolTalker  ServiceId = {9482F4B4-E343-43B6-B170-9A65BC822C77}, Server URL = https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx
    2018/03/14 13:13:48.2849814 1468  5172  ProtocolTalker  OK to reuse existing configuration
    2018/03/14 13:13:48.2849850 1468  5172  ProtocolTalker  Existing cookie is valid, just use it
    2018/03/14 13:13:48.6285095 1468  5172  WebServices     Auto proxy settings for this web service call.
    2018/03/14 13:13:48.8733390 1468  5172  ProtocolTalker  PTInfo: syncing with server using normal query
    2018/03/14 13:13:48.9614006 1468  5172  ProtocolTalker  SyncUpdates round trips: 2
    1600/12/31 19:00:00.0000000 6464  6056                  Unknown( 10): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 6464  6056                  Unknown( 11): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:52.7363697 1468  2468  Agent           * START * Queueing Finding updates [CallerId = <<PROCESS>>: powershell.exe  Id = 4]
    2018/03/14 13:13:52.7363742 1468  2468  Agent           Removing service 00000000-0000-0000-0000-000000000000 from sequential scan list
    2018/03/14 13:13:52.7363769 1468  2468  Agent           Added service 00000000-0000-0000-0000-000000000000 to sequential scan list
    1600/12/31 19:00:00.0000000 6464  6056                  Unknown( 12): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:59.9050464 1468  5172  Agent           Added update 9DCB114A-30A2-4455-96C0-EE3057CBCA8A.201 to search result
    2018/03/14 13:13:59.9050500 1468  5172  Agent           Added update 5DC25E3E-31B9-4AC7-B1B7-A62A9821390D.202 to search result
    2018/03/14 13:13:59.9050571 1468  5172  Agent           Found 2 updates and 20 categories in search; evaluated appl. rules of 663 out of 1003 deployed entities
    2018/03/14 13:13:59.9211201 1468  5172  Agent           * END * Finding updates CallerId = UpdateOrchestrator  Id = 3
    2018/03/14 13:13:59.9266392 1468  932   Agent           * END * Queueing Finding updates [CallerId = <<PROCESS>>: powershell.exe  Id = 4]
    1600/12/31 19:00:00.0000000 1468  1344                  Unknown( 16): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:59.9306363 1468  932   Agent           * START * Finding updates CallerId = <<PROCESS>>: powershell.exe  Id = 4
    2018/03/14 13:13:59.9306372 1468  932   Agent           Online = Yes; AllowCachedResults = No; Ignore download priority = No
    2018/03/14 13:13:59.9306378 1468  932   Agent           Criteria = Type='Software'""
    2018/03/14 13:13:59.9306404 1468  932   Agent           ServiceID = {00000000-0000-0000-0000-000000000000} Third party service
    2018/03/14 13:13:59.9306436 1468  932   Agent           Search Scope = {Machine}
    2018/03/14 13:13:59.9306458 1468  932   Agent           Caller SID for Applicability: S-1-5-18
    2018/03/14 13:13:59.9306463 1468  932   Agent           RegisterService is set
    2018/03/14 13:13:59.9369747 1468  932   Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir SecondaryServiceAuth URL: 117cab2d-82b1-4b5a-a08c-4d62dbee7782""
    2018/03/14 13:13:59.9379243 1468  932   SLS             CoCreateInstance Failed: hr = 0x80040154
    2018/03/14 13:13:59.9379264 1468  932   Agent           Failed to retrieve SLS response data for service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, error = 0x80040154
    2018/03/14 13:13:59.9379284 1468  932   Agent           Caller Service Recovery failed to opt in to service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, hr=0X80040154
    2018/03/14 13:13:59.9386577 1468  932   Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir Client/Server URL: https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx""
    2018/03/14 13:14:00.0184636 1468  932   ProtocolTalker  ServiceId = {9482F4B4-E343-43B6-B170-9A65BC822C77}, Server URL = https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx
    2018/03/14 13:14:00.0184729 1468  932   ProtocolTalker  OK to reuse existing configuration
    2018/03/14 13:14:00.0184758 1468  932   ProtocolTalker  Existing cookie is valid, just use it
    1600/12/31 19:00:00.0000000 1468  1344                  Unknown( 17): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  1344                  Unknown( 20): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:14:00.3146497 1468  932   WebServices     Auto proxy settings for this web service call.
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=fe1b6309-dedb-392e-308c-ec757efded1a (No Format Information found).
    2018/03/14 13:14:00.5606902 1468  932   ProtocolTalker  PTInfo: syncing with server using normal query
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 11): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 12): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 13): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 14): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    2018/03/14 13:14:00.6073273 1468  6692  Shared          Effective power state: AC
    2018/03/14 13:14:00.6073341 1468  6692  Agent           Obtained a network PDC reference for callID {D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556} with No-Progress-Timeout set to 4294967295; ActivationID: 177.
    2018/03/14 13:14:00.6079074 1468  6692  DownloadManager * START * Begin Downloading Updates [CallerId = UpdateOrchestrator] [Call ID = D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556]
    2018/03/14 13:14:00.6079101 1468  6692  DownloadManager Priority = 3, NetworkCostPolicy = 0, Interactive = 1, Download on Battery = 1, Bypass Regulation = 1, Owner is system = 1, Proxy session id = 1, ServiceId = 9482F4B4-E343-43B6-B170-9A65BC822C77
    2018/03/14 13:14:00.6079106 1468  6692  DownloadManager Updates to download = 1
    2018/03/14 13:14:00.6079111 1468  6692  Agent             Title = Windows Malicious Software Removal Tool x64 - March 2018 (KB890830)
    2018/03/14 13:14:00.6079139 1468  6692  Agent             UpdateId = 9DCB114A-30A2-4455-96C0-EE3057CBCA8A.201
    2018/03/14 13:14:00.6079143 1468  6692  Agent               Bundles 1 updates:
    2018/03/14 13:14:00.6079166 1468  6692  Agent                 1646D819-86C1-4A05-A33D-17220837A4D7.201
    2018/03/14 13:14:00.6079357 1468  6692  DownloadManager No locked revisions found for update 9DCB114A-30A2-4455-96C0-EE3057CBCA8A; locking the user-specified revision.
    2018/03/14 13:14:00.6085654 1468  6692  DownloadManager No locked revisions found for update 1646D819-86C1-4A05-A33D-17220837A4D7; locking the user-specified revision.
    2018/03/14 13:14:00.6091025 1468  6692  DownloadManager Regulation: {9482F4B4-E343-43B6-B170-9A65BC822C77} - Loaded sequence number 65535 for regulation category PerUpdate.
    2018/03/14 13:14:00.6091031 1468  6692  DownloadManager Regulation: {9482F4B4-E343-43B6-B170-9A65BC822C77} - Loaded sequence number 65535 for regulation category Low.
    2018/03/14 13:14:00.6091035 1468  6692  DownloadManager Regulation: {9482F4B4-E343-43B6-B170-9A65BC822C77} - Loaded sequence number 65535 for regulation category Normal.
    2018/03/14 13:14:00.6091041 1468  6692  DownloadManager Regulation: {9482F4B4-E343-43B6-B170-9A65BC822C77} - Loaded sequence number 65535 for regulation category High.
    2018/03/14 13:14:00.6517864 1468  6692  DownloadManager Failed to connect to the DO service; (hr = 80040154)
    2018/03/14 13:14:00.6517872 1468  6692  DownloadManager GetDOManager() failed, hr=80246008, hrExtended=80040154
    2018/03/14 13:14:00.6517879 1468  6692  DownloadManager Failed creating DO job with hr 80246008
    2018/03/14 13:14:00.6544905 1468  6692  DownloadManager DO download failed with error 80246008[Extended: 80040154], falling back to BITS and retrying with new Download Job.
    2018/03/14 13:14:00.6832673 1468  932   ProtocolTalker  SyncUpdates round trips: 2
    2018/03/14 13:14:00.9248336 1468  6692  DownloadManager BITS job initialized: JobId = {55BCFE05-F2EF-460A-BD5C-697A087AB6AE}
    2018/03/14 13:14:00.9517398 1468  6692  DownloadManager Downloading from http://download.windowsupdate.com/c/msdownload/update/software/uprl/2018/03/windows-kb890830-x64-v5.58-delta_3ea3c19c7ffec04e47df1375c28aaf6d56bff6d4.exe to C:\Windows\SoftwareDistribution\Download\d4f39899188c3476bbfe7c02d44ec5ef\3ea3c19c7ffec04e47df1375c28aaf6d56bff6d4 (full file)
    2018/03/14 13:14:00.9531354 1468  6692  DownloadManager New download job {55BCFE05-F2EF-460A-BD5C-697A087AB6AE} for UpdateId 1646D819-86C1-4A05-A33D-17220837A4D7.201
    2018/03/14 13:14:00.9685289 1468  6692  DownloadManager Download job 55BCFE05-F2EF-460A-BD5C-697A087AB6AE resumed.
    2018/03/14 13:14:01.0966327 1468  6692  Shared          Effective power state: AC
    2018/03/14 13:14:01.0966374 1468  6692  Agent           Released network PDC reference for callId {D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556}; ActivationID: 177
    2018/03/14 13:14:01.0966420 1468  6692  Agent           Obtained a network PDC reference for callID {D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556} with No-Progress-Timeout set to 4294967295; ActivationID: 178.
    2018/03/14 13:14:01.0968154 1468  1176  Agent           WU client calls back to download call {D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556} with code Call progress and error 0
    2018/03/14 13:14:01.0976259 1468  6692  DownloadManager * END * Begin Downloading Updates CallerId = UpdateOrchestrator

    It seems that the DownloadManager is failing over to BITS and then after that it does what it feels like.

    2018/03/14 13:13:48.1927846 1468  5172  Agent           * START * Finding updates CallerId = UpdateOrchestrator  Id = 3
    2018/03/14 13:13:48.1927855 1468  5172  Agent           Online = Yes; AllowCachedResults = No; Ignore download priority = No
    2018/03/14 13:13:48.1927865 1468  5172  Agent           Criteria = IsInstalled=0 and DeploymentAction='Installation' or IsPresent=1 and DeploymentAction='Uninstallation' or IsInstalled=1 and DeploymentAction='Installation' and RebootRequired=1 or IsInstalled=0 and DeploymentAction='Uninstallation' and RebootRequired=1""
    2018/03/14 13:13:48.1927898 1468  5172  Agent           ServiceID = {9482F4B4-E343-43B6-B170-9A65BC822C77} Windows Update
    2018/03/14 13:13:48.1927902 1468  5172  Agent           Search Scope = {Machine}
    2018/03/14 13:13:48.1927925 1468  5172  Agent           Caller SID for Applicability: S-1-5-21-787576246-839995514-475923621-56991
    2018/03/14 13:13:48.1927930 1468  5172  Agent           ProcessDriverDeferrals is set
    2018/03/14 13:13:48.1927933 1468  5172  Agent           RegisterService is set
    2018/03/14 13:13:48.1963651 1468  5172  Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir SecondaryServiceAuth URL: 117cab2d-82b1-4b5a-a08c-4d62dbee7782""
    2018/03/14 13:13:48.1973573 1468  5172  SLS             CoCreateInstance Failed: hr = 0x80040154
    2018/03/14 13:13:48.1973594 1468  5172  Agent           Failed to retrieve SLS response data for service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, error = 0x80040154
    2018/03/14 13:13:48.1973616 1468  5172  Agent           Caller Service Recovery failed to opt in to service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, hr=0X80040154
    2018/03/14 13:13:48.1980569 1468  5172  Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir Client/Server URL: https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx""
    2018/03/14 13:13:48.2848310 1468  5172  ProtocolTalker  ServiceId = {9482F4B4-E343-43B6-B170-9A65BC822C77}, Server URL = https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx
    2018/03/14 13:13:48.2849814 1468  5172  ProtocolTalker  OK to reuse existing configuration
    2018/03/14 13:13:48.2849850 1468  5172  ProtocolTalker  Existing cookie is valid, just use it
    2018/03/14 13:13:48.6285095 1468  5172  WebServices     Auto proxy settings for this web service call.
    2018/03/14 13:13:48.8733390 1468  5172  ProtocolTalker  PTInfo: syncing with server using normal query
    2018/03/14 13:13:48.9614006 1468  5172  ProtocolTalker  SyncUpdates round trips: 2
    1600/12/31 19:00:00.0000000 6464  6056                  Unknown( 10): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 6464  6056                  Unknown( 11): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:52.7363697 1468  2468  Agent           * START * Queueing Finding updates [CallerId = <<PROCESS>>: powershell.exe  Id = 4]
    2018/03/14 13:13:52.7363742 1468  2468  Agent           Removing service 00000000-0000-0000-0000-000000000000 from sequential scan list
    2018/03/14 13:13:52.7363769 1468  2468  Agent           Added service 00000000-0000-0000-0000-000000000000 to sequential scan list
    1600/12/31 19:00:00.0000000 6464  6056                  Unknown( 12): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:59.9050464 1468  5172  Agent           Added update 9DCB114A-30A2-4455-96C0-EE3057CBCA8A.201 to search result
    2018/03/14 13:13:59.9050500 1468  5172  Agent           Added update 5DC25E3E-31B9-4AC7-B1B7-A62A9821390D.202 to search result
    2018/03/14 13:13:59.9050571 1468  5172  Agent           Found 2 updates and 20 categories in search; evaluated appl. rules of 663 out of 1003 deployed entities
    2018/03/14 13:13:59.9211201 1468  5172  Agent           * END * Finding updates CallerId = UpdateOrchestrator  Id = 3
    2018/03/14 13:13:59.9266392 1468  932   Agent           * END * Queueing Finding updates [CallerId = <<PROCESS>>: powershell.exe  Id = 4]
    1600/12/31 19:00:00.0000000 1468  1344                  Unknown( 16): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:13:59.9306363 1468  932   Agent           * START * Finding updates CallerId = <<PROCESS>>: powershell.exe  Id = 4
    2018/03/14 13:13:59.9306372 1468  932   Agent           Online = Yes; AllowCachedResults = No; Ignore download priority = No
    2018/03/14 13:13:59.9306378 1468  932   Agent           Criteria = Type='Software'""
    2018/03/14 13:13:59.9306404 1468  932   Agent           ServiceID = {00000000-0000-0000-0000-000000000000} Third party service
    2018/03/14 13:13:59.9306436 1468  932   Agent           Search Scope = {Machine}
    2018/03/14 13:13:59.9306458 1468  932   Agent           Caller SID for Applicability: S-1-5-18
    2018/03/14 13:13:59.9306463 1468  932   Agent           RegisterService is set
    2018/03/14 13:13:59.9369747 1468  932   Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir SecondaryServiceAuth URL: 117cab2d-82b1-4b5a-a08c-4d62dbee7782""
    2018/03/14 13:13:59.9379243 1468  932   SLS             CoCreateInstance Failed: hr = 0x80040154
    2018/03/14 13:13:59.9379264 1468  932   Agent           Failed to retrieve SLS response data for service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, error = 0x80040154
    2018/03/14 13:13:59.9379284 1468  932   Agent           Caller Service Recovery failed to opt in to service 117cab2d-82b1-4b5a-a08c-4d62dbee7782, hr=0X80040154
    2018/03/14 13:13:59.9386577 1468  932   Misc            Got 9482F4B4-E343-43B6-B170-9A65BC822C77 redir Client/Server URL: https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx""
    2018/03/14 13:14:00.0184636 1468  932   ProtocolTalker  ServiceId = {9482F4B4-E343-43B6-B170-9A65BC822C77}, Server URL = https://fe2.update.microsoft.com/v6/ClientWebService/client.asmx
    2018/03/14 13:14:00.0184729 1468  932   ProtocolTalker  OK to reuse existing configuration
    2018/03/14 13:14:00.0184758 1468  932   ProtocolTalker  Existing cookie is valid, just use it
    1600/12/31 19:00:00.0000000 1468  1344                  Unknown( 17): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  1344                  Unknown( 20): GUID=eb73583d-5481-33b4-202d-9bb270eddffa (No Format Information found).
    2018/03/14 13:14:00.3146497 1468  932   WebServices     Auto proxy settings for this web service call.
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=fe1b6309-dedb-392e-308c-ec757efded1a (No Format Information found).
    2018/03/14 13:14:00.5606902 1468  932   ProtocolTalker  PTInfo: syncing with server using normal query
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 11): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 12): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 13): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 14): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    2018/03/14 13:14:00.6073273 1468  6692  Shared          Effective power state: AC
    2018/03/14 13:14:00.6073341 1468  6692  Agent           Obtained a network PDC reference for callID {D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556} with No-Progress-Timeout set to 4294967295; ActivationID: 177.
    2018/03/14 13:14:00.6079074 1468  6692  DownloadManager * START * Begin Downloading Updates [CallerId = UpdateOrchestrator] [Call ID = D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556]
    2018/03/14 13:14:00.6079101 1468  6692  DownloadManager Priority = 3, NetworkCostPolicy = 0, Interactive = 1, Download on Battery = 1, Bypass Regulation = 1, Owner is system = 1, Proxy session id = 1, ServiceId = 9482F4B4-E343-43B6-B170-9A65BC822C77
    2018/03/14 13:14:00.6079106 1468  6692  DownloadManager Updates to download = 1
    2018/03/14 13:14:00.6079111 1468  6692  Agent             Title = Windows Malicious Software Removal Tool x64 - March 2018 (KB890830)
    2018/03/14 13:14:00.6079139 1468  6692  Agent             UpdateId = 9DCB114A-30A2-4455-96C0-EE3057CBCA8A.201
    2018/03/14 13:14:00.6079143 1468  6692  Agent               Bundles 1 updates:
    2018/03/14 13:14:00.6079166 1468  6692  Agent                 1646D819-86C1-4A05-A33D-17220837A4D7.201
    2018/03/14 13:14:00.6079357 1468  6692  DownloadManager No locked revisions found for update 9DCB114A-30A2-4455-96C0-EE3057CBCA8A; locking the user-specified revision.
    2018/03/14 13:14:00.6085654 1468  6692  DownloadManager No locked revisions found for update 1646D819-86C1-4A05-A33D-17220837A4D7; locking the user-specified revision.
    2018/03/14 13:14:00.6091025 1468  6692  DownloadManager Regulation: {9482F4B4-E343-43B6-B170-9A65BC822C77} - Loaded sequence number 65535 for regulation category PerUpdate.
    2018/03/14 13:14:00.6091031 1468  6692  DownloadManager Regulation: {9482F4B4-E343-43B6-B170-9A65BC822C77} - Loaded sequence number 65535 for regulation category Low.
    2018/03/14 13:14:00.6091035 1468  6692  DownloadManager Regulation: {9482F4B4-E343-43B6-B170-9A65BC822C77} - Loaded sequence number 65535 for regulation category Normal.
    2018/03/14 13:14:00.6091041 1468  6692  DownloadManager Regulation: {9482F4B4-E343-43B6-B170-9A65BC822C77} - Loaded sequence number 65535 for regulation category High.
    2018/03/14 13:14:00.6517864 1468  6692  DownloadManager Failed to connect to the DO service; (hr = 80040154)
    2018/03/14 13:14:00.6517872 1468  6692  DownloadManager GetDOManager() failed, hr=80246008, hrExtended=80040154
    2018/03/14 13:14:00.6517879 1468  6692  DownloadManager Failed creating DO job with hr 80246008
    2018/03/14 13:14:00.6544905 1468  6692  DownloadManager DO download failed with error 80246008[Extended: 80040154], falling back to BITS and retrying with new Download Job.
    2018/03/14 13:14:00.6832673 1468  932   ProtocolTalker  SyncUpdates round trips: 2
    2018/03/14 13:14:00.9248336 1468  6692  DownloadManager BITS job initialized: JobId = {55BCFE05-F2EF-460A-BD5C-697A087AB6AE}
    2018/03/14 13:14:00.9517398 1468  6692  DownloadManager Downloading from http://download.windowsupdate.com/c/msdownload/update/software/uprl/2018/03/windows-kb890830-x64-v5.58-delta_3ea3c19c7ffec04e47df1375c28aaf6d56bff6d4.exe to C:\Windows\SoftwareDistribution\Download\d4f39899188c3476bbfe7c02d44ec5ef\3ea3c19c7ffec04e47df1375c28aaf6d56bff6d4 (full file)
    2018/03/14 13:14:00.9531354 1468  6692  DownloadManager New download job {55BCFE05-F2EF-460A-BD5C-697A087AB6AE} for UpdateId 1646D819-86C1-4A05-A33D-17220837A4D7.201
    2018/03/14 13:14:00.9685289 1468  6692  DownloadManager Download job 55BCFE05-F2EF-460A-BD5C-697A087AB6AE resumed.
    2018/03/14 13:14:01.0966327 1468  6692  Shared          Effective power state: AC
    2018/03/14 13:14:01.0966374 1468  6692  Agent           Released network PDC reference for callId {D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556}; ActivationID: 177
    2018/03/14 13:14:01.0966420 1468  6692  Agent           Obtained a network PDC reference for callID {D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556} with No-Progress-Timeout set to 4294967295; ActivationID: 178.
    2018/03/14 13:14:01.0968154 1468  1176  Agent           WU client calls back to download call {D5F7F5EB-ABCB-4BB8-96F9-EE752ECE6556} with code Call progress and error 0
    2018/03/14 13:14:01.0976259 1468  6692  DownloadManager * END * Begin Downloading Updates CallerId = UpdateOrchestrator
    2018/03/14 13:14:01.0986823 1468  6692  DownloadManager Download job 55BCFE05-F2EF-460A-BD5C-697A087AB6AE resumed.
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 10): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 11): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 12): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 13): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    1600/12/31 19:00:00.0000000 1468  6500                  Unknown( 14): GUID=aa07f95d-91be-3f47-51b3-717e4c7ddc98 (No Format Information found).
    2018/03/14 13:14:01.1411776 1468  6692  Shared          Effective power state: AC
    2018/03/14 13:14:01.1411861 1468  6692  Agent           Obtained a network PDC reference for callID {91254FB9-A7BB-41C5-ADFB-97250993E325} with No-Progress-Timeout set to 4294967295; ActivationID: 183.
    2018/03/14 13:14:01.1418655 1468  6692  DownloadManager * START * Begin Downloading Updates [CallerId = UpdateOrchestrator] [Call ID = 91254FB9-A7BB-41C5-ADFB-97250993E325]
    2018/03/14 13:14:01.1418682 1468  6692  DownloadManager Priority = 3, NetworkCostPolicy = 0, Interactive = 1, Download on Battery = 1, Bypass Regulation = 1, Owner is system = 1, Proxy session id = 1, ServiceId = 9482F4B4-E343-43B6-B170-9A65BC822C77
    2018/03/14 13:14:01.1418686 1468  6692  DownloadManager Updates to download = 1
    2018/03/14 13:14:01.1418692 1468  6692  Agent             Title = 2018-03 Cumulative Update for Windows Server 2016 for x64-based Systems (KB4088787)
    2018/03/14 13:14:01.1418719 1468  6692  Agent             UpdateId = 5DC25E3E-31B9-4AC7-B1B7-A62A9821390D.202
    2018/03/14 13:14:01.1418723 1468  6692  Agent               Bundles 1 updates:
    2018/03/14 13:14:01.1418748 1468  6692  Agent                 87D0215F-EDEC-40CA-879B-72A6F88BC84C.202
    2018/03/14 13:14:01.1418961 1468  6692  DownloadManager No locked revisions found for update 5DC25E3E-31B9-4AC7-B1B7-A62A9821390D; locking the user-specified revision.
    2018/03/14 13:14:01.1424671 1468  6692  DownloadManager No locked revisions found for update 87D0215F-EDEC-40CA-879B-72A6F88BC84C; locking the user-specified revision.
    2018/03/14 13:14:01.4025454 1468  6692  Handler         Loaded state: cCompleteIterations: 0, pt: Unknown, nNextRequestID: 0.
    2018/03/14 13:14:01.4047600 1468  6692  DownloadManager Download job 55BCFE05-F2EF-460A-BD5C-697A087AB6AE resumed.
    2018/03/14 13:14:01.4110913 1468  6692  DownloadManager Queueing update {87D0215F-EDEC-40CA-879B-72A6F88BC84C}.202 for download handler request generation.
    2018/03/14 13:14:01.6304588 1468  6692  Handler         Loaded state: cCompleteIterations: 0, pt: Unknown, nNextRequestID: 0.
    2018/03/14 13:14:01.6727776 1468  6692  Shared          Effective power state: AC
    2018/03/14 13:14:01.6727841 1468  6692  Agent           Released network PDC reference for callId {91254FB9-A7BB-41C5-ADFB-97250993E325}; ActivationID: 183
    2018/03/14 13:14:01.6727929 1468  6692  Agent           Obtained a network PDC reference for callID {91254FB9-A7BB-41C5-ADFB-97250993E325} with No-Progress-Timeout set to 4294967295; ActivationID: 184.
    2018/03/14 13:14:01.6729720 1468  1176  Agent           WU client calls back to download call {91254FB9-A7BB-41C5-ADFB-97250993E325} with code Call progress and error 0
    2018/03/14 13:14:01.6737846 1468  6692  DownloadManager * END * Begin Downloading Updates CallerId = UpdateOrchestrator

    • Edited by nichor0826 Wednesday, March 14, 2018 7:11 PM
    Wednesday, March 14, 2018 7:00 PM
  • on an affected client, run gpresult /h gpo.html and pastebin or attach the file to the post so that we can have a look. 99 times out of 100, the issue you're explaining has to do with GPO and incorrect settings, or not ENOUGH settings, or TOO MANY settings that cause Dual Scan

    Adam Marshall, MCSE: Security
    http://www.adamj.org
    Microsoft MVP - Windows and Devices for IT

    Thursday, March 15, 2018 3:06 AM
  • Hello Adamj.

    Thank you for the reply on this.  I believe the link you shared is correctly identifying the issue we are seeing here.  I combed through the logs a bit more and saw that when WSUS redirects the Server 2016 clients to Microsoft Update to download their update files, it seems to be scanning again and then downloading everything.

    My question is - is there a way that we can have our WSUS environment setup so that WU clients go to our WSUS server for approvals, then download the files from Microsoft Update?  We have a very distributed environment with lots of small sites and I would prefer to not have to manage an update point at all locations (40+).

    Per your request, I have attached the results from gpresult for Administrative Templates/Windows Components/Windows Updates.

    Policy Setting Winning GPO
    Allow Automatic Updates immediate installation Disabled C_Set Windows Update Policy (Servers)
    Allow non-administrators to receive update notifications Enabled C_Set Windows Update Policy (Servers)
    Automatic Updates detection frequency  Enabled C_Set Windows Update Policy (Servers)
    Check for updates at the following
    interval (hours): 12
    Policy Setting Winning GPO
    Configure Automatic Updates   Enabled C_Set Windows Update Policy (Servers)
    Configure automatic updating: 3 - Auto download and notify for install
    The following settings are only required and applicable if 4 is selected.
    Install during automatic maintenance Disabled
    Scheduled install day: 7 - Every Saturday
    Scheduled install time: 02:00
    If you have selected “4 – Auto download and schedule the install” for your scheduled install day and specified a schedule, you also have the option to limit updating to a weekly, bi-weekly or monthly occurrence, using the options below:
    Every week  
    First week of the month  
    Second week of the month  
    Third week of the month  
    Fourth week of the month  
    Install updates for other Microsoft products  
    Policy Setting Winning GPO
    Do not include drivers with Windows Updates  Enabled C_Set Windows Update Policy (Servers)
    Enabling Windows Update Power Management to automatically wake up the system to install scheduled updates   Enabled C_Set Windows Update Policy (Servers)
    No auto-restart with logged on users for scheduled automatic updates installations   Disabled C_Set Windows Update Policy (Servers)
    Re-prompt for restart with scheduled installations   Enabled C_Set Windows Update Policy (Servers)
    Wait the following period before
    prompting again with a scheduled
    restart (minutes): 20
    Policy Setting Winning GPO
    Reschedule Automatic Updates scheduled installations   Enabled C_Set Windows Update Policy (Servers)
    Wait after system
    startup (minutes): 20
    Policy Setting Winning GPO
    Specify active hours range for auto-restarts   Enabled C_Set Windows Update Policy (Servers)
    Specify the max active hours range:
    Max range: 18
    Policy Setting Winning GPO
    Specify intranet Microsoft update service location   Enabled C_Set Windows Update Policy (Servers)
    Set the intranet update service for detecting updates: http://MyWSUSServer.domain.com:8530
    Set the intranet statistics server: http://MyWSUSServer.domain.com:8530
    Set the alternate download server:  
    (example: http://IntranetUpd01)
    Download files with no Url in the metadata if alternate download server is set.  
    Policy Setting Winning GPO
    Turn off auto-restart for updates during active hours   Enabled C_Set Windows Update Policy (Servers)
    Active Hours
    Start: 6 AM
    End: 10 PM



    • Edited by nichor0826 Thursday, March 15, 2018 1:14 PM formatting
    Thursday, March 15, 2018 1:10 PM

  • As for your GPOs - I see you have not set the Alternative download server, but more importantly, it's what I DON'T see that is the problem. I don't see any other policies that surround the system. The reason why I asked for the full gpresult, is there are other settings that are affecting Windows Update and Dual Scan that are NOT part of the hierarchical structure of Administrative Templates/Windows Components/Windows Updates.

    Showing policies from GPOs are ok, however the resultant set of applied policies are better because you can actually see what's going on on the computer.

    As for WSUS, it has the option in Update Files and Languages to store or not store updates locally on the WSUS Server. Simlply select the one you want for that WSUS Server and click ok.

    Let me offer an alternative solution. 2 WSUS Servers - 1 upstream at HQ that saves files locally that feed your HQ systems; and a 2nd Downstream WSUS server at HQ that is a downstream replica server, but this server is setup to NOT store files locally and to download the updates from Microsoft.

    Then you have 2 WSUS Location ONLY GPOs - one for your HQ that points to your upstream server and 1 for all other 'mini sites' that point to the downstream replica server and is applied through GPO to each 'Site' (hidden by default so you will have to show the Sites in GPMC).

    In both cases, use WSUS Automated Maintenance to keep both WSUS Systems maintained.

    Please have a look at the WSUS Automated Maintenance (WAM) system. It is an automated maintenance system for WSUS, the last system you'll ever need to maintain WSUS!

    https://community.spiceworks.com/scripts/show/2998-wsus-automated-maintenance-formerly-adamj-clean-wsus

    What it does:

    1. Add WSUS Index Optimization to the database to increase the speed of many database operations in WSUS by approximately 1000-1500 times faster.
    2. Remove all Drivers from the WSUS Database (Default; Optional).
    3. Shrink your WSUSContent folder's size by declining multiple types of updates including by default any superseded updates, preview updates, expired updates, Itanium updates, and beta updates. Optional extras: Language Packs, IE7, IE8, IE9, IE10, Embedded, NonEnglishUpdates, ComputerUpdates32bit, WinXP.
    4. Remove declined updates from the WSUS Database.
    5. Clean out all the synchronization logs that have built up over time (configurable, with the default keeping the last 14 days of logs).
    6. Compress Update Revisions.
    7. Remove Obsolete Updates.
    8. Computer Object Cleanup (configurable, with the default of deleting computer objects that have not synced within 30 days).
    9. Application Pool Memory Configuration to display the current private memory limit and easily set it to any configurable amount including 0 for unlimited. This is a manual execution only.
    10. Checks to see if you have a dirty database, and if you do, fixes it. This is primarily for Server 2012 WSUS, and is a manual execution only.
    11. Run the Recommended SQL database Maintenance script on the actual SQL database.
    12. Run the Server Cleanup Wizard.

    It will email the report out to you or save it to a file, or both.

    Although the script is lengthy, it has been made to be super easy to setup and use so don't over think it. There are some prerequisites and instructions at the top of the script. After installing the prerequisites and configuring the variables for your environment (email settings only if you are accepting all the defaults), simply run:

    .\Clean-WSUS.ps1 -FirstRun

    If you wish to view or increase the Application Pool Memory Configuration, or run the Dirty Database Check, you must run it with the required switch. See Get-Help .\Clean-WSUS.ps1 -Examples

    If you're having trouble, there's also a -HelpMe option that will create a log so you can send it to me for support.


    Adam Marshall, MCSE: Security
    http://www.adamj.org
    Microsoft MVP - Windows and Devices for IT

    Thursday, March 15, 2018 5:07 PM
  • Adamj,

    I actually did find your script a couple days ago and ran it against my WSUS server.  It improved performance in many ways, but did not correct this issue in particular.  From our conversation, I don't believe it should have anyway.

    Forgive me for being a relative noob to TechNet but how would I go about pasting in the gpresult HTML file here?  Or how would I otherwise get it to you?  I would be more than happy to do so.

    Friday, March 16, 2018 1:50 PM
  • pastebin.com it and then add the link here - easiest way.

    Adam Marshall, MCSE: Security
    http://www.adamj.org
    Microsoft MVP - Windows and Devices for IT

    Friday, March 16, 2018 3:29 PM