Troubleshoot the Install Application task sequence in Microsoft Configuration Manager

What does this guide do?

This guide helps you understand the Install Application task sequence process and troubleshoot common problems that may occur. The Install Application task sequence step issued to install applications as part of the overall task sequence. This step can install a set of applications that are specified by the task sequence step, or a set of applications that are specified by a dynamic list of task sequence variables. When this step is run, the application installation begin immediately without waiting for a policy polling interval.

The information in this guide applies to System Center 2012 Configuration Manager (ConfigMgr 2012), System Center 2012 R2 Configuration Manager (ConfigMgr 2012 R2) and all versions of Configuration Manager in the current branch (e.g. Configuration Manager 1511 and Configuration Manager 1602).

Note that this guide assumes that the Configuration Manager environment has already been installed and configured. For additional information please see the Documentation Library for System Center 2012 Configuration Manager.

Who is it for?

This guide is for IT professionals who need to understand, diagnose and troubleshoot the Install Application task sequence process in Microsoft System Center Configuration Manager.

How does it work?

This guide begins where the Install Application task sequence process kicks off and examine search of the major steps. Suggestions for troubleshooting failures are provided as you progress through the guide.

Estimated time of completion:

30-45 minutes.

Getting Started

Overview of the Install Application task

The Install Application task process outlined here covers a single application installtask, although it can also be used for troubleshooting the installation of multipleapplications based on a list.

When the Install Application process runs, the application checks the applicability of therequirement rules and detection method on the deployment types of theapplication. Based on the results of this check, the application installs theapplicable deployment type. If a deployment type contains dependencies, the dependent deployment type is evaluated and installed as part of the Install Application step.

Note

Application dependencies are not supported forstand-alone media.

For more information about the Install Application task sequence process please review this TechNet article.

Task Sequence Manager parses the task sequence XML and begins the Install Application task

Application installations in a task sequence have a lot incommon with application installations outside of a task sequence, in that theyboth leverage Configuration manager compliance settings.However, they do not function exactly the same as there are more components involved due to the nature of running during a task sequence.

