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.

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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58/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. 


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.

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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58/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. 


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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58'
Install Application sets variables for the application. 
SMSTS.log: 
01-13-2016 17:56:35.666    InstallApplication    1608 (0x648)    Setting TSEnv variable 'SMSTSAppPolicyEvaluationJobID__ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58'=''01-13-2016 17:56:35.666    InstallApplication    1608 (0x648)    Setting TSEnv variable 'SMSTSInstallApplicationJobID__ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58'='
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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58'
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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58 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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58 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_6b689e63-9887-46c5-9062-4a5604d52d33/application_3a4c09b5-fdb6-45c2-8177-340f032e5e58'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [2] Added/updated setting 'ccm_civersioninfo:modelname=scopeid_6b689e63-9887-46c5-9062-4a5604d52d33/application_3a4c09b5-fdb6-45c2-8177-340f032e5e58:version=10'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [3] Added/updated setting 'ccm_civersioninfo:modelname=scopeid_6b689e63-9887-46c5-9062-4a5604d52d33/deploymenttype_124d1234-48ca-4037-bac8-bdcbdedeebae:version=6'. 01-13-2016 17:56:36.150    InstallApplication    1608 (0x648)    [4] Added/updated setting 'ccm_civersioninfo:modelname=scopeid_6b689e63-9887-46c5-9062-4a5604d52d33/requiredapplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58: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_6b689e63-9887-46c5-9062-4a5604d52d33/application_3a4c09b5-fdb6-45c2-8177-340f032e5e58'. 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:4a6ea5f2-110c-4417-b494-ea84eba71d3b"; 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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58". 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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58:10will be targeted for SYSTEM 01-13-2016 17:56:36.275   CIStore    2608 (0xa30)   CCIStore::ProcessCITargetEvent - CI ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae:6will 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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58 Version:10 has been added for download
CIStateStore.log: 
01-13-2016 17:56:36.322    CIStateStore    2608 (0xa30)    CCIStateTransition::ExtractStateDetails - CI ModelName ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae, version 6 not found in store.
CIStore.log: 
01-13-2016 17:56:36.369    CIStore    2608 (0xa30)    CCIStoreTargetedCIDownloader::AddCI - CI Modelname:ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae 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.





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:
  1. App PROPERTIES - Results have basic App CI info. Name only.
  2. App MANIFEST - links Policy Platform CI Documents with the Application CI.
  3. App Intent Policy - Desired State of the Application, required.
  4. 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.
  5. App PROPERTIES again. Note the different HASH. This time the results include, extended/custom PROPERITES, Publisher, release date, icons, etc.
  6. App DT PROPERTIES. Results include Description, estimated install time, post install behavior, etc.
  7. App DT MANIFEST results have extended info, WMI namespaces for the CI Manifests.
  8. App policy, results include Policy Platform MOF to be compiled client side with Desired State, App Properties and App DT Properties.
  9. App DT Policy is compressed. Unable to decompress.
