ConfigMgr 2012–Application Model–Internals– Part II - Client Side Deployment
In part I of this blog series we discussed the server side internals when building and configuring a deployment in the new application model. With the delay between part I and part II I have now given you plenty of time to absorb the part I information and be ready to proceed to the client side! :)
For part II, we will pick up at the stage where two applications have been built and deployed. The deployment will take two forms, one targeted to a collection of users (which is where we will spend the bulk of our time) and another deployed to a collection of devices. Both deployments will be configured as optional. We will begin tracing from the point at which the deployments have already shown up and the user initiates the installation action. This means that the activity to detect a policy update and begin processing will have already taken place. Because there is a great deal of similarity between the applications, we will focus on tracing the user targeted deployment. Before we get started with tracing though, lets take a look at the deployments themselves as they show up on the client and also review both the user and device deployments as they currently exist in WMI.
Deployments
As already stated, we have two deployments – one to users and one to devices. The deployment to users is available in both software center AND the application web catalog, which can be accessed by URL directly or by using the ‘Find additional applications from the Application Catalog’ option in software center – as shown
.
The deployment to devices is available in Software Center as shown.
So why is it that a deployment to devices shows up in software center only but a deployment to users shows up in both the software center AND the application web catalog? Simple – choosing user deployment is the only option that allows an application to be listed in the web catalog. A deployment will always show up in software center because of the options shown below which are a part of every deployment.
WMI
We notice that we have our deployments showing up in software center. As such, we know that policy has been correctly retrieved and details pertaining to the deployment stored away in WMI so they are available at runtime. Devices and users have different storage locations for root policy. Lets take a look at a couple of key WMI classes associated with the deployments.
In the namespaces below we see the details of the deployments, including unique deployment ID’s (in bold), the name of the applications being deployed and configuration detail for the applications.
User Deployment
root\ccm\policy\s_1_5_21_2382599338_2815126685_3026542690_500\actualconfig
Note that the long identifier in the namespace is a unique ID associated with the targeted user.
instance of CCM_ApplicationCIAssignment
{
AssignedCIs = {"<?xml version='1.0' ?>\n\t\t<CI>\n\t\t\t <ID>ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/2</ID> \n\t\t\t <ModelName>ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989</ModelName> \n\t\t\t<Version>1.00</Version>\n\t\t\t<CIVersion>2</CIVersion>\n\t\t\t<ApplicabilityCondition>\n\t\t\t\t\n\t\t\t</ApplicabilityCondition>\n\t\t\t<EnforcementEnabled>FALSE</EnforcementEnabled>\n\t\t\t<DisplayName></DisplayName>\n\t\t</CI>"};
AssignmentAction = 2;
AssignmentID = " {88BD1003-882F-4272-BDD5-F0D2E94F3009} ";
AssignmentName = "Microsoft RichCopy 4.0 - System and User Target - Install and Uninstall Demo_All Users_Install";
DesiredConfigType = 1;
DisableMomAlerts = FALSE;
DPLocality = 80;
LogComplianceToWinEvent = FALSE;
NonComplianceCriticality = 0;
NotifyUser = TRUE;
OverrideServiceWindows = FALSE;
Priority = 1;
RaiseMomAlertsOnFailure = FALSE;
RebootOutsideOfServiceWindows = FALSE;
Reserved1 = "";
Reserved2 = "";
Reserved3 = "";
SendDetailedNonComplianceStatus = FALSE;
StartTime = "20121112145500.000000+***";
StateMessagePriority = 5;
SuppressReboot = 0;
UseGMTTimes = TRUE;
UserUIExperience = TRUE;
UseSiteEvaluation = TRUE;
WoLEnabled = FALSE;
};
Device Deployment
root\ccm\policy\machine\actualconfig
instance of CCM_ApplicationCIAssignment
{
AssignedCIs = {"<?xml version='1.0' ?>\n\t\t<CI>\n\t\t\t <ID>ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_ec9bf435-7b3a-4740-94b2-5275c43531a4/3</ID> \n\t\t\t\n\t\t\t<Version>1.0 <ModelName>ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_ec9bf435-7b3a-4740-94b2-5275c43531a4</ModelName> 0</Version>\n\t\t\t<CIVersion>3</CIVersion>\n\t\t\t<ApplicabilityCondition>\n\t\t\t\t\n\t\t\t</ApplicabilityCondition>\n\t\t\t<EnforcementEnabled>FALSE</EnforcementEnabled>\n\t\t\t<DisplayName></DisplayName>\n\t\t</CI>"};
AssignmentAction = 2;
AssignmentID = " {F9D02DD6-E945-4791-B545-9A4A9E954560} ";
AssignmentName = "Robocopy from RichCopy_Sample Package Deployment_Install";
DesiredConfigType = 1;
DisableMomAlerts = FALSE;
DPLocality = 80;
LogComplianceToWinEvent = FALSE;
NonComplianceCriticality = 0;
NotifyUser = FALSE;
OverrideServiceWindows = FALSE;
Priority = 1;
RaiseMomAlertsOnFailure = FALSE;
RebootOutsideOfServiceWindows = FALSE;
Reserved1 = "";
Reserved2 = "";
Reserved3 = "";
SendDetailedNonComplianceStatus = FALSE;
StartTime = "20121112145700.000000+***";
StateMessagePriority = 5;
SuppressReboot = 0;
UpdateDeadline = "20121112145700.000000+***";
UseGMTTimes = TRUE;
UserUIExperience = TRUE;
UseSiteEvaluation = TRUE;
WoLEnabled = FALSE;
};
Tracking the Deployments
User Deployment
The user deployment is initiated from the application web catalog. When working in the logs it is always a good idea to keep track of times when key activities take place. For our example the deployment was initiated at 10:41 PM. We monitor until we see the success page pop up. In addition, if you were to monitor software center you would see the action of installation happening there and likely a success indicator in software center will likely lag slightly behind the web catalog success screen.
Once deployment is complete, collect all of the client logs and copy them to a unique location so we can avoid further updates. To view the logs we will use CMTrace. Launch it directly and select File>Open and navigate to the folder where you copied the log files. Sort the log files by date and highlight all of those that were updated from 10:41 PM forward – these will be the logs that were active during software installation and, accordingly, will be the ones that contain the information we are interested in reviewing to trace the software deployment. Having highlighted all of the logs, select ‘Merge selected files’ and then select Open, as shown.
Choosing to merge the logs together weaves all of the selected logs by time stamp and is a really good way to see the hand-off that happens between different components as they process through the application deployment. By using this approach it is likely that you will also get log sections that just happen to be active during deployment time but actually are not relevant to the application deployment (or whatever else you are tracking) - those items are generally easy to identify and discard as you are looking through the logging.
Note: I have seen in the past where some logs that are active do not update their time stamp so sorting by time stamp will fail to identify those components and they may be overlooked. Even with this possibility using the approach of merging the logs is a great first step to understand the process. As you work through the process you will learn all of the components that are involved and you will ultimately no longer need to use the merge approach as you will know just which component to review for a given problem.
After merging the logs we need to find the start of the action that began when we initiated install. Since we know the install started at 10:41 PM we scroll to that time frame in the log and see where we need to start reading in the logs to see what transpired! In my case I intentionally initiated the install at exactly 10:41 PM so that its easier to find the start of the action in the logs, as shown below. One thing you will also likely note from merging the logs is that there is a bunch of logging information that you can pass right past since it was from a time frame before when the application install was initiated. Note the position of the slider bar in the screenshot. It’s from this port forward that we care about the logs for our example.
We can see the first component involved is the CCMSDKProvider, which is a new component in ConfigMgr 2012. :ets walk through the activity that took place during application install. My intention here is NOT to go line by line (which would be incredibly tedious and mind numbing) but, instead, to call out some highlights of activity that happens to get the application installed. As we begin working through the trace I will show the complete log but as we get further along and log entries start seeming to repeat I will omit certain sections for brevity. In addition, I have included the component and time stamp details in each log entry below. It makes the log entries a bit more difficult to read here but is important to highlight the component hand-off that is taking place and the time stamps. I have bolded sections of the log entries to help you avoid getting lost in the log ‘noise’ and I comments to highlight and discuss various actions. I’ve highlighted my comments in red to set them apart from the remainder of the text.
CCMSDKProvider starts off the process by getting the users capability, retrieving the Client Device ID, determining the client version, and finally handing off to Policy SDK to begin applying the policy.
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:04 PM 3720 (0x0E88)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:05 PM 3720 (0x0E88)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:05 PM 3720 (0x0E88)
Calling GetUserCapability. CCMSDKProvider 11/13/2012 10:41:05 PM 3720 (0x0E88)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:05 PM 3720 (0x0E88)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:05 PM 3720 (0x0E88)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:05 PM 3720 (0x0E88)
Retreiving the Client's Device ID CCMSDKProvider 11/13/2012 10:41:05 PM 3720 (0x0E88)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Determining the client version. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:07 PM 3720 (0x0E88)
Calling GetUserCapability. CCMSDKProvider 11/13/2012 10:41:08 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:08 PM 3720 (0x0E88)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:08 PM 3720 (0x0E88)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:08 PM 3720 (0x0E88)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:08 PM 3720 (0x0E88)
Calling ApplyPolicyEx CCMSDKProvider 11/13/2012 10:41:08 PM 524 (0x020C)
At this stage PolicySDK begins work to retrieve and act on the application policy. Notice that the UserID called out in the logs exactly maps to the WMI namespace we showed earlier for the user (root\ccm\policy\s_1_5_21_2382599338_2815126685_3026542690_500\actualconfig), Also note that the Policy ID called out below maps to the Assignment ID reflected in the WMI detail for the user, as shown above. Also as shown above, the PolicyID shown maps to what was listed in WMI for the user.
------------------- PolicySdk 11/13/2012 10:41:09 PM 3824 (0x0EF0)
ApplyPolicyEx BEGIN PolicySdk 11/13/2012 10:41:09 PM 3824 (0x0EF0)
ID : [User;S-1-5-21-2382599338-2815126685-3026542690-500;CCM_Policy_Policy4.PolicyID="{88BD1003-882F-4272-BDD5-F0D2E94F3009}",PolicyVersion="1.00",PolicySource="CcmPortal";CCM_Policy_Policy4.PolicyID="Windows/All_Windows_Client_Server/VI/VS",PolicyVersion="1.00",
PolicySource="CcmPortal";CCM_Policy_Policy4.PolicyID="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/VI/VS",PolicyVersion="1.00",PolicySource="CcmPortal"] PolicySdk 11/13/2012 10:41:09 PM 3824 (0x0EF0)
Processing completed in 93 ms PolicySdk 11/13/2012 10:41:09 PM 3824 (0x0EF0)
ApplyPolicyEx END PolicySdk 11/13/2012 10:41:09 PM 3824 (0x0EF0)
--------------------- PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
OK, quick pause. Notice above the seemingly confusing long strings of ID’s? What the heck are those and why do I care? Glad you asked. In the logs you rarely will see your application referred to in plain text. Would be nice if we had plain text (aka readable text!) more often but we don’t. But once you become accustomed to this style of representation in the logs it’s really no big deal. So, the previous section of log was actually calling out that we were working on our RichCopy application. How do I know? Notice the PolicyID listed as ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989. If we go back to the console and focus in on the RichCopy application we will see a CI UniqueID column. This column, when present (not present by default), will list out the ID for the application that can be correlated to the log files to help you in tracking, as shown.
OK, back to the logs. After the policy is retrieved it is validated and the assignment compiled/applied.
ApplyPolicyImpl BEGIN PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Verifying signature using labsrvcmps1.contoso.com certificate PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Verified signature successfully PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
CcmPortal PolicySource is valid and registered PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Processing User S-1-5-21-2382599338-2815126685-3026542690-500 assignments from 'CcmPortal'. PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Received policy update with 3 assignments PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Compiling policy assignment '{6ff8980c-2260-40c3-8550-cfc9a139f649}' (ver. 1.00) from 'CcmPortal' (2012-11-14 04:41:09.461) PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Compiling policy '{88BD1003-882F-4272-BDD5-F0D2E94F3009}' version '1.00' hash 'SHA256:5BB49438F0D2BF45606F150AF44D9A33E20A8449690599F046DCA3F5342CFD8A' from 'CcmPortal' (2012-11-14 04:41:09.461) PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Policy {88BD1003-882F-4272-BDD5-F0D2E94F3009} version 1.00 hash SHA256:5BB49438F0D2BF45606F150AF44D9A33E20A8449690599F046DCA3F5342CFD8A already exists on client PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Deleting policy assignment '{6ff8980c-2260-40c3-8550-cfc9a139f649}' PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Compiling policy assignment '{2ea05c16-df6c-44c1-a44b-c237f12bd47e}' (ver. 1.00) from 'CcmPortal' (2012-11-14 04:41:09.461) PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Compiling policy 'Windows/All_Windows_Client_Server/VI/VS' version '1.00' hash 'SHA256:2D646F6A67F56E7A13A7EBF26C6488EA4BB7D9C2AA83447DFC3B3647B9015243' from 'CcmPortal' (2012-11-14 04:41:09.461) PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Policy Windows/All_Windows_Client_Server/VI/VS version 1.00 hash SHA256:2D646F6A67F56E7A13A7EBF26C6488EA4BB7D9C2AA83447DFC3B3647B9015243 already exists on client PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Deleting policy assignment '{2ea05c16-df6c-44c1-a44b-c237f12bd47e}' PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Compiling policy assignment '{1decc1b2-59dc-49da-bac8-8cf4920798af}' (ver. 1.00) from 'CcmPortal' (2012-11-14 04:41:09.461) PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Compiling policy 'ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/VI/VS' version '1.00' hash 'SHA256:BA62C8E9B23D73B60A0FA97DC2E77643DC37B3E2009B9D7FCAF725AA5AF696DD' from 'CcmPortal' (2012-11-14 04:41:09.461) PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Policy ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/VI/VS version 1.00 hash SHA256:BA62C8E9B23D73B60A0FA97DC2E77643DC37B3E2009B9D7FCAF725AA5AF696DD already exists on client PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Deleting policy assignment '{1decc1b2-59dc-49da-bac8-8cf4920798af}' PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Updating settings in \\cmclt1\root\ccm\policy\s_1_5_21_2382599338_2815126685_3026542690_500\actualconfig PolicySdk 11/13/2012 10:41:09 PM 4024 (0x0FB8)
Raising event:
At this stage we have successfully evaluate the settings and processing continues. Note the namespace called out for WMI is the one we referenced earlier.
instance of CCM_PolicyAgent_SettingsEvaluationComplete
{
ClientID = "GUID:0CD5BD52-D9BD-4D0C-B0AF-DAC54966D594";
DateTime = "20121114044110.305000+000";
PolicyNamespace = " \\\\cmclt1\\root\\ccm\\policy\\s_1_5_21_2382599338_2815126685_3026542690_500\\actualconfig";
ProcessID = 4252;
ThreadID = 4024;
};
PolicySdk 11/13/2012 10:41:10 PM 4024 (0x0FB8)
Raising event (#1 of 1):
instance of CCM_PolicyAgent_SettingsEvaluationComplete {
ClientID = "GUID:0CD5BD52-D9BD-4D0C-B0AF-DAC54966D594";
DateTime = "20121114044110.305000+000";
PolicyNamespace = " \\\\cmclt1\\root\\ccm\\policy\\s_1_5_21_2382599338_2815126685_3026542690_500\\actualconfig";
ProcessID = 4252;
ThreadID = 4024;
};
The status from the recent activity is reported by calling StatusAgent. StatusAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
Successfully raised 1 event(s) StatusAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
Applied policies PolicySdk 11/13/2012 10:41:10 PM 4024 (0x0FB8)
Status 0 Return 00000000 PolicySdk 11/13/2012 10:41:10 PM 4024 (0x0FB8)
Processing completed in 891 ms PolicySdk 11/13/2012 10:41:10 PM 4024 (0x0FB8)
ApplyPolicyImpl END PolicySdk 11/13/2012 10:41:10 PM 4024 (0x0FB8)
Event forwarder SmsPolicyEventForwarder:SmsSoftwareDistribution.Instance0 received 1 events StatusAgent 11/13/2012 10:41:10 PM 3824 (0x0EF0)
[00CDBE70] Handling 1 events StatusAgent 11/13/2012 10:41:10 PM 3824 (0x0EF0)
[00CDBE70] Handling event class CCM_PolicyAgent_SettingsEvaluationComplete StatusAgent 11/13/2012 10:41:10 PM 3824 (0x0EF0)
Event forwarder SmsPolicyEventForwarder:SmsSoftwareDistribution.Instance0 successfully handled 1 events StatusAgent 11/13/2012 10:41:10 PM 3824 (0x0EF0)
Now we are back to CCMSDKProvider to check the state of policy after processing
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:10 PM 524 (0x020C)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:10 PM 524 (0x020C)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:10 PM 524 (0x020C)
Calling GetPolicyState CCMSDKProvider 11/13/2012 10:41:10 PM 524 (0x020C)
GetPolicyState ID : [User;S-1-5-21-2382599338-2815126685-3026542690-500;CCM_Policy_Policy4.PolicyID="{88BD1003-882F-4272-BDD5-F0D2E94F3009}",PolicyVersion="1.00",PolicySource="CcmPortal";CCM_Policy_Policy4.PolicyID="Windows/All_Windows_Client_Server/VI/VS",PolicyVersion="1.00",PolicySource="CcmPortal";CCM_Policy_Policy4.PolicyID="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/VI/VS",PolicyVersion="1.00",PolicySource="CcmPortal"] PolicySdk 11/13/2012 10:41:10 PM 3824 (0x0EF0)
GetPolicyState Status : [0] State : [5] PolicySdk 11/13/2012 10:41:10 PM 3824 (0x0EF0)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:10 PM 524 (0x020C)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:10 PM 524 (0x020C)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:10 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:10 PM 524 (0x020C)
At this stage we begin the work to pull down Configuration Items (CI’s) needed for the job. This work is initiated by CIAgent. Other components are invoked as needed to get the work of CI download done – such as CIDownloader. There is A LOT to discuss here. Note the bolded entries show the flow as we move through obtaining the various CI components required.
CAgent::CreateJob - Creating new CI Agent Job for user: S-1-5-21-2382599338-2815126685-3026542690-500 CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
*** Keep the system awake CCMEXEC 11/13/2012 10:41:10 PM 3736 (0x0E98)
Power lease [510954] started by 'CIAgent: job initialized' for 120 minutes pwrmgmt 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CAgent::EvaluateCIs CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=Init) CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): Client requesting CIAgentJob context info for key: StateMessagePriority CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=Init, To=WaitingForAssignedCI) for Event=Transition CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=WaitingForAssignedCI) CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore DownloadCIs CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=DownloadCIs, CurrentState=WaitingForAssignedCI) CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=WaitingForAssignedCI, To=DownloadingCIs) for Event=Transition CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=DownloadingCIs) CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): Client requesting CIAgentJob context info for key: PostRebootDetect CIAgent 11/13/2012 10:41:10 PM 4024 (0x0FB8)
CCIDownloader::CreateJob CIDownloader 11/13/2012 10:41:10 PM 4024 (0x0FB8)
We now need to download CI’s so we spin up the CIDownloader thread to help us with that. We can see first that if there are any errors encountered the whole process will stop. Also note that we will often have a number of CI’s to download – though some may already be downloaded. So expect that we can spend some time here in these log sections. Ci’s consist of internal models that are required by the client and also user defined CI’s that are created as you build the application. For a reminder as to what these CI’s are, refer back to part I of this series.
CIDownloaderJob({F9FE9C29-D422-4F01-8C03-CA7D39BDD160}): SetFailureCondition - Job will fail immediately on error CIDownloader 11/13/2012 10:41:10 PM 4024 (0x0FB8)
Here we begin adding individual CI’s that need to be downloaded.
[Calculate Scope] - Adding CI Modelname:ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989 Version:2 to Scoped CIs List of root Modelname:ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989 Version:2 CIDownloader 11/13/2012 10:41:10 PM 4024 (0x0FB8)
**
QueryCIStateStoreFromSQL 1 rows returned for query select
st.ModelName,st.Revision,st.UserSID,st.LastUpdateTime,st.Applicability,st.State,st.DesiredState,st.Severity,st.EvaluationState,st.EvaluationStateProgress, st.DisplayName,st.DetailedReport,st.CheckSum,st.LatestRevision,st.TotalSupressionCount,st.TotalEnforcements,st.TotalConflicts,st.NumCompliantRules,
st.EnforcementState,st.EnforceError,st.LaunchState,st.LaunchErrorCode,st.LaunchAdditionalErrorInfo,st.EnforcementStateProgress,st.LastEvalTime,
st.LastError,st.LastInstallTime,st.StartTime,st.EnforcementDeadline,st.UpdateDeadline,st.DCMDetectionState,st.Priority,st.Precedence,st.IsEnforcable,
st.DPLocality,st.DisableMomAlerts,st.RaiseMomAlertsOnFailure,st.SupressReboot,st.OverrideServiceWindows,st.RebootOutsideOfServiceWindows, st.UseSiteEvaluation,st.UseGMTTimes,st.NotifyUser,st.UserUIExperience,st.WolEnabled,st.ContentSize,st.RetriesRemaining, st.IsUserPolicyEffective, st.SupersessionState, st.IsPreflightOnly from ConfigurationItemState st where ModelName = 'ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989' and Revision = 2 and UserSID = 'S-1-5-21-2382599338-2815126685-3026542690-500'. CIStateStore 11/13/2012 10:41:10 PM 4024 (0x0FB8)
OK, hold the phone. What? Is the purple section above correct? The client is doing a SQL query? Surely that is wrong. WQL query I can believe but SQL? Surprise! Yes, this is actually a SQL query being run by the client – and you will see a few more below as processing continues (called out in purple). New to ConfigMgr 2012 is that every client has a SQL database for tracking application related items. If you browse to the windows\ccm folder, you can find it, as shown below. The CCMStore.sdf is the database (SQL Express) and the CCMStore.log tracks activity in the database.
I won’t go into detail here but you can even open this database to poke around if you want using SQL tools. Note: Edit this or any database is totally unsupported and should be done for education purposes only. If you decide to open the CCMStore.sdf you should make a copy of it and open that copy vs. trying to edit the database on the live client. Further, there should be NO need to edit this database. If a circumstance arises where it is thought to be needed you should be working with Microsoft support. If the database becomes messed up for some reason the far easier and better way to get it restored to proper function is to reinstall the client.
OK, that was fun! Let’s get back to the logs
CDownloadPayloadInfo::AddCI - CI with ModelName ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989, Version 2 is already available. Requested Model:VersionSpecific will be downloaded. CIDownloader 11/13/2012 10:41:11 PM 4024 (0x0FB8)
[Calculate Scope] - Adding CI Modelname:ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989 Version:2 to Scoped CIs List of root Modelname:ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989 Version:2 CIDownloader 11/13/2012 10:41:11 PM 4024 (0x0FB8)
QueryCIStateStoreFromSQL 1 rows returned for query select st.ModelName,st.Revision,st.UserSID,st.LastUpdateTime,st.Applicability,st.State,st.DesiredState,st.Severity,st.EvaluationState,st.EvaluationStateProgress, st.DisplayName,st.DetailedReport,st.CheckSum,st.LatestRevision,st.TotalSupressionCount,st.TotalEnforcements,st.TotalConflicts,st.NumCompliantRules,
st.EnforcementState,st.EnforceError,st.LaunchState,st.LaunchErrorCode,st.LaunchAdditionalErrorInfo,st.EnforcementStateProgress,st.LastEvalTime,
st.LastError,st.LastInstallTime,st.StartTime,st.EnforcementDeadline,st.UpdateDeadline,st.DCMDetectionState,st.Priority,st.Precedence,st.IsEnforcable,
st.DPLocality,st.DisableMomAlerts,st.RaiseMomAlertsOnFailure,st.SupressReboot,st.OverrideServiceWindows,st.RebootOutsideOfServiceWindows, st.UseSiteEvaluation,st.UseGMTTimes,st.NotifyUser,st.UserUIExperience,st.WolEnabled,st.ContentSize,st.RetriesRemaining, st.IsUserPolicyEffective, st.SupersessionState, st.IsPreflightOnly from ConfigurationItemState st where ModelName = 'ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989' and Revision = 2 and UserSID = 'S-1-5-21-2382599338-2815126685-3026542690-500'. CIStateStore 11/13/2012 10:41:11 PM 4024 (0x0FB8)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:11 PM 524 (0x020C)
Creation event received for process 472 mtrmgr 11/13/2012 10:41:11 PM 2316 (0x090C)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:11 PM 524 (0x020C)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:11 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:12 PM 524 (0x020C)
Process ID 472 is for process C:\Program Files\Microsoft Policy Platform\policyHost.exe mtrmgr 11/13/2012 10:41:12 PM 2316 (0x090C)
No matching rule found for process 472 mtrmgr 11/13/2012 10:41:12 PM 3828 (0x0EF4)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:13 PM 524 (0x020C)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:13 PM 524 (0x020C)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:13 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:13 PM 524 (0x020C)
CDownloadPayloadInfo::AddCI - CI with ModelName ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989, Version 2 is already available. Requested Model:VersionSpecific will be downloaded. CIDownloader 11/13/2012 10:41:13 PM 4024 (0x0FB8)
[Calculate Scope] - Adding CI Modelname:ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0 Version:1 to Scoped CIs List of root Modelname:ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989 Version:2 CIDownloader 11/13/2012 10:41:13 PM 4024 (0x0FB8)
QueryCIStateStoreFromSQL 1 rows returned for query select st.ModelName,st.Revision,st.UserSID,st.LastUpdateTime,st.Applicability,st.State,st.DesiredState,st.Severity,st.EvaluationState,st.EvaluationStateProgress, st.DisplayName,st.DetailedReport,st.CheckSum,st.LatestRevision,st.TotalSupressionCount,st.TotalEnforcements,st.TotalConflicts,st.NumCompliantRules,
st.EnforcementState,st.EnforceError,st.LaunchState,st.LaunchErrorCode,st.LaunchAdditionalErrorInfo,st.EnforcementStateProgress,st.LastEvalTime,
st.LastError,st.LastInstallTime,st.StartTime,st.EnforcementDeadline,st.UpdateDeadline,st.DCMDetectionState,st.Priority,st.Precedence,st.IsEnforcable,
st.DPLocality,st.DisableMomAlerts,st.RaiseMomAlertsOnFailure,st.SupressReboot,st.OverrideServiceWindows,st.RebootOutsideOfServiceWindows, st.UseSiteEvaluation,st.UseGMTTimes,st.NotifyUser,st.UserUIExperience,st.WolEnabled,st.ContentSize,st.RetriesRemaining, st.IsUserPolicyEffective, st.SupersessionState, st.IsPreflightOnly from ConfigurationItemState st where ModelName = 'ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0' and Revision = 1 and UserSID = 'S-1-5-21-2382599338-2815126685-3026542690-500' . CIStateStore 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CDownloadPayloadInfo::AddCI - CI with ModelName ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0, Version 1 is already available. Requested Model:VersionSpecific will be downloaded. CIDownloader 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIDownloaderJob({F9FE9C29-D422-4F01-8C03-CA7D39BDD160}): CI with ModelName ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989, Version 2. Model:(null) added to job. CIDownloader 11/13/2012 10:41:13 PM 4024 (0x0FB8) CCIDownloader::StartJob CIDownloader 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIDownloader job empty. CIDownloader 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): Nothing to be downloaded. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
At this stage the downloading is finished and we begin processing (persisting) the CI’s we have downloaded.
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore PersistCIs CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=PersistCIs, CurrentState=DownloadingCIs) CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=DownloadingCIs, To=PersistingCIModels) for Event=Transition CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::Execute [GlobalSemaphore] Trying to aquire global semaphore CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::Execute [GlobalSemaphore] Queued for global semaphore acquisition. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): GlobalJobEvent() called [GlobalSemaphore] CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::Execute [GlobalSemaphore] Acquired global semaphore. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=PersistingCIModels) CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CCIDownloader::DeleteJob for job {F9FE9C29-D422-4F01-8C03-CA7D39BDD160} CIDownloader 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIDownloader job deleted. CIDownloader 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989:2 (Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo) targeted to S-1-5-21-2382599338-2815126685-3026542690-500 (Dependant of policy CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2) is in scope for evaluation. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0:1 (Microsoft RichCopy 4.0 - Full Install - Available) targeted to S-1-5-21-2382599338-2815126685-3026542690-500 (Dependant of policy CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2) is in scope for evaluation. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
Failed to get the display name of the CI. Status messages will be based on the CI ID. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2 () targeted to S-1-5-21-2382599338-2815126685-3026542690-500 (Dependant of policy CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2) is in scope for evaluation. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
QueryCIStateStoreFromSQL 1 rows returned for query select st.ModelName,st.Revision,st.UserSID,st.LastUpdateTime,st.Applicability,st.State,st.DesiredState,st.Severity,st.EvaluationState,st.EvaluationStateProgress, st.DisplayName,st.DetailedReport,st.CheckSum,st.LatestRevision,st.TotalSupressionCount,st.TotalEnforcements,st.TotalConflicts,st.NumCompliantRules,
st.EnforcementState,st.EnforceError,st.LaunchState,st.LaunchErrorCode,st.LaunchAdditionalErrorInfo,st.EnforcementStateProgress,st.LastEvalTime,
st.LastError,st.LastInstallTime,st.StartTime,st.EnforcementDeadline,st.UpdateDeadline,st.DCMDetectionState,st.Priority,st.Precedence,st.IsEnforcable,
st.DPLocality,st.DisableMomAlerts,st.RaiseMomAlertsOnFailure,st.SupressReboot,st.OverrideServiceWindows,st.RebootOutsideOfServiceWindows, st.UseSiteEvaluation,st.UseGMTTimes,st.NotifyUser,st.UserUIExperience,st.WolEnabled,st.ContentSize,st.RetriesRemaining, st.IsUserPolicyEffective, st.SupersessionState, st.IsPreflightOnly from ConfigurationItemState st join ConfigurationItems ci on st.ModelName=ci.ModelName and st.Revision=ci.Revision where ci.type=21 and st.UserSID='S-1-5-21-2382599338-2815126685-3026542690-500' and StartTime is not NULL. CIStateStore 11/13/2012 10:41:13 PM 4024 (0x0FB8)
QueryCIStateStoreFromSQL 1 rows returned for query select st.ModelName,st.Revision,st.UserSID,st.LastUpdateTime,st.Applicability,st.State,st.DesiredState,st.Severity,st.EvaluationState,st.EvaluationStateProgress, st.DisplayName,st.DetailedReport,st.CheckSum,st.LatestRevision,st.TotalSupressionCount,st.TotalEnforcements,st.TotalConflicts,st.NumCompliantRules,
st.EnforcementState,st.EnforceError,st.LaunchState,st.LaunchErrorCode,st.LaunchAdditionalErrorInfo,st.EnforcementStateProgress,st.LastEvalTime,
st.LastError,st.LastInstallTime,st.StartTime,st.EnforcementDeadline,st.UpdateDeadline,st.DCMDetectionState,st.Priority,st.Precedence,st.IsEnforcable,
st.DPLocality,st.DisableMomAlerts,st.RaiseMomAlertsOnFailure,st.SupressReboot,st.OverrideServiceWindows,st.RebootOutsideOfServiceWindows, st.UseSiteEvaluation,st.UseGMTTimes,st.NotifyUser,st.UserUIExperience,st.WolEnabled,st.ContentSize,st.RetriesRemaining, st.IsUserPolicyEffective, st.SupersessionState, st.IsPreflightOnly from ConfigurationItemState st join ConfigurationItems ci on st.ModelName=ci.ModelName and st.Revision=ci.Revision where ci.type=21 and st.UserSID='SYSTEM' and StartTime is not NULL. CIStateStore 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=PersistingCIModels, To=InvokingSdmMethod) for Event=Transition CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
Persisting of download CI’s complete, now we begin invoking further processing using the SDM model. For further information on SDM model, refer to one of my software updates blog post available here. While that post details software updates in ConfigMgr 2007, the definitions of terms applies to applications (which is just another type of CI in ConfigMgr 2012) and continues to be relevant.
In the next section we start to process through the CI’s and bind them to policies.
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=InvokingSdmMethod) CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): StartEnactment - CI - ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989 CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): StartEnactment - Attempting to invoke Policy Platform Client CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
Acquiring lock CIAgent 11/13/2012 10:41:13 PM 4024 (0x0FB8)
DCM::LanternUtils::CreateBindingInstance - Creating binding document for Policy: ScopeId_94B6C63C_6EE7_4F59_A303_0104DF8EC959_Application_34d4a800_ccdd_4aaf_8188_cacebe028989_2_Platform_PolicyDocument, Revision: 2. CIAgent 11/13/2012 10:41:14 PM 4024 (0x0FB8)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:14 PM 524 (0x020C)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:14 PM 524 (0x020C)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:14 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:14 PM 524 (0x020C)
DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_94B6C63C_6EE7_4F59_A303_0104DF8EC959_Application_34d4a800_ccdd_4aaf_8188_cacebe028989_2_Platform_PolicyDocument CIAgent 11/13/2012 10:41:14 PM 4024 (0x0FB8)
DCM::LanternUtils::CreateBindingInstance - Creating binding document for Policy: ScopeId_94B6C63C_6EE7_4F59_A303_0104DF8EC959_Application_34d4a800_ccdd_4aaf_8188_cacebe028989_2_Configuration_PolicyDocument, Revision: 2. CIAgent 11/13/2012 10:41:14 PM 4024 (0x0FB8)
DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_94B6C63C_6EE7_4F59_A303_0104DF8EC959_Application_34d4a800_ccdd_4aaf_8188_cacebe028989_2_Configuration_PolicyDocument CIAgent 11/13/2012 10:41:14 PM 4024 (0x0FB8)
DCM::LanternUtils::CreateBindingInstance - Creating binding document for Policy: ScopeId_94B6C63C_6EE7_4F59_A303_0104DF8EC959_DeploymentType_8c11eaf6_d27c_45a3_834e_3cf263bd1eb0_1_Discovery_PolicyDocument, Revision: 1. CIAgent 11/13/2012 10:41:14 PM 4024 (0x0FB8)
DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_94B6C63C_6EE7_4F59_A303_0104DF8EC959_DeploymentType_8c11eaf6_d27c_45a3_834e_3cf263bd1eb0_1_Discovery_PolicyDocument CIAgent 11/13/2012 10:41:14 PM 4024 (0x0FB8)
DCM::LanternUtils::CreateBindingInstance - Creating binding document for Policy: ScopeId_94B6C63C_6EE7_4F59_A303_0104DF8EC959_DeploymentType_8c11eaf6_d27c_45a3_834e_3cf263bd1eb0_1_Requirements_PolicyDocument, Revision: 1. CIAgent 11/13/2012 10:41:14 PM 4024 (0x0FB8)
DCM::LanternUtils::ScopeAndBindPolicies - [ScopedPolicies] ScopeId_94B6C63C_6EE7_4F59_A303_0104DF8EC959_DeploymentType_8c11eaf6_d27c_45a3_834e_3cf263bd1eb0_1_Requirements_PolicyDocument CIAgent 11/13/2012 10:41:14 PM 4024 (0x0FB8)
Entering ExecQueryAsync for query "select * from CCM_AppDeliveryType where (AppDeliveryTypeId = "ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0" AND Revision = 1)" AppDiscovery 11/13/2012 10:41:15 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:15 PM 3720 (0x0E88)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:15 PM 3720 (0x0E88)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:15 PM 3720 (0x0E88)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:15 PM 3720 (0x0E88)
All of the needed CI components are here so we can begin to evaluate the application. Here we see that the first step we do is to validate whether the application is already installed or not. If it’s there then why install it again? This is new in ConfigMgr 2012. In previous versions we were able to detect if an application was present IF it had been previously installed by ConfigMgr. If the app were installed by other than ConfigMgr we wouldn’t know so would install it again. With this new logic if the app is there by some other means or by ConfigMgr, we bypass the install. This also illustrates how important it is to have your detection logic built solid for a deployment. If this all seems very software update like, you would be correct. For some checks there are similarities between the application model and software updates model.
Regarding detection logic (and other configurations as well), one item that can really lead to confusion in detection logic is applications that are wrapped. If using an MSI wrapper, as an example, the product code reflected will be that of the wrapper and not that of the actual product being installed. In this case, default MSI detection logic will be built for the wrapper and not the application we are actually installing so this could lead to confused results here as well as when trying to deinstall software automatically, such as in the case of a supercedence relationship and more. Wrapping applications in ConfigMgr 2012 should only be done if the available application log doesn’t meet your needs – and even then you should look at it twice and three times before choosing to wrap!
Performing detection of app deployment type Microsoft RichCopy 4.0 - Full Install - Available(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0, revision 1) for user. AppDiscovery 11/13/2012 10:41:15 PM 524 (0x020C)
+++ MSI application not discovered [MSI Product Code: {86F4F32B-77C7-4951-B33C-05D41A8190C1}, MSI Product version: ] AppDiscovery 11/13/2012 10:41:15 PM 524 (0x020C)
+++ Did not detect app deployment type Microsoft RichCopy 4.0 - Full Install - Available(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0, revision 1) for S-1-5-21-2382599338-2815126685-3026542690-500. AppDiscovery 11/13/2012 10:41:15 PM 524 (0x020C)
Lantern job:B73DBE34-56EB-4BE7-B1E6-6AB9865983E0 succeeded. CIAgent 11/13/2012 10:41:16 PM 4024 (0x0FB8)
Releasing lock CIAgent 11/13/2012 10:41:16 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:16 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): Invocation succeeded for policy platform job B73DBE34-56EB-4BE7-B1E6-6AB9865983E0 CIAgent 11/13/2012 10:41:16 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): ReportMethodInvocation :: Enactment succeeded CIAgent 11/13/2012 10:41:16 PM 4024 (0x0FB8)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:16 PM 524 (0x020C)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:16 PM 524 (0x020C)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:16 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:16 PM 524 (0x020C)
CDCMReporting::FinalConstruct. DCMReporting 11/13/2012 10:41:16 PM 4024 (0x0FB8)
At this stage I’m omitting a large number of lines of log. The last line above shows the DCMReporting component being invoked which will reflect back the results of processing so far in state messages. Don’t let the names of components mislead you. DCM may seem unrelated but is the framework for state messaging that is leveraged by software updates and now application deployment.
QueryCIStateStoreFromSQL 0 rows returned for query select st.ModelName,st.Revision,st.UserSID,st.LastUpdateTime,st.Applicability,st.State,st.DesiredState,st.Severity,st.EvaluationState,st.EvaluationStateProgress, st.DisplayName,st.DetailedReport,st.CheckSum,st.LatestRevision,st.TotalSupressionCount,st.TotalEnforcements,st.TotalConflicts,st.NumCompliantRules,
st.EnforcementState,st.EnforceError,st.LaunchState,st.LaunchErrorCode,st.LaunchAdditionalErrorInfo,st.EnforcementStateProgress,st.LastEvalTime,
st.LastError,st.LastInstallTime,st.StartTime,st.EnforcementDeadline,st.UpdateDeadline,st.DCMDetectionState,st.Priority,st.Precedence,st.IsEnforcable,
st.DPLocality,st.DisableMomAlerts,st.RaiseMomAlertsOnFailure,st.SupressReboot,st.OverrideServiceWindows,st.RebootOutsideOfServiceWindows, st.UseSiteEvaluation,st.UseGMTTimes,st.NotifyUser,st.UserUIExperience,st.WolEnabled,st.ContentSize,st.RetriesRemaining, st.IsUserPolicyEffective, st.SupersessionState, st.IsPreflightOnly from ConfigurationItemState st where ModelName = 'ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989' and Revision = 2 and UserSID = 'SYSTEM'. CIStateStore 11/13/2012 10:41:17 PM 4024 (0x0FB8)
ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0/1 :- Current State = NotInstalled, Applicability = Applicable, ResolvedState = Available, Title = Microsoft RichCopy 4.0 - Full Install - Available AppIntentEval 11/13/2012 10:41:17 PM 4024 (0x0FB8)
ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989/2 :- Current State = NotInstalled, Applicability = Applicable, ResolvedState = Available, Title = Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo AppIntentEval 11/13/2012 10:41:17 PM 4024 (0x0FB8)
Above we see the application and deployment type being evaluated. Both are evaluated as not being installed based on the previous test but both are indicated as applicable.
ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/2 :- Current State = NonCompliant, Applicability = Applicable, ResolvedState = Compliant, Title = ApplicationIntentPolicy AppIntentEval 11/13/2012 10:41:17 PM 4024 (0x0FB8)
Based on the above and the fact that we have manually initiated deployment we see the application now listed as required and in a noncompliant state but with a resolved state of compliant – meaning the application needs to be installed.
CDCMReporting::ProcessCIReports DCMReporting 11/13/2012 10:41:17 PM 4024 (0x0FB8)
CDCMReporting::GenerateXMLReports DCMReporting 11/13/2012 10:41:17 PM 4024 (0x0FB8)
____________________________ CIStateStore 11/13/2012 10:41:17 PM 4024 (0x0FB8)
An existing CI state is changed CIStateStore 11/13/2012 10:41:17 PM 4024 (0x0FB8)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989:2] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:17 PM 4024 (0x0FB8)
____________________________ CIStateStore 11/13/2012 10:41:17 PM 4024 (0x0FB8)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989/2 has been updated StateMessage 11/13/2012 10:41:17 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}):State - Reporting (scan):: AppModel - ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989:2 - State = NotInstalled ResolvedState = Available Applicability = Applicable CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
At this stage we are essentially reporting scan results indicating the application itself is not installed but is available and applicable.
____________________________ CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
An existing CI state is changed CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0:1] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
____________________________ CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0/1 has been updated StateMessage 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}):State - Reporting (scan):: Deployment Type - ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0:1 - State = NotInstalled ResolvedState = Available Applicability = Applicable CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
And now we are more scan results indicating the specific application deployment type is not installed but is available and applicable.
____________________________ CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
An existing CI state is changed CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2] CIEvalState changed: Evaluating --> Idle CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
And now evaluation is complete. Notice that the thread reporting is CIStateStore. A few lines down we see the same data reflected in the CIAgent log. This is representative of threads communicating back and forth. You will see what appears to be repeating information throughout the logs and this is a clue that there could be some communication going on between threads.
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/2 has been updated StateMessage 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CDCMReporting::FinalRelease DCMReporting 11/13/2012 10:41:18 PM 4024 (0x0FB8)
____________________________ CIStateStore 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}):State - Reporting (scan):: Install Policy Type - ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2 - State = NonCompliant ResolvedState = Compliant Applicability = Applicable CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::ReleaseGlobalSemaphore [GlobalSemaphore] Released global download semaphore CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore NotifyComplete CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=NotifyComplete, CurrentState=InvokingSdmMethod) CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=InvokingSdmMethod, To=CompletedSdmMethodInvocation) for Event=Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
And then finally we see an indication we have transitioned to the CompletedSdmMethodInvocation step.
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=CompletedSdmMethodInvocation) CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=CompletedSdmMethodInvocation, To=StateDownloadingContents) for Event=Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateDownloadingContents)
With all of the detection done it’s now time to download the content associated with the CI’s just evaluated.
CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
{46A6A533-3AEE-47D9-842E-D21B2763F938} - Initiating ContentDownload tasks. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
{46A6A533-3AEE-47D9-842E-D21B2763F938} - Skipping policy CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2 and all dependents for ContentDownload task since CI action was not requested. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
All tasks are already in completed state CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore CITaskComplete CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=CITaskComplete, CurrentState=StateDownloadingContents) CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=StateDownloadingContents, To=StateEnforcingCIs) for Event=Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
The log snips above indicate there is no need to download the CI contents as they are already present and now we are transitioning out of the downloading state to the enforcement state – where the application actually gets applied.
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateEnforcingCIs) CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
{46A6A533-3AEE-47D9-842E-D21B2763F938} - Initiating Enforce tasks. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
{46A6A533-3AEE-47D9-842E-D21B2763F938} - Skipping policy CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2 and all dependents for Enforce task since CI action was not requested. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
{46A6A533-3AEE-47D9-842E-D21B2763F938} - No mandatory Enforce tasks. No actions will be performed. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore CITaskComplete CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=CITaskComplete, CurrentState=StateEnforcingCIs) CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=StateEnforcingCIs, To=StateEnforcementReporting) for Event=Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateEnforcementReporting) CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): Enforcement Reporting CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=StateEnforcementReporting, To=Completed) for Event=Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=Completed) CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): TransitionState(From=Completed, To=StateWaitOnCompletion) for Event=Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
Request to delete CIAgent job {46A6A533-3AEE-47D9-842E-D21B2763F938} CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): Deleting CIAgent Job CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
We have all the CI’s handled now so deleting the job.
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore JobDelete CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
Queued Deletion for job {46A6A533-3AEE-47D9-842E-D21B2763F938} CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): Client requesting CIAgentJob context info for key: StateMessagePriority CIAgent 11/13/2012 10:41:18 PM 4024 (0x0FB8)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:18 PM 888 (0x0378)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateWaitOnCompletion) CIAgent 11/13/2012 10:41:18 PM 888 (0x0378)
CIAgentJob({46A6A533-3AEE-47D9-842E-D21B2763F938}): CAgentJob::HandleEvent(Event=JobDelete, CurrentState=StateWaitOnCompletion) CIAgent 11/13/2012 10:41:18 PM 888 (0x0378)
Internal Request to delete CIAgent job {46A6A533-3AEE-47D9-842E-D21B2763F938} CIAgent 11/13/2012 10:41:18 PM 888 (0x0378)
Deleted CIAgent job {46A6A533-3AEE-47D9-842E-D21B2763F938} CIAgent 11/13/2012 10:41:18 PM 888 (0x0378)
State message(State ID : 2) with TopicType 1703 and TopicId {88BD1003-882F-4272-BDD5-F0D2E94F3009} has been recorded for S-1-5-21-2382599338-2815126685-3026542690-500 StateMessage 11/13/2012 10:41:18 PM 4024 (0x0FB8)
Power lease [510954] canceled by 'CIAgent: job released' pwrmgmt 11/13/2012 10:41:18 PM 888 (0x0378)
*** System is now free to go to sleep CCMEXEC 11/13/2012 10:41:18 PM 3736 (0x0E98)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:18 PM 524 (0x020C)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:18 PM 524 (0x020C)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:18 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:18 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:19 PM 524 (0x020C)
Making calls to Verify the user and timestamp. CCMSDKProvider 11/13/2012 10:41:19 PM 524 (0x020C)
Successfully Verified the user and timestamp. CCMSDKProvider 11/13/2012 10:41:19 PM 524 (0x020C)
Making call to Verify the signature. CCMSDKProvider 11/13/2012 10:41:19 PM 524 (0x020C)
Calling GetUserCapability. CCMSDKProvider 11/13/2012 10:41:20 PM 3720 (0x0E88)
CAgent::CreateJob - Creating new CI Agent Job for user: S-1-5-21-2382599338-2815126685-3026542690-500 CIAgent 11/13/2012 10:41:20 PM 3736 (0x0E98)
Power lease [510958] started by 'CIAgent: job initialized' for 120 minutes pwrmgmt 11/13/2012 10:41:20 PM 3736 (0x0E98)
CAgent::EvaluateCIs CIAgent 11/13/2012 10:41:20 PM 3736 (0x0E98)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:20 PM 3736 (0x0E98)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::HandleEvent(Event=Transition, CurrentState=Init) CIAgent 11/13/2012 10:41:20 PM 3736 (0x0E98)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): Client requesting CIAgentJob context info for key: StateMessagePriority CIAgent 11/13/2012 10:41:20 PM 3736 (0x0E98)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): TransitionState(From=Init, To=WaitingForAssignedCI) for Event=Transition CIAgent 11/13/2012 10:41:20 PM 3736 (0x0E98)
Finally, we are beginning the process of installing the application.
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:20 PM 3736 (0x0E98)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:20 PM 3736 (0x0E98)
*** Keep the system awake CCMEXEC 11/13/2012 10:41:20 PM 3736 (0x0E98)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::HandleEvent(Event=Transition, CurrentState=WaitingForAssignedCI) CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore DownloadCIs CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob
Entering ExecQueryAsync for query "select * from CCM_AppDeliveryType where (AppDeliveryTypeId = "ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0" AND Revision = 1)" AppDiscovery 11/13/2012 10:41:20 PM 524 (0x020C)
Notice this query – just a plain ole WMI request.
In the below log snips we again initiate detection as the first check before we attempt to install the application. The app has not been installed since the first check so we reflect that it still isn’t there. At this stage you may wonder why we do this again so close to the first detection earlier in the logs. Remember that the logs here reflect activity that began when I initiated the application deployment – so we have to go through all the phases at once. If this had been a required deployment that had a trigger date sometime in the future the client would have gone through this a couple of different times – the first time when the application first arrived and later when the trigger time came due. In the first pass we would realize the application is required so would go through the work of detecting whether the app is there and, if not, do the work to download all content needed so that at install time, it is available in the local cache. At trigger time we will recheck applicability just to be sure the application wasn’t deployed between the first check and now.
Performing detection of app deployment type Microsoft RichCopy 4.0 - Full Install - Available(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0, revision 1) for user. AppDiscovery 11/13/2012 10:41:20 PM 524 (0x020C)
+++ MSI application not discovered [MSI Product Code: {86F4F32B-77C7-4951-B33C-05D41A8190C1}, MSI Product version: ] AppDiscovery 11/13/2012 10:41:20 PM 524 (0x020C)
+++ Did not detect app deployment type Microsoft RichCopy 4.0 - Full Install - Available(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0, revision 1) for S-1-5-21-2382599338-2815126685-3026542690-500. AppDiscovery 11/13/2012 10:41:20 PM 524 (0x020C)
Lantern job:91E2C8AF-E3A8-41C2-A393-1335A811F371 succeeded. CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
Releasing lock CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): Invocation succeeded for policy platform job 91E2C8AF-E3A8-41C2-A393-1335A811F371 CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): ReportMethodInvocation :: Enactment succeeded CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CDCMReporting::FinalConstruct. DCMReporting 11/13/2012 10:41:20 PM 888 (0x0378)
We are now back in the DCMReporting section so skipping a good number of lines in the logs. Also, in the section below we go back through some of the processing loops we saw earlier so not describing them again.
Evaluating Application policies for S-1-5-21-2382599338-2815126685-3026542690-500 AppIntentEval 11/13/2012 10:41:20 PM 888 (0x0378)
CDCMReporting::ProcessSynchronizationDetailReport DCMReporting 11/13/2012 10:41:20 PM 888 (0x0378)
ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0/1 :- Current State = NotInstalled, Applicability = Applicable, ResolvedState = Available, Title = Microsoft RichCopy 4.0 - Full Install - Available AppIntentEval 11/13/2012 10:41:20 PM 888 (0x0378)
ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989/2 :- Current State = NotInstalled, Applicability = Applicable, ResolvedState = Available, Title = Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo AppIntentEval 11/13/2012 10:41:20 PM 888 (0x0378)
ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/2 :- Current State = NonCompliant, Applicability = Applicable, ResolvedState = Compliant, Title = ApplicationIntentPolicy AppIntentEval 11/13/2012 10:41:20 PM 888 (0x0378)
QueryCIStateStoreFromSQL 0 rows returned for query select st.ModelName,st.Revision,st.UserSID,st.LastUpdateTime,st.Applicability,st.State,st.DesiredState,st.Severity,st.EvaluationState,st.EvaluationStateProgress, st.DisplayName,st.DetailedReport,st.CheckSum,st.LatestRevision,st.TotalSupressionCount,st.TotalEnforcements,st.TotalConflicts,st.NumCompliantRules,
st.EnforcementState,st.EnforceError,st.LaunchState,st.LaunchErrorCode,st.LaunchAdditionalErrorInfo,st.EnforcementStateProgress,st.LastEvalTime,
st.LastError,st.LastInstallTime,st.StartTime,st.EnforcementDeadline,st.UpdateDeadline,st.DCMDetectionState,st.Priority,st.Precedence,st.IsEnforcable,
st.DPLocality,st.DisableMomAlerts,st.RaiseMomAlertsOnFailure,st.SupressReboot,st.OverrideServiceWindows,st.RebootOutsideOfServiceWindows, st.UseSiteEvaluation,st.UseGMTTimes,st.NotifyUser,st.UserUIExperience,st.WolEnabled,st.ContentSize,st.RetriesRemaining, st.IsUserPolicyEffective, st.SupersessionState, st.IsPreflightOnly from ConfigurationItemState st where ModelName = 'ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989' and Revision = 2 and UserSID = 'SYSTEM' . CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
CDCMReporting::ProcessCIReports DCMReporting 11/13/2012 10:41:20 PM 888 (0x0378)
CDCMReporting::GenerateXMLReports DCMReporting 11/13/2012 10:41:20 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989:2] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
An existing CI state is changed CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989/2 has been updated StateMessage 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}):State - Reporting (scan):: AppModel - ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989:2 - State = NotInstalled ResolvedState = Available Applicability = Applicable CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
An existing CI state is changed CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0:1] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0/1 has been updated StateMessage 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}):State - Reporting (scan):: Deployment Type - ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0:1 - State = NotInstalled ResolvedState = Available Applicability = Applicable CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
An existing CI state is changed CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2] CIEvalState changed: Evaluating --> Idle CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:20 PM 888 (0x0378)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/2 has been updated StateMessage 11/13/2012 10:41:20 PM 888 (0x0378)
CDCMReporting::FinalRelease DCMReporting 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}):State - Reporting (scan):: Install Policy Type - ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2 - State = NonCompliant ResolvedState = Compliant Applicability = Applicable CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::ReleaseGlobalSemaphore [GlobalSemaphore] Released global download semaphore CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore NotifyComplete CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::HandleEvent(Event=NotifyComplete, CurrentState=InvokingSdmMethod) CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): TransitionState(From=InvokingSdmMethod, To=CompletedSdmMethodInvocation) for Event=Transition CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::HandleEvent(Event=Transition, CurrentState=CompletedSdmMethodInvocation) CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): TransitionState(From=CompletedSdmMethodInvocation, To=StateDownloadingContents) for Event=Transition CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateDownloadingContents) CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
{8B5DA8E3-8375-48B7-BE90-07B4886F982B} - Initiating ContentDownload tasks. CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
Job({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CI ModelName ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989 version 2 will be INSTALLED. : Task(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989.2.ContentDownload) CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
Job({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CI ModelName ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0 version 1 will be INSTALLED. : Task(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989.2.ContentDownload) CIAgent 11/13/2012 10:41:20 PM 888 (0x0378)
Something different here. Now we start the process to download the actual content associated with the CI’s
Initiating task ContentDownload for CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1 (Microsoft RichCopy 4.0 - Full Install - Available) for target: S-1-5-21-2382599338-2815126685-3026542690-500 CITaskMgr 11/13/2012 10:41:21 PM 888 (0x0378)
ActionType - Install will use Content Id: Content_27225d97-2cf4-4581-a7a7-4465d3ac2229 + Content Version: 1 for AppDT "Microsoft RichCopy 4.0 - Full Install - Available" [ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0], Revision - 1 AppDiscovery 11/13/2012 10:41:21 PM 524 (0x020C)
Requesting locations synchronously for content Content_27225d97-2cf4-4581-a7a7-4465d3ac2229.1 with priority Foreground ContentAccess 11/13/2012 10:41:21 PM 888 (0x0378)
Requesting a location for downloading the content (note the content_ ID) associated with the deployment type being installed. Remember our discussion earlier about how to track the application GUID to an entry in the console. You can do the same with the content_ ID as shown in the screenshot below.
Initiating content download : CITask(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1.S-1-5-21-2382599338-2815126685-3026542690-500.Install.ContentDownload) CITaskMgr 11/13/2012 10:41:21 PM 888 (0x0378)
ActionType - Install will use Content Id: Content_27225d97-2cf4-4581-a7a7-4465d3ac2229 + Content Version: 1 for AppDT "Microsoft RichCopy 4.0 - Full Install - Available" [ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0], Revision - 1 AppDiscovery 11/13/2012 10:41:21 PM 524 (0x020C)
The ContentAccess component (CAS) marshals the process of acquiring content for a deployment. If the content is already available in the local client cache then the job CAS has to perform is short. If the content is not already in the local cache then CAS has to go retrieve it from the distribution point which involves making a location request and invoking DataTransferService and ContentTransferManager. In this case, the content is already available in the client cache.
Requesting content Content_27225d97-2cf4-4581-a7a7-4465d3ac2229.1, size(KB) 6427, under context S-1-5-21-2382599338-2815126685-3026542690-500 with priority Foreground ContentAccess 11/13/2012 10:41:21 PM 888 (0x0378)
Saved Content ID Mapping Content_27225d97-2cf4-4581-a7a7-4465d3ac2229.1, C:\Windows\ccmcache\5 ContentAccess 11/13/2012 10:41:21 PM 888 (0x0378)
Content for Content_27225d97-2cf4-4581-a7a7-4465d3ac2229.1 was found in cache ContentAccess 11/13/2012 10:41:21 PM 888 (0x0378)
Contents already available. CITaskMgr 11/13/2012 10:41:22 PM 888 (0x0378)
Contents download already in Success state : CITask(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1.S-1-5-21-2382599338-2815126685-3026542690-500.Install.ContentDownload) CITaskMgr 11/13/2012 10:41:22 PM 888 (0x0378)
State transition to (Success), Param(0) : CITask(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1.S-1-5-21-2382599338-2815126685-3026542690-500.Install.ContentDownload) CITaskMgr 11/13/2012 10:41:22 PM 888 (0x0378)
Power lease [510961] started by 'CITask: Application content requested' for 30 minutes pwrmgmt 11/13/2012 10:41:22 PM 888 (0x0378)
Already completed state (Success) : CITask(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1.S-1-5-21-2382599338-2815126685-3026542690-500.Install.ContentDownload) CITaskMgr 11/13/2012 10:41:22 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
An existing CI state is changed CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0:1] CIEnforceState changed: EnforcementUnknown --> DownloadContentSuccess CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0:1] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0/1 has been updated StateMessage 11/13/2012 10:41:22 PM 888 (0x0378)
State message(State ID : 2009) with TopicType 1702 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0/1 has been recorded for S-1-5-21-2382599338-2815126685-3026542690-500 StateMessage 11/13/2012 10:41:22 PM 888 (0x0378)
Raising client SDK event for class CCM_Application, instance CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0, actionType 23l, value SoftwareCatalog, user S-1-5-21-2382599338-2815126685-3026542690-500, session 4294967295l, level 0l, verbosity 30l CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
The class name is CCM_Application CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The target instance path is CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The action type is 23 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The user SID is S-1-5-21-2382599338-2815126685-3026542690-500 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The logon session ID is -1 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The message level is 0 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The value is SoftwareCatalog CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The verbosity is 30 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
Job({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): Already Completed : Task(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1.ContentDownload) CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
An existing CI state is changed CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989:2] CIEnforceState changed: EnforcementUnknown --> DownloadContentSuccess CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989:2] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
Received a WMI event (CCM_InstanceEvent) (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at EventWatcher_EventArrived) SCClient 11/13/2012 10:41:22 PM 15 (0x000F)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989/2 has been updated StateMessage 11/13/2012 10:41:22 PM 888 (0x0378)
Received a WMI event (CCM_InstanceEvent) (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at EventWatcher_EventArrived) SCClient 11/13/2012 10:41:22 PM 5 (0x0005)
State message(State ID : 2009) with TopicType 1702 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989/2 has been recorded for S-1-5-21-2382599338-2815126685-3026542690-500 StateMessage 11/13/2012 10:41:22 PM 888 (0x0378)
Raising client SDK event for class CCM_Application, instance CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0, actionType 23l, value SoftwareCatalog, user S-1-5-21-2382599338-2815126685-3026542690-500, session 4294967295l, level 0l, verbosity 30l CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
Event object details:
The CCM_InstanceEvent entry reflects a WMI event that provides some good detail. First, the ActionType of 23 indicates the application installation is starting. We also see the TargetInstancePath which again confirms what application is being handled. At the end of TargetInstancePath we seethe IsMachineTarget set to 0 which confirms that the application is user targeted. We also see the Value item which reflects the deployment is from the SoftwareCatalog. We will see further CCM_InstanceEvent information as we continue through the log.
instance of CCM_InstanceEvent
{
ActionType = 23;
ClassName = "CCM_Application";
MessageLevel = 0;
SessionID = 4294967295;
TargetInstancePath = "CCM_Application.Id=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989\",Revision=\"2\",IsMachineTarget=0";
TIME_CREATED = "129973416822847509";
UserSID = "S-1-5-21-2382599338-2815126685-3026542690-500";
Value = "SoftwareCatalog";
Verbosity = 30;
};
(Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at EventWatcher_EventArrived) SCClient 11/13/2012 10:41:22 PM 15 (0x000F)
The class name is CCM_Application CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The target instance path is CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The action type is 23 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The user SID is S-1-5-21-2382599338-2815126685-3026542690-500 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The logon session ID is -1 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The message level is 0 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
The verbosity is 30 CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
Job({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): Already Completed : Task(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989.2.ContentDownload) CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
An existing CI state is changed CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2] CIEnforceState changed: EnforcementUnknown --> DownloadContentSuccess CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
[ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989:2] AreDetailsUpdated: No CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
____________________________ CIStateStore 11/13/2012 10:41:22 PM 888 (0x0378)
State message with TopicType 1701 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/2 has been updated StateMessage 11/13/2012 10:41:22 PM 888 (0x0378)
Event maps to notification type = Application Enforcement Progress (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at EventWatcher_EventArrived) SCClient 11/13/2012 10:41:22 PM 15 (0x000F)
The target instance path for this notification is CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0 (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at HandleInstanceEvent) SCClient 11/13/2012 10:41:22 PM 15 (0x000F)
State message(State ID : 2009) with TopicType 1702 and TopicId ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989/2 has been recorded for S-1-5-21-2382599338-2815126685-3026542690-500 StateMessage 11/13/2012 10:41:22 PM 888 (0x0378)
Job({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): Already Completed : Task(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989.2.ContentDownload) CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::HandleEvent(Event=CITaskComplete, CurrentState=StateDownloadingContents) CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
All tasks are already in completed state CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore CITaskComplete CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): TransitionState(From=StateDownloadingContents, To=StateEnforcingCIs) for Event=Transition CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
Event object details:
instance of CCM_InstanceEvent
{
ActionType = 23;
ClassName = "CCM_Application";
MessageLevel = 0;
SessionID = 4294967295;
TargetInstancePath = "CCM_Application.Id=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989\",Revision=\"2\",IsMachineTarget=0";
TIME_CREATED = "129973416822847509";
UserSID = "S-1-5-21-2382599338-2815126685-3026542690-500";
Value = "SoftwareCatalog";
Verbosity = 30;
};
(Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at EventWatcher_EventArrived) SCClient 11/13/2012 10:41:22 PM 5 (0x0005)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): QueueDebug - Executing Event. CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
The value is SoftwareCatalog CCMSDKProvider 11/13/2012 10:41:22 PM 524 (0x020C)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::QueueEvent - Queueing event and incrementing semaphore Transition CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
Event maps to notification type = Application Enforcement Progress (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at EventWatcher_EventArrived) SCClient 11/13/2012 10:41:22 PM 5 (0x0005)
The target instance path for this notification is CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0 (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at HandleInstanceEvent) SCClient 11/13/2012 10:41:22 PM 5 (0x0005)
Getting a WMI instance for CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0 (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at GetInstance) SCClient 11/13/2012 10:41:22 PM 15 (0x000F)
Getting a WMI instance for CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0 (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at GetInstance) SCClient 11/13/2012 10:41:22 PM 5 (0x0005)
CIAgentJob({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CAgentJob::HandleEvent(Event=Transition, CurrentState=StateEnforcingCIs) CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
{8B5DA8E3-8375-48B7-BE90-07B4886F982B} - Initiating Enforce tasks. CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
Job({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CI ModelName ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989 version 2 will be INSTALLED. : Task(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989.2.Enforce) CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
Job({8B5DA8E3-8375-48B7-BE90-07B4886F982B}): CI ModelName ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0 version 1 will be INSTALLED. : Task(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989.2.Enforce) CIAgent 11/13/2012 10:41:22 PM 888 (0x0378)
Initiating task Enforce for CI ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1 (Microsoft RichCopy 4.0 - Full Install - Available) for target: S-1-5-21-2382599338-2815126685-3026542690-500 CITaskMgr 11/13/2012 10:41:22 PM 888 (0x0378)
Got instance from WMI for \\CMCLT1\root\ccm\ClientSDK:CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0 in state 26 (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at GetInstance) SCClient 11/13/2012 10:41:22 PM 15 (0x000F)
Got instance from WMI for \\CMCLT1\root\ccm\ClientSDK:CCM_Application.Id="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989",Revision="2",IsMachineTarget=0 in state 26 (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at GetInstance) SCClient 11/13/2012 10:41:23 PM 5 (0x0005)
Power lease [510965] started by 'CITask: enforcing app' for 120 minutes pwrmgmt 11/13/2012 10:41:23 PM 888 (0x0378)
Now we start to get into some great detail. In the blob below we see a number of things. Starting at the top, we have the AllowedActions entry which details that both Install and Uninstall actions are defined for our application. Following this we have an Instance of CCM_AppDeploymentType which provides detal on our deployment types for the application. In our case there is only a single deployment type and we can again see the AllowedActions and the fact the deployment type is detected as Applicable. We also see the size of the content and the DeploymentReport which provides detail on the deploymenttype and various configured relationships. Moving on down we have additional detail that was configured in the UI about the deployment type such as ErrorCode, EstimatedInstallTime and more.
instance of CCM_Application
{
AllowedActions = {"Install", "Uninstall"};
AppDTs = {
instance of CCM_AppDeploymentType
{
AllowedActions = {"Install", "Uninstall"};
ApplicabilityState = "Applicable";
ContentSize = 6427;
DeploymentReport = "<ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0\" Version=\"1\" Type=\"Deployment Type\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalDependancyViolations=\"0\" TotalSupersedesViolations=\"0\" TotalNonSupersedenceViolations=\"0\" TotalCompliantCount=\"1\" SupersessionState=\"None\" TotalRequirementsCount=\"0\" TotalDiscoveryViolations=\"0\"><CIProperties><Name>Microsoft RichCopy 4.0 - Full Install - Available</Name><Description/></CIProperties><NonSupersedenceViolations Count=\"0\"/><SupersedesViolations Count=\"0\"/><DependancyViolations Count=\"0\"/><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"1\"><CompliantRule><RuleLogicalName>NonSupersedence</RuleLogicalName><RuleName>NonSupersedence</RuleName><RuleDescription/
></CompliantRule></CompliantRules><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations SuppressedCount=\"0\" MaxSeverity=\"None\" Count=\"0\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"/><BaseConfigurationItems/></ConfigurationItemReport>";
ErrorCode = 0;
EstimatedInstallTime = 0;
EvaluationState = 3;
FullName = "Microsoft RichCopy 4.0 - Full Install - Available";
Id = "ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0";
InstallState = "NotInstalled";
LastEvalTime = "20121113224120.000000+000";
Name = "Microsoft RichCopy 4.0 - Full Install - Available";
PercentComplete = 0;
PostInstallAction = "BasedOnExitCode";
ResolvedState = "Available";
RetriesRemaining = 10;
Revision = "1";
SupersessionState = "None";
Type = 1;
}};
ApplicabilityState = "Applicable";
DeploymentReport = "<ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"Application_34d4a800-ccdd-4aaf-8188-cacebe028989\" Version=\"2\" Type=\"AppModel\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" TotalConflicts=\"0\" MaxOverallSeverity=\"None\" SupersessionState=\"None\"><CIProperties><Name>Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo</Name><Description/></CIProperties><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"0\"/><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"><ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0\" Version=\"1\" Type=\"Deployment Type\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalDependancyViolations=\"0\" TotalSupersedesViolations=\"0\" TotalNonSupersedenceViolations=\"0\" TotalCompliantCount=\"1\" SupersessionState=\"None\" TotalRequirementsCount=\"0\" TotalDiscoveryViolations=\"0\" Policy=\"Required\"><CIProperties><Name>Microsoft RichCopy 4.0 - Full Install - Available</Name><Description/></CIProperties><NonSupersedenceViolations Count=\"0\"/><SupersedesViolations Count=\"0\"/><DependancyViolations Count=\"0\"/><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"1\"><CompliantRule><RuleLogicalName>NonSupersedence</RuleLogicalName><RuleName>NonSupersedence</RuleName><
RuleDescription/></CompliantRule></CompliantRules><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations SuppressedCount=\"0\" MaxSeverity=\"None\" Count=\"0\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"/><BaseConfigurationItems/></ConfigurationItemReport></ReferencedConfigurationItems><BaseConfigurationItems/><
ReferencingConfigurationItems><ReferencingConfigurationItem AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989\" Version=\"2\"/></ReferencingConfigurationItems></ConfigurationItemReport>";
Description = "A simple file transfer tool";
EnforcePreference = 2;
ErrorCode = 0;
EvaluationState = 26;
FileTypes = "";
FullName = "Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo";
Icon = "";
Id = "ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989";
InformativeUrl = "";
InProgressActions = {"Install", "Update", "Uninstall"};
InstallState = "NotInstalled";
IsMachineTarget = FALSE;
IsPreflightOnly = FALSE;
LastEvalTime = "20121113224120.000000+000";
LastInstallTime = "20121112125029.000000+000";
Name = "Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo";
NotifyUser = TRUE;
PercentComplete = 0;
Publisher = "Microsott";
ReleaseDate = "20120608053437.000000+000";
ResolvedState = "Available";
Revision = "2";
SoftwareVersion = "4.0";
StartTime = "20121112085500.000000+000";
SupersessionState = "None";
Type = 1;
UserUIExperience = TRUE;
};
(Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at GetInstance) SCClient 11/13/2012 10:41:23 PM 5 (0x0005)
Getting AutoInstallRequiredSoftware setting. CCMSDKProvider 11/13/2012 10:41:23 PM 3720 (0x0E88)
Adding task for client "CITaskMgr": id - "a50f83bb-6ab3-4bd4-be67-91398cee0768", pri - 20, service window - 0, max time for sw - 7200. MaintenanceCoordinator 11/13/2012 10:41:23 PM 888 (0x0378)
instance of CCM_Application
{
AllowedActions = {"Install", "Uninstall"};
AppDTs = {
instance of CCM_AppDeploymentType
{
AllowedActions = {"Install", "Uninstall"};
ApplicabilityState = "Applicable";
ContentSize = 6427;
DeploymentReport = "<ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0\" Version=\"1\" Type=\"Deployment Type\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalDependancyViolations=\"0\" TotalSupersedesViolations=\"0\" TotalNonSupersedenceViolations=\"0\" TotalCompliantCount=\"1\" SupersessionState=\"None\" TotalRequirementsCount=\"0\" TotalDiscoveryViolations=\"0\"><CIProperties><Name>Microsoft RichCopy 4.0 - Full Install - Available</Name><Description/></CIProperties><NonSupersedenceViolations Count=\"0\"/><SupersedesViolations Count=\"0\"/><DependancyViolations Count=\"0\"/><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"1\"><CompliantRule><RuleLogicalName>NonSupersedence</RuleLogicalName><RuleName>NonSupersedence</RuleName><RuleDescription/>
</CompliantRule></CompliantRules><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations SuppressedCount=\"0\" MaxSeverity=\"None\" Count=\"0\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"/><BaseConfigurationItems/></ConfigurationItemReport>";
ErrorCode = 0;
EstimatedInstallTime = 0;
EvaluationState = 3;
FullName = "Microsoft RichCopy 4.0 - Full Install - Available";
Id = "ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0";
InstallState = "NotInstalled";
LastEvalTime = "20121113224120.000000+000";
Name = "Microsoft RichCopy 4.0 - Full Install - Available";
PercentComplete = 0;
PostInstallAction = "BasedOnExitCode";
ResolvedState = "Available";
RetriesRemaining = 10;
Revision = "1";
SupersessionState = "None";
Type = 1;
}};
ApplicabilityState = "Applicable";
DeploymentReport = "<ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"Application_34d4a800-ccdd-4aaf-8188-cacebe028989\" Version=\"2\" Type=\"AppModel\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" TotalConflicts=\"0\" MaxOverallSeverity=\"None\" SupersessionState=\"None\"><CIProperties><Name>Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo</Name><Description/></CIProperties><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"0\"/><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"><ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0\" Version=\"1\" Type=\"Deployment Type\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalDependancyViolations=\"0\" TotalSupersedesViolations=\"0\" TotalNonSupersedenceViolations=\"0\" TotalCompliantCount=\"1\" SupersessionState=\"None\" TotalRequirementsCount=\"0\" TotalDiscoveryViolations=\"0\" Policy=\"Required\"><CIProperties><Name>Microsoft RichCopy 4.0 - Full Install - Available</Name><Description/></CIProperties><NonSupersedenceViolations Count=\"0\"/><SupersedesViolations Count=\"0\"/><DependancyViolations Count=\"0\"/><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"1\"><CompliantRule><RuleLogicalName>NonSupersedence</RuleLogicalName><RuleName>NonSupersedence</RuleName><RuleDescription/>
</CompliantRule></CompliantRules><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations SuppressedCount=\"0\" MaxSeverity=\"None\" Count=\"0\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"/><BaseConfigurationItems/></ConfigurationItemReport></ReferencedConfigurationItems><BaseConfigurationItems/><ReferencingConfigurationItems>
<ReferencingConfigurationItem AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"RequiredApplication_34d4a800-ccdd-4aaf-8188-cacebe028989\" Version=\"2\"/></ReferencingConfigurationItems></ConfigurationItemReport>";
Description = "A simple file transfer tool";
EnforcePreference = 2;
ErrorCode = 0;
EvaluationState = 26;
FileTypes = "";
FullName = "Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo";
Icon = "";
Id = "ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989";
InformativeUrl = "";
InProgressActions = {"Install", "Update", "Uninstall"};
InstallState = "NotInstalled";
IsMachineTarget = FALSE;
IsPreflightOnly = FALSE;
LastEvalTime = "20121113224120.000000+000";
LastInstallTime = "20121112125029.000000+000";
Name = "Microsoft RichCopy 4.0 - System and User Target - Install / Uninstall Demo";
NotifyUser = TRUE;
PercentComplete = 0;
Publisher = "Microsott";
ReleaseDate = "20120608053437.000000+000";
ResolvedState = "Available";
Revision = "2";
SoftwareVersion = "4.0";
StartTime = "20121112085500.000000+000";
SupersessionState = "None";
Type = 1;
UserUIExperience = TRUE;
};
(Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at GetInstance) SCClient 11/13/2012 10:41:23 PM 15 (0x000F)
Quick check to see if there is any action required to install additional software needed by our application. This would come into play for dependent applications. Remember, the deployment we are tracking here is very basic – no dependencies, no supercedence, no requirement roles. If we add those the process is very similar but even more verbose as the system has to check for and handle all of those various relationships.
Getting AutoInstallRequiredSoftware setting. CCMSDKProvider 11/13/2012 10:41:23 PM 3720 (0x0E88)
Executing WMI query: select * from CCM_RequestedAppPolicy where AppId="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989" (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at ExecuteQuery) SCClient 11/13/2012 10:41:23 PM 5 (0x0005)
Executing WMI query: select * from CCM_RequestedAppPolicy where AppId="ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_34d4a800-ccdd-4aaf-8188-cacebe028989" (Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at ExecuteQuery) SCClient 11/13/2012 10:41:23 PM 15 (0x000F)
Submitted new MTC request a50f83bb-6ab3-4bd4-be67-91398cee0768 CITaskMgr 11/13/2012 10:41:23 PM 888 (0x0378)
State transition to (WaitSerialize), Param(0) : CITask(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1.S-1-5-21-2382599338-2815126685-3026542690-500.Install.Enforce) CITaskMgr 11/13/2012 10:41:23 PM 888 (0x0378)
Signaled task 'a50f83bb-6ab3-4bd4-be67-91398cee0768' (agent 'CITaskMgr'). MaintenanceCoordinator 11/13/2012 10:41:23 PM 888 (0x0378)
Done scheduling task. Winning task 'a50f83bb-6ab3-4bd4-be67-91398cee0768' (agent 'CITaskMgr') MaintenanceCoordinator 11/13/2012 10:41:23 PM 888 (0x0378)
OK, from here we still have a TON of log entries to go through. Many of them are from SCClient intermixed with other components. The information provided is good but it’s very verbose and can be a bit daunting to sift through. So, I’ve eliminated a significant portion of the logs to get to the portion where we actually install the application, which is seen in appenforce and starts below.
And with the edits we arrive at the log section that details the application install. We see all of the detail associated with the application install as we roll through the AppEnforce log
Executing Command line: "C:\Windows\system32\msiexec.exe" /i "RichCopySetup.msi" /q /qn with user context AppEnforce 11/13/2012 10:41:41 PM 524 (0x020C)
Working directory C:\Windows\ccmcache\5 AppEnforce 11/13/2012 10:41:41 PM 524 (0x020C)
Post install behavior is BasedOnExitCode AppEnforce 11/13/2012 10:41:41 PM 524 (0x020C)
Waiting for process 4352 to finish. Timeout = 120 minutes. AppEnforce 11/13/2012 10:41:41 PM 524 (0x020C)
We have started the install – just waiting for it to finish up.
Sending message for schedule 'Machine/{00000000-0000-0000-0000-000000000115}' (Target: 'direct:StateMessageManager', Name: '') Scheduler 11/13/2012 10:41:47 PM 888 (0x0378)
Our process has exited with a 0 exit code meaning success!
Process 4352 terminated with exitcode: 0 AppEnforce 11/13/2012 10:42:19 PM 524 (0x020C)
Looking for exit code 0 in exit codes table... AppEnforce 11/13/2012 10:42:19 PM 524 (0x020C)
Matched exit code 0 to a Success entry in exit codes table. AppEnforce 11/13/2012 10:42:19 PM 524 (0x020C)
And now we go through another detection! Why? The configured detection logic is important not only to test if a deployment is there before installing it again but also to validate the installation actually did succeed as expected. Note the success above. If the application install was a success but the detection logic is unable to confirm the application is present post install then the overall installation will be noted as a failure. Again, very much the same kind of pattern we see with software updates.
Performing detection of app deployment type Microsoft RichCopy 4.0 - Full Install - Available(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0, revision 1) for user. AppEnforce 11/13/2012 10:42:19 PM 524 (0x020C)
+++ Discovered MSI application [AppDT Id: ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0, Revision: 1, MSI Product code: {86F4F32B-77C7-4951-B33C-05D41A8190C1}, MSI Product version: ] AppEnforce 11/13/2012 10:42:19 PM 524 (0x020C)
++++++ App enforcement completed (56 seconds) for App DT "Microsoft RichCopy 4.0 - Full Install - Available" [ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0], Revision: 1, User SID: S-1-5-21-2382599338-2815126685-3026542690-500] ++++++ AppEnforce 11/13/2012 10:42:19 PM 524 (0x020C)
Application enforcement completed : CITask(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_8c11eaf6-d27c-45a3-834e-3cf263bd1eb0.1.S-1-5-21-2382599338-2815126685-3026542690-500.Install.Enforce) CITaskMgr 11/13/2012 10:42:19 PM 3824 (0x0EF0)
In this case we did successfully detect the application and all that is left to do is cleanup from the operations. I will stop detailing the logging at this point.
So the user targeted install initiated from the software catalog is complete – and we learned a lot about the process by watching the logs. Now lets take a look at the process that happens when deployment is initiated from the software center and that deployment is targeted to devices.
Device Deployment
As we our focus to deployments targeted to devices you might be concerned you will have to sift through all these logs again. Don’t worry! There is a lot of similarity in the device targeted deployments and what we just went through.. In fact, for this run I will just call out a very few key differences to illustrate.
For this install the action starts at 11:03:37 PM in the logs. In fact, the only real thing I will call out is a brief snippet as below to illustrate some of the differences between user targeted and device targeted applications and the way they represent and the AppEnforce portion of the log showing the actual installation of the application.
+++ Application not discovered. [AppDT Id: ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663, Revision: 3] AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
App enforcement environment:
Context: Machine Command line: "installrobo.bat"
Allow user interaction: No
UI mode: 1
User token: null
Session Id: 1
Content path: C:\Windows\ccmcache\6
Working directory: AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
Prepared working directory: C:\Windows\ccmcache\6 AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
instance of CCM_Application
{
AllowedActions = {"Install", "Uninstall"};
AppDTs = {
instance of CCM_AppDeploymentType
{
AllowedActions = {"Install", "Uninstall"};
ApplicabilityState = "Applicable";
ContentSize = 78;
DeploymentReport = "<ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663\" Version=\"3\" Type=\"Deployment Type\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalDependancyViolations=\"0\" TotalSupersedesViolations=\"0\" TotalNonSupersedenceViolations=\"0\" TotalCompliantCount=\"1\" SupersessionState=\"None\" TotalRequirementsCount=\"0\" TotalDiscoveryViolations=\"0\"><CIProperties><Name>RoboCopy from RichCopy DT</Name><Description/></CIProperties><NonSupersedenceViolations Count=\"0\"/><SupersedesViolations Count=\"0\"/><DependancyViolations Count=\"0\"/><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"1\"><CompliantRule><RuleLogicalName>NonSupersedence</RuleLogicalName><RuleName>NonSupersedence</RuleName><RuleDescription/></CompliantRule></CompliantRules><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations SuppressedCount=\"0\" MaxSeverity=\"None\" Count=\"0\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"/><BaseConfigurationItems/></ConfigurationItemReport>";
ErrorCode = 0;
EstimatedInstallTime = 0;
EvaluationState = 10;
FullName = "RoboCopy from RichCopy DT";
Id = "ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663";
InstallState = "NotInstalled";
LastEvalTime = "20121114230344.000000+000";
Name = "RoboCopy from RichCopy DT";
PercentComplete = 0;
PostInstallAction = "BasedOnExitCode";
ResolvedState = "Available";
RetriesRemaining = 10;
Revision = "3";
SupersessionState = "None";
Type = 1;
}};
ApplicabilityState = "Applicable";
DeploymentReport = "<ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"Application_ec9bf435-7b3a-4740-94b2-5275c43531a4\" Version=\"4\" Type=\"AppModel\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" TotalConflicts=\"0\" MaxOverallSeverity=\"None\" SupersessionState=\"None\"><CIProperties><Name>Robocopy from RichCopy</Name><Description/></CIProperties><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"0\"/><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"><ConfigurationItemReport AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663\" Version=\"3\" Type=\"Deployment Type\" ComputerName=\"CMCLT1\" CIComplianceState=\"NotInstalled\" CIDesiredState=\"Available\" CIApplicablityState=\"Applicable\" CISeverity=\"None\" TotalConstraintViolations=\"0\" TotalModelViolations=\"0\" TotalSuppressionCount=\"0\" TotalEnforcements=\"0\" MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalDependancyViolations=\"0\" TotalSupersedesViolations=\"0\" TotalNonSupersedenceViolations=\"0\" TotalCompliantCount=\"1\" SupersessionState=\"None\" TotalRequirementsCount=\"0\" TotalDiscoveryViolations=\"0\" Policy=\"Required\"><CIProperties><Name>RoboCopy from RichCopy DT</Name><Description/></CIProperties><NonSupersedenceViolations Count=\"0\"/><SupersedesViolations Count=\"0\"/><DependancyViolations Count=\"0\"/><RequirementViolations Count=\"0\"/><ConflictViolations Count=\"0\"/><CompliantRules Count=\"1\"><CompliantRule><RuleLogicalName>NonSupersedence</RuleLogicalName><RuleName>NonSupersedence</RuleName><RuleDescription/></CompliantRule></CompliantRules><ModelViolations Count=\"0\" SuppressedCount=\"0\" MaxSeverity=\"None\"/><DiscoveryViolations SuppressedCount=\"0\" MaxSeverity=\"None\" Count=\"0\"/><ReferencedConfigurationItems MaxOverallSeverity=\"None\" TotalConflicts=\"0\" TotalConstraintViolations=\"0\" TotalDiscoveryViolations=\"0\" TotalModelViolations=\"0\" TotalEnforcements=\"0\" TotalSuppressionCount=\"0\"/><BaseConfigurationItems/></ConfigurationItemReport></ReferencedConfigurationItems><BaseConfigurationItems/><ReferencingConfigurationItems><ReferencingConfigurationItem AuthoringScope=\"ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959\" LogicalName=\"RequiredApplication_ec9bf435-7b3a-4740-94b2-5275c43531a4\" Version=\"4\"/></ReferencingConfigurationItems></ConfigurationItemReport>";
EnforcePreference = 2;
ErrorCode = 0;
EvaluationState = 26;
FileTypes = "";
FullName = "Robocopy from RichCopy";
Icon = "";
Id = "ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/Application_ec9bf435-7b3a-4740-94b2-5275c43531a4";
InformativeUrl = "";
InProgressActions = {"Install", "Update"};
InstallState = "NotInstalled";
IsMachineTarget = TRUE; IsPreflightOnly = FALSE;
LastEvalTime = "20121114230344.000000+000";
LastInstallTime = "20121112090742.000000+000";
Name = "Robocopy from RichCopy";
NotifyUser = FALSE;
PercentComplete = 0;
ReleaseDate = "20120608053457.000000+000";
ResolvedState = "Available";
Revision = "4";
StartTime = "20121112130700.000000+000";
SupersessionState = "None";
Type = 1;
UserUIExperience = TRUE;
};
(Microsoft.SoftwareCenter.Client.Data.WmiConnectionManager at GetInstance) SCClient 11/14/2012 11:03:47 PM 5 (0x0005)
And now the AppEnforce section
+++ Starting Install enforcement for App DT "RoboCopy from RichCopy DT" ApplicationDeliveryType - ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663, Revision - 3, ContentPath - C:\Windows\ccmcache\6, Execution Context - System AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
A user is logged on to the system. AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
Performing detection of app deployment type RoboCopy from RichCopy DT(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663, revision 3) for system. AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
+++ Application not discovered. [AppDT Id: ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663, Revision: 3] AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
App enforcement environment:
Context: Machine Command line: "installrobo.bat"
Allow user interaction: No
UI mode: 1
User token: null
Session Id: 1
Content path: C:\Windows\ccmcache\6 Working directory: AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
Prepared working directory: C:\Windows\ccmcache\6 AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
Prepared command line: "C:\Windows\ccmcache\6\installrobo.bat" AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
Executing Command line: "C:\Windows\ccmcache\6\installrobo.bat" with user context AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
Working directory C:\Windows\ccmcache\6 AppEnforce 11/14/2012 11:03:47 PM 2976 (0x0BA0)
Post install behavior is BasedOnExitCode AppEnforce 11/14/2012 11:03:48 PM 2976 (0x0BA0)
Waiting for process 736 to finish. Timeout = 120 minutes. AppEnforce 11/14/2012 11:03:48 PM 2976 (0x0BA0)
Process 736 terminated with exitcode: 0 AppEnforce 11/14/2012 11:03:49 PM 2976 (0x0BA0)
Looking for exit code 0 in exit codes table... AppEnforce 11/14/2012 11:03:49 PM 2976 (0x0BA0)
Matched exit code 0 to a Success entry in exit codes table. AppEnforce 11/14/2012 11:03:49 PM 2976 (0x0BA0)
Performing detection of app deployment type RoboCopy from RichCopy DT(ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663, revision 3) for system. AppEnforce 11/14/2012 11:03:49 PM 2976 (0x0BA0)
+++ Discovered application [AppDT Id: ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663, Revision: 3] AppEnforce 11/14/2012 11:03:50 PM 2976 (0x0BA0)
++++++ App enforcement completed (3 seconds) for App DT "RoboCopy from RichCopy DT" [ScopeId_94B6C63C-6EE7-4F59-A303-0104DF8EC959/DeploymentType_6cdc15aa-139f-4f9f-8ccd-e44079281663], Revision: 3, User SID: ] ++++++ AppEnforce 11/14/2012 11:03:50 PM 2976 (0x0BA0)
See? A bit more painless on the device targeted logs. While there are differences they are minor and mainly deal with the context being used for the install which will impact some of the WMI paths referenced and such but overall the flow is similar.
So take a deep breath, you made it through. Congratulations for sticking with me! Hopefully this gives you more insight on what to look for, how to look for it and what the information means as you work through troubleshooting application deployments.
Comments
Anonymous
December 10, 2012
Hey Steve Is there a way to find out wrappers(technology) of the deployment using clientsdk before the application is not installed on the client (assuming deadline is sometime in the near future? Thanks JohnAnonymous
August 25, 2014
Great Article Steve.............. Thanks a lot .............