As the task sequence progresses, it maintains the status oftasks and the associated execution status using task sequence environmentvariables (see https://technet.microsoft.com/en-us/library/hh273375.aspx for more information). These built in variables provide information about theenvironment where the task sequence is running, and their values for thesevariables are available throughout the whole task sequence. In the case of an Install Application task, these built invariables are initialized before the process runs in the task sequence.

Task Sequence Manager sets global environment variables for the next instruction, _SMSTSCurrentActionName to Install Application and _SMSTSNexInstructionPointer to the Instruction Pointer assigned to this task. This can be observed in the following entries in SMSTS.log:

01-13-2016 17:56:35.510   TSManager    2176 (0x880)    Start executing an instruction. Instructionname: Install Application. Instruction pointer: 32 01-13-2016 17:56:35.510   TSManager    2176 (0x880)    Set a global environment variable_SMSTSCurrentActionName=Install Application 01-13-2016 17:56:35.510   TSManager    2176 (0x880)    Set a global environment variable_SMSTSNextInstructionPointer=32

TSManager then saves the execution state of the task sequenceand the environment (TSEnv.dat) to the local hard disk as seen here in SMSTS.log:

01-13-2016 17:56:35.510    TSManager    2176 (0x880)    Successfully save execution state and environment to local hard disk

Task Sequence Manager starts the execution of the next instruction in the sequence, based on the execution history of the previous instruction and the next instruction pointer:

01-13-2016 17:56:35.510   TSManager    2176 (0x880)    Start executing an instruction. Instructionname: Install Application. Instruction pointer: 32

Task Sequence Manager then sets local default variables for applications:

01-13-201617:56:35.510    TSManager    2176 (0x880)    Set a local default variableOSDApp0Description01-13-201617:56:35.510    TSManager    2176 (0x880)    Set a local default variableOSDApp0DisplayName 01-13-201617:56:35.510    TSManager    2176 (0x880)    Set a local default variable OSDApp0Name 01-13-201617:56:35.510    TSManager    2176 (0x880)    Set a local default variable OSDAppCount 01-13-201617:56:35.525    TSManager    2176 (0x880)    Set a global environment variable_SMSTSLogPath=C:\WINDOWS\CCM\Logs\SMSTSLog

Task Sequence Manager now sets the command line for the application install (smsappinstall.exe) based on the task sequence XML policy that it has parsed and begins executing it bycalling smsappinstall.exe, as shown here in SMSTS.log:

01-13-2016 17:56:35.525   TSManager    2176 (0x880)    Executing command line: smsappinstall.exe/app:ScopeId_GUID/Application_GUID/basevar: /continueOnError:False

At this point the Install Application task (smsappinstall.exe) begins to install the application, although the command line to run the installation will not happen for some time yet.First, all the necessary information must be acquired.

Troubleshoot the process above

Continue on to the next step

Getting Started

Overview of the Install Application task

Note

Application dependencies are not supported forstand-alone media.

For more information about the Install Application task sequence process please review this TechNet article.

Task Sequence Manager parses the task sequence XML and begins the Install Application task

01-13-2016 17:56:35.510   TSManager    2176 (0x880)    Start executing an instruction. Instructionname: Install Application. Instruction pointer: 32 01-13-2016 17:56:35.510   TSManager    2176 (0x880)    Set a global environment variable_SMSTSCurrentActionName=Install Application 01-13-2016 17:56:35.510   TSManager    2176 (0x880)    Set a global environment variable_SMSTSNextInstructionPointer=32

TSManager then saves the execution state of the task sequenceand the environment (TSEnv.dat) to the local hard disk as seen here in SMSTS.log:

01-13-2016 17:56:35.510    TSManager    2176 (0x880)    Successfully save execution state and environment to local hard disk

Task Sequence Manager starts the execution of the next instruction in the sequence, based on the execution history of the previous instruction and the next instruction pointer:

01-13-2016 17:56:35.510   TSManager    2176 (0x880)    Start executing an instruction. Instructionname: Install Application. Instruction pointer: 32

Task Sequence Manager then sets local default variables for applications:

01-13-201617:56:35.510    TSManager    2176 (0x880)    Set a local default variableOSDApp0Description01-13-201617:56:35.510    TSManager    2176 (0x880)    Set a local default variableOSDApp0DisplayName 01-13-201617:56:35.510    TSManager    2176 (0x880)    Set a local default variable OSDApp0Name 01-13-201617:56:35.510    TSManager    2176 (0x880)    Set a local default variable OSDAppCount 01-13-201617:56:35.525    TSManager    2176 (0x880)    Set a global environment variable_SMSTSLogPath=C:\WINDOWS\CCM\Logs\SMSTSLog

01-13-2016 17:56:35.525   TSManager    2176 (0x880)    Executing command line: smsappinstall.exe/app:ScopeId_GUID/Application_GUID/basevar: /continueOnError:False

Troubleshoot the process above

Continue on to the next step

Task Sequence Manager parses the task sequence XML and begins the Install Application task

During this step, the Install Application component evaluates the task sequence policy and stores it in WMI. The application checks the applicability of the requirement rules and detection method on the deployment types of the application. This is done using CIStore and CIStateStore to evaluate the applicability and state of the Configuration Items and the Configuration Data Content associated with the application and deployment Type. The result is that the CI's will be marked for download.

Install Application parses the command line and identifies the application name.

SMSTS.log:

01-13-2016 17:56:35.572    InstallApplication    1608 (0x648)    Application Names: 01-13-2016 17:56:35.572    InstallApplication    1608 (0x648)    'ScopeId_GUID/Application_GUID'

Install Application sets variables for the application.

SMSTS.log:

01-13-2016 17:56:35.666    InstallApplication    1608 (0x648)    Setting TSEnv variable 'SMSTSAppPolicyEvaluationJobID__ScopeId_GUID/Application_GUID'=''01-13-2016 17:56:35.666    InstallApplication    1608 (0x648)    Setting TSEnv variable 'SMSTSInstallApplicationJobID__ScopeId_GUID/Application_GUID'='

It next looks for policy scope ID.

SMSTS.log:

01-13-2016 17:56:35.666    InstallApplication    1608 (0x648)    Retrieving value from TSEnv for '_SMSTSPolicy_ScopeId_GUID/Application_GUID

Now it looks for and retrieves the value of the application policy from the task sequence environment (TSEnv.dat).

SMSTS.log:

01-13-2016 17:56:35.666    InstallApplication    1608 (0x648)    Found App policy modelname:ScopeId_GUID/RequiredApplication_GUID and CIversion:10

Install Application then decompresses the policy.

SMSTS.log:

01-13-2016 17:56:35.666    InstallApplication    1608 (0x648)    Found App policy modelname:ScopeId_GUID/RequiredApplication_GUID and CIversion:10 01-13-2016 17:56:35.682    InstallApplication    1608 (0x648)    ::DecompressBuffer(65536) 01-13-2016 17:56:35.682    InstallApplication    1608 (0x648)    Decompression (zlib) succeeded: original size 145382, uncompressed size 1238794.

The policies are stored in WMI by the Install Application component in the root\ccm\policy\actualconfig namespace.

SMSTS.log:

01-13-2016 17:56:36.119    InstallApplication    1608 (0x648)    Locked ActualConfig successfully 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    New/Changed ActualConfig policy instance(s) : 6 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [1] Added/updated setting 'ccm_applicationciassignment:assignmentid=dep-meh20009-scopeid_GUID/application_GUID'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [2] Added/updated setting 'ccm_civersioninfo:modelname=scopeid_GUID/application_GUID:version=10'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [3] Added/updated setting 'ccm_civersioninfo:modelname=scopeid_GUID/deploymenttype_GUID:version=6'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [4] Added/updated setting 'ccm_civersioninfo:modelname=scopeid_GUID/requiredapplication_GUID:version=10'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [5] Added/updated setting 'ccm_civersioninfo:modelname=windows/all_windows_client_server:version=1'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [6] Added/updated setting 'ccm_scheduler_scheduledmessage:scheduledmessageid=dep-meh20009-scopeid_GUID/application_GUID'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    Unlocked ActualConfig successfully 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    Raising event: instance of CCM_PolicyAgent_SettingsEvaluationComplete { ClientID = "GUID:ClientGUID"; DateTime = "20160113225636.150000+000"; PolicyNamespace = "\\\\.\\root\\ccm\\policy\\machine\\actualconfig"; ProcessID = 1392; ThreadID = 1608; };

Policy Agent Provider then processes the change in the actualconfig policy namespace.

PolicyAgentProvider.log

01-13-2016 17:56:36.150    PolicyAgentProvider    2424 (0x978)    [000000B205C423A8] 1 settings change(s) detected. 01-13-2016 17:56:36.182    PolicyAgentProvider    2424 (0x978)    [000000B205C423A8] Queued worker to process these 1 settings change(s) 01-13-2016 17:56:36.182    PolicyAgentProvider    2420 (0x974)    --- Processing 1 settings change(s). 01-13-2016 17:56:36.182    PolicyAgentProvider    2420 (0x974)    --- [1] __InstanceCreationEvent settings change on object CCM_ApplicationCIAssignment.AssignmentID="DEP-MEH20009-ScopeId_GUID/Application_GUID". 01-13-2016 17:56:36.182    PolicyAgentProvider    2420 (0x974)    --- Begin Indicating 1 settings change(s). 01-13-2016 17:56:36.182    PolicyAgentProvider    2420 (0x974)    --- Completed Indicating 1 settings change(s).

DCMAgent processes the change and begins to evaluate the CI's for the application install.

DCMAgent.log:

01-13-2016 17:56:36.197   DCMAgent    2608 (0xa30)    DCMAgent::ProcessAssignmentChange.

Policy Agent then updates the Configuration Item info in the CI Store.

CIStore.log:

01-13-2016 17:56:36.260   CIStore    2608 (0xa30)   CCIStore::ProcessCITargetEvent - CIScopeId_GUID/Application_GUID:10 will be targeted for SYSTEM 01-13-2016 17:56:36.275   CIStore    2608 (0xa30)   CCIStore::ProcessCITargetEvent - CI ScopeId_GUID/DeploymentType_GUID:6 will be targeted for SYSTEM

The state of the application CI is added for the download, then the state of any associated application deployment type CI's are checked by the CIStateStore. Any CIs marked as 'not found' are added for download.

CIStore.log:

01-13-2016 17:56:36.275    CIStore    2608 (0xa30)    CCIStoreTargetedCIDownloader::AddCI - CI Modelname:ScopeId_GUID/Application_GUID Version:10 has been added for download

CIStateStore.log:

01-13-2016 17:56:36.322    CIStateStore    2608 (0xa30)    CCIStateTransition::ExtractStateDetails - CI ModelName ScopeId_GUID/DeploymentType_GUID, version 6 not found in store.

CIStore.log:

01-13-2016 17:56:36.369    CIStore    2608 (0xa30)    CCIStoreTargetedCIDownloader::AddCI - CI Modelname:ScopeId_GUID/DeploymentType_GUID Version:6 has been added for download

Now that this is done, the DCM agent will start its job to evaluate the application policies and begin acquiring the necessary information from the database.

Troubleshoot the process above

Continue on to the next step

DCM Agent manages acquisition of the Configuration Items from the site database

In the previous step, the CIs were marked for download. The DCM agent will now utilize CI Agent to begin acquiring the Configuration Items and Configuration Data Content (SDM package) from the database. This includes information such as Application Properties, Application Manifest, Deployment Type Properties, Deployment Type Manifest, Application Intent Policies for Compliance, etc.

The acquisition of this information does not happen all at once. The DCM agent utilizes the following client-side components at different times to do this work:

CI Agent
CI Downloader
CIStore
Data Transfer Service
Content Transfer Manager
All of this information is requested from the database via the management point and the requests and responses can be monitored via the MP_GetSDMPackage.log file.
Full Order of MP_GetSDMDocument execution/Data Transfer Service download for each App Install task:

App PROPERTIES - Results have basic App CI info. Name only.
App MANIFEST - links Policy Platform CI Documents with the Application CI.
App Intent Policy - Desired State of the Application, required.
App MANIFEST again. Note the different HASH. This time the results have extended info, WMI namespaces for WMI namespaces for the CI Manifests, App DT CI References.
App PROPERTIES again. Note the different HASH. This time the results include, extended/custom PROPERITES, Publisher, release date, icons, etc.
App DT PROPERTIES. Results include Description, estimated install time, post install behavior, etc.
App DT MANIFEST results have extended info, WMI namespaces for the CI Manifests.
App policy, results include Policy Platform MOF to be compiled client side with Desired State, App Properties and App DT Properties.
App DT Policy is compressed. Unable to decompress.

Tip:

Each component involved in the process will create a job, with a Job ID that can be used to track the progress. DCM Agent is always the first in the process. When troubleshooting, note the Job ID's for each component as you review the logs then follow the Job ID.

Below is an example of the request and download of only the Application PROPERTIES and MANIFEST (steps 1 and 2 from above).

DCM Agent job ID.
DCMAgent.log:

01-13-201617:56:36.979    DCMAgent    1568(0x620)    CDCMAgentJobMgr::StartJob - Starting DCM Agent job{ID}

DCM Agent creates a job for CI Agent.
DCMAgent.log:

01-13-2016 17:56:37.088    DCMAgent    2768 (0xad0)    DCMAgentJob({ID}): CDCMAgent::InitiateCIAgentJob - Starting CI Agent Job {E672EA3F-29D7-46E5-B05E-7D72DF2C50E0} for target: machine. Refer to this CI agent job ID in ciagent.log for more details

CIDownloader creates a job.
CIDownloader.log:

01-13-2016 17:56:37.166    CIDownloader    2728 (0xaa8)    CIDownloaderJob({ID}): SetFailureCondition - Job will fail immediately on error

DCM Agent is tracking the progress via its own job.
DCMAgent.log:

01-13-2016 17:56:37.182    DCMAgent    2768 (0xad0)    DCMAgentJob({ID}): CDCMAgentJob::HandleEvent(Event=NotifyProgress, CurrentState=Evaluating)

CIDownloader calculates the scope of the CI which initiates a check of the CI Store.
CIDownloader.log:

01-13-2016 17:56:37.182    CIDownloader    2728 (0xaa8)    [Calculate Scope] - Adding CI Modelname:ScopeId_GUID/RequiredApplication_GUID Version:10 to Scoped CIs List of root Modelname:ScopeId_GUID/RequiredApplication_GUID Version:10

CIStore.log:

01-13-201617:56:37.182    CIStore    2728(0xaa8)    CCIStore::GetTargetedCIReference invoked for CIScopeId_GUID/RequiredApplication_GUID:10targeted to SYSTEM

The CI is queried for in CI State Store and not found.
CIStateStore.log:

01-13-201617:56:37.197    CIStateStore    2728(0xaa8)    CCIStateTransition::ExtractStateDetails - CIModelNameScopeId_GUID/RequiredApplication_GUID,version 10 not found in store.

Since it is not found, it is then added to the CIDownloader job.
CIDownloader.log:

01-13-201617:56:37.213    CIDownloader    2728(0xaa8)   CIDownloaderJob({ID}): CI with ModelNameScopeId_GUID/RequiredApplication_GUID,Version 10. Model:(null) added to job.

CI Agent now starts the CIDownloader job to download the CI's.
CIAgent.log:

01-13-201617:56:37.229    CIAgent    2728(0xaa8)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}):Started CIDownloadJob({1B065017-7AC4-4729-B15D-6415BED35D0E})

The CIDownloader job transitions to the Downloading Packages phase and adds the source files for the CIs to the request. Note that at this point, Packages refers to the SDM package, not content (binaries).
CIDownloader.log:

01-13-201617:56:37.229    CIDownloader    2728(0xaa8)   CIDownloaderJob({ID}): DownloadPackages  01-13-201617:56:37.229    CIDownloader    2728(0xaa8)    --Source file:.sms_dcm?Id&amp;DocumentId=ScopeId_GUID/RequiredApplication_GUID/10/MANIFEST&amp;Hash=HashString&amp;Compression=zlib  01-13-201617:56:37.229    CIDownloader    2728(0xaa8)    --Source file:.sms_dcm?Id&amp;DocumentId=ScopeId_GUID/RequiredApplication_GUID/10/PROPERTIES&amp;Hash=HashString&amp;Compression=zlib

CIDownloader calls into Data Transfer Service to request the manifest and properties for the application as well as the Application Deployment Type.
DataTransferService.log:

01-13-201617:56:37.275    DataTransferService    2728(0xaa8)    Added(source=.sms_dcm?Id&DocumentId=ScopeId_GUID/RequiredApplication_GUID/10/PROPERTIES&Hash=HashString&Compression=zlib,dest={JobID}_2.zip)pair from manifest.  01-13-201617:56:37.275    DataTransferService    2728(0xaa8)    Added(source=.sms_dcm?Id&DocumentId=ScopeId_GUID/RequiredApplication_GUID/10/MANIFEST&Hash=HashString&Compression=zlib,dest={JobID}_1.zip)pair from manifest.

Data Transfer Service calls into the MP_GetSDMPacakge ISAPI on the management point, which in turn requests the SDM package information from the database by triggering a SQL stored procedure.
SQL Profiler:

exec MP_GetSdmDocument N'ScopeId_GUID/RequiredApplication_GUID/10/PROPERTIES',N'HashString',N'1',N'1'  exec MP_GetSdmDocument N'ScopeId_GUID/RequiredApplication_GUID/10/MANIFEST',N'HashString',N'1',N'1'

Data Transfer Service starts a BITS job and adds the path to the job once the response is received and begins downloading the data.
DataTransferService.log:

01-13-201617:56:37.432    DataTransferService    2316(0x90c)    Starting BITS job'{ID}' for DTS job'{ID}' under user 'S-1-5-18'.  01-13-201617:56:37.479    DataTransferService    2316(0x90c)    BITSHelper: Full source path to be transferred = http://PS1.contoto.lab:80/SMS_MP/.sms_dcm?Id&DocumentId=ScopeId_GUID/RequiredApplication_GUID/10/PROPERTIES&Hash=HashString&Compression=zlib 01-13-201617:56:37.479    DataTransferService    2316(0x90c)    Adding to BITS job:{ID}_2.zip  01-13-201617:56:37.479    DataTransferService    2316(0x90c)    BITSHelper: Full source path to be transferred= http://PS1.contoto.lab:80/SMS_MP/.sms_dcm?Id&DocumentId=ScopeId_GUID/RequiredApplication_GUID/10/MANIFEST&Hash=HashString&Compression=zlib 56:37.479   DataTransferService    2316 (0x90c)    Adding toBITS job: {ID}_1.zip

Monitor DataTransferService.log for the completion of the SDM package download and search for lines similar to below.
Configuration Item #1

01-13-2016 17:56:37.588    DataTransferService    2748 (0xabc)    Job: {ID}, Total Files: 2, Transferred Files: 2, Total Bytes: 1160, Transferred Bytes: 1160 01-13-2016 17:56:37.588    DataTransferService    2748 (0xabc)    DTSJob {ID} successfully completed download.

Configuration Item #2

01-13-2016 17:56:37.791    DataTransferService    1568 (0x620)    Job: {ID}, Total Files: 3, Transferred Files: 3, Total Bytes: 2616, Transferred Bytes: 2616 01-13-2016 17:56:37.791    DataTransferService    1568 (0x620)    DTSJob {ID} successfully completed download.

Configuration Item #3

01-13-2016 17:56:37.994    DataTransferService    2748 (0xabc)    Job: {ID}, Total Files: 3, Transferred Files: 3, Total Bytes: 3216, Transferred Bytes: 3216 01-13-2016 17:56:37.994    DataTransferService    2748 (0xabc)    DTSJob {ID} successfully completed download.

Configuration Item #4

01-13-2016 17:56:38.104    DataTransferService    1568 (0x620)    Job: {ID}, Total Files: 1, Transferred Files: 1, Total Bytes: 4172, Transferred Bytes: 4172 01-13-2016 17:56:38.104    DataTransferService    1568 (0x620)    DTSJob {ID} successfully completed download.

Troubleshoot the process above

Continue on to the next step

CI Agent processes the CIs and saves them locally in CCMStore.sdf

Once the Data Transfer Service job has completed downloading all of the CIs referenced by Application Install, CIDownloader will check the hash of the CIs, decompress them, and then persist them in CI Store. It will do this for each of the CIs associated with the application.

The following process will occur for any CI that has a relationship with the application being installed during this task. Merging the logs will help track the progress of each. Follow the Job ID's.

Individually, after each CI is completely downloaded, Data Transfer Service marks the job complete and CIDownloader confirms the hash.

DataTransferService.log:

01-13-2016 17:56:37.588    DataTransferService    2748 (0xabc)    Job: {ID}, Total Files: 2, Transferred Files: 2, Total Bytes: 1160, Transferred Bytes: 116001-13-2016 17:56:37.588    DataTransferService    2748 (0xabc)    DTSJob {ID} successfully completed download. 01-13-2016 17:56:37.604    DataTransferService    2316 (0x90c)    DTSJob {ID} in state 'NotifiedComplete'.

CIDownloader.log:

01-13-2016 17:56:37.619    CIDownloader    2768 (0xad0)    ::DecompressFile(C:\WINDOWS\CCM\CIDownloader\Staging\}_1.zip,65536,C:\WINDOWS\CCM\CIDownloader\Staging\{JobID}_1.xml) 01-13-2016 17:56:37.619    CIDownloader    2768 (0xad0)    VerifyCIDocumentHash - Preparing to verify hash for CI document ScopeId_GUID/RequiredApplication_GUID/10/MANIFEST01-13-2016 17:56:37.619    CIDownloader    2768 (0xad0)    ::DecompressFile(C:\WINDOWS\CCM\CIDownloader\Staging\{JobID}_2.zip,65536,C:\WINDOWS\CCM\CIDownloader\Staging\{JobID}_2.xml) 01-13-2016 17:56:37.619    CIDownloader    2768 (0xad0)    VerifyCIDocumentHash - Preparing to verify hash for CI document ScopeId_GUID/RequiredApplication_GUID/10/PROPERTIES

Once CIDownloader has acquired all the CIs from the management point, it will call back into CI Agent and begin persisting the CIs.

CIAgent.log:

01-13-2016 17:56:38.119    CIAgent    2768 (0xad0)    CIAgentJob({ID}): CAgentJob::NotifyComplete - CIDownloader callback 01-13-2016 17:56:38.119    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=PersistingCIModels) 01-13-2016 17:56:38.119    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): PersistCIModels

CIDownloader will persist the CIs into the CI Digest Store.

CIDownloader.log:

01-13-2016 17:56:38.119    CIDownloader    2728 (0xaa8)    CCIDigestStore::PersistIntegratedCIDefinitions 01-13-2016 17:56:38.182    CIDownloader    2728 (0xaa8)    DCM::LanternUtils::StoreModelDocument 01-13-2016 17:56:38.385    CIDownloader    2728 (0xaa8)    DCM::LanternUtils::StoreModelDocument succeeded 01-13-2016 17:56:38.385    CIDownloader    2728 (0xaa8)    CCIDigestStore::PersistIntegratedCIDefinitions - Lantern model document compiled to WMI. 01-13-2016 17:56:38.463    CIDownloader    2728 (0xaa8)    CCIDigestStore::PersistIntegratedCIDefinitions - Creating file C:\WINDOWS\CCM\CIDownloader\DigestStore\321EC9594015C9F9E6780EB4FEC210A78BEC119CB44ADE46A94C5F5B26F47948.xml 01-13-2016 17:56:38.463    CIDownloader    2728 (0xaa8)    CCIDigestStore::PersistIntegratedCIDefinitions - Creating file C:\WINDOWS\CCM\CIDownloader\DigestStore\B7BE90F13A8B7B3BD870B8DC5D0DF3E8378137B385988C2037A5C94EF21E4BCB.xml 01-13-2016 17:56:38.463    CIDownloader    2728 (0xaa8)    CCIDigestStore::PersistIntegratedCIDefinitions - Dcm Digest persisted to CIDigestStore.

CIDownloader completes persisting of the CIs and marks its job complete.

CIDownloader.log:

01-13-2016 17:56:38.463    CIDownloader    2728 (0xaa8)    CCIDigestStore::PersistIntegratedCIDefinitions - Dcm Digest persisted to CIDigestStore. 01-13-2016 17:56:38.463    CIDownloader    2728 (0xaa8)    CCIDownloader::CompleteJob for job {ID}.