Below is an example of the request and download of only the Application PROPERTIES and MANIFEST (steps 1 and 2 from above).


  1. DCM Agent job ID.
    DCMAgent.log: 
    01-13-201617:56:36.979    DCMAgent    1568(0x620)    CDCMAgentJobMgr::StartJob - Starting DCM Agent job{563BD69E-91AA-4F0F-9AD8-7C9B030D25B8}
  2. DCM Agent creates a job for CI Agent.
    DCMAgent.log: 
    01-13-2016 17:56:37.088    DCMAgent    2768 (0xad0)    DCMAgentJob({563BD69E-91AA-4F0F-9AD8-7C9B030D25B8}): 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
  3. CIDownloader creates a job.
    CIDownloader.log:
    01-13-2016 17:56:37.166    CIDownloader    2728 (0xaa8)    CIDownloaderJob({1B065017-7AC4-4729-B15D-6415BED35D0E}): SetFailureCondition - Job will fail immediately on error
  4. DCM Agent is tracking the progress via its own job.
    DCMAgent.log: 

    01-13-2016 17:56:37.182    DCMAgent    2768 (0xad0)    DCMAgentJob({563BD69E-91AA-4F0F-9AD8-7C9B030D25B8}): CDCMAgentJob::HandleEvent(Event=NotifyProgress, CurrentState=Evaluating)
  5. 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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58 Version:10 to Scoped CIs List of root Modelname:ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58 Version:10

    CIStore.log:

    01-13-201617:56:37.182    CIStore    2728(0xaa8)    CCIStore::GetTargetedCIReference invoked for CIScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58:10targeted to SYSTEM 
  6. 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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58,version 10 not found in store. 
  7. 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({1B065017-7AC4-4729-B15D-6415BED35D0E}): CI with ModelNameScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58,Version 10. Model:(null) added to job. 
  8. 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}) 
  9. 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({1B065017-7AC4-4729-B15D-6415BED35D0E}): DownloadPackages  01-13-201617:56:37.229    CIDownloader    2728(0xaa8)    --Source file:.sms_dcm?Id&DocumentId=ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/MANIFEST&Hash=63FF5809FEE3EF93CA485E47077672BA6A55D7C447DE98D9D5C9C3356535DD37&Compression=zlib  01-13-201617:56:37.229    CIDownloader    2728(0xaa8)    --Source file:.sms_dcm?Id&DocumentId=ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/PROPERTIES&Hash=04DF351EAF30F2C9B880612EF932BA51FCB89AC518D345342B3F442566133F8F&Compression=zlib 
  10. 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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/PROPERTIES&Hash=04DF351EAF30F2C9B880612EF932BA51FCB89AC518D345342B3F442566133F8F&Compression=zlib,dest={A0E3D71F-9DAB-44A9-8E36-671F1F976D78}_2.zip)pair from manifest.  01-13-201617:56:37.275    DataTransferService    2728(0xaa8)    Added(source=.sms_dcm?Id&DocumentId=ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/MANIFEST&Hash=63FF5809FEE3EF93CA485E47077672BA6A55D7C447DE98D9D5C9C3356535DD37&Compression=zlib,dest={A0E3D71F-9DAB-44A9-8E36-671F1F976D78}_1.zip)pair from manifest.
  11. 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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/PROPERTIES',N'04DF351EAF30F2C9B880612EF932BA51FCB89AC518D345342B3F442566133F8F',N'1',N'1'  exec MP_GetSdmDocument N'ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/MANIFEST',N'63FF5809FEE3EF93CA485E47077672BA6A55D7C447DE98D9D5C9C3356535DD37',N'1',N'1'

  12. 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'{B8EC70C9-6387-43EF-910B-B395E78C8471}' for DTS job'{D7A8D813-227E-4FFC-A34F-E1958357A603}' 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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/PROPERTIES&Hash=04DF351EAF30F2C9B880612EF932BA51FCB89AC518D345342B3F442566133F8F&Compression=zlib 01-13-201617:56:37.479    DataTransferService    2316(0x90c)    Adding to BITS job:{A0E3D71F-9DAB-44A9-8E36-671F1F976D78}_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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/MANIFEST&Hash=63FF5809FEE3EF93CA485E47077672BA6A55D7C447DE98D9D5C9C3356535DD37&Compression=zlib 56:37.479   DataTransferService    2316 (0x90c)    Adding toBITS job: {A0E3D71F-9DAB-44A9-8E36-671F1F976D78}_1.zip 
  13. 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: {D7A8D813-227E-4FFC-A34F-E1958357A603}, Total Files: 2, Transferred Files: 2, Total Bytes: 1160, Transferred Bytes: 1160 01-13-2016 17:56:37.588    DataTransferService    2748 (0xabc)    DTSJob {D7A8D813-227E-4FFC-A34F-E1958357A603} successfully completed download.
    Configuration Item #2 
    01-13-2016 17:56:37.791    DataTransferService    1568 (0x620)    Job: {DEE2FAB0-1A75-4A10-940F-5C8A1505D74C}, Total Files: 3, Transferred Files: 3, Total Bytes: 2616, Transferred Bytes: 2616 01-13-2016 17:56:37.791    DataTransferService    1568 (0x620)    DTSJob {DEE2FAB0-1A75-4A10-940F-5C8A1505D74C} successfully completed download.
    Configuration Item #3 
    01-13-2016 17:56:37.994    DataTransferService    2748 (0xabc)    Job: {428CBC19-4B05-435C-81E7-CA0CE9FB3FDD}, Total Files: 3, Transferred Files: 3, Total Bytes: 3216, Transferred Bytes: 3216 01-13-2016 17:56:37.994    DataTransferService    2748 (0xabc)    DTSJob {428CBC19-4B05-435C-81E7-CA0CE9FB3FDD} successfully completed download.
    Configuration Item #4 
    01-13-2016 17:56:38.104    DataTransferService    1568 (0x620)    Job: {499D21C7-6759-4D38-9442-88606FE4FCD8}, Total Files: 1, Transferred Files: 1, Total Bytes: 4172, Transferred Bytes: 4172 01-13-2016 17:56:38.104    DataTransferService    1568 (0x620)    DTSJob {499D21C7-6759-4D38-9442-88606FE4FCD8} successfully completed download.



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: {D7A8D813-227E-4FFC-A34F-E1958357A603}, Total Files: 2, Transferred Files: 2, Total Bytes: 1160, Transferred Bytes: 116001-13-2016 17:56:37.588    DataTransferService    2748 (0xabc)    DTSJob {D7A8D813-227E-4FFC-A34F-E1958357A603} successfully completed download. 01-13-2016 17:56:37.604    DataTransferService    2316 (0x90c)    DTSJob {D7A8D813-227E-4FFC-A34F-E1958357A603} in state 'NotifiedComplete'.
CIDownloader.log: 
01-13-2016 17:56:37.619    CIDownloader    2768 (0xad0)    ::DecompressFile(C:\WINDOWS\CCM\CIDownloader\Staging\{A0E3D71F-9DAB-44A9-8E36-671F1F976D78}_1.zip,65536,C:\WINDOWS\CCM\CIDownloader\Staging\{A0E3D71F-9DAB-44A9-8E36-671F1F976D78}_1.xml) 01-13-2016 17:56:37.619    CIDownloader    2768 (0xad0)    VerifyCIDocumentHash - Preparing to verify hash for CI document ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/10/MANIFEST01-13-2016 17:56:37.619    CIDownloader    2768 (0xad0)    ::DecompressFile(C:\WINDOWS\CCM\CIDownloader\Staging\{A0E3D71F-9DAB-44A9-8E36-671F1F976D78}_2.zip,65536,C:\WINDOWS\CCM\CIDownloader\Staging\{A0E3D71F-9DAB-44A9-8E36-671F1F976D78}_2.xml) 01-13-2016 17:56:37.619    CIDownloader    2768 (0xad0)    VerifyCIDocumentHash - Preparing to verify hash for CI document ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58/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({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): CAgentJob::NotifyComplete - CIDownloader callback 01-13-2016 17:56:38.119    CIAgent    2728 (0xaa8)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): CAgentJob::HandleEvent(Event=Transition, CurrentState=PersistingCIModels) 01-13-2016 17:56:38.119    CIAgent    2728 (0xaa8)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): 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 {1B065017-7AC4-4729-B15D-6415BED35D0E}.
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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58 Version: 10 01-13-2016 17:56:38.479    CIStore    2728 (0xaa8)    CCIStore::GetCIEx - Requested CI ModelName ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58, 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_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae Version: 6 01-13-2016 17:56:38.510    CIStore    2728 (0xaa8)    CCIStore::GetCIEx - Requested CI ModelName ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae, 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.




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({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): 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({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): StartEnactment - CI - ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58 01-13-2016 17:56:38.541    CIAgent    2316 (0x90c)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): Evaluation for CI 'ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58.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({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): Evaluation for CI 'ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58.10'is required. 01-13-2016 17:56:38.541    CIAgent    2316 (0x90c)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): StartEnactment - Attempting to invoke Policy Platform Client 01-13-2016 17:56:38.885    CIAgent    2316 (0x90c)    DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_6B689E63_9887_46C5_9062_4A5604D52D33_Application_3a4c09b5_fdb6_45c2_8177_340f032e5e58_10_Platform_PolicyDocument 01-13-2016 17:56:38.885    CIAgent    2316 (0x90c)    DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_6B689E63_9887_46C5_9062_4A5604D52D33_Application_3a4c09b5_fdb6_45c2_8177_340f032e5e58_10_Configuration_PolicyDocument
CI Agent completes the Enactment.
CIAgent.log: 
01-13-2016 17:56:38.885    CIAgent    2316 (0x90c)    DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_6B689E63_9887_46C5_9062_4A5604D52D33_DeploymentType_124d1234_48ca_4037_bac8_bdcbdedeebae_6_Discovery_PolicyDocument 01-13-2016 17:56:39.619    CIAgent    2768 (0xad0)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): Invocation succeeded for policy platform job CA4F9CFB-5463-446F-BC61-D63EB6507BFA 01-13-2016 17:56:39.619    CIAgent    2316 (0x90c)    Lantern job:CA4F9CFB-5463-446F-BC61-D63EB6507BFA succeeded. 01-13-2016 17:56:39.619    CIAgent    2768 (0xad0)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): 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({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): TransitionState(From=StateDownloadingContents, To=StateEnforcingCIs) for Event=Transition 01-13-2016 17:56:39.963    CIAgent    2768 (0xad0)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): 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({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateEnforcingCIs)
DCMAgent.log: 
01-13-2016 17:56:39.979    DCMAgent    1844 (0x734)    CAppMgmtSDK::GetEvaluationState ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58.10 = AvailableForEnforcement
CIAgent.log: 
01-13-2016 17:56:40.057    CIAgent    2728 (0xaa8)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): 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 {E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}
DCMAgent.log: 
01-13-2016 17:56:40.088    DCMAgent    2728 (0xaa8)    DCMAgentJob({563BD69E-91AA-4F0F-9AD8-7C9B030D25B8}): CDCMAgentJob::HandleEvent(Event=Transition, CurrentState=Success)
CIAgent.log: 
01-13-2016 17:56:40.104    CIAgent    2356 (0x934)    CIAgentJob({E672EA3F-29D7-46E5-B05E-7D72DF2C50E0}): 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 {563BD69E-91AA-4F0F-9AD8-7C9B030D25B8} 01-13-2016 17:56:40.135    DCMAgent    2728 (0xaa8)    DCMAgentJob({C566083F-0CB6-42E2-B80D-08ACD220DC9F}): QueueDebug - Executing Event. 01-13-2016 17:56:40.104    DCMAgent    2728 (0xaa8)    Job complete. Exiting event pump.

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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58' has started. Please refer to DCMAgent.log for the details on this job. JobID='{C566083F-0CB6-42E2-B80D-08ACD220DC9F}'
DCM Agent creates a new job for CI Agent.
DCMAgent.log: 
01-13-2016 17:56:40.135    DCMAgent    2356 (0x934)    DCMAgentJob({C566083F-0CB6-42E2-B80D-08ACD220DC9F}): CDCMAgent::InitiateCIAgentJob - Starting CI Agent Job {3A50D878-160C-4C20-8762-617064BB3EAD} 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({3A50D878-160C-4C20-8762-617064BB3EAD}): [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({3A50D878-160C-4C20-8762-617064BB3EAD}): CAgentJob::HandleEvent(Event=Transition, CurrentState=WaitingForAssignedCI) 01-13-2016 17:56:40.135    CIAgent    2728 (0xaa8)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): CAgentJob::HandleEvent(Event=DownloadCIs, CurrentState=WaitingForAssignedCI) 01-13-2016 17:56:40.135    CIAgent    2768 (0xad0)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): 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({890E8C1A-8FC2-4751-BDAC-7C43D192E0F2}): 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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58, 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({3A50D878-160C-4C20-8762-617064BB3EAD}): Nothing to be downloaded. 01-13-2016 17:56:40.182    CIAgent    2316 (0x90c)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): 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({3A50D878-160C-4C20-8762-617064BB3EAD}):  CI ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae:6 (ConfigMgr 2012 Toolkit R2 - Windows Installer (*.msi file)) targeted to  (Dependant of policy CI ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58:10) is in scope for evaluation. 01-13-2016 17:56:40.213    CIAgent    2728 (0xaa8)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): 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({3A50D878-160C-4C20-8762-617064BB3EAD}): StartEnactment - CI - ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58 01-13-2016 17:56:40.244    CIAgent    2728 (0xaa8)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): StartEnactment - Attempting to invoke Policy Platform Client 01-13-2016 17:56:40.322    CIAgent    2768 (0xad0)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): ReportMethodInvocation :: Enactment succeeded 01-13-2016 17:56:40.322    CIAgent    2768 (0xad0)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): 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({3A50D878-160C-4C20-8762-617064BB3EAD}):State - Reporting (scan):: AppModel - ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58:10 - State = NotInstalled ResolvedState = Available Applicability = Applicable ConfigureState= NotNeeded 01-13-2016 17:56:40.385    CIAgent    2768 (0xad0)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}):State - Reporting (scan):: Deployment Type - ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae:6 - State = NotInstalled ResolvedState = Available Applicability = Applicable ConfigureState= NotNeeded 01-13-2016 17:56:40.463    CIAgent    2728 (0xaa8)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}): CI ModelName ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58 version 10 will be INSTALLED. : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58.10.ContentDownload) 01-13-2016 17:56:40.463    CIAgent    2728 (0xaa8)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}): CI ModelName ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae version 6 will be INSTALLED. : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58.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({3A50D878-160C-4C20-8762-617064BB3EAD}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateDownloadingContents) 01-13-2016 17:56:40.417    CIAgent    2728 (0xaa8)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): DownloadBinaryContents 01-13-2016 17:56:40.417    CIAgent    2728 (0xaa8)    {3A50D878-160C-4C20-8762-617064BB3EAD} - Initiating ContentDownload tasks. 01-13-2016 17:56:40.463    CIAgent    2728 (0xaa8)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}) : Successfully initialized : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae.6.ContentDownload) 01-13-2016 17:56:40.463    CIAgent    2728 (0xaa8)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}) : Successfully initialized : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58.10.ContentDownload)
The complicated part is now over. Now we move on to download the binaries.

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_63fbf078-1815-4e37-9614-b60ce7947805.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='Content_63fbf078-1815-4e37-9614-b60ce7947805' and Version='1' 01-13-2016 17:56:42.448    ContentTransferManager    2768 (0xad0)    Attempting to send Location Request for PackageID='Content_63fbf078-1815-4e37-9614-b60ce7947805' 01-13-2016 17:56:42.448    ContentTransferManager    2728 (0xaa8)    Created CTM job {39721C9F-B4C0-43BC-B2CA-AE9B494BB116} 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_63fbf078-1815-4e37-9614-b60ce7947805" 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 '{7A2A5944-DD5C-4763-B685-4B4F703FC723}' for package Content_63fbf078-1815-4e37-9614-b60ce7947805 01-13-2016 17:56:42.463    ContentTransferManager    2768 (0xad0)    CTM job {39721C9F-B4C0-43BC-B2CA-AE9B494BB116} 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.
MP_Location.log: 
01-13-2016 17:56:42.516    MP_LocationManager    4044 (0xfcc)    MP_GetContentDPInfoProtected (UID:Content_63fbf078-1815-4e37-9614-b60ce7947805,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="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>
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_63fbf078-1815-4e37-9614-b60ce7947805.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_63fbf078-1815-4e37-9614-b60ce7947805.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 {39721C9F-B4C0-43BC-B2CA-AE9B494BB116}: (LOCAL) http://PS1DP.contoto.lab/SMS_DP_SMSPKG$/Content_63fbf078-1815-4e37-9614-b60ce7947805.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 {39721C9F-B4C0-43BC-B2CA-AE9B494BB116} (corresponding DTS job {64817005-37EB-4A1F-B2E8-FCE9689CD154}) started download from 'http://PS1DP.contoto.lab/SMS_DP_SMSPKG$/Content_63fbf078-1815-4e37-9614-b60ce7947805.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_63fbf078-1815-4e37-9614-b60ce7947805.1 01-13-2016 17:56:42.557    DataTransferService    2752 (0xac0)    UpdateURLWithTransportSettings(): NEW URL - http://ps1dp.contoto.lab:80/SMS_DP_SMSPKG$/Content_63fbf078-1815-4e37-9614-b60ce7947805.1/sccm?/ConfigMgrTools.msi 01-13-2016 17:56:42.573    DataTransferService    2752 (0xac0)    Starting BITS download for DTS job '{64817005-37EB-4A1F-B2E8-FCE9689CD154}'. 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_63fbf078-1815-4e37-9614-b60ce7947805.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: {64817005-37EB-4A1F-B2E8-FCE9689CD154}, Total Files: 1, Transferred Files: 0, Total Bytes: 5664768, Transferred Bytes: 262144 01-13-2016 17:56:42.869    DataTransferService    1568 (0x620)    Job: {64817005-37EB-4A1F-B2E8-FCE9689CD154}, Total Files: 1, Transferred Files: 1, Total Bytes: 5664768, Transferred Bytes: 5664768 01-13-2016 17:56:42.885    DataTransferService    2752 (0xac0)    DTSJob {64817005-37EB-4A1F-B2E8-FCE9689CD154} in state 'NotifiedComplete'. 01-13-2016 17:56:42.885    DataTransferService    2752 (0xac0)    DTS job {64817005-37EB-4A1F-B2E8-FCE9689CD154} 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={39721C9F-B4C0-43BC-B2CA-AE9B494BB116}) - Cancelling DTS job  with provider <default> 01-13-2016 17:56:42.901    ContentAccess    2348 (0x92c)    Using hash from LS Content Information: 6FB054E0532351D888291FF52F74E0085940AEA90EC85A5B999B6CFBE94663FC
CAS.log: 
01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    Computed hash: 6FB054E0532351D888291FF52F74E0085940AEA90EC85A5B999B6CFBE94663FC 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_63fbf078-1815-4e37-9614-b60ce7947805.1, C:\WINDOWS\ccmcache\1 01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    CacheManager: ADD new cache entry for id:Content_63fbf078-1815-4e37-9614-b60ce7947805 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_63fbf078-1815-4e37-9614-b60ce7947805 Size 5532 KB bytes 01-13-2016 17:56:42.948    ContentAccess    2348 (0x92c)    Download succeeded for download request {86F26D40-3858-4B2E-81FA-58611502FD4C}
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({3A50D878-160C-4C20-8762-617064BB3EAD}): TransitionState(From=StateDownloadingContents, To=StateEnforcingCIs) for Event=Transition 01-13-2016 17:56:43.041    CIAgent    2728 (0xaa8)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): EnforceCIs 01-13-2016 17:56:43.041    CIAgent    2728 (0xaa8)    {3A50D878-160C-4C20-8762-617064BB3EAD} - Initiating Enforce tasks. 01-13-2016 17:56:43.073    CIAgent    2728 (0xaa8)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}) : Performing : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58.10.Enforce) 01-13-2016 17:56:43.073    CIAgent    2728 (0xaa8)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}) : Performing : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58.10.Enforce) 01-13-2016 17:56:43.073    CIAgent    2728 (0xaa8)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}) : Performing : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae.6.Enforce)

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_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae], 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_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae, 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_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae, 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_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58'='' 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_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae, revision 6) for system. 01-13-2016 17:56:47.635    AppEnforce    2216 (0x8a8)    +++ Discovered application [AppDT Id: ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae, 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_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae], Revision: 6, User SID: ] ++++++


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_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae: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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58: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({3A50D878-160C-4C20-8762-617064BB3EAD}): Already Completed : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/DeploymentType_124d1234-48ca-4037-bac8-bdcbdedeebae.6.Enforce) 01-13-2016 17:56:47.823    CIAgent    2348 (0x92c)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}): Already Completed : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/Application_3a4c09b5-fdb6-45c2-8177-340f032e5e58.10.Enforce) 01-13-2016 17:56:47.823    CIAgent    2348 (0x92c)    Job({3A50D878-160C-4C20-8762-617064BB3EAD}): Already Completed : Task(ScopeId_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58.10.Enforce) 01-13-2016 17:56:47.838    CIAgent    2316 (0x90c)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): 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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5-fdb6-45c2-8177-340f032e5e58:10] CIState changed: NonCompliant --> Compliant
CIAgent.log :
01-13-2016 17:56:47.963    CIAgent    2728 (0xaa8)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): CAgentJob::HandleEvent(Event=Transition, CurrentState=Completed) 01-13-2016 17:56:47.963    CIAgent    2728 (0xaa8)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): CAgentJob::HandleEvent(Event=Transition, CurrentState=Completed) 01-13-2016 17:56:47.963    CIAgent    2728 (0xaa8)    CIAgentJob({3A50D878-160C-4C20-8762-617064BB3EAD}): Deleting CIAgent Job 01-13-2016 17:56:47.963    CIAgent    2728 (0xaa8)    Deleted CIAgent job {3A50D878-160C-4C20-8762-617064BB3EAD}
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_6B689E63-9887-46C5-9062-4A5604D52D33/RequiredApplication_3a4c09b5- fdb6-45c2-8177-340f032e5e58.10 = Enforced 01-13-2016 17:56:47.979    DCMAgent    2316 (0x90c)    DCMAgentJob({C566083F-0CB6-42E2-B80D-08ACD220DC9F}): 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 {C566083F-0CB6-42E2-B80D-08ACD220DC9F}
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


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.


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.
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:4a6ea5f2-110c-4417-b494-ea84eba71d3b.
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.


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.


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:
  1. Bad data in the database, returns corrupted CI or SDM Package Data. Out of date versions, etc.
  2. WMI issues, accessing policy namespaces locally on the machine executing the task sequence.
  3. Failure communicating with the MP or the DB.
  4. BITS jobs failures.
  5. Network related errors, downloads, etc.
  6. IIS issues with SMS_MP vDir (SMS_CCM\SMS_MP folder).
  7. 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


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

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.


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


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


Properties

Article ID: 18408 - Last Review: 17-May-2016 - Revision: 25

Feedback