Using log files to track the software update deployment process in System Center 2012 Configuration Manager

Summary
When you deploy software updates in System Center 2012 Configuration Manager (ConfigMgr 2012 or ConfigMgr 2012 R2), you typically add the updates to a software update group and then deploy the software update group to clients. When you create the deployment, the update policy is sent to client computers, and the update content files are downloaded from a distribution point to the local cache on the client computer. The updates are then available for installation on the client. In the "More Information" section, we examine this process in detail and show how the process can be tracked by using log files. This information may be helpful when you're trying to identify and resolve problems in the software update process.

Note For more information about software updates in System Center 2012 Configuration Manager, see the following Microsoft Knowledge Base (KB) article:

3092358 Software update troubleshooting and maintenance in Microsoft Configuration Manager

More information
  1. After the deployment and the deployment policy have been created on the server, clients receive the policy on the next policy evaluation cycle.

    Note Before you can track a deployment, you must first find the Deployment Unique ID of the deployment by adding the Deployment Unique ID column in the console. For the deployment in the following example, the Deployment Unique ID is B040D195-8FA8-48D3-953F-17E878DAB23D.

    When policy is received, the following entry is logged in PolicyAgent.log:

    Initializing download of policy 'CCM_Policy_Policy5.PolicyID="{B040D195-8FA8-48D3-953F-17E878DAB23D}",PolicySource="SMS:PR1",PolicyVersion="1.00"' from 'http://PR1SITE.CONTOSO.COM/SMS_MP/.sms_pol?{B040D195-8FA8-48D3-953F-17E878DAB23D}.SHA256:0EE489DB3036BE80BB43676340249A254278BEBDDD80B6004C11FF10F12BC9D6' PolicyAgent_ReplyAssignments 2/9/2014 7:05:01 PM 2572 (0x0A0C) Download of policy CCM_Policy_Policy5.PolicyID="{B040D195-8FA8-48D3-953F-17E878DAB23D}",PolicySource="SMS:PR1",PolicyVersion="1.00" completed (DTS Job ID: {D53DAB18-ED97-4373-A3BE-3FBA5DB3C6C6}) PolicyAgent_PolicyDownload 2/9/2014 7:05:01 PM 2572 (0x0A0C) PolicyEvaluator.log: Initializing download of policy 'CCM_Policy_Policy5.PolicyID="{B040D195-8FA8-48D3-953F-17E878DAB23D}",PolicySource="SMS:PR1",PolicyVersion="1.00"' from 'http://PR1SITE.CONTOSO.COM/SMS_MP/.sms_pol?{B040D195-8FA8-48D3-953F-17E878DAB23D}.SHA256:0EE489DB3036BE80BB43676340249A254278BEBDDD80B6004C11FF10F12BC9D6' PolicyAgent_ReplyAssignments 2/9/2014 7:05:01 PM 2572 (0x0A0C) Download of policy CCM_Policy_Policy5.PolicyID="{B040D195-8FA8-48D3-953F-17E878DAB23D}",PolicySource="SMS:PR1",PolicyVersion="1.00" completed (DTS Job ID: {D53DAB18-ED97-4373-A3BE-3FBA5DB3C6C6}) PolicyAgent_PolicyDownload 2/9/2014 7:05:01 PM 2572 (0x0A0C) 
    Both the policy and the deadline schedule are evaluated. This is done by the scheduler component. In this example, deadline randomization is disabled in Computer Agent client settings. Therefore, the deployment evaluation is initiated on the deadline and without randomization. This is shown in the Scheduler.log file as follows:

    Initialized trigger ("3E692B0000080000") for schedule 'Machine/DEADLINE:{B040D195-8FA8-48D3-953F-17E878DAB23D}': Conditions=1 with deadline 4320 minutes Allow randomization override=1 HasMissedOccurrence=FALSE ScheduleLoadedTime="02/09/2014 19:05:947" LastFireTime="00/00/00 00:00:00" CurrentTime="02/09/2014 19:05:947" Scheduler 2/9/2014 7:05:01 PM 3260 (0x0CBC) Processing trigger '3E692B0000080000' for scheduler 'Machine/DEADLINE:{B040D195-8FA8-48D3-953F-17E878DAB23D}'. MaxRandomDelay = 120, MissedOccur = 0, RandomizeEvenIfMissed = 1, PreventRandomizationInducedMisses = 0 Scheduler 2/9/2014 7:05:01 PM 3260 (0x0CBC) Randomization is disabled in client settings and this schedule is set to honor client setting. Scheduler 2/9/2014 7:05:01 PM 3260 (0x0CBC) SMSTrigger '3E692B0000080000' for scheduler 'Machine/DEADLINE:{B040D195-8FA8-48D3-953F-17E878DAB23D}' will fire at 02/09/2014 07:15:00 PM without randomization. Scheduler 2/9/2014 7:05:01 PM 3260 (0x0CBC).
  2. At the scheduled deadline, Scheduler notifies the Updates Deployment Agent to initiate the Deployment Evaluation process, as shown in Scheduler.log:

    Sending message for schedule 'Machine/DEADLINE:{B040D195-8FA8-48D3-953F-17E878DAB23D}' (Target: 'direct:UpdatesDeploymentAgent', Name: '') Scheduler 2/9/2014 7:15:00 PM 3216 (0x0C90) SMSTrigger '3E692B0000080000' (Schedule ID: 'Machine/DEADLINE:{B040D195-8FA8-48D3-953F-17E878DAB23D}', Message Name: '', Target: 'direct:UpdatesDeploymentAgent') will never fire again. Scheduler 2/9/2014 7:15:00 PM 3216 (0x0C90) UpdatesDeployment.log: Message received: '<?xml version='1.0' ?> <CIAssignmentMessage MessageType='EnforcementDeadline'> <AssignmentID>{B040D195-8FA8-48D3-953F-17E878DAB23D}</AssignmentID> </CIAssignmentMessage>' UpdatesDeploymentAgent 2/9/2014 7:15:00 PM 3216 (0x0C90) 
    Updates Deployment Agent starts the Deployment Evaluation process by requesting a Software Update scan to make sure that the deployed updates are still applicable. This can be seen in UpdatesDeploymentAgent.log:

    Assignment {B040D195-8FA8-48D3-953F-17E878DAB23D} has total CI = 3 UpdatesDeploymentAgent 2/9/2014 7:15:00 PM 3216 (0x0C90) Deadline received for assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent 2/9/2014 7:15:00 PM 3216 (0x0C90) Detection job ({99ADA372-0738-44E4-9C4D-EBA30F23E9FD}) started for assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent 2/9/2014 7:15:00 PM 3216 (0x0C90) UpdatesHandler.log: Successfully initiated scan for job ({99ADA372-0738-44E4-9C4D-EBA30F23E9FD}). UpdatesHandler 2/9/2014 7:15:04 PM 3696 (0x0E70) Scan completion received for job ({99ADA372-0738-44E4-9C4D-EBA30F23E9FD}). UpdatesHandler 2/9/2014 7:15:04 PM 3696 (0x0E70) Initial scan completed for the job ({99ADA372-0738-44E4-9C4D-EBA30F23E9FD}). UpdatesHandler 2/9/2014 7:15:04 PM 3696 (0x0E70) Evaluating status of the updates for the job ({99ADA372-0738-44E4-9C4D-EBA30F23E9FD}). UpdatesHandler 2/9/2014 7:15:04 PM 3696 (0x0E70) CompleteJob - Job ({99ADA372-0738-44E4-9C4D-EBA30F23E9FD}) removed from job manager list. UpdatesHandler 2/9/2014 7:15:04 PM 3696 (0x0E70)
  3. At this point the scan request is handled by Scan Agent component. Scan Agent calls WUAHandler to perform a scan and then hands the results back to Updates Handler and Updates Deployment Agent. For more information about the scan process, see the following KB article:

    3090184 How to troubleshoot Software Update scan failures in Microsoft Configuration Manager

    After the scan is completed, Updates Deployment Agent is notified. This is noted in UpdatesDeploymentAgent.log as follows:

    DetectJob completion received for assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent 2/9/2014 7:15:04 PM 3696 (0x0E70) Making updates available for assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent 2/9/2014 7:15:04 PM 3696 (0x0E70) Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_e06056e3-0199-4c68-8ac3-bdddff356a0a) Name (Security Update for Windows Server 2008 R2 x64 Edition (KB2698365)) ArticleID (2698365) added to the targeted list of deployment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent 2/9/2014 7:15:04 PM 3696 (0x0E70) Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_ada7cf51-66b0-4a00-b37b-68d569d6ff8b) Name (Security Update for Windows Server 2008 R2 x64 Edition (KB2712808)) ArticleID (2712808) added to the targeted list of deployment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent 2/9/2014 7:15:04 PM 3696 (0x0E70) Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_3cbcf577-5139-49b8-afe8-620af5c52f95) Name (Security Update for Windows Server 2008 R2 x64 Edition (KB2705219)) ArticleID (2705219) added to the targeted list of deployment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent 2/9/2014 7:15:04 PM 3696 (0x0E70)
  4. Updates Deployment Agent raises State Messages for the deployment to update the current Evaluation and Compliance state. This is noted in UpdatesDeploymentAgent.log as follows:

    Raised assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) state message successfully. TopicType = Evaluate, StateId = 2, StateName = ASSIGNMENT_EVALUATE_SUCCESS UpdatesDeploymentAgent 2/9/2014 7:15:04 PM 3696 (0x0E70) Raised assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) state message successfully. TopicType = Compliance, Signature = 5e176837, IsCompliant = False UpdatesDeploymentAgent 2/9/2014 7:15:04 PM 3696 (0x0E70) 
    Updates Deployment Agent now starts a job to download the software update files from the Distribution Point. This can be seen in UpdatesDeploymentAgent.log shown here:

    DownloadCIContents Job ({C531FD04-FADA-4F75-A399-EEA2D3EDB56C}) started for assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent Progress received for assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_e06056e3-0199-4c68-8ac3-bdddff356a0a) Progress: Status = ciStateDownloading, PercentComplete = 0, Result = 0x0 UpdatesDeploymentAgent Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_ada7cf51-66b0-4a00-b37b-68d569d6ff8b) Progress: Status = ciStateDownloading, PercentComplete = 0, Result = 0x0 UpdatesDeploymentAgent Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_3cbcf577-5139-49b8-afe8-620af5c52f95) Progress: Status = ciStateDownloading, PercentComplete = 0, Result = 0x0 UpdatesDeploymentAgent 
    It is also noted in UpdatesHandler.log, as follows:

    Initiating download for the job ({C531FD04-FADA-4F75-A399-EEA2D3EDB56C}). UpdatesHandler Update Id = 3cbcf577-5139-49b8-afe8-620af5c52f95, State = StateDownloading, Result = 0x0 UpdatesHandler Update Id = ada7cf51-66b0-4a00-b37b-68d569d6ff8b, State = StateDownloading, Result = 0x0 UpdatesHandler Update Id = e06056e3-0199-4c68-8ac3-bdddff356a0a, State = StateDownloading, Result = 0x0 UpdatesHandler Timeout Options: Priority = 2, DPLocality = 1048578, Location = 604800, Download = 864000, PerDPInactivity = 0, TotalInactivityTimeout = 0, bUseBranchCache = True, bPersistOnWriteFilterDevices = True, bOverrideServiceWindow = False UpdatesHandler
  5. Updates Handler initiates the download request from Content Access Service for the three actionable updates that are listed above. Note that the download job is started for the child update in the bundle and that the Content ID is logged. 

    Bundle update (3cbcf577-5139-49b8-afe8-620af5c52f95) is requesting download from child updates for action (INSTALL) UpdatesHandler Content Text = <Content ContentId="fbb5724a-aa0f-47f9-908a-47068fd8ad6f" Version="1"><FileContent Name="windows6.1-kb2705219-v2-x64.cab" Hash="8E8E0175D46B5A8D52C4856FA3D282FAA12ACD63" HashAlgorithm="SHA1" Size="199093"/></Content> Bundle update (ada7cf51-66b0-4a00-b37b-68d569d6ff8b) is requesting download from child updates for action (INSTALL) UpdatesHandler Content Text = <Content ContentId="3e9b1132-9ccd-439d-b32a-5cefd19735d1" Version="1"><FileContent Name="windows6.1-kb2712808-x64.cab" Hash="060B60401B3DE3DCE053A68C65E9EB050874EB80" HashAlgorithm="SHA1" Size="805071"/></Content> Bundle update (e06056e3-0199-4c68-8ac3-bdddff356a0a) is requesting download from child updates for action (INSTALL) UpdatesHandler Content Text = <Content ContentId="d2a9ee23-9cab-4843-b040-e2da1cc167e9" Version="1"><FileContent Name="windows6.1-kb2698365-x64.cab" Hash="BF20BB36FC73C0D1F53EA1E635B8AA46C71D7B1F" HashAlgorithm="SHA1" Size="2496330"/></Content> 
    Content Access Service starts a download job for each update and creates a Content Transfer Manager (CTM) job. A CTM job is created for each update separately, and CAS.log entries resemble the following for each: 

    Requesting content fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1, size(KB) 0, under context System with priority Medium ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) Created and initialized a DownloadContentRequest ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) Target location for content fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1 is C:\Windows\ccmcache\1 ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) CDownloadManager::RequestDownload fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1.System ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) Submitted CTM job {E0452CF4-5B04-4A1A-B8EB-10B11B063249} to download Content fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1 under context System ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) Successfully created download request {856FA4CA-D02A-4E2C-841E-841ED3C7EC01} for content fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1 ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) Created and submitted a new Content Request for fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1.System ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90)
  6. Content Transfer Manager starts working on the download job. It first requests the location for the content that must be downloaded. This location request is handled by Location Services, which sends the location request to the management point, obtains the location response, and then hands it back to the Content Transfer Manager. This can be seen in ContentTransferManager.log:

    Starting CTM job {E0452CF4-5B04-4A1A-B8EB-10B11B063249}. ContentTransferManager 2/9/2014 7:15:05 PM 3216 (0x0C90) CTM job {E0452CF4-5B04-4A1A-B8EB-10B11B063249} entered phase CCM_DOWNLOADSTATUS_DOWNLOADING_DATA ContentTransferManager 2/9/2014 7:15:05 PM 3216 (0x0C90) Queued location request '{C56C01F2-2388-4710-BF3B-A526DB40E35F}' for CTM job '{E0452CF4-5B04-4A1A-B8EB-10B11B063249}'. ContentTransferManager 2/9/2014 7:15:05 PM 3216 (0x0C90) CCTMJob::EvaluateState(JobID={E0452CF4-5B04-4A1A-B8EB-10B11B063249}, State=RequestedLocations) ContentTransferManager 2/9/2014 7:15:05 PM 3216 (0x0C90) 
    This is also noted in LocationServices.log:

    Created filter for LS request {C56C01F2-2388-4710-BF3B-A526DB40E35F}. LocationServices 2/9/2014 7:15:05 PM 3216 (0x0C90) ContentLocationReply : <ContentLocationReply SchemaVersion="1.00"><ContentInfo PackageFlags="0"><ContentHashValues/></ContentInfo><Sites><Site><MPSite SiteCode="PR1" MasterSiteCode="PR1" SiteLocality="LOCAL" IISPreferedPort="80" IISSSLPreferedPort="443"/><LocationRecords><LocationRecord><URL Name="http://PR1SITE.CONTOSO.COM/SMS_DP_SMSPKG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f" Signature="http://PR1SITE.CONTOSO.COM/SMS_DP_SMSSIG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1.tar"/><ADSite Name="Default-First-Site-Name"/><IPSubnets><IPSubnet Address="192.168.10.0"/><IPSubnet Address=""/></IPSubnets><Metric Value=""/><Version>7958</Version><Capabilities SchemaVersion="1.0"><Property Name="SSLState" Value="0"/></Capabilities><ServerRemoteName>PR1SITE.CONTOSO.COM</ServerRemoteName><DPType>SERVER</DPType><Windows Trust="1"/><Locality>LOCAL</Locality></LocationRecord></LocationRecords></Site></Sites><RelatedContentIDs/></ContentLocationReply> LocationServices 2/9/2014 7:15:05 PM 3532 (0x0DCC) Distribution Point='http://PR1SITE.CONTOSO.COM/SMS_DP_SMSPKG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f', Locality='LOCAL', DPType='SERVER', Version='7958', Capabilities='<Capabilities SchemaVersion="1.0"><Property Name="SSLState" Value="0"/></Capabilities>', Signature='http://PR1SITE.CONTOSO.COM/SMS_DP_SMSSIG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1.tar', ForestTrust='TRUE', LocationServices 2/9/2014 7:15:05 PM 3532 (0x0DCC) Calling back with locations for location request {C56C01F2-2388-4710-BF3B-A526DB40E35F} LocationServices 2/9/2014 7:15:05 PM 3532 (0x0DCC) 
    Content Transfer Manager receives the Distribution Point location for the requested content and starts a Data Transfer Service job to initiate the download of the update. We see this in ContentTransferManager.log:

    CCTMJob::UpdateLocations({E0452CF4-5B04-4A1A-B8EB-10B11B063249}) ContentTransferManager 2/9/2014 7:15:05 PM 3532 (0x0DCC) CTM_NotifyLocationUpdate ContentTransferManager 2/9/2014 7:15:05 PM 3532 (0x0DCC) Persisted location 'http://PR1SITE.CONTOSO.COM/SMS_DP_SMSPKG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f', Order 0, for CTM job {E0452CF4-5B04-4A1A-B8EB-10B11B063249} ContentTransferManager 2/9/2014 7:15:05 PM 3532 (0x0DCC) Persisted locations for CTM job {E0452CF4-5B04-4A1A-B8EB-10B11B063249}: (LOCAL) http://PR1SITE.CONTOSO.COM/SMS_DP_SMSPKG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f ContentTransferManager 2/9/2014 7:15:05 PM 3532 (0x0DCC) CTM job {E0452CF4-5B04-4A1A-B8EB-10B11B063249} (corresponding DTS job {594E9A72-43D1-48D1-A639-D18DF7D286A2}) started download from 'http://PR1SITE.CONTOSO.COM/SMS_DP_SMSPKG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f' for full content download. ContentTransferManager 2/9/2014 7:15:05 PM 3532 (0x0DCC) CCTMJob::EvaluateState(JobID={E0452CF4-5B04-4A1A-B8EB-10B11B063249}, State=DownloadingData) ContentTransferManager 2/9/2014 7:15:05 PM 3732 (0x0E94) CTM job {E0452CF4-5B04-4A1A-B8EB-10B11B063249} entered phase CCM_DOWNLOADSTATUS_DOWNLOADING_DATA ContentTransferManager 2/9/2014 7:15:05 PM 3532 (0x0DCC) 
    We also see this in CAS.log:

    Location update from CTM for content fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1 and request {856FA4CA-D02A-4E2C-841E-841ED3C7EC01} ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) Download location found 0 - http://PR1SITE.CONTOSO.COM/SMS_DP_SMSPKG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) Download request only, ignoring location update ContentAccess 2/9/2014 7:15:05 PM 3216 (0x0C90) Download started for content fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1 ContentAccess 2/9/2014 7:15:05 PM 848 (0x0350) 
    At this point, Data Transfer Service creates a BITS job to download the file and then monitors the download progress as noted in DataTransferService.log:

    DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} created to download from 'http://PR1SITE.CONTOSO.COM:80/SMS_DP_SMSPKG$/fbb5724a-aa0f-47f9-908a-47068fd8ad6f' to 'C:\Windows\ccmcache\1'. DataTransferService 2/9/2014 7:15:05 PM 3532 (0x0DCC) DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} in state 'DownloadingManifest'. DataTransferService 2/9/2014 7:15:05 PM 3216 (0x0C90) CDTSJob::ProcessManifestCallback - processing manifest for job '{594E9A72-43D1-48D1-A639-D18DF7D286A2}'. DataTransferService 2/9/2014 7:15:05 PM 3532 (0x0DCC) DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} in state 'RetrievedManifest'. DataTransferService 2/9/2014 7:15:05 PM 3532 (0x0DCC) Execute called for DTS job '{594E9A72-43D1-48D1-A639-D18DF7D286A2}'. Current state: 'RetrievedManifest'. DataTransferService 2/9/2014 7:15:05 PM 3532 (0x0DCC) DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} in state 'PendingDownload'. DataTransferService 2/9/2014 7:15:05 PM 3532 (0x0DCC) Starting BITS download for DTS job '{594E9A72-43D1-48D1-A639-D18DF7D286A2}'. DataTransferService 2/9/2014 7:15:05 PM 3532 (0x0DCC) DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} set BITS job to use default credentials. DataTransferService 2/9/2014 7:15:06 PM 3532 (0x0DCC) Starting BITS job '{38E74FCB-4397-4CA9-94AE-BDD49F550EC9}' for DTS job '{594E9A72-43D1-48D1-A639-D18DF7D286A2}' under user 'S-1-5-18'. DataTransferService 2/9/2014 7:15:06 PM 3532 (0x0DCC) DTS::SetCustomHeadersOnBITSJob - setting custom headers on DTS job '{594E9A72-43D1-48D1-A639-D18DF7D286A2}': <none> DataTransferService 2/9/2014 7:15:06 PM 3532 (0x0DCC) DTS::AddTransportSecurityOptionsToBITSJob - Removing security info from DTS job '{594E9A72-43D1-48D1-A639-D18DF7D286A2}'. DataTransferService 2/9/2014 7:15:06 PM 3532 (0x0DCC) DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} in state 'DownloadingData'. DataTransferService 2/9/2014 7:15:06 PM 3532 (0x0DCC) Job: {594E9A72-43D1-48D1-A639-D18DF7D286A2}, Total Files: 1, Transferred Files: 0, Total Bytes: 199093, Transferred Bytes: 5760 DataTransferService 2/9/2014 7:15:06 PM 2656 (0x0A60) Job: {594E9A72-43D1-48D1-A639-D18DF7D286A2}, Total Files: 1, Transferred Files: 0, Total Bytes: 199093, Transferred Bytes: 199093 DataTransferService 2/9/2014 7:15:12 PM 2656 (0x0A60) CDTSJob::JobTransferred : DTS Job ID='{594E9A72-43D1-48D1-A639-D18DF7D286A2}' BITS Job ID='{38E74FCB-4397-4CA9-94AE-BDD49F550EC9}' DataTransferService 2/9/2014 7:15:12 PM 2552 (0x09F8) Job: {594E9A72-43D1-48D1-A639-D18DF7D286A2}, Total Files: 1, Transferred Files: 1, Total Bytes: 199093, Transferred Bytes: 199093 DataTransferService 2/9/2014 7:15:12 PM 2552 (0x09F8) DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} in state 'RetrievedData'. DataTransferService 2/9/2014 7:15:12 PM 2552 (0x09F8) DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} successfully completed download. DataTransferService 2/9/2014 7:15:12 PM 2552 (0x09F8) BITS job '{38E74FCB-4397-4CA9-94AE-BDD49F550EC9}' is not found. The BITS job may have completed already. DataTransferService 2/9/2014 7:15:12 PM 2552 (0x09F8) CBITSDownloadMonitor(DTSJobID={594E9A72-43D1-48D1-A639-D18DF7D286A2}, BITSJobID={38E74FCB-4397-4CA9-94AE-BDD49F550EC9}) ignoring cancelled object. DataTransferService 2/9/2014 7:15:12 PM 2552 (0x09F8) DTSJob {594E9A72-43D1-48D1-A639-D18DF7D286A2} in state 'NotifiedComplete'. DataTransferService 2/9/2014 7:15:12 PM 3532 (0x0DCC) DTS job {594E9A72-43D1-48D1-A639-D18DF7D286A2} has completed: Status : SUCCESS, Start time : 02/09/2014 19:15:05, Completion time : 02/09/2014 19:15:12, Elapsed time : 7 seconds DataTransferService 2/9/2014 7:15:12 PM 3532 (0x0DCC) 
  7. After the download is complete, CTM and CAS are notified, and they mark the download jobs as completed. CAS performs a hash verification of the downloaded content to verify the integrity of the downloaded file. This process occurs for each file, although the following example involves a single update being downloaded. Here's what we see in ContentTransferManager.log:

    CCTMJob::EvaluateState(JobID={E0452CF4-5B04-4A1A-B8EB-10B11B063249}, State=Success) ContentTransferManager CCTMJob::EvaluateState(JobID={E0452CF4-5B04-4A1A-B8EB-10B11B063249}, State=Complete) ContentTransferManager CAS.log: Download completed for content fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1 under context System ContentAccess 2/9/2014 7:15:12 PM 3532 (0x0DCC) The hash we are verifying is SDMPackage:<Content ContentId="fbb5724a-aa0f-47f9-908a-47068fd8ad6f" Version="1"><FileContent Name="windows6.1-kb2705219-v2-x64.cab" Hash="8E8E0175D46B5A8D52C4856FA3D282FAA12ACD63" HashAlgorithm="SHA1" Size="199093"/></Content> ContentAccess 2/9/2014 7:15:12 PM 3532 (0x0DCC) CContentAccessService::NotifyDownloadComplete Start Content Hashing ContentAccess 2/9/2014 7:15:12 PM 3532 (0x0DCC) Hashing file c:\windows\ccmcache\1\windows6.1-kb2705219-v2-x64.cab ContentAccess 2/9/2014 7:15:12 PM 3532 (0x0DCC) Hash matches ContentAccess 2/9/2014 7:15:12 PM 3532 (0x0DCC) Hash verification succeeded for content fbb5724a-aa0f-47f9-908a-47068fd8ad6f.1 downloaded under context System ContentAccess 2/9/2014 7:15:12 PM 3532 (0x0DCC) 
    Then Updates Deployment Agent raises a State Message to update the current enforcement state and then starts the installation of the update. We see the followingin UpdatesDeploymentAgent.log:

    Raised assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) state message successfully. TopicType = Enforce, StateId = 8, StateName = ASSIGNMENT_ENFORCE_ADVANCE_DOWNLOAD_SUCCESS UpdatesDeploymentAgent 2/9/2014 7:15:16 PM 3532 (0x0DCC) Starting install for assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) UpdatesDeploymentAgent 2/9/2014 7:15:16 PM 3532 (0x0DCC) ApplyCIs - JobId = {CEE4AA3A-DE7B-4D9F-8949-E421BBBF2993} UpdatesDeploymentAgent 2/9/2014 7:15:16 PM 3532 (0x0DCC) Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_3cbcf577-5139-49b8-afe8-620af5c52f95) Progress: Status = ciStateWaitInstall, PercentComplete = 0, DownloadSize = 0, Result = 0x0 UpdatesDeploymentAgent 2/9/2014 7:15:16 PM 2860 (0x0B2C) Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_ada7cf51-66b0-4a00-b37b-68d569d6ff8b) Progress: Status = ciStateWaitInstall, PercentComplete = 0, DownloadSize = 0, Result = 0x0 UpdatesDeploymentAgent 2/9/2014 7:15:16 PM 2860 (0x0B2C) Update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_e06056e3-0199-4c68-8ac3-bdddff356a0a) Progress: Status = ciStateWaitInstall, PercentComplete = 0, DownloadSize = 0, Result = 0x0 UpdatesDeploymentAgent 2/9/2014 7:15:16 PM 2860 (0x0B2C) 
    We also see this in UpdatesHandler.log:

    Job {CEE4AA3A-DE7B-4D9F-8949-E421BBBF2993} is starting execution UpdatesHandler 2/9/2014 7:15:16 PM 1428 (0x0594) CDeploymentJob::InstallUpdatesInBatch - Batch or non-batch install is not in progress for the job ({CEE4AA3A-DE7B-4D9F-8949-E421BBBF2993}). So allowing install.. UpdatesHandler 2/9/2014 7:15:16 PM 3216 (0x0C90) Update (3cbcf577-5139-49b8-afe8-620af5c52f95) added to the installation batch UpdatesHandler 2/9/2014 7:15:16 PM 3216 (0x0C90) Update (ada7cf51-66b0-4a00-b37b-68d569d6ff8b) added to the installation batch UpdatesHandler 2/9/2014 7:15:16 PM 3216 (0x0C90) Update (e06056e3-0199-4c68-8ac3-bdddff356a0a) added to the installation batch UpdatesHandler 2/9/2014 7:15:17 PM 3216 (0x0C90) Got execute info for (3) updates UpdatesHandler 2/9/2014 7:15:17 PM 3216 (0x0C90) Updates installation started as batch UpdatesHandler 2/9/2014 7:15:26 PM 3216 (0x0C90)
  8. Windows Update Agent Handler then copies the downloaded binaries to the Windows Update Agent cache (C:\Windows\SoftwareDistribution\Download) directory and instructs Windows Update Agent to start the installation process. This can be seen in WUAHandler.log:

    Adding file to list for CopyToCache(): C:\Windows\ccmcache\1\windows6.1-kb2705219-v2-x64.cab WUAHandler 2/9/2014 7:15:25 PM 3216 (0x0C90) CopyToCache() for update (fbb5724a-aa0f-47f9-908a-47068fd8ad6f) completed successfully WUAHandler 2/9/2014 7:15:26 PM 3216 (0x0C90) Adding file to list for CopyToCache(): C:\Windows\ccmcache\2\windows6.1-kb2712808-x64.cab WUAHandler 2/9/2014 7:15:26 PM 3216 (0x0C90) CopyToCache() for update (3e9b1132-9ccd-439d-b32a-5cefd19735d1) completed successfully WUAHandler 2/9/2014 7:15:26 PM 3216 (0x0C90) Adding file to list for CopyToCache(): C:\Windows\ccmcache\3\windows6.1-kb2698365-x64.cab WUAHandler 2/9/2014 7:15:26 PM 3216 (0x0C90) CopyToCache() for update (d2a9ee23-9cab-4843-b040-e2da1cc167e9) completed successfully WUAHandler 2/9/2014 7:15:26 PM 3216 (0x0C90) Update(s) downloaded to WUA file cache, starting installation. WUAHandler 2/9/2014 7:15:26 PM 3216 (0x0C90) Async installation of updates started. WUAHandler 2/9/2014 7:15:26 PM 3216 (0x0C90) Update 1 (3cbcf577-5139-49b8-afe8-620af5c52f95) finished installing (0x00000000), Reboot Required? Yes WUAHandler 2/9/2014 7:15:29 PM 2840 (0x0B18) Update 2 (ada7cf51-66b0-4a00-b37b-68d569d6ff8b) finished installing (0x00000000), Reboot Required? Yes WUAHandler 2/9/2014 7:15:30 PM 996 (0x03E4) Update 3 (e06056e3-0199-4c68-8ac3-bdddff356a0a) finished installing (0x00000000), Reboot Required? Yes WUAHandler 2/9/2014 7:15:39 PM 268 (0x010C) Async install completed. WUAHandler 2/9/2014 7:15:39 PM 2396 (0x095C) Installation of updates completed. WUAHandler 2/9/2014 7:15:39 PM 2604 (0x0A2C) 
    We also see the following in WindowsUpdate.log:

    2014-02-09 19:15:26:130 800 ed0 Agent ** START ** Agent: Installing updates [CallerId = CcmExec] 2014-02-09 19:15:26:130 800 ed0 Agent * Updates to install = 3 2014-02-09 19:15:26:254 1048 84c Handler Starting install of CBS update FBB5724A-AA0F-47F9-908A-47068FD8AD6F 2014-02-09 19:15:29:218 1048 84c Handler Completed install of CBS update with type=3, requiresReboot=1, installerError=0, hr=0x0 2014-02-09 19:15:29:265 1048 84c Handler Starting install of CBS update 3E9B1132-9CCD-439D-B32A-5CEFD19735D1 2014-02-09 19:15:30:435 1048 84c Handler Completed install of CBS update with type=3, requiresReboot=1, installerError=0, hr=0x0 2014-02-09 19:15:30:451 1048 84c Handler Starting install of CBS update D2A9EE23-9CAB-4843-B040-E2DA1CC167E9 2014-02-09 19:15:39:296 1048 84c Handler Completed install of CBS update with type=3, requiresReboot=1, installerError=0, hr=0x0 2014-02-09 19:15:39:327 788 9f8 COMAPI - Reboot required = Yes 2014-02-09 19:15:39:327 788 9f8 COMAPI -- END -- COMAPI: Install [ClientId = CcmExec]
  9. After the updates are installed, Updates Deployment Agent checks whether any updates require a reboot, and then it notifies the user if client settings are configured to allow such notifications. This is shown in UpdatesDeployment.log:

    No installations in pipeline, notify reboot. NotifyUI = True UpdatesDeploymentAgent 2/9/2014 7:15:39 PM 3216 (0x0C90) Notify reboot with deadline = Sunday, Feb 09, 2014. - 19:15:39, Ignore reboot Window = False, NotifyUI = True UpdatesDeploymentAgent 2/9/2014 7:15:39 PM 3216 (0x0C90) Raised assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) state message successfully. TopicType = Enforce, StateId = 5, StateName = ASSIGNMENT_ENFORCE_PENDING_REBOOT UpdatesDeploymentAgent 2/9/2014 7:15:39 PM 2604 (0x0A2C)
  10. After the computer restarts, a post-reboot detection scan is started for the deployment to verify that updates are installed and to raise state messages for the update and deployment to indicate that updates are installed and that enforcement was successful. This is noted in UpdatesDeployment.log:

    CTargetedUpdatesManager::DetectRebootPendingUpdates - Total Pending reboot updates = 3 UpdatesDeploymentAgent 2/9/2014 7:18:56 PM 2780 (0x0ADC) Initiated detect for pending reboot updates after system restart - JobId = {53F4851F-7E63-4C7E-952D-78345039FFFC} UpdatesDeploymentAgent 2/9/2014 7:18:56 PM 2780 (0x0ADC) CUpdatesJob({53F4851F-7E63-4C7E-952D-78345039FFFC}): Job completion received. UpdatesDeploymentAgent 2/9/2014 7:19:19 PM 2436 (0x0984) CUpdatesJob({53F4851F-7E63-4C7E-952D-78345039FFFC}): Detect after reboot job completed with result = 0x0 UpdatesDeploymentAgent 2/9/2014 7:19:19 PM 2436 (0x0984) Raised update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_e06056e3-0199-4c68-8ac3-bdddff356a0a) enforcement state message successfully. StateId = 10, StateName = CI_ENFORCEMENT_SUCCESSFULL UpdatesDeploymentAgent 2/9/2014 7:19:19 PM 2436 (0x0984) Raised update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_ada7cf51-66b0-4a00-b37b-68d569d6ff8b) enforcement state message successfully. StateId = 10, StateName = CI_ENFORCEMENT_SUCCESSFULL UpdatesDeploymentAgent 2/9/2014 7:19:19 PM 2436 (0x0984) Raised update (Site_D3A5F7EA-25D4-4C6B-B47C-C74997522A76/SUM_3cbcf577-5139-49b8-afe8-620af5c52f95) enforcement state message successfully. StateId = 10, StateName = CI_ENFORCEMENT_SUCCESSFULL UpdatesDeploymentAgent 2/9/2014 7:19:19 PM 2436 (0x0984) Raised assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) state message successfully. TopicType = Compliance, Signature = 5e176837, IsCompliant = True UpdatesDeploymentAgent 2/9/2014 7:19:19 PM 2456 (0x0998) Raised assignment ({B040D195-8FA8-48D3-953F-17E878DAB23D}) state message successfully. TopicType = Enforce, StateId = 4, StateName = ASSIGNMENT_ENFORCE_SUCCESS UpdatesDeploymentAgent 2/9/2014 7:19:19 PM 2456 (0x0998) 
    At this point, the software updates deployment has been downloaded and successfully installed on the client, and the process is complete.
Properties

Article ID: 3090265 - Last Review: 09/14/2015 22:50:00 - Revision: 3.0

Microsoft System Center 2012 Configuration Manager, Microsoft System Center 2012 Configuration Manager Service Pack 2, Microsoft System Center 2012 Configuration Manager Service Pack 1, Microsoft System Center 2012 R2 Configuration Manager, Microsoft System Center 2012 R2 Configuration Manager Service Pack 1

  • kbhowto kbsurveynew kbexpertiseadvanced kbinfo KB3090265
Feedback