CI Agent checks the CI Store now for the CIs needed by the Application Install process. CI Store returns the appropriate values.

CIAgent.log:

01-13-2016 17:56:38.479    CIAgent    2728 (0xaa8)    CCIInfo::AddDepedentCI for ModelName: ScopeId_GUID/Application_GUID Version: 10 01-13-2016 17:56:38.479    CIStore    2728 (0xaa8)    CCIStore::GetCIEx - Requested CI ModelName ScopeId_GUID/Application_GUID, Version 10 returned from [Store] 01-13-2016 17:56:38.479    CIStore    2728 (0xaa8)    Found property (DisplayName) value but only with fallback to US English: ConfigMgr 2012 Toolkit R2 01-13-2016 17:56:38.510    CIAgent    2728 (0xaa8)    CCIInfo::AddDepedentCI for ModelName: ScopeId_GUID/DeploymentType_GUID Version: 6 01-13-2016 17:56:38.510    CIStore    2728 (0xaa8)    CCIStore::GetCIEx - Requested CI ModelName ScopeId_GUID/DeploymentType_GUID, Version 6 returned from [Store] 01-13-2016 17:56:38.510    CIStore    2728 (0xaa8)    Found property (DisplayName) value but only with fallback to default: ConfigMgr 2012 Toolkit R2 - Windows Installer (*.msi file)

Next, CI Agent will perform further processing by invoking the SDM model. SDM packages link together CIs and provide further information about the configuration that will be implemented. Part of this process also binds the CIs to policies using the Microsoft Policy Platform.

Troubleshoot the process above

Continue on to the next step

CI Agent performs further processing of CIs using the SDM model

All of the work of acquiring the necessary CIs and SDM package data has been downloaded at this point. CI Agent will invoke SDMMethod to bind the CIs to their Policy Platform/Lantern Policies stored in WMI (located at root\Microsoft\PolicyPlatform\Documents\Local), evaluate their applicability, and ultimately mark them as Available for Enforcement before cleaning up its jobs.

CIAgent.log:

01-13-2016 17:56:38.510    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): TransitionState(From=PersistingCIModels, To=InvokingSdmMethod) for Event=Transition

CI Agent begins enactment and evaluation for the application CIs.

CIAgent.log:

01-13-2016 17:56:38.541    CIAgent    2316 (0x90c)    CIAgentJob({ID}): StartEnactment - CI - ScopeId_GUID/RequiredApplication_GUID 01-13-2016 17:56:38.541    CIAgent    2316 (0x90c)    CIAgentJob({ID}): Evaluation for CI 'ScopeId_GUID/RequiredApplication_GUID.10'is required.

CI Agent invokes the Policy Platform Client and binds the policies by invoking the Microsoft Policy Platform.

CIAgent.log:

01-13-2016 17:56:38.541    CIAgent    2316 (0x90c)    CIAgentJob({ID}): Evaluation for CI 'ScopeId_GUID/RequiredApplication_GUID.10'is required. 01-13-2016 17:56:38.541    CIAgent    2316 (0x90c)    CIAgentJob({ID}): StartEnactment - Attempting to invoke Policy Platform Client 01-13-2016 17:56:38.885    CIAgent    2316 (0x90c)    DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_GUID_Application_GUID_Platform_PolicyDocument 01-13-2016 17:56:38.885    CIAgent    2316 (0x90c)    DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_GUID_Application_GUID_Configuration_PolicyDocument

CI Agent completes the Enactment.

CIAgent.log:

01-13-2016 17:56:38.885    CIAgent    2316 (0x90c)    DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_GUID_DeploymentType_GUID_Discovery_PolicyDocument 01-13-2016 17:56:39.619    CIAgent    2768 (0xad0)    CIAgentJob({ID}): Invocation succeeded for policy platform job ID01-13-2016 17:56:39.619    CIAgent    2316 (0x90c)    Lantern job:ID succeeded. 01-13-2016 17:56:39.619    CIAgent    2768 (0xad0)    CIAgentJob({ID}): ReportMethodInvocation :: Enactment succeeded

CI Agent now transitions its job to downloading CIs and then immediately transitions it’s state again, this time to enforcing CI's.

CIAgent.log:

01-13-2016 17:56:39.963    CIAgent    2768 (0xad0)    CIAgentJob({ID}): TransitionState(From=StateDownloadingContents, To=StateEnforcingCIs) for Event=Transition 01-13-2016 17:56:39.963    CIAgent    2768 (0xad0)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=CITaskComplete, CurrentState=StateEnforcingCIs)

CI Agent will check one more time to ensure that the application is not already installed. DCM Agent marks the CI as Available for Enforcement and then reports that state.

CIAgent.log:

01-13-2016 17:56:39.963    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateEnforcingCIs)

DCMAgent.log:

01-13-2016 17:56:39.979    DCMAgent    1844 (0x734)    CAppMgmtSDK::GetEvaluationState ScopeId_GUID/RequiredApplication_GUID.10 = AvailableForEnforcement

CIAgent.log:

01-13-2016 17:56:40.057    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateEnforcementReporting)

Now that the CIs have been evaluated, downloaded, decompressed, persisted and then evaluated again, CI Agent and DCM Agent clean up the jobs they created to do all that work.

CIAgent.log:

01-13-2016 17:56:40.072    CIAgent    2356 (0x934)    Internal Request to delete CIAgent job {ID}

DCMAgent.log:

01-13-2016 17:56:40.088    DCMAgent    2728 (0xaa8)    DCMAgentJob({ID}): CDCMAgentJob::HandleEvent(Event=Transition, CurrentState=Success)

CIAgent.log:

01-13-2016 17:56:40.104    CIAgent    2356 (0x934)    CIAgentJob({ID}): Job complete. Exiting event pump.

DCMAgent.log

01-13-2016 17:56:40.104    DCMAgent    2728 (0xaa8)    CDCMAgentJobMgr::DeleteJob - Request to delete DCM Agent job {ID} 01-13-2016 17:56:40.135    DCMAgent    2728 (0xaa8)    DCMAgentJob({ID}): QueueDebug - Executing Event. 01-13-2016 17:56:40.104    DCMAgent    2728 (0xaa8)    Job complete. Exiting event pump.

Troubleshoot the process above

Continue on to the next step

DCM Agent confirms that all CIs are present and flags content for download

Install Application will now call back into the SDK to install the application. This creates a new job for DCM Agent, which in turn creates a job for CI Agent and all of the components it uses. The same process will occur, where CI Agent utilizes the components to ensure that all the CIs have been downloaded, evaluated and persisted. The result of this step is that the content (binaries) for the Application Install process will be marked for download.

Install Application invokes the App Management SDK (DCM Agent) to install the application.

InstallApplication.log:

01-13-2016 17:56:40.119    InstallApplication    1608 (0x648)    Invoking App Management SDK to install application 01-13-2016 17:56:40.135    InstallApplication    1608 (0x648)    Installing application 'ScopeId_GUID/RequiredApplication_GUID' has started. Please refer to DCMAgent.log for the details on this job. JobID='{ID}'

DCM Agent creates a new job for CI Agent.

DCMAgent.log:

01-13-2016 17:56:40.135    DCMAgent    2356 (0x934)    DCMAgentJob({ID}): CDCMAgent::InitiateCIAgentJob - Starting CI Agent Job {ID} for target: machine. Refer to this CI agent job ID in ciagent.log for more details

CIAgent.log:

01-13-2016 17:56:40.135    CIAgent    2356 (0x934)    CIAgentJob({ID}): [LeakTest] AgentJob created

This new CI Agent job right away goes into the Waiting for Assigned CIs state and immediately transitions to downloading CIs.

CIAgent.log:

01-13-2016 17:56:40.135    CIAgent    2768 (0xad0)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=WaitingForAssignedCI) 01-13-2016 17:56:40.135    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=DownloadCIs, CurrentState=WaitingForAssignedCI) 01-13-2016 17:56:40.135    CIAgent    2768 (0xad0)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=DownloadingCIs)

CIDownloader creates a job to do the download and checks if the CIs are present.

CIDownloader.log:

 01-13-2016 17:56:40.135    CIDownloader    2768 (0xad0)    CIDownloaderJob({ID}): SetFailureCondition - Job will fail immediately on error

CIDownloader reports to CI Agent that all the CIs for the application are present in the store.

CIDownloader.log:

01-13-2016 17:56:40.166    CIDownloader    2768 (0xad0)    CDownloadPayloadInfo::AddCI - CI with ModelName ScopeId_GUID/Application_GUID, Version 10 is already available.

CI Agent logs that nothing is to be downloaded. This is because the CI for the application, application DT and requirements have already been downloaded. CI Agent moves on to persisting the CI models.

CIAgent.log:

