Software Updates in Configuration Manager Current Branch Deep Dive – Client Operations

~ Ibrahim Aladwan

Hello everyone, my name is Ibrahim Aladwan and I’m a support engineer on the Configuration Manager team. Today I’d like to take a minute and go through the update process in System Center Configuration Manager current branch (ConfigMgr 1511, ConfigMgr 1602, etc.) and demonstrate how things work from the client side of things.

Overview

When a client computer in the target collection for a deployment receives machine policy, the Software Update Client Agent starts an evaluation scan. The client agent downloads the content for any required software updates from a distribution point to the local client cache soon after it receives the deployment, but waits until after the software available time setting for the deployment before the software updates are available for installation. This differs for software updates in optional deployments (deployments that do not have an installation deadline), as they are not downloaded until a user manually starts the installation. When the configured deadline passes, the Software Updates client agent performs a scan to verify that the software updates are still required, and assuming they are, it then checks the local cache on the client computer to verify that the software update source files are still available and installs the updates. If the content was deleted from the client cache to make room for another deployment, the client re-downloads the software updates from the distribution point to the client cache. Software updates are always downloaded to the client cache regardless of the configured maximum client cache size. When the installation is complete, the client agent verifies that the software updates are no longer required, then sends a state message to the management point to indicate that the software updates are now installed on the client.

Taking a Closer Look

To get a better understanding of this, let’s take a look at the client log files and track the progress as we deploy KB 3176493. The client and site server components record process information in individual log files, and by default, client and server component logging is enabled in Configuration Manager. You can use the information in these log files to help you troubleshoot issues that might occur in your Configuration Manager environment. For additional information on these log files please refer to the following:

Technical Reference for Log Files in Configuration Manager

So here’s what KB 3176493 looks like when we start:

Capture_thumb[2]

Software Update Scanning and Evaluation

When the Evaluation cycle is requested (manual or on schedule), entries similar to the following will appear in ScanAgent.log:

Message received: ‘<?xml version=’1.0′ ?>              <UpdateSourceMessage MessageType=’ScanByUpdateSource’>
<ForceScan>TRUE</ForceScan>
<UpdateSourceIDs>
<ID>{39B24983-D827-4C7C-8782-029410E9C146}</ID>
</UpdateSourceIDs>
</UpdateSourceMessage>’
ScanAgent

On the SQL Server, SQL profiler will show that Configuration Manager is executing the stored procedure MP_GetWSUSServerLocations:

RPC:Completed        exec MP_GetWSUSServerLocations N'{39B24983-D827-4C7C-8782-029410E9C146}’,N’167′,N’FCH’,N’FCH’,N’0′,N’server.contoso.local’         System Center 2012 Configuration Manager            SYSTEM    NT AUTHORITY\SYSTEM          16              131           0                  38              1816         72              8/10/2016 1:24:05 AM
0X000000000700000032004D0050005F0047006500740057005300550053005300650072007600650072004C006F0063006100740069006F006E007300720000

This value is then returned to LocationService.log:

Calling back with the following WSUS locations        LocationServices
8/10/2016 1:24:05 AM        7956 (0x1F14) WSUS Path=’
http://server.contoso.local:8530′, Server=’server.contoso.local’, Version=’167′        LocationServices

ScanAgent.log also shows the following:

*****Policy Change notification received for ToolUniqueID={39B24983-D827-4C7C-8782-029410E9C146}        ScanAgent        8/10/2016 1:24:01 AM
*****ScanByUpdates request received with ForceReScan=0, ScanOptions=0x00000008,  WSUSLocationTimeout = 604800        ScanAgent

ScanAgent then checks the update source and Time-To-Live (TTL) settings for the last scan results and submits a request for WSUS server location, then LocationService retrieves the WSUS location from the Management Point and returns the URL and the server name, as seen here in ScanAgent.log:

ScanJob({DCB47C9A-3D45-4495-8116-5EE9E0F3B4D2}): – – – – – -Locations requested for ScanJobID={DCB47C9A-3D45-4495-8116-5EE9E0F3B4D2} (LocationRequestID={6CBEFDD4-7390-4A41-AA4D-4D3F8B72111F}), will process the scan request once locations are available.        ScanAgent        8/10/2016 1:24:03 AM

*****WSUSLocationUpdate received for location request guid={6CBEFDD4-7390-4A41-AA4D-4D3F8B72111F}        ScanAgent

Next, the Windows Update scan is initiated and we see the following in ScanAgent.log:

*****ScanByUpdates request received with ForceReScan=0, ScanOptions=0x00000008, WSUSLocationTimeout = 604800        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
– – -Evaluating Update Status…        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
Found CategoryID of :0fa1201d-4330-4fa8-8ae9-b877473b6441 for Update:4d52d21e-e4a1-4043-bcda-69a696b2b257        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
CScanAgent::ScanByUpdates – Found UpdateClassification 0fa1201d-4330-4fa8-8ae9-b877473b6441 for Update:4d52d21e-e4a1-4043-bcda-69a696b2b257        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
Found CategoryID of :0fa1201d-4330-4fa8-8ae9-b877473b6441 for Update:a12fff7b-aefc-4815-ab2e-0048ada4ea9e        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
CScanAgent::ScanByUpdates – Found UpdateClassification 0fa1201d-4330-4fa8-8ae9-b877473b6441 for Update:a12fff7b-aefc-4815-ab2e-0048ada4ea9e        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
Found CategoryID of :0fa1201d-4330-4fa8-8ae9-b877473b6441 for Update:c071152f-3697-44f4-b77c-bf07519dd63e        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
CScanAgent::ScanByUpdates – Found UpdateClassification 0fa1201d-4330-4fa8-8ae9-b877473b6441 for Update:c071152f-3697-44f4-b77c-bf07519dd63e        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
Found CategoryID of :0fa1201d-4330-4fa8-8ae9-b877473b6441 for Update:e6561a3e-2ee6-48e4-8770-78068771cfcb        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
CScanAgent::ScanByUpdates – Found UpdateClassification 0fa1201d-4330-4fa8-8ae9-b877473b6441 for Update:e6561a3e-2ee6-48e4-8770-78068771cfcb        ScanAgent        8/10/2016 1:26:41 AM        5148 (0x141C)

State messages are created for each software update that changed in compliance state, then state messages are sent to the Management Point as seen in StateMessage.log:

Adding message with TopicType 500 and TopicId 4d52d21e-e4a1-4043-bcda-69a696b2b257 to WMI        StateMessage        8/10/2016 1:25:53 AM        5148 (0x141C)
State message(State ID : 2) with TopicType 500 and TopicId 4d52d21e-e4a1-4043-bcda-69a696b2b257 has been recorded for SYSTEM        StateMessage        8/10/2016 1:25:53 AM        5148 (0x141C)
Successfully forwarded State Messages to the MP        StateMessage        5148 (0x141C)

We also see entries similar to the following in WUAHandler.log:

Its a WSUS Update Source type ({39B24983-D827-4C7C-8782-029410E9C146}), adding it.        WUAHandler        8/10/2016 1:24:42 AM        7544 (0x1D78)
Existing WUA Managed server was already set (
http://FC-CM01.fourthcoffee.local:8530), skipping Group Policy registration.        WUAHandler        8/10/2016 1:24:42 AM        7544 (0x1D78)
Added Update Source ({39B24983-D827-4C7C-8782-029410E9C146}) of content type: 2        WUAHandler        8/10/2016 1:24:42 AM        7544 (0x1D78)
Scan results will include superseded updates only when they are superseded by service packs and definition updates.        WUAHandler        8/10/2016 1:24:42 AM        7544 (0x1D78)
Search Criteria is (DeploymentAction=* AND Type=’Software’) OR (DeploymentAction=* AND Type=’Driver’)        WUAHandler        8/10/2016 1:24:42 AM        7544 (0x1D78)
Async searching of updates using WUAgent started.        WUAHandler        8/10/2016 1:24:42 AM        7544 (0x1D78)
Async searching completed.        WUAHandler        8/10/2016 1:25:52 AM        1308 (0x051C)
Successfully completed scan.        WUAHandler        8/10/2016 1:25:52 AM        5148 (0x141C)

Installation

When a client computer in the target collection for the deployment receives the machine policy, machine policy including new or changed deployment assignment policy is downloaded. UpdatesDeployment.log receives modification event and triggers evaluation and installation process, as shown here:

Assignment {b8cf0a9f-3b46-4ce7-9712-b281aa88b953} has total CI = 16        UpdatesDeploymentAgent        8/10/2016 1:24:02 AM        7956 (0x1F14)
OnPolicyModify for assignment ({b8cf0a9f-3b46-4ce7-9712-b281aa88b953})…         UpdatesDeploymentAgent        8/10/2016 1:24:02 AM        7956 (0x1F14)
Update (Site_39B24983-D827-4C7C-8782-029410E9C146/SUM_4d52d21e-e4a1-4043-bcda-69a696b2b257) Name (Cumulative Update for Windows 10 Version 1511 (KB3176493)) ArticleID (3176493) added to the targeted list of deployment ({b8cf0a9f-3b46-4ce7-9712-b281aa88b953})        UpdatesDeploymentAgent        8/10/2016 1:26:41 AM        5148 (0x141C)
Raising client SDK event for class CCM_SoftwareUpdate, instance CCM_SoftwareUpdate.UpdateID=”Site_39B24983-D827-4C7C-8782-029410E9C146/SUM_4d52d21e-e4a1-4043-bcda-69a696b2b257″, actionType 11l, value NULL, user NULL, session 4294967295l, level 0l, verbosity 30l        UpdatesDeploymentAgent        8/10/2016 1:26:41 AM        5148 (0x141C)

UpdatesStore will check the status of each update and look for the source, then CIDownloader determines applicability for each update. This is shown in UpdateStore.log:

Queried Update (4d52d21e-e4a1-4043-bcda-69a696b2b257): Status=Missing, Title=Cumulative Update for Windows 10 Version 1511 (KB3176493), BulletinID=MS16-095, QNumbers=3176493, LocaleID=, ProductID=0fa1201d-4330-4fa8-8ae9-b877473b6441, UpdateClassification = 0fa1201d-4330-4fa8-8ae9-b877473b6441, ExcludeForStateReporting=FALSE.        UpdatesStore        8/10/2016 1:25:53 AM        4316 (0x10DC)
Querying update status of 2 updates.        UpdatesStore        8/10/2016 3:10:47 AM        6232 (0x1858)
Queried Update (4d52d21e-e4a1-4043-bcda-69a696b2b257): Status=Missing, Title=Cumulative Update for Windows 10 Version 1511 (KB3176493), BulletinID=MS16-095, QNumbers=3176493, LocaleID=, ProductID=0fa1201d-4330-4fa8-8ae9-b877473b6441, UpdateClassification = 0fa1201d-4330-4fa8-8ae9-b877473b6441, ExcludeForStateReporting=FALSE.        UpdatesStore        8/10/2016 3:26:49 AM        6232 (0x1858)
Queried Update (4d52d21e-e4a1-4043-bcda-69a696b2b257): Status=Installed, Title=Cumulative Update for Windows 10 Version 1511 (KB3176493), BulletinID=MS16-095, QNumbers=3176493, LocaleID=, ProductID=0fa1201d-4330-4fa8-8ae9-b877473b6441, UpdateClassification = 0fa1201d-4330-4fa8-8ae9-b877473b6441, ExcludeForStateReporting=FALSE.        UpdatesStore        8/10/2016 5:08:07 AM        3628 (0x0E2C)

UpdatesHandler then retrieves download settings and software update relationships, then calls to download content.

Entries similar to the following appear in UpdatesHanlder.log:

Bundle update (4d52d21e-e4a1-4043-bcda-69a696b2b257) is requesting download from child updates for action (INSTALL)        UpdatesHandler        8/10/2016 1:26:41 AM        7556 (0x1D84)
StateCore – bundle update (4d52d21e-e4a1-4043-bcda-69a696b2b257) state changed from (WAIT_CONTENTS) to (EXECUTE_READY) as child update state changed        UpdatesHandler        8/10/2016 3:10:43 AM        6548 (0x1994)
Bundle update (4d52d21e-e4a1-4043-bcda-69a696b2b257) is requesting download from child updates for action (INSTALL)        UpdatesHandler        8/10/2016 3:10:48 AM        4432 (0x1150)

Entries similar to the following appear in WUAHandler.log:

Going to search using WSUS update source.        WUAHandler        8/10/2016 3:10:49 AM        3688 (0x0E68)
Synchronous searching of all updates started…        WUAHandler        8/10/2016 3:10:49 AM        3688 (0x0E68)
Successfully completed synchronous searching of updates.        WUAHandler        8/10/2016 3:11:00 AM        3688 (0x0E68)
1. Update: 4d52d21e-e4a1-4043-bcda-69a696b2b257, 205 BundledUpdates: 1        WUAHandler        8/10/2016 3:11:00 AM        3688 (0x0E68)
Update: a12fff7b-aefc-4815-ab2e-0048ada4ea9e, 200 BundledUpdates: 0        WUAHandler        8/10/2016 3:11:00 AM        3688 (0x0E68)
1. Update (Missing): Cumulative Update for Windows 10 Version 1511 (KB3176493) (4d52d21e-e4a1-4043-bcda-69a696b2b257, 205)        WUAHandler        8/10/2016 3:11:00 AM        3688 (0x0E68)
Async installation of updates started.        WUAHandler        8/10/2016 3:12:58 AM        3688 (0x0E68)
Update 1 (4d52d21e-e4a1-4043-bcda-69a696b2b257) finished installing (0x00000000), Reboot Required? Yes        WUAHandler        8/10/2016 3:26:35 AM        4708 (0x1264)
Async install completed.        WUAHandler        8/10/2016 3:26:46 AM        5660 (0x161C)
Installation of updates completed.        WUAHandler        8/10/2016 3:26:46 AM        6232 (0x1858)

Then we get the content location and the following is logged in LocationService.log:

Calling back with the following distribution points        LocationServices        8/10/2016 3:09:02 AM        5648 (0x1610)
Distribution Point=’
http://FC-CM01.fourthcoffee.local/SMS_DP_SMSPKG$/a12fff7b-aefc-4815-ab2e-0048ada4ea9e’, Locality=’LOCAL’, DPType=’SERVER’, Version=’8325′, Capabilities='<Capabilities SchemaVersion=”1.0″><Property Name=”SSLState” Value=”0″/></Capabilities>’, Signature=’http://FC-CM01.fourthcoffee.local/SMS_DP_SMSSIG$/a12fff7b-aefc-4815-ab2e-0048ada4ea9e.1.tar’, ForestTrust=’TRUE’,        LocationServices        8/10/2016 3:09:02 AM        5648 (0x1610)
Filtering locations for request {E68DF60D-00D0-4330-9ECE-8742B48CB801}.        LocationServices        8/10/2016 3:09:02 AM        5648 (0x1610)

Then software update content is downloaded to the cache and the following is logged in DataTransferService.log:

UpdateURLWithTransportSettings(): OLD URL – http://FC-CM01.fourthcoffee.local/SMS_DP_SMSPKG$/a12fff7b-aefc-4815-ab2e-0048ada4ea9e        DataTransferService        8/10/2016 3:09:02 AM        5648 (0x1610)
UpdateURLWithTransportSettings(): NEW URL –
http://FC-CM01.fourthcoffee.local:80/SMS_DP_SMSPKG$/a12fff7b-aefc-4815-ab2e-0048ada4ea9e        DataTransferService        8/10/2016 3:09:02 AM        5648 (0x1610)
DTSJob {252AF5CA-A261-49FA-82DB-50556214AEAC} created to download from ‘
http://FC-CM01.fourthcoffee.local:80/SMS_DP_SMSPKG$/a12fff7b-aefc-4815-ab2e-0048ada4ea9e’ to ‘C:\Windows\ccmcache\1b’.        DataTransferService        8/10/2016 3:09:02 AM        5648 (0x1610)
DTSJob {252AF5CA-A261-49FA-82DB-50556214AEAC} in state ‘DownloadingManifest’.        DataTransferService        8/10/2016 3:09:02 AM        6548 (0x1994)
GET: Host=FC-CM01.fourthcoffee.local, Path=/SMS_DP_SMSPKG$/a12fff7b-aefc-4815-ab2e-0048ada4ea9e, Port=80, Protocol=http, Flags=133, Options=224        DataTransferService        8/10/2016 3:09:02 AM        4320 (0x10E0)

UpdatesDeploymentAgent then raises a state message (download complete) and calls WUAHandler to handle the software update installation via WUA. You can see this via the following entries in UpdatesDeployment.log:

ApplyCIs – JobId = {301925A8-283F-42AE-95F0-272A10359929}        UpdatesDeploymentAgent        8/10/2016 3:10:47 AM        4432 (0x1150)
……
Update (Site_39B24983-D827-4C7C-8782-029410E9C146/SUM_4d52d21e-e4a1-4043-bcda-69a696b2b257) Progress: Status = ciStateInstalling, PercentComplete = 10, DownloadSize = 0, Result = 0x0        UpdatesDeploymentAgent        8/10/2016 3:19:31 AM        4432 (0x1150)
Update (Site_39B24983-D827-4C7C-8782-029410E9C146/SUM_4d52d21e-e4a1-4043-bcda-69a696b2b257) Progress: Status = ciStateInstalling, PercentComplete = 100, DownloadSize = 0, Result = 0x0        UpdatesDeploymentAgent        8/10/2016 3:24:54 AM        3688 (0x0E68)

CUpdatesJob({301925A8-283F-42AE-95F0-272A10359929}): Job completion received.        UpdatesDeploymentAgent        8/10/2016 3:26:50 AM        4320 (0x10E0)
CUpdatesJob({301925A8-283F-42AE-95F0-272A10359929}): Delete job from WMI        UpdatesDeploymentAgent        8/10/2016 3:26:50 AM        4320 (0x10E0)

WUA then installs the updates and we see the following in CBS.log:

2016-08-10 03:13:02, Info CBS Opened cabinet package, package directory: \\?\C:\WINDOWS\SoftwareDistribution\Download\b0e4281cd82e8b66165a25b8a4ae6648\, sandbox location: \\?\C:\WINDOWS\SoftwareDistribution\Download\b0e4281cd82e8b66165a25b8a4ae6648\inst\, cabinet location: \\?\C:\WINDOWS\SoftwareDistribution\Download\b0e4281cd82e8b66165a25b8a4ae6648\Windows10.0-KB3176493-x86.cab, manifest location: \\?\C:\WINDOWS\SoftwareDistribution\Download\b0e4281cd82e8b66165a25b8a4ae6648\inst\update.mum

2016-08-10 03:14:36, Info CBS Extracting all files from cabinet \\?\C:\WINDOWS\SoftwareDistribution\Download\b0e4281cd82e8b66165a25b8a4ae6648\inst\Cab_1_for_KB3176493.cab

Next, state messages are created for each software update that changed in compliance state, and these state messages are sent to the management point as seen in StateMessage.log:

State message(State ID : 3) with TopicType 500 and TopicId 4d52d21e-e4a1-4043-bcda-69a696b2b257 has been recorded for SYSTEM        StateMessage        8/10/2016 5:08:07 AM        3784 (0x0EC8)

At this point the updates are installed and the hierarchy is updated.

More Information

For more information about state message and ID, please see the table below.

image

Ref: State Messages in Configuration Manager 2007

For more information on Software Updates, see Introduction to Software Updates in Configuration Manager

Ibrahim Aladwan, Support Engineer
Microsoft System Center Configuration Manager