01-13-2016 17:56:40.182    CIAgent    2768 (0xad0)    CIAgentJob({ID}): Nothing to be downloaded. 01-13-2016 17:56:40.182    CIAgent    2316 (0x90c)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=PersistingCIModels)

CI Agent invokes the SDM method again, only this time it will flag that the binaries (install.msi) have not been downloaded.

CIAgent.log:

01-13-2016 17:56:40.213    CIAgent    2316 (0x90c)    CIAgentJob({ID}):  CI ScopeId_GUID/DeploymentType_GUID:6 (ConfigMgr 2012 Toolkit R2 - Windows Installer (*.msi file)) targeted to  (Dependant of policy CI ScopeId_GUID/RequiredApplication_GUID:10) is in scope for evaluation. 01-13-2016 17:56:40.213    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=InvokingSdmMethod)

CI Agent starts enactment again, calls into Microsoft Policy Platform and confirms that the CIs are bound to policies.

CIAgent.log:

01-13-2016 17:56:40.244    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): StartEnactment - CI - ScopeId_GUID/RequiredApplication_GUID 01-13-2016 17:56:40.244    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): StartEnactment - Attempting to invoke Policy Platform Client 01-13-2016 17:56:40.322    CIAgent    2768 (0xad0)    CIAgentJob({ID}): ReportMethodInvocation :: Enactment succeeded 01-13-2016 17:56:40.322    CIAgent    2768 (0xad0)    CIAgentJob({ID}): ReportMethodInvocation :: Obtained lantern reports

At this point CI Agent marks both the application and application DT as Available and Applicable as well as that they will be installed.

CIAgent.log:

01-13-2016 17:56:40.369    CIAgent    2768 (0xad0)    CIAgentJob({ID}):State - Reporting (scan):: AppModel - ScopeId_GUID/Application_GUID:10 - State = NotInstalled ResolvedState = Available Applicability = Applicable ConfigureState= NotNeeded 01-13-2016 17:56:40.385    CIAgent    2768 (0xad0)    CIAgentJob({ID}):State - Reporting (scan):: Deployment Type - ScopeId_GUID/DeploymentType_GUID:6 - State = NotInstalled ResolvedState = Available Applicability = Applicable ConfigureState= NotNeeded 01-13-2016 17:56:40.463    CIAgent    2728 (0xaa8)    Job({ID}): CI ModelName ScopeId_GUID/Application_GUID version 10 will be INSTALLED. : Task(ScopeId_GUID/RequiredApplication_GUID.10.ContentDownload) 01-13-2016 17:56:40.463    CIAgent    2728 (0xaa8)    Job({ID}): CI ModelName ScopeId_GUID/DeploymentType_GUID version 6 will be INSTALLED. : Task(ScopeId_GUID/Application_GUID.10.ContentDownload)

Now CI Agent will begin the work of downloading the binaries for the application Install.

CIAgent.log:

01-13-2016 17:56:40.417    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateDownloadingContents) 01-13-2016 17:56:40.417    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): DownloadBinaryContents 01-13-2016 17:56:40.417    CIAgent    2728 (0xaa8)    {ID} - Initiating ContentDownload tasks. 01-13-2016 17:56:40.463    CIAgent    2728 (0xaa8)    Job({ID}) : Successfully initialized : Task(ScopeId_GUID/DeploymentType_GUID.6.ContentDownload) 01-13-2016 17:56:40.463    CIAgent    2728 (0xaa8)    Job({ID}) : Successfully initialized : Task(ScopeId_GUID/Application_GUID.10.ContentDownload)

The complicated part is now over. Now we move on to download the binaries.

Continue on to the next step

Troubleshoot this issue

Content for the Application Install task is downloaded using the standard content request/response process

To download the content for the installation, standard content request processes are used. The components involved on the client side are Location Services, Content Access (CAS), Content Transfer Manager and Data Transfer Manager. On the server side, the components involved include MP_Location and MP_GetDPInfoContent, as well as IIS on the distribution point (DP) where the content will be accessed from.

Content Access (CAS) will access the information about the content request from WMI.

CAS.log:

01-13-2016 17:56:40.572    ContentAccess    2728 (0xaa8)    CContentAccessService::Initialize 01-13-2016 17:56:40.572    ContentAccess    2728 (0xaa8)    CDownloadManager::InitializeFromWmi 01-13-2016 17:56:40.572    ContentAccess    2728 (0xaa8)    ===== CacheManager: Initializing cache state from Wmi. ===== 01-13-2016 17:56:40.588    ContentAccess    2728 (0xaa8)    Loading cache configuration from Wmi. 01-13-2016 17:56:42.166    ContentAccess    2728 (0xaa8)    CacheManager: Getting cached content information for Content_GUID.1.

Content Transfer Manager creates and sends the Content Location Request.

ContentTransferManager.log:

01-13-2016 17:56:42.432    ContentTransferManager    2768 (0xad0)    Attempting to create Location Request for PackageID='PackageID' and Version='1' 01-13-2016 17:56:42.448    ContentTransferManager    2768 (0xad0)    Attempting to send Location Request for PackageID='Content_GUID' 01-13-2016 17:56:42.448    ContentTransferManager    2728 (0xaa8)    Created CTM job {ID} for user S-1-5-18 01-13-2016 17:56:42.448    ContentTransferManager    2768 (0xad0)    ContentLocationRequest : <ContentLocationRequest SchemaVersion="1.00" ExcludeFileList=""><Package ID="UID:Content_GUID" Version="1"/><AssignedSite SiteCode="MEH"/><ClientLocationInfo LocationType="SMSUpdate" DistributeOnDemand="0" UseAzure="0" AllowWUMU="0" UseProtected="0" AllowCaching="0" BranchDPFlags="0" UseInternetDP="0" AllowHTTP="1" AllowSMB="0" AllowMulticast="0"><ADSite Name="Default-First-Site-Name"/><Forest Name="contoto.lab"/><Domain Name="contoto.lab"/><IPAddresses><IPAddress SubnetAddress="10.10.25.128" Address="10.10.25.130"/><IPAddress SubnetAddress="10.10.25.128" Address="10.10.25.166"/></IPAddresses></ClientLocationInfo></ContentLocationRequest> 01-13-2016 17:56:42.463    ContentTransferManager    2768 (0xad0)    Created and Sent Location Request '{ID}' for package Content_GUID 01-13-2016 17:56:42.463    ContentTransferManager    2768 (0xad0)    CTM job {ID} entered phase CCM_DOWNLOADSTATUS_DOWNLOADING_DATA

MP_Location receives the request and processes it by executing a stored procedure in the database. Either MP_GetDPInfoProtected or MP_GetDPInfoUnprotected.

TIP:

MP_GetContentDPInfoProtected is called when the client falls within a boundary group that has a protected DP (protected DPs are the ones that do not allow fallback). MP_GetContentDPInfoUnprotected is called when the client does not fall within a boundary group that has a protected DP.

MP_Location.log:

01-13-2016 17:56:42.516    MP_LocationManager    4044 (0xfcc)    MP_GetContentDPInfoProtected (UID:Content_GUID,1,MEH,<ServerNameList><ServerName>PS1DP.CONTOTO.LAB</ServerName></ServerNameList>,SMSUpdate,00000000,contoto.lab,contoto.lab,<ClientLocationInfo LocationType="SMSUpdate" DistributeOnDemand="0" UseAzure="0" AllowWUMU="0" UseProtected="0" AllowCaching="0" BranchDPFlags="0" UseInternetDP="0" AllowHTTP="1" AllowSMB="0" AllowMulticast="0"><ADSite Name="DEFAULT-FIRST-SITE-NAME"/><Forest Name="contoto.lab"/><Domain Name="contoto.lab"/><IPAddresses><IPAddress SubnetAddress="10.10.25.128" Address="10.10.25.130"/><IPAddress SubnetAddress="10.10.25.128" Address="10.10.25.166"/></IPAddresses></ClientLocationInfo>)

MP_Location sends the response which includes the list of available distribution points where the binaries can be downloaded.

MP_Location.log:

01-13-2016 17:56:42.523    MP_LocationManager    4044 (0xfcc)    MP LM: Reply message body: <ContentLocationReply SchemaVersion="1.00" ContentFlags="200960" HashAlgorithm="32780" AlgorithmPreference="4" Hash="HashString" ExcludeFileListHash="" RelatedContentID=""><ContentInfo PackageFlags="32"><ContentHashValues><Hash Algorithm="32780" HashString="HashString" HashPreference="4"/></ContentHashValues></ContentInfo><Sites><Site><MPSite SiteCode="MEH" MasterSiteCode="MEH" SiteLocality="LOCAL" IISPreferedPort="80" IISSSLPreferedPort="443"/><LocationRecords><LocationRecord><URL Name="http://PS1DP.contoto.lab/SMS_DP_SMSPKG$/Content_GUID.1" Signature="http://PS1DP.contoto.lab/SMS_DP_SMSSIG$/Content_63fbf078-1815-4e37-9614-b60ce7947805.1.tar"/><ADSite Name="Default-First-Site-Name"/><IPSubnets><IPSubnet Address="10.10.25.128"/><IPSubnet Address=""/></IPSubnets><Metric Value=""/><Version>8239</Version><Capabilities SchemaVersion="1.0"><Property Name="SSLState" Value="0"/></Capabilities><ServerRemoteName>PS1DP.contoto.lab</ServerRemoteName><DPType>SERVER</DPType><Windows Trust="1"/><Locality>LOCAL</Locality></LocationRecord></LocationRecords></Site><Site><MPSite SiteCode="MEH" MasterSiteCode="MEH" SiteLocality="LOCAL"/><LocationRecords/></Site></Sites><RelatedContentIDs/></ContentLocationReply>

The response is received by Location Services on the client.

LocationServices.log:

01-13-2016 17:56:42.510    LocationServices    2752 (0xac0)    ContentLocationReply : <ContentLocationReply SchemaVersion="1.00" ContentFlags="200960" HashAlgorithm="32780" AlgorithmPreference="4" Hash="6FB054E0532351D888291FF52F74E0085940AEA90EC85A5B999B6CFBE94663FC" ExcludeFileListHash="" RelatedContentID=""><ContentInfo PackageFlags="32"><ContentHashValues><Hash Algorithm="32780" HashString="6FB054E0532351D888291FF52F74E0085940AEA90EC85A5B999B6CFBE94663FC" HashPreference="4"/></ContentHashValues></ContentInfo><Sites><Site><MPSite SiteCode="MEH" MasterSiteCode="MEH" SiteLocality="LOCAL" IISPreferedPort="80" IISSSLPreferedPort="443"/><LocationRecords><LocationRecord><URL Name="http://PS1DP.contoto.lab/SMS_DP_SMSPKG$/Content_63fbf078-1815-4e37-9614-b60ce7947805.1" Signature="http://PS1DP.contoto.lab/SMS_DP_SMSSIG$/Content_63fbf078-1815-4e37-9614-b60ce7947805.1.tar"/><ADSite Name="Default-First-Site-Name"/><IPSubnets><IPSubnet Address="10.10.25.128"/><IPSubnet Address=""/></IPSubnets><Metric Value=""/><Version>8239</Version><Capabilities SchemaVersion="1.0"><Property Name="SSLState" Value="0"/></Capabilities><ServerRemoteName>PS1DP.contoto.lab</ServerRemoteName><DPType>SERVER</DPType><Windows Trust="1"/><Locality>LOCAL</Locality></LocationRecord></LocationRecords></Site><Site><MPSite SiteCode="MEH" MasterSiteCode="MEH" SiteLocality="LOCAL"/><LocationRecords/></Site></Sites><RelatedContentIDs/></ContentLocationReply>

Location Services parses the reply to get the distribution point list which it sends to Content Transfer Manager.

LocationServices.log:

01-13-2016 17:56:42.526    LocationServices    2752 (0xac0)    Distribution Point='http://PS1DP.contoto.lab/SMS_DP_SMSPKG$/Content_GUID.1', Locality='LOCAL', DPType='SERVER', Version='8239', Capabilities='<Capabilities SchemaVersion="1.0"><Property Name="SSLState" Value="0"/></Capabilities>', Signature='http://PS1DP.contoto.lab/SMS_DP_SMSSIG$/Content_GUID.1.tar', ForestTrust='TRUE',

Content Transfer Manager persists the location for the job it has created for downloading the binaries.

ContentTransferManager.log:

01-13-2016 17:56:42.526    ContentTransferManager    2752 (0xac0)    Persisted locations for CTM job {ID}: (LOCAL) http://PS1DP.contoto.lab/SMS_DP_SMSPKG$/Content_GUID.1

Content Transfer Manager then creates a job for Data Transfer Service to download the binaries.

ContentTransferManager.log:

01-13-2016 17:56:42.541    ContentTransferManager    2752 (0xac0)    CTM job {ID} (corresponding DTS job {ID}) started download from 'http://PS1DP.contoto.lab/SMS_DP_SMSPKG$/Content_GUID.1' for full content download.

Data Transfer Service builds the job with the URL and starts a BITS job to do the download.

DataTransferService.log:

01-13-2016 17:56:42.541    DataTransferService    2752 (0xac0)    Sending PROPFIND request using URL http://PS1DP.contoto.lab:80/SMS_DP_SMSPKG$/Content_GUID.1 01-13-2016 17:56:42.557    DataTransferService    2752 (0xac0)    UpdateURLWithTransportSettings(): NEW URL - http://ps1dp.contoto.lab:80/SMS_DP_SMSPKG$/Content_GUID.1/sccm?/ConfigMgrTools.msi 01-13-2016 17:56:42.573    DataTransferService    2752 (0xac0)    Starting BITS download for DTS job '{ID}'. 01-13-2016 17:56:42.573    DataTransferService    2752 (0xac0)    BITSHelper: Full source path to be transferred = http://PS1DP.contoto.lab:80/SMS_DP_SMSPKG$/Content_GUID.1/sccm?/ConfigMgrTools.msi

Data Transfer Service completes the download and marks the job successful.

DataTransferService.log:

01-13-2016 17:56:42.666    DataTransferService    2748 (0xabc)    Job: {ID}, Total Files: 1, Transferred Files: 0, Total Bytes: 5664768, Transferred Bytes: 262144 01-13-2016 17:56:42.869    DataTransferService    1568 (0x620)    Job: {ID}, Total Files: 1, Transferred Files: 1, Total Bytes: 5664768, Transferred Bytes: 5664768 01-13-2016 17:56:42.885    DataTransferService    2752 (0xac0)    DTSJob {ID} in state 'NotifiedComplete'. 01-13-2016 17:56:42.885    DataTransferService    2752 (0xac0)    DTS job {ID} has completed: Status : SUCCESS,

Content Transfer Manager then cleans up the DTS job and CAS begins verifying the hash of the downloaded binaries.

ContentTransferManager.log:

01-13-2016 17:56:42.901    ContentTransferManager    2728 (0xaa8)    CCTMJob::_Cleanup(JobID={ID}) - Cancelling DTS job  with provider <default> 01-13-2016 17:56:42.901    ContentAccess    2348 (0x92c)    Using hash from LS Content Information: HashString

CAS.log:

01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    Computed hash: HashString 01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    Success hash verification with hash algorithm = 32780, preference : 4

Content Access then maps the content to the CCM cache where the downloaded binaries are now stored.

CAS.log:

01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    Saved Content ID Mapping Content_GUID.1, C:\WINDOWS\ccmcache\1 01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    CacheManager: ADD new cache entry for id:Content_GUID Version : 1 Size : 5532K RefCount:1 LastRef Minutes : 0 State : ACTIVE PinDuration : 0 Location : C:\WINDOWS\ccmcache\1 01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    Created a New Cache Item at location C:\WINDOWS\ccmcache\1 for 1.Content_GUID Size 5532 KB bytes 01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    Download succeeded for download request {GUID}

CI State Store updates CIEnforcementState of the CIs to Download Content Success. CI Agent then picks back up and begins enforcing the CIs.

CIAgent.log:

01-13-2016 17:56:43.041    CIAgent    2316 (0x90c)    CIAgentJob({ID}): TransitionState(From=StateDownloadingContents, To=StateEnforcingCIs) for Event=Transition 01-13-2016 17:56:43.041    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): EnforceCIs 01-13-2016 17:56:43.041    CIAgent    2728 (0xaa8)    {ID} - Initiating Enforce tasks. 01-13-2016 17:56:43.073    CIAgent    2728 (0xaa8)    Job({ID}) : Performing : Task(ScopeId_GUID/RequiredApplication_GUID.10.Enforce) 01-13-2016 17:56:43.073    CIAgent    2728 (0xaa8)    Job({ID}) : Performing : Task(ScopeId_GUID/Application_GUID.10.Enforce) 01-13-2016 17:56:43.073    CIAgent    2728 (0xaa8)    Job({ID}) : Performing : Task(ScopeId_GUID/DeploymentType_GUID.6.Enforce)

Troubleshoot the process above

Continue on to the next step

Application Deployment Type is enforced by executing the command line

Now comes the work of enforcing the installation of the application which will utilize the standard Application Install components and flow: AppDiscovery and AppEnforce.

AppDiscovery discovers the application and its properties.

AppDiscovery.log:

ActionType - Install,Max execute time = 120 minutes for AppDT "ConfigMgr 2012 Toolkit R2 - Windows Installer (*.msi file)" [ScopeId_GUID/DeploymentType_GUID], Revision - 6

AppEnforce now begins the install enforcement by performing detection of the Application Deployment Type. In the case of an MSI it uses the product code to check whether it is already installed. Assuming that the detection state is Not Discovered, the installation will proceed.

AppEnforce.log:

01-13-2016 17:56:43.104    AppEnforce    2216 (0x8a8)    +++ Starting Install enforcement for App DT "ConfigMgr 2012 Toolkit R2 - Windows Installer (*.msi file)" ApplicationDeliveryType - ScopeId_GUID/DeploymentType_GUID, Revision - 6, ContentPath - C:\WINDOWS\ccmcache\1, Execution Context - Any 01-13-2016 17:56:44.666    AppEnforce    2216 (0x8a8)    +++ Application not discovered. [AppDT Id: ScopeId_GUID/DeploymentType_GUID, Revision: 6]

Now AppEnforce will prepare the enforcement environment by parsing the command line and other install parameters, then prepares the working directory and executes the command line.

AppEnforce.log:

01-13-2016 17:56:44.682    AppEnforce    2216 (0x8a8)    App enforcement environment:  Context: Machine   Command line: msiexec /i "ConfigMgrTools.msi" /q /L*V "C:\Windows\CCM\Logs\MSI_install.log"   Allow user interaction: No   UI mode: 0   User token: null Session   Id: 4294967295 Content   path: C:\WINDOWS\ccmcache\1 Working directory: 01-13-2016 17:56:44.682    AppEnforce    2216 (0x8a8)    Prepared working directory: C:\WINDOWS\ccmcache\1 01-13-2016 17:56:44.713    AppEnforce    2216 (0x8a8)    Parsed CmdLine: msiexec /i "ConfigMgrTools.msi" /q /L*V "C:\Windows\CCM\Logs\MSI_install.log" 01-13-2016 17:56:44.713    AppEnforce    2216 (0x8a8)    Found executable file msiexec with complete path C:\WINDOWS\system32\msiexec.exe 01-13-2016 17:56:45.666    AppEnforce    2216 (0x8a8)    Executing Command line: "C:\WINDOWS\system32\msiexec.exe" /i "ConfigMgrTools.msi" /q /L*V "C:\Windows\CCM\Logs\MSI_install.log" /qn with system context 01-13-2016 17:56:44.729    AppEnforce    2216 (0x8a8)    Parsed CmdLine: "C:\WINDOWS\system32\msiexec.exe" /i "ConfigMgrTools.msi" /q /L*V "C:\Windows\CCM\Logs\MSI_install.log" /qn 01-13-2016 17:56:45.666    AppEnforce    2216 (0x8a8)    Executing Command line: "C:\WINDOWS\system32\msiexec.exe" /i "ConfigMgrTools.msi" /q /L*V "C:\Windows\CCM\Logs\MSI_install.log" /qn with system context

At this point, assuming there is logging for the MSI installation, msiexec.exe takes over and performs the installation.

MSI Logging.log:

=== Verbose logging started: 1/13/2016  17:56:45  Build type: SHIP UNICODE 5.00.9600.00  Calling process: C:\WINDOWS\system32\msiexec.exe ===

Once the installation is complete, msiexec.exe will send the return code to Install Application which will set the necessary TS environment variables indicating success, and then report the successful install back to AppEnforce.

AppEnforce.log:

MSI (c) (BC:EC) [17:56:47:604]: MainEngineThread is returning 0 01-13-2016 17:56:47.979    InstallApplication    1384 (0x568)    NotifyProgress received: 1 (Application is installed successfully ) 01-13-2016 17:56:48.010    InstallApplication    1608 (0x648)    Installation job completed with exit code 0x00000000 01-13-2016 17:56:48.010    InstallApplication    1608 (0x648)    Execution status received: 1 (Application is installed successfully ) 01-13-2016 17:56:48.010    InstallApplication    1608 (0x648)    Setting TSEnv variable '_TSAppInstallStatus'='Success' 01-13-2016 17:56:48.010    InstallApplication    1608 (0x648)    Setting TSEnv variable 'SMSTSInstallApplicationJobID__ScopeId_GUID/Application_GUID'='' 01-13-2016 17:56:48.010    InstallApplication    1608 (0x648)    Step 2 out of 2 complete 01-13-2016 17:56:48.010    InstallApplication    1608 (0x648)    Sending success status message

AppEnforce matches the success code to the table specified in the Return Codes tab in the properties of the Application Deployment Type. It then performs detection again and marks the install enforcement complete.

AppEnforce.log:

01-13-2016 17:56:47.620    AppEnforce    2216 (0x8a8)    Looking for exit code 0 in exit codes table... 01-13-2016 17:56:47.620    AppEnforce    2216 (0x8a8)    Found a match in the success exit codes. 01-13-2016 17:56:47.620    AppEnforce    2216 (0x8a8)    Matched exit code 0 to a Success entry in exit codes table. 01-13-2016 17:56:47.620    AppEnforce    2216 (0x8a8)    Performing detection of app deployment type ConfigMgr 2012 Toolkit R2 - Windows Installer (*.msi file)(ScopeId_GUID/DeploymentType_GUID, revision 6) for system. 01-13-2016 17:56:47.635    AppEnforce    2216 (0x8a8)    +++ Discovered application [AppDT Id: ScopeId_GUID/DeploymentType_GUID, Revision: 6] 01-13-2016 17:56:47.635    AppEnforce    2216 (0x8a8)    ++++++ App enforcement completed (4 seconds) for App DT "ConfigMgr 2012 Toolkit R2 - Windows Installer (*.msi file)" [ScopeId_GUID/DeploymentType_GUID], Revision: 6, User SID: ] ++++++

Troubleshoot the process above

Continue on to the next step

The application is detected as installed and Enforcement State is reported back to Task Sequence Manager

All this time, CI Agent has been checking with CI State Store for the Enforcement State of the CIs. DCM Agent has been doing the same as well, monitoring the progress and logging it to DCMAgent.log. Now that the installation is complete and detection has marked it as installed, CI State Store will detect that the state of an existing CI has changed from Enforcing to EnforcementSuccess.

CIStateStore.log:

01-13-2016 17:56:47.667    CIStateStore    2728 (0xaa8)    An existing CI state is changed 01-13-2016 17:56:47.667    CIStateStore    2728 (0xaa8)    [ScopeId_GUID/DeploymentType_GUID:6] CIEnforceState changed: Enforcing --> EnforcementSuccess 01-13-2016 17:56:47.729    CIStateStore    2348 (0x92c)    An existing CI state is changed 01-13-2016 17:56:47.776    CIStateStore    2728 (0xaa8)    [ScopeId_GUID/RequiredApplication_GUID:10] CIEnforceState changed: Enforcing --> EnforcementSuccess

Once it receives this new enforcement state from CI State Store, CI Agent will mark it’s jobs complete and transition to reporting the enforcement state.

CIAgent.log:

01-13-2016 17:56:47.823    CIAgent    2348 (0x92c)    JobTaskHelper - Initiating next task if needed 01-13-2016 17:56:47.823    CIAgent    2348 (0x92c)    Job({ID}): Already Completed : Task(ScopeId_GUID/DeploymentType_GUID.6.Enforce) 01-13-2016 17:56:47.823    CIAgent    2348 (0x92c)    Job({ID}): Already Completed : Task(ScopeId_GUID/Application_GUID.10.Enforce) 01-13-2016 17:56:47.823    CIAgent    2348 (0x92c)    Job({ID}): Already Completed : Task(ScopeId_GUID/RequiredApplication_GUID.10.Enforce) 01-13-2016 17:56:47.838    CIAgent    2316 (0x90c)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateEnforcementReporting)

Enforcement reporting involves checking CI State Store for the compliance state of the application CI. Once it is set to compliant, CI Agent will transition to Completed and cleanup it’s job.

CIStateStore.log:

01-13-2016 17:56:47.932    CIStateStore    2316 (0x90c)    [ScopeId_GUID/RequiredApplication_GUID:10] CIState changed: NonCompliant --> Compliant

CIAgent.log :

01-13-2016 17:56:47.963    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=Completed) 01-13-2016 17:56:47.963    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): CAgentJob::HandleEvent(Event=Transition, CurrentState=Completed) 01-13-2016 17:56:47.963    CIAgent    2728 (0xaa8)    CIAgentJob({ID}): Deleting CIAgent Job 01-13-2016 17:56:47.963    CIAgent    2728 (0xaa8)    Deleted CIAgent job {ID}

DCM Agent passes the success notification back to the Install Application (smsappinstall.exe) process and DCM Agent cleans up its job.

DCMAgent.log:

01-13-2016 17:56:47.979    DCMAgent    1384 (0x568)    CAppMgmtSDK::GetEvaluationState ScopeId_GUID/RequiredApplication_GUID.10 = Enforced 01-13-2016 17:56:47.979    DCMAgent    2316 (0x90c)    DCMAgentJob({ID}): CDCMAgentJob::HandleEvent(Event=NotifyProgress, CurrentState=Success) 01-13-2016 17:56:47.979    InstallApplication    1608 (0x648)    Received job completion notification from DCM Agent 01-13-2016 17:56:47.995    DCMAgent    2348 (0x92c)    CDCMAgentJobMgr::DeleteJob - Request to delete DCM Agent job {ID}

Lastly, the exit code is returned back to Task Sequence Manager who updates the appropriate TS environment variables and resumes the next task in the sequence.

SMSTS.log:

01-13-2016 17:56:48.073    TSManager    2176 (0x880)    Process completed with exit code 0 01-13-2016 17:56:48.073    TSManager    2176 (0x880)    Successfully completed the action (Install Application) with the exit win32 code 0

Continue to troubleshooting

Not solved,see additional information

Troubleshooting Install Application failures

There are three likely points of failure when executing an Install Application task. Each is listed below with links to troubleshooting steps for each.

Note

For troubleshooting purposes it is considered a best practice to create and use a duplicate copy of your production task sequence. The task sequence may need to be modified to include additional data gathering tasks and will need to be deployed to a test machine.

Errors downloading configuration Items associated with the Application (App CI, App DT CI, Lantern Policies, etc).

Errors downloading content for the application (.msi files, .exe files, config files, etc).

Errors while executing the command line to install the Application and Reporting Compliance.

Troubleshooting Install Application failures – Part 1

Task Sequence Manager

Based on the flow and execution of the task sequence, there is a low probability of a failure occurring during this step of the Install Application process. This is because at this point, Task Sequence Manager has successfully parsed the task sequence XML and has set an instruction pointer for the current task. Also, the policy for the task sequence is downloaded when the task sequence begins. The results are returned to the task sequence and stored in the task sequence environment using variables which are saved on disk as TSEnv.dat.

Based on that understanding, here are some items to consider when investigating these issues where there may be an additional piece of information uncovered that can be used for troubleshooting the error condition.

Tip

The policy body for the task sequence selected is downloaded from the database at the beginning of the task sequence and stored within the Task Sequence Environment using variables.

MP_GetPolicy will log this activity. To find this request in the MP_GetPolicy log search for the Deployment ID or Task Sequence ID.

01-13-2016 17:32:54.579    MP_GetPolicy_ISAPI    12688 (0x3190)    MP GP: Query String Before Decode: MEH20009-MEH0000A-6F6BCC28.15_00 01-13-2016 17:32:54.579    MP_GetPolicy_ISAPI    12688 (0x3190)    MP GP: ID : MEH20009-MEH0000A-6F6BCC28 01-13-2016 17:32:54.579    MP_GetPolicy_ISAPI    12688 (0x3190)    MP GP: Initializing request from client GUID:ClientGUID.

The following stored procedure is executed to retrieve the policy body:

exec MP_GetPolicyBodyAfterAuthorization

Task Sequence variables

The results of the policy body request are returned to the machine and saved in the task sequence environment (TSEnv.dat). The policy body for the task sequence and all its dependent polices are stored here using variables. Task Sequence Manager will log a large portion of what it is reading from the environment.

Continue troubleshooting

My problem is solved

Not solved,see additional information

Troubleshooting Install Application failures – Part 2

This next section is often times where the error surfaces but rarely where the error occurs. The Install Application component is the top level process for installing the application and any error from the list of components it invokes would roll back up to it. The actual cause of the failure is most likely in a subsequent step and is reported back to the Install Application task, resulting in the Install Application task to return a failure with a generic error code. More often than not it is the reason behind a large majority of Install Application tasks returning the following error:

InstallApplication    296 (0x128)    App install failed. InstallApplication    296 (0x128)    Install application action failed: 'APP NAME HERE'. Error Code 0x80004005

For this reason, here is a list of the most common errors that are returned to the Install Application task with some items to review for each.

Failure Type	What to Check
SMSTS log shows InstallApplication 2740 (0xab4) Policy Evaluation failed, hr=0x87d00269' or Required management point not found (Error: 87D00269	This error indicates that the machine is unable to reach (communicate with) the management point. Confirm whether you are using a custom website for the MP. If so, review How to Create the Custom Website in Internet Information Services (IIS) and ensure that a copy of the default document (default.htm) has been placed in the root folder that hosts the website. Also, ensure that HTTP redirection is not enabled on the default website.
SMTS log shows InstallApplication 3248 (0xcb0) Policy Evaluation failed, hr=0x80004005	Ensure that you have the most current updates for Configuration Manager installed.
SMSTS log shows Install Static Applications failed, hr=0x87d00267	Ensure that you have installed the latest version of ConfigMgr 2012 R2 SP1.
SMSTS log shows 'Execution status received: 24 (Application download failed)	Review https://support.microsoft.com/en-us/kb/3007095 and ensure that you are up to date and have the most current updates for Configuration Manager installed (as of this writing, either ConfigMgr 2012 R2 CU4, ConfigMgr 2012 R2 SP1, or current builds 1511 or 1602).
SMTS log shows Install application action failed: 'APP NAME HERE'. Error Code 0x80004005'	Review CCMExec.log to confirm that SMS Agent Host is started without error.

Continue troubleshooting

My problem is solved

Not solved,see additional information

Troubleshooting Install Application failures – Part 3

The next steps are a combination of multiple components working together. The work is done via jobs created locally to evaluate the existence of the CIs via CI Store (CCMStore.sdf) or marking them as not found. The next phase of this step, when DataTransferService uses Background Intelligence Service (BITS) and HTTP communication with the MP to request the CIs and download them, is where many issues can potentially arise.

Possible points of failure for these steps include the following:

Bad data in the database, returns corrupted CI or SDM Package Data. Out of date versions, etc.
WMI issues, accessing policy namespaces locally on the machine executing the task sequence.
Failure communicating with the MP or the DB.
BITS jobs failures.
Network related errors, downloads, etc.
IIS issues with SMS_MP vDir (SMS_CCM\SMS_MP folder).
Evaluation errors after install.

Examine the following log files to gain clues as to where this process is failing:

CIDownloader.log
DCMAgent.log
CIStore.log
CIStateStore.log
DataTransferService.log

Continue troubleshooting

My problem is solved

Not solved,see additional information

Troubleshooting Install Application failures – Part 4

At this point in the task sequence we have requested and downloaded content several times. This was accomplished using the standard content request/response procedures that are used in standard software/application installs outside of a task sequence. Because the task sequence has already used these procedures successfully there is a low probability of them failing during this task. However, should problems arise with content location requests or access, examine the following log files to gain clues as to where the process is failing:

CIAgent.log
CAS.log
ContentTransferManager.log
DataTransferService.log
LocationServices.log
MP_Location.log

Continue troubleshooting

My problem is solved

Not solved,see additional information

Troubleshooting Install Application failures – Part 5

The applications that are installed must meet thefollowing criteria:

The application must be a deployment type of Windows Installer or Script installer. Note that Windows app package (.appx file) deployment types are not supported.
It must run under the local system account and not the user account.
It must not interact with the desktop. The program must run silently or in an unattended mode.
It must not initiate a restart on its own. The application must request a restart by using the standard restart code (a 3010 exit code). This ensures that the task sequence step will handle the restart correctly. If the application does return a 3010 exit code, the underlying task sequence engine performs the restart. After the restart the task sequence automatically continues.

To gather additional information regarding the source of the failure, examine the MSI log. The following article can provide additional information and has good foundational MSI log troubleshooting information:

Read a Deployment Tool MSI Log

The article below has product specific info as well as some good general MSI log troubleshooting tips:

Troubleshooting Office installation failures

If you discover MSI installer return codes denoting a failure, see Common MSI Installer Return Codes or the table below.

Return Code	Code Type	Description
0	Success	No reboot
1601	Error	Installer issue
1602	Error	User cancelled
1603	Error	Fatal Error
1605	Error	This action is only valid for products that are currently installed.
1618	Error	Another installation is already in progress.
1639	Error	Invalid command line argument.
1641	Success	Hard Reboot; The installer has initiated a restart.
3010	Success	Soft Reboot; A restart is required to complete the install.

Continue troubleshooting

My problem is solved

Not solved,see additional information

Troubleshooting Install Application failures – Part 5

Deployments that have problems will typically report errors in the Monitoring workspace. You can see these when you click the Deployments node and then click the Error tab. For information on how to troubleshoot these errors see the following:

Tips and Tricks: How to Take Action on Assets That Report a Failed Deployment in System Center 2012 Configuration Manager

Solved

Not solved,see additional information

Successful

Congratulations! Your Install Application process problem has been resolved.

Additional information

For additional information regarding the Install Application process or task sequences and Operating System Deployment (OSD), please see the following:

Documentation Library for System Center 2012 Configuration Manager

Task Sequence Steps in Configuration Manager

Technical Reference for Deploying Operating Systems in Configuration Manager

You can also post a question in our Configuration Manager 2012 support forum for Operating System Deployment here:

https://social.technet.microsoft.com/Forums/en-US/home?forum=configmanagerosd

Visit our blog for all the latest news, information and tech tips on Microsoft System Center Configuration Manager:

https://blogs.technet.microsoft.com/configurationmgr

Last Updated: 19-Apr-2018

Did this solve your problem?