大家在使用SCCM分发软件的过程中，总是会遇到一些问题，遇到问题时，我们总会不停的检查这儿检查那儿，忙了半天也没个头绪。其实，SCCM给了我们很丰富的日志记录来做故障排除，我们的每个操作，新添加的每个软件，每次播发服务器的日志都会有记录。
今天，我们就来一起探讨一下SCCM软件分发的故障排除。
软件分发故障排除的思路大概是按照操作的顺序，分别从服务器端和客户端的日志记录中去寻找出现错误的地方。这里没有现成的错误来提供给大家分析。我会把我在做故障排除的过程中的步骤写出来供大家探讨。
1 首先检查服务器的各个组件是否工作正常，可以通过控制台的站点状态和configmgr服务管理器来检查。
2 服务器与客户端的网络通信是否正常。
3 客户端的相关端口是否打开，如果是测试软件分发功能，可以直接把防火墙关掉。
4 客户端，服务器与域控之间的通信是否正常，这个关系到客户端是否能自动找到管理点。
5 在这里，我们设定服务器和客户端一切正常，防火墙也正常，网络也正常。我们看看一个正常情况下的软件分发，在服务器和客户端上我们从哪些日志中能观察出端倪。
服务器端：
首先检查包状态，这里状况必须为一安装，而且如果手动更新过分发点或者指定了更新计划，那么安装的源版本会增加。更新分发点是因为，我们有时会改变安装文件的内容，添加一个文件，或者更改了一个文件中的内容等等，这种情况下我们就需要更新分发点，让SCCM服务器的\\<servername>\smspkge$共享下的以包ID为名称的目录下的内容更新。客户端获取软件源文件就是在smspkge$这个共享下获取的。
{题外内容：针对软件分发，我们可以做一个简单的规划，比如源文件放在哪里，SCCM服务器上或者文件服务器上。如果放在SCCM服务器上，势必会增加SCCM的存储负担，建议放在文件服务器上，因为一般来说文件服务器的磁盘空间大而且有灾备和故障恢复，如果你的文件服务器配置DFS的话，还可以利用DFS的一些优越特性。上一篇文章中，我们在建立新的软件包的过程中，服务器会问我们此包是否包含源文件，各位还记得吗？我们可不可以这样考虑，我把软件都放到一个客户端都能访问到的文件服务器上，一个可访问的UNC路径。那么，我在制作包的时候，我就可以选择此包不包含源文件，这样我便可以节约SCCM的存储空间。而且，我也不需要去更新我的分发点了，就算我改变了软件包中的内容。如果采用上面的方法，要注意的是，你在新建程序的时候，在命令那里一定要输入完成的路径如下：\\\\<servername>\<softwarename>\<setupfilename.exe or msi> /<安装参数>。你也可以制作一个安装脚本，让客户端运行安装脚本也能行啊。}
我们从上图中可看出包是否更新到了分发点。那么我们还可以从服务器的日志中观察到:
我们从distmgr.log中查看包的建立记录，注意下图的日志我是新建立了一个包产生的，ID和上图的不一样，而且我采用了一个softshare$自定义的共享。大家注意，你在采用自定义共享的时候，请在共享的后面最好加上包的名称，根据日志，我们看出SCCM在自定义共享中建立包的时候，没有像默认的smspkge$共享中的那样以包ID为名称建立文件夹。
STATMSG: ID=2300 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_DISTRIBUTION_MANAGER" SYS=SCCM2 SITE=100 PID=2384 TID=2920 GMTDATE=Sun Apr 01 13:57:18.621 2012 ISTR0="winzip" ISTR1="10000017" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=1 AID0=400 AVAL0="10000017" SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Start adding package 10000017... SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
The Package Action is 2 and the Update Mask is 0. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
CreatePackageSignature() called for Package 10000017 with version 1 with source as E:\software\winrar. KeepUnpackedSignature = 1 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
RDC:Successfully created RDC signatures for source E:\software\winrar for package 10000017 version 1 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
GetPackageSignature() called for package 10000017 with version 1. UnpackedSignature = 1 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Starting to hash E:\software\winrar for package 10000017 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Aquired context SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Created MD5 hash SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Starting to new hash E:\software\winrar for package 10000017 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Aquired context SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Created SHAhash SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Aquired context SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Created SHAhash SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Getting provider type for algorithm 32780 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Aquired context SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Creating hash for algorithm 32780 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Created hash for version 3 and algorithm 32780 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Aquired context SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Creating hash for algorithm 32780 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Created hash for version 3 and algorithm 32780 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
The hash for algorithm 32780 is 5:32780:1:1AD4BCD55D3E78F01EF541D45E920943DB8528BCF5C092213B1C05F440962C70 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
The RDC signature hash for algorithm 32780 is 5:32780:1:54C5844C9617C2D81FEEC894B7D1E40BAB097E4F4FE841B5C01D27ABA51103F7 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Getting provider type for algorithm 32772 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Adding these contents to the package 10000017 version 1. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
DeleteUnpackedSignature() called for package 10000017 with version 1 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
The hash of package 10000017 is 029061845B35ED81E2532E0D0AB2169A SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
The new hash of package 10000017 is 22FA8536CC3C6666EB8D0E77CFD180A27E64366D SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Package 10000017 uses the source directory directly. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
The size of package 10000017 is 1509 KBytes SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Adding these contents to the package 10000017 version 1. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Created policy provider trigger for ID 10000017 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Successfully created/updated the package 10000017 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
STATMSG: ID=2311 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_DISTRIBUTION_MANAGER" SYS=SCCM2 SITE=100 PID=2384 TID=2920 GMTDATE=Sun Apr 01 13:57:18.903 2012 ISTR0="10000017" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=1 AID0=400 AVAL0="10000017" SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Start adding package to server ["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\... SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\ is NOT a Branch DP SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Will wait for 1 threads to end. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Thread Handle = 4780 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Attempting to add or update a package on a distribution point. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
for ["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\, machine account is to be used SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
STATMSG: ID=2342 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_DISTRIBUTION_MANAGER" SYS=SCCM2 SITE=100 PID=2384 TID=3524 GMTDATE=Sun Apr 01 13:57:18.977 2012 ISTR0="winzip" ISTR1="["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=2 AID0=400 AVAL0="10000017" AID1=404 AVAL1="["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\" SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Established connection to ["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Signature share exists on distribution point path MSWNET:["SMS_SITE=100"]\\SCCM2\SMSSIG$\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
The distribution point ["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\ doesn't point to an existing path. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Share SOFTSHARE$ does not exist on distribution point ["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
The best drive on the distribution point is E:\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
The best drive for installing package on the distribution point ["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\ is E:\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Try to create export SOFTSHARE$ on ["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
The drive share is accessible. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Successfully created the directory for the export. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Successfully inserted SOFTSHARE$ as an export to ["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Creating, reading and or updating Operations Management server role registry keys for a Distribution Point ... SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Get access to the package directory and the number of free bytes at that location. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Attempting to make an accessible connection to MSWNET:["SMS_SITE=100"]\\SCCM2\SOFTSHARE$\, get its NOS path, and get its number of free bytes. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Used 1 out of 3 allowed processing threads. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3016 (0x0BC8)
Established connection to MSWNET:["SMS_SITE=100"]\\SCCM2\SOFTSHARE$\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Getting the NAL path's NOS equivalent. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
The NOS path is \\SCCM2\SOFTSHARE$\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Getting the number of free bytes. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Sleep 3600 seconds... SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3016 (0x0BC8)
The number of free K bytes 120398060 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Successfully made an accessible connection, got a NOS path, and, if requested, got the number of free bytes at this location. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Attempting to make an accessible connection to MSWNET:["SMS_SITE=100"]\\SCCM2\SMSSIG$\, get its NOS path, and get its number of free bytes. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Established connection to MSWNET:["SMS_SITE=100"]\\SCCM2\SMSSIG$\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Getting the NAL path's NOS equivalent. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
The NOS path is \\SCCM2\SMSSIG$\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
The number of free bytes at the specified location has not been requested. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Successfully made an accessible connection, got a NOS path, and, if requested, got the number of free bytes at this location. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Successfully set access security on MSWNET:["SMS_SITE=100"]\\SCCM2\SOFTSHARE$\ for package 10000017 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
GetPackageSignature() called for package 10000017 with version 1. UnpackedSignature = 0 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Copying E:\software\winrar\WinRAR.exe to E:\SOFTSHARE$\WinRAR.exe, OK SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
RDC:Successfully copied package signature file C:\SMSPKGSIG\10000017.1.tar to \\SCCM2\SMSSIG$\\10000017.1.tar SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
RDC:Successfully set access security on \\SCCM2\SMSSIG$\\10000017.1.tar for package 10000017 signature file SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Successfully copied package 10000017 from E:\software\winrar\ to MSWNET:["SMS_SITE=100"]\\SCCM2\SOFTSHARE$\ SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
STATMSG: ID=2329 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_DISTRIBUTION_MANAGER" SYS=SCCM2 SITE=100 PID=2384 TID=3524 GMTDATE=Sun Apr 01 13:57:29.180 2012 ISTR0="10000017" ISTR1="E:\software\winrar\" ISTR2="MSWNET:["SMS_SITE=100"]\\SCCM2\SOFTSHARE$\" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=2 AID0=400 AVAL0="10000017" AID1=404 AVAL1="["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\" SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
STATMSG: ID=2330 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_DISTRIBUTION_MANAGER" SYS=SCCM2 SITE=100 PID=2384 TID=3524 GMTDATE=Sun Apr 01 13:57:29.200 2012 ISTR0="10000017" ISTR1="["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=2 AID0=400 AVAL0="10000017" AID1=404 AVAL1="["Display=\\SCCM2\"]MSWNET:["SMS_SITE=100"]\\SCCM2\" SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Successfully created/updated the package server in the data source SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
Performing cleanup prior to returning. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 3524 (0x0DC4)
DP thread with array index 0 ended. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
DP thread with thread handle 4780 and thread ID 3524 ended. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Updating package info for package 10000017 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Created policy provider trigger for ID 10000017 SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Package 10000017 does not have a preferred sender. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Package 10000017 is new or has changed, replicating to all applicable sites. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
StoredPkgVersion (0) of package 10000017. StoredPkgVersion in database is 0. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
SourceVersion (1) of package 10000017. SourceVersion in database is 1. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Adding these contents to the package 10000017 version 1. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
STATMSG: ID=2301 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_DISTRIBUTION_MANAGER" SYS=SCCM2 SITE=100 PID=2384 TID=2920 GMTDATE=Sun Apr 01 13:57:29.485 2012 ISTR0="winzip" ISTR1="10000017" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=1 AID0=400 AVAL0="10000017" SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
Exiting package processing thread. SMS_DISTRIBUTION_MANAGER 1601/1/1 0:00:00 2920 (0x0B68)
从上面的日志中我们就可以判断出包是否建立好，是否正常的更新到了分发点。而且可以看到各个步骤的详细信息，这么充分的信息足以让我们判断包在建立的过程中问题出在那里。
6 包建立好了，接下来我们开配置播发，播发的建立时由offermgr.log和policypv.log日志文件来记录，我们来看看正常情况下的条目，我马上配置一个播发，注意播发ID。
我们来看看日志里都记录了什么：
offermgr.log
Processing New offer 1002000F SMS_OFFER_MANAGER 1601/1/1 0:00:00 2296 (0x08F8)
STATMSG: ID=3900 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_OFFER_MANAGER" SYS=SCCM2 SITE=100 PID=2384 TID=2296 GMTDATE=Sun Apr 01 14:15:14.524 2012 ISTR0="winzip for test" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=1 AID0=401 AVAL0="1002000F" SMS_OFFER_MANAGER 1601/1/1 0:00:00 2296 (0x08F8)
Examining collection: 1000000E SMS_OFFER_MANAGER 1601/1/1 0:00:00 2296 (0x08F8)
Advanced client offer changes detected for collection 1000000E, 1 added and 0 deleted. SMS_OFFER_MANAGER 1601/1/1 0:00:00 2296 (0x08F8)
Prepared policies based on 1 offer(s) for 1 resources in collection 1000000E SMS_OFFER_MANAGER 1601/1/1 0:00:00 2296 (0x08F8)
服务器事件截图:
policypv.log
Looking for software policy and policy assignments that should be removed... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Did not find any software policy or policy assignments that should be removed. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Looking for Branch DP package policy and policy assignments that should be removed... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Did not find any Branch DP package policy or policy assignments that should be removed. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Looking for software policy and policy assignments that should be created... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Did not find any software policy or policy assignments that should be created. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Looking for Branch DP package policy and policy assignments that should be created... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Did not find any Branch DP package policy or policy assignments that should be created. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Did not find any changes in dependent programs. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Looking for software policy and policy assignments that should be updated because of changes in package 10000017. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Did not find any software policy and policy assignments that should be updated because of changes in package 10000017. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C){在这里的时候都我都还没有建立播发，SCCM也没有发现有播发}
Looking policy and policy assignments that should be updated for Branch DP package 10000017 ... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
There is no need to update policy for Branch DP package 10000017 as the CRC has not changed SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Successfully updated policy and policy assignment based on package 10000017 SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Processing DependentPolicy changes SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Processing TSReferencePolicy changes SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Querying the scan tool table... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
scan tool crc: 0, 0 SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
No changes to Scan Tool Policy SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
not yet time to do quarantine purge SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Waiting for changes... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Detected changes in offer 1002000F {这里检测到了一个播发，就是我刚刚建立的} SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Looking for CIN files SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
MEP-ProcessChangedObjects. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
MEP-ProcessObjectsInRetry. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Looking for software policy and policy assignments that should be removed... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Did not find any software policy or policy assignments that should be removed. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Looking for Branch DP package policy and policy assignments that should be removed... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Did not find any Branch DP package policy or policy assignments that should be removed. SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Looking for software policy and policy assignments that should be created... SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
STATMSG: ID=5100 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_POLICY_PROVIDER" SYS=SCCM2 SITE=100 PID=2384 TID=1036 GMTDATE=Sun Apr 01 14:15:19.668 2012 ISTR0="winzip" ISTR1="10000017" ISTR2="install" ISTR3="winzip for test" ISTR4="1002000F" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=2 AID0=405 AVAL0="1002000F-10000017-B2A66207" AID1=406 AVAL1="{b7cdbe27-6e4c-4d20-950b-879c1a30377a}" SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
Successfully created policy 1002000F-10000017-B2A66207 and policy assignment {b7cdbe27-6e4c-4d20-950b-879c1a30377a} based on package 10000017, program install and offer 1002000F SMS_POLICY_PROVIDER 1601/1/1 0:00:00 1036 (0x040C)
服务器端的追终我们算完成了，接下来，我们看看客户端的日志是如何记录的。
客户端：
在客户端，我们首先采用手动更新策略的方法来获得策略，在客户端凡是对三个工具的使用都是记录到smscliui.log的日志里面。每次记录是以cclicfgcontrolpanel:oninit开始。onexit结束。中间内容很多，我们找最重要的内容来看。
CCliCfgControlPanel::OnInit smscliui 2012/4/1 22:33:22 3200 (0x0C80)
Succeeded loading resource DLL 'C:\Windows\system32\CCM\2052\cfg_res.dll' smscliui 2012/4/1 22:33:22 3200 (0x0C80)
………………………………………….
Perform Action: Request & Evaluate User Policy - {3A88A2F3-0C39-45fa-8959-81F21BF500CE}. Message sent, id={10F18857-99AD-493B-8971-616F7A247BEC} smscliui 2012/4/1 22:34:43 2072 (0x0818){这条很重要，说明了我的操作，我做了一次用户策略的更新。}
Execute WMI Query: Select * From CCM_ClientActions where ActionID = "{8EF4D77C-8A23-45c8-BEC3-630827704F51}", Namespace: \\.\root\ccm\policy\machine smscliui 2012/4/1 22:34:45 1148 (0x047C)
Perform Action: Request & Evaluate Machine Policy - {8EF4D77C-8A23-45c8-BEC3-630827704F51}. Message sent, id={8A0F0CF8-7781-4D76-B90B-F007AEE52B15} smscliui 2012/4/1 22:34:46 2072 (0x0818)这条很重要，说明了我的操作，我做了一次计算机策略的更新
The schedule remains disabled smscliui 2012/4/1 22:34:52 3200 (0x0C80)
Received CCliCfgPropSheet::OnDestroy notification smscliui 2012/4/1 22:34:52 3200 (0x0C80)
CCliCfgDcmPage::FreeCallback - Detection Job is null. smscliui 2012/4/1 22:34:52 3200 (0x0C80)
CCliCfgControlPanel::OnExit smscliui 2012/4/1 22:34:52 3200 (0x0C80)
从smscliui.log的日志看来，我的操作并没有什么问题。
接下来，我们看看policyagent.log日志，这个日志是记录客户端策略更新情况的。在服务器的policypv.log中我们找到了刚才制定播发后产生的策略的ID是1002000F-10000017-B2A66207，我们跟着这个ID号，在客户端中的policyagent.log日志去查找，看客户端是否更新到了最新的策略。
Download of policy 'CCM_Policy_Policy4.PolicyID="1002000F-10000017-B2A66207",PolicySource="SMS:100",PolicyVersion="1.00"' started (DTS job ID: '{51537B40-D0FC-4C3C-8528-AD9534740A8A}') PolicyAgent_ReplyAssignments 2012/4/1 22:16:04 1744 (0x06D0)
In CDataTransferService::~CDataTransferService PolicyAgent_ReplyAssignments 2012/4/1 22:16:04 1744 (0x06D0)
Successfully initiated download of policy 'CCM_Policy_Policy4.PolicyID="1002000F-10000017-B2A66207",PolicySource="SMS:100",PolicyVersion="1.00"' PolicyAgent_ReplyAssignments 2012/4/1 22:16:04 1744 (0x06D0)
Raising event:
instance of CCM_PolicyAgent_PolicyDownloadStarted
{
ClientID = "GUID:D3E515D4-74FD-489C-B51E-D58A0177F8AD";
DateTime = "20120401141604.240000+000";
DownloadMethod = "BITS";
DownloadSource = "http://SCCM2.CONTOSO.COM/SMS_MP/.sms_pol?1002000F-10000017-B2A66207.1_00";
PolicyNamespace = "\\\\LUCY-PC\\ROOT\\ccm\\Policy\\Machine\\RequestedConfig";
PolicyPath = "CCM_Policy_Policy4.PolicyID=\"1002000F-10000017-B2A66207\",PolicySource=\"SMS:100\",PolicyVersion=\"1.00\"";
ProcessID = 1684;
ThreadID = 1744;
};
PolicyAgent_ReplyAssignments 2012/4/1 22:16:04 1744 (0x06D0)
Raising event:
instance of CCM_PolicyAgent_AssignmentEnabled
{
AssignmentConditionID = "";
AssignmentID = "{b7cdbe27-6e4c-4d20-950b-879c1a30377a}";
ClientID = "GUID:D3E515D4-74FD-489C-B51E-D58A0177F8AD";
DateTime = "20120401141604.256000+000";
PolicyID = "1002000F-10000017-B2A66207";
PolicyNamespace = "\\\\LUCY-PC\\ROOT\\ccm\\Policy\\Machine\\RequestedConfig";
PolicySource = "SMS:100";
PolicyVersion = "1.00";
ProcessID = 1684;
ThreadID = 1744;
};
PolicyAgent_ReplyAssignments 2012/4/1 22:16:04 1744 (0x06D0)
Cleaning policy for 'SMS:100' in '\\LUCY-PC\ROOT\ccm\Policy\Machine\RequestedConfig' (2012-04-01 22:15:24.720) PolicyAgent_ReplyAssignments 2012/4/1 22:16:04 1744 (0x06D0)
Trigger policy update for the compiled assignments PolicyAgent_ReplyAssignments 2012/4/1 22:16:04 1744 (0x06D0)
Download of policy CCM_Policy_Policy4.PolicyID="1002000F-10000017-B2A66207",PolicySource="SMS:100",PolicyVersion="1.00" completed (DTS Job ID: {51537B40-D0FC-4C3C-8528-AD9534740A8A}) PolicyAgent_PolicyDownload 2012/4/1 22:16:06 3132 (0x0C3C)
Raising event:
instance of CCM_PolicyAgent_PolicyDownloadSucceeded
{
ClientID = "GUID:D3E515D4-74FD-489C-B51E-D58A0177F8AD";
DateTime = "20120401141606.021000+000";
DownloadMethod = "BITS";
DownloadSource = "http://SCCM2.CONTOSO.COM/SMS_MP/.sms_pol?1002000F-10000017-B2A66207.1_00";
PolicyNamespace = "\\\\LUCY-PC\\ROOT\\ccm\\Policy\\Machine\\RequestedConfig";
PolicyPath = "CCM_Policy_Policy4.PolicyID=\"1002000F-10000017-B2A66207\",PolicySource=\"SMS:100\",PolicyVersion=\"1.00\"";
ProcessID = 1684;
ThreadID = 3132;
};
PolicyAgent_PolicyDownload 2012/4/1 22:16:06 3132 (0x0C3C)
策略下载完成，这个时候，我们应该在控制面板，”运行播发程序“里面看到我们要播发的程序了。
我们运行一次播发程序，看客户端是如何记录安装过程的。在运行播发后，第一件事情是把内容下载到客户端。这里我们分3步来检测客户端，分别是execmgr.log和datatransferservices.log。
运行播发程序后，首先会在execmgr.log中记录:
Policy is updated for Program: install, Package: 10000017, Advert: 1002000F execmgr 2012/4/1 22:36:48 1148 (0x047C)
Raising event:
[SMS_CodePage(936), SMS_LocaleID(2052)]
instance of SoftDistProgramOfferReceivedEvent
{
AdvertisementId = "1002000F";
ClientID = "GUID:D3E515D4-74FD-489C-B51E-D58A0177F8AD";
DateTime = "20120401143648.067000+000";
MachineName = "LUCY-PC";
ProcessID = 1684;
SiteCode = "100";
ThreadID = 1148;
};
execmgr 2012/4/1 22:36:48 1148 (0x047C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 22:36:48 1148 (0x047C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 22:36:48 1148 (0x047C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 22:36:48 1148 (0x047C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 22:36:48 1148 (0x047C)
CUIEventGenerator::NotifyNewProgram entered execmgr 2012/4/1 22:36:48 1148 (0x047C)
CUIEventGenerator::NotifyNewProgram succeeded execmgr 2012/4/1 22:36:48 1148 (0x047C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:33 228 (0x00E4)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:33 228 (0x00E4)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:33 228 (0x00E4)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:33 228 (0x00E4)
Verifying content availability for package 10000017 optional program install execmgr 2012/4/1 23:07:33 228 (0x00E4)
Requesting content from CAS for package 10000017 version 1 execmgr 2012/4/1 23:07:33 228 (0x00E4)
Successfully created a content request handle {C8D02C37-CF18-4747-81A9-40B81AB1B03B} for the package 10000017 version 1 execmgr 2012/4/1 23:07:33 228 (0x00E4)
Content availability verification for package 10000017 program install is in progress execmgr 2012/4/1 23:07:33 228 (0x00E4)
Content for optional program is now available. The location request ID is {C8D02C37-CF18-4747-81A9-40B81AB1B03B} execmgr 2012/4/1 23:07:34 2524 (0x09DC)
看到这条记录，证明我们可以运行安装程序了，接下来，我们看看内容下载的记录：
In CDataTransferService::DownloadDataEx2 DataTransferService 2012/4/1 22:34:46 2072 (0x0818)
UpdateURLWithTransportSettings(): OLD URL - http://SCCM2.CONTOSO.COM/SMS_MP/.sms_pol?1002000F-10000017-B2A66207.3_00 DataTransferService 2012/4/1 22:34:46 2072 (0x0818)
UpdateURLWithTransportSettings(): NEW URL - http://SCCM2.CONTOSO.COM:80/SMS_MP/.sms_pol?1002000F-10000017-B2A66207.3_00 DataTransferService 2012/4/1 22:34:46 2072 (0x0818)
Processing DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}' for user 'S-1-5-18'. DataTransferService 2012/4/1 22:34:46 2072 (0x0818)
DTSJob {426E3699-25D1-40FA-99DC-D29D904F2DB6} created to download from 'http://SCCM2.CONTOSO.COM/SMS_MP/.sms_pol?1002000F-10000017-B2A66207.3_00' to 'C:\Windows\system32\CCM\Temp\{BA3DE544-E775-46A2-9D6C-3D8291CDE924}.tmp'. DataTransferService 2012/4/1 22:34:46 2072 (0x0818)
Execute called for DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}'. Current state: 'RetrievedManifest'. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
DTSJob {426E3699-25D1-40FA-99DC-D29D904F2DB6} in state 'PendingDownload'. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}' for user 'S-1-5-18' has been cleared to run. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
QUEUE: Active job count incremented, value = 1. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
Execute called for DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}'. Current state: 'PendingDownload'. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
CDTSJob::ProcessDownload DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
Starting BITS download for DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}'. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
DTSJob {426E3699-25D1-40FA-99DC-D29D904F2DB6} set BITS job to use default credentials. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
Starting BITS job '{39B420EE-BAC3-4B37-AA56-9461B4D24CC8}' for DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}' under user 'S-1-5-18'. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
Recording ID of BITS job. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
In AddUntransferredFilesToBITS DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
Calling AddFileSet on BITS job. DataTransferService 2012/4/1 22:34:46 3892 (0x0F34)
DTS::AddTransportSecurityOptionsToBITSJob - Removing security info from DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}'. DataTransferService 2012/4/1 22:34:47 3892 (0x0F34)
DTSJob {426E3699-25D1-40FA-99DC-D29D904F2DB6} in state 'DownloadingData'. DataTransferService 2012/4/1 22:34:47 3892 (0x0F34)
CDTSJob::JobTransferred DataTransferService 2012/4/1 22:34:47 1148 (0x047C)
CDTSJob::JobTransferred : DTS Job ID='{426E3699-25D1-40FA-99DC-D29D904F2DB6}' DataTransferService 2012/4/1 22:34:47 1148 (0x047C)
DTSJob {426E3699-25D1-40FA-99DC-D29D904F2DB6} in state 'RetrievedData'. DataTransferService 2012/4/1 22:34:47 1148 (0x047C)
DTSJob {426E3699-25D1-40FA-99DC-D29D904F2DB6} successfully completed download. DataTransferService 2012/4/1 22:34:47 1148 (0x047C)
CBITSDownloadMonitor::~CBITSDownloadMonitor({426E3699-25D1-40FA-99DC-D29D904F2DB6}) DataTransferService 2012/4/1 22:34:47 1148 (0x047C)
Execute called for DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}'. Current state: 'RetrievedData'. DataTransferService 2012/4/1 22:34:47 3892 (0x0F34)
QUEUE: Active job count decremented, value = 0. DataTransferService 2012/4/1 22:34:47 3892 (0x0F34)
DTSJob {426E3699-25D1-40FA-99DC-D29D904F2DB6} in state 'NotifiedComplete'. DataTransferService 2012/4/1 22:34:47 3892 (0x0F34)
DTS job {426E3699-25D1-40FA-99DC-D29D904F2DB6} has completed:
Status : SUCCESS
Start time : 04/01/2012 22:34:46
Completion time : 04/01/2012 22:34:47
Elapsed time : 1 seconds DataTransferService 2012/4/1 22:34:47 3892 (0x0F34)
Deleting persisted data for DTS job '{426E3699-25D1-40FA-99DC-D29D904F2DB6}'. DataTransferService 2012/4/1 22:34:47 3892 (0x0F34)
datatransferservices.log只是记录了客户端下载到了DTS任务，我个人认为，DSTjob记录了客户端要下载的内容，到什么地方去下载包等等信息。而真正去下载包的过程记录在了cas.log中。
我们看看，cas.log.中记录了什么，内容很多我只摘录了关键部分。
Requesting content 10000017.1, size(KB) 1509, under context S-1-5-21-3650397070-3013653581-3419594766-500 with priority Low ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
CCacheManager::GetCachedContent ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
CCacheManager::FindCacheInfo ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
Created and initialized a LocationContentRequest ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
LocationContentRequest::SubmitLocationRequest 10000017.1, timeout 604800 seconds ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
LSCreateRequestInWMI ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
In LSNapInitializeLocationFilter for request {3F8AB56D-AD00-475A-AEF6-2BA05ED14889}. ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
LSCreateRequestMessageBody ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
ContentLocationRequest : <ContentLocationRequest SchemaVersion="1.00"><Package ID="10000017" Version="1"/><AssignedSite SiteCode="100"/><ClientLocationInfo LocationType="SMSPackage" UseProtected="0" AllowCaching="0" BranchDPFlags="0" UseInternetDP="0" AllowHTTP="1" AllowSMB="1" AllowMulticast="1" AllowFileStreaming="0"><ADSite Name="Default-First-Site-Name"/><IPAddresses><IPAddress SubnetAddress="192.168.1.0" Address="192.168.1.121"/></IPAddresses></ClientLocationInfo></ContentLocationRequest>
ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
Created and Sent Location Request '{3F8AB56D-AD00-475A-AEF6-2BA05ED14889}' for package 10000017 ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
LS job {3F8AB56D-AD00-475A-AEF6-2BA05ED14889} submitted to get DP locations for content 10000017.1 ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
Successfully created location request {C8D02C37-CF18-4747-81A9-40B81AB1B03B} for content 10000017.1 ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
Created and submitted a new Content Request for 10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500 ContentAccess 2012/4/1 23:07:33 228 (0x00E4)
Location update from LS for content 10000017.1 and location request {C8D02C37-CF18-4747-81A9-40B81AB1B03B} ContentAccess 2012/4/1 23:07:34 2524 (0x09DC)
Download location found 0 - \\SCCM2.CONTOSO.COM\SOFTSHARE$\ ContentAccess 2012/4/1 23:07:34 2524 (0x09DC)
Matching DP Location found 0 - \\SCCM2.CONTOSO.COM\SOFTSHARE$\ ContentAccess 2012/4/1 23:07:34 2524 (0x09DC)
LocationContentRequest::GetDetails 10000017.1 ContentAccess 2012/4/1 23:07:34 2524 (0x09DC)
LocationContentRequest.GetDetails returned ContentId 10000017 and Content Version 1 ContentAccess 2012/4/1 23:07:34 2524 (0x09DC)
Releasing content request {C8D02C37-CF18-4747-81A9-40B81AB1B03B} ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
Canceling LS Job {3F8AB56D-AD00-475A-AEF6-2BA05ED14889} for content 10000017.1 ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
LocationContentRequest::RemoveFromWmi ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
Requesting content 10000017.1, size(KB) 1509, under context S-1-5-21-3650397070-3013653581-3419594766-500 with priority Low ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CCacheManager::GetCachedContent ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CCacheManager::FindCacheInfo ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CCacheManager::GetCacheConfiguration ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CCacheManager::FreeSpaceAndCheckDisk ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CCacheManager::DeleteCacheToFreeSpace ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
We have enough space in cache. Now we will check for actual disk space. ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CCacheManager::FreeSpaceAndCheckDisk - found space in cache ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
Created and initialized a DownloadContentRequest ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CCacheManager::CalculateCachePath ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
Target location for content 10000017.1 is C:\Windows\system32\CCM\Cache\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500 ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
DownloadContentRequest::SubmitDownloadRequest ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CDownloadManager::RequestDownload 10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500 ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
DownloadManager::FindDownloadInfo with 10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500 ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
Calling DownloadContentEx, the type is 0 ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
Submitted CTM job {6998692F-69AF-49A8-A86F-8F61E97D7498} to download Content 10000017.1 under context S-1-5-21-3650397070-3013653581-3419594766-500 ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
DownloadInfo::SaveToWmi ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
DownloadManager: Request saved to Wmi ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
Successfully created download request {ED24AB3A-D20B-416D-8E91-4E81C348202E} for content 10000017.1 ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
Created and submitted a new Content Request for 10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500 ContentAccess 2012/4/1 23:07:36 228 (0x00E4)
CContentAccessService::NotifyDownloadProgressEx - downloaded size -1, total size 0 ContentAccess 2012/4/1 23:07:36 2384 (0x0950)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:36 2384 (0x0950)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:36 2384 (0x0950)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:36 2384 (0x0950)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:36 2384 (0x0950)
CUIEventGenerator::NotifyDownloadProgress entered ContentAccess 2012/4/1 23:07:36 2384 (0x0950)
CUIEventGenerator::NotifyDownloadProgress succeeded ContentAccess 2012/4/1 23:07:36 2384 (0x0950)
Location update from CTM for content 10000017.1 and request {ED24AB3A-D20B-416D-8E91-4E81C348202E} ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
Download location found 0 - \\SCCM2.CONTOSO.COM\SOFTSHARE$\ ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
Download request only, ignoring location update ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
CContentAccessService::NotifyDownloadProgressEx - downloaded size -2, total size 0 ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
Download started for content 10000017.1 ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
DownloadInfo::SaveToWmi ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
Raising event:
[SMS_CodePage(936), SMS_LocaleID(2052)]
instance of SoftDistDownloadStartedEvent
{
ClientID = "GUID:D3E515D4-74FD-489C-B51E-D58A0177F8AD";
DateTime = "20120401150736.917000+000";
MachineName = "LUCY-PC";
PackageId = "10000017";
PackageName = "10000017";
PackageVersion = "1";
ProcessID = 1684;
SiteCode = "100";
ThreadID = 2520;
};
ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
CUIEventGenerator::NotifyDownloadProgress entered ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
CUIEventGenerator::NotifyDownloadProgress succeeded ContentAccess 2012/4/1 23:07:36 2520 (0x09D8)
CContentAccessService::NotifyDownloadProgressEx - downloaded size -3, total size 0
CUIEventGenerator::NotifyDownloadProgress entered ContentAccess 2012/4/1 23:07:37 2520 (0x09D8)
CUIEventGenerator::NotifyDownloadProgress succeeded ContentAccess 2012/4/1 23:07:37 2520 (0x09D8)
CContentAccessService::NotifyDownloadProgressEx - downloaded size -5, total size 0
CContentAccessService::NotifyDownloadProgressEx - downloaded size 0, total size 0 )
CContentAccessService::NotifyDownloadProgressEx - downloaded size 180, total size 1509 )
CContentAccessService::NotifyDownloadProgressEx - downloaded size 420, total size 1509 )
CContentAccessService::NotifyDownloadProgressEx - downloaded size 660, total size 1509 )
CContentAccessService::NotifyDownloadProgressEx - downloaded size 900, total size 1509 )
CContentAccessService::NotifyDownloadProgressEx - downloaded size 1140, total size 1509 )
CContentAccessService::NotifyDownloadProgressEx - downloaded size 1500, total size 1509 )
CContentAccessService::NotifyDownloadComplete
ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Download completed for content 10000017.1 under context S-1-5-21-3650397070-3013653581-3419594766-500 ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
DownloadInfo::SaveToWmi ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CUIEventGenerator::NotifyDownloadProgress entered ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CUIEventGenerator::NotifyDownloadProgress succeeded ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CUIEventGenerator::NotifyDownloadProgress entered ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CUIEventGenerator::NotifyDownloadProgress succeeded ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
The hash we are verifying is 5:32780:1:1AD4BCD55D3E78F01EF541D45E920943DB8528BCF5C092213B1C05F440962C70 ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CContentAccessService::NotifyDownloadComplete Start Content Hashing ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Found an alternate data stream ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Found alternate stream :Zone.Identifier:$DATA. This stream will be removed. ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Attempting to delete ADS c:\windows\system32\ccm\cache\10000017.1.s-1-5-21-3650397070-3013653581-3419594766-500\winrar.exe:Zone.Identifier:$DATA ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Hash matches 1AD4BCD55D3E78F01EF541D45E920943DB8528BCF5C092213B1C05F440962C70 ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Hash matches 1AD4BCD55D3E78F01EF541D45E920943DB8528BCF5C092213B1C05F440962C70 ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Hash verification succeeded for content 10000017.1 downloaded under context S-1-5-21-3650397070-3013653581-3419594766-500 ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CCacheManager::GetCachedContent ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CCacheManager::FindCacheInfo ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CCacheManager::CreateCachedContent ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CachedContentInfo::SaveToWmi ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CachedContentInfo.SaveToWmi succeeded ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CCacheManager::CreateCachedContent succeeded ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Created a New Cache Item at location C:\Windows\system32\CCM\Cache\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500 for 1.10000017 Size 1509 KB bytes ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Download succeeded for download request {ED24AB3A-D20B-416D-8E91-4E81C348202E} ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
CDownloadManager::OnDownloadComplete ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
DownloadInfo::RemoveFromWmi for DownloadInfoEx2.DownloadId="6998692f-69af-49a8-a86f-8f61e97d7498",UserSid="S-1-5-21-3650397070-3013653581-3419594766-500" succeded ContentAccess 2012/4/1 23:07:39 1112 (0x0458)
Raising event:{向服务器提交日志记录}
[SMS_CodePage(936), SMS_LocaleID(2052)]
instance of SoftDistDownloadCompletedEvent
{
ClientID = "GUID:D3E515D4-74FD-489C-B51E-D58A0177F8AD";
DateTime = "20120401150739.948000+000";
MachineName = "LUCY-PC";
PackageId = "10000017";
PackageName = "10000017";
PackageVersion = "1";
ProcessID = 1684;
SiteCode = "100";
ThreadID = 1112;
};
内容下载完了，接下来就是安装过程了，安装过程记录在execmgr.log中：
Content is available for program install. execmgr 2012/4/1 23:07:39 1112 (0x0458)
Notify user package 10000017 optional program install is ready to run execmgr 2012/4/1 23:07:39 1112 (0x0458)
Execution Request for package 10000017 program install state change from WaitingContent to NotifyExecution execmgr 2012/4/1 23:07:39 1112 (0x0458)
Persisting request for program install package 10000017 in state Running execmgr 2012/4/1 23:07:39 1112 (0x0458)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:39 1112 (0x0458)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:39 1112 (0x0458)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:39 1112 (0x0458)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:39 1112 (0x0458)
CUIEventGenerator::NotifyProgramReady entered execmgr 2012/4/1 23:07:39 1112 (0x0458)
CUIEventGenerator::NotifyProgramReady succeeded execmgr 2012/4/1 23:07:40 1112 (0x0458)
CExecutionRequestManager::OnContinueExecution package 10000017 program install execmgr 2012/4/1 23:07:41 1116 (0x045C)
CExecutionRequest::EnterRsRuningState install execmgr 2012/4/1 23:07:41 1116 (0x045C)
Executing program WinRAR.exe /s in Admin context execmgr 2012/4/1 23:07:41 1116 (0x045C)
Execution Request for package 10000017 program install state change from Running to NotifyExecution execmgr 2012/4/1 23:07:41 1116 (0x045C)
Persisting request for program install package 10000017 in state Running execmgr 2012/4/1 23:07:41 1116 (0x045C)
ExecuteScriptByScriptEngine: User context passed to ExecuteProgram is [NT AUTHORITY\SYSTEM]. execmgr 2012/4/1 23:07:41 1116 (0x045C)
CExecutionContext::CExecutionContext execmgr 2012/4/1 23:07:41 1116 (0x045C)
Command line arguments when parsed WinRAR.exe execmgr 2012/4/1 23:07:41 1116 (0x045C)
Command line arguments when parsed /s execmgr 2012/4/1 23:07:41 1116 (0x045C)
Execution Manager timer has been fired. execmgr 2012/4/1 23:07:41 1852 (0x073C)
Checking content location C:\Windows\system32\CCM\Cache\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500 for use execmgr 2012/4/1 23:07:41 1116 (0x045C)
Successfully selected content location C:\Windows\system32\CCM\Cache\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500 execmgr 2012/4/1 23:07:41 1116 (0x045C)
GetFileVersionInfoSize failed for file C:\Windows\system32\CCM\Cache\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500\WinRAR.exe, error 1813 execmgr 2012/4/1 23:07:41 1116 (0x045C)
CProgramExecution::CProgramExecution execmgr 2012/4/1 23:07:41 1116 (0x045C)
Executing program as a script execmgr 2012/4/1 23:07:41 1116 (0x045C)
Successfully prepared command line "C:\Windows\system32\CCM\Cache\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500\WinRAR.exe" /s execmgr 2012/4/1 23:07:41 1116 (0x045C)
Command line = "C:\Windows\system32\CCM\Cache\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500\WinRAR.exe" /s, Working Directory = C:\Windows\system32\CCM\Cache\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500\ execmgr 2012/4/1 23:07:41 1116 (0x045C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1116 (0x045C)
Created Process for the passed command line execmgr 2012/4/1 23:07:41 1116 (0x045C)
Raising event:
[SMS_CodePage(936), SMS_LocaleID(2052)]
instance of SoftDistProgramStartedEvent
{
AdvertisementId = "1002000F";
ClientID = "GUID:D3E515D4-74FD-489C-B51E-D58A0177F8AD";
CommandLine = "\"C:\\Windows\\system32\\CCM\\Cache\\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500\\WinRAR.exe\" /s";
DateTime = "20120401150741.308000+000";
MachineName = "LUCY-PC";
PackageName = "10000017";
ProcessID = 1684;
ProgramName = "install";
SiteCode = "100";
ThreadID = 1116;
UserContext = "NT AUTHORITY\\SYSTEM";
WorkingDirectory = "C:\\Windows\\system32\\CCM\\Cache\\10000017.1.S-1-5-21-3650397070-3013653581-3419594766-500\\";
};
execmgr 2012/4/1 23:07:41 1116 (0x045C)
Raised Program Started Event for Ad:1002000F, Package:10000017, Program: install execmgr 2012/4/1 23:07:41 1116 (0x045C)
GetProcessInfo - Process creation time high = 30216217, low = 788148665 execmgr 2012/4/1 23:07:41 1116 (0x045C)
Execution Manager received Temp Path C:\Windows\TEMP\ execmgr 2012/4/1 23:07:41 1116 (0x045C)
Power lease started with ID = 11016 for 7200 seconds execmgr 2012/4/1 23:07:41 1116 (0x045C)
Persisting request for program install package 10000017 in state Running execmgr 2012/4/1 23:07:41 1116 (0x045C)
CExecutionRequestManager::OnTimer - Processing the ClearNewProgramNotificationTimer execmgr 2012/4/1 23:07:41 1852 (0x073C)
CExecutionRequestManager::ProcessClearNewProgramNotificationTimer execmgr 2012/4/1 23:07:41 1852 (0x073C)
Entering CTimerTask::CancelTimer. execmgr 2012/4/1 23:07:41 1852 (0x073C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1852 (0x073C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1852 (0x073C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1852 (0x073C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1852 (0x073C)
CUIEventGenerator::ClearNewProgramAvailable entered execmgr 2012/4/1 23:07:41 1852 (0x073C)
CUIEventGenerator::ClearNewProgramAvailable succeeded execmgr 2012/4/1 23:07:41 1852 (0x073C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1852 (0x073C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1852 (0x073C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1852 (0x073C)
Cached CCM (user, session) is: (S-1-5-21-3650397070-3013653581-3419594766-500,2). execmgr 2012/4/1 23:07:41 1852 (0x073C)
CUIEventGenerator::ClearNewProgramAvailable entered execmgr 2012/4/1 23:07:41 1852 (0x073C)
CUIEventGenerator::ClearNewProgramAvailable succeeded execmgr 2012/4/1 23:07:41 1852 (0x073C)
Program exit code 0 execmgr 2012/4/1 23:07:41 1852 (0x073C)
CExecutionStatus::CExecutionStatus execmgr 2012/4/1 23:07:41 1852 (0x073C)
Looking for MIF file to get program status execmgr 2012/4/1 23:07:41 1852 (0x073C)
Looking for MIF file in directory C:\Windows\ execmgr 2012/4/1 23:07:41 1852 (0x073C)
Looking for MIF file in directory C:\Windows\system32\ execmgr 2012/4/1 23:07:41 1852 (0x073C)
Script for Package:10000017, Program: install succeeded with exit code 0 execmgr 2012/4/1 23:07:41 1852 (0x073C)
Raising event:
[SMS_CodePage(936), SMS_LocaleID(2052)]
instance of SoftDistProgramCompletedSuccessfullyEvent
{
AdvertisementId = "1002000F";
ClientID = "GUID:D3E515D4-74FD-489C-B51E-D58A0177F8AD";
DateTime = "20120401150741.808000+000";
MachineName = "LUCY-PC";
PackageName = "10000017";
ProcessID = 1684;
ProgramName = "install";
SiteCode = "100";
ThreadID = 1852;
UserContext = "NT AUTHORITY\\SYSTEM";
};
execmgr 2012/4/1 23:07:41 1852 (0x073C)
Raised Program Success Event for Ad:1002000F, Package:10000017, Program: install execmgr 2012/4/1 23:07:41 1852 (0x073C)
Execution is complete for program install. The exit code is 0, the execution status is Success execmgr 2012/4/1 23:07:41 1852 (0x073C)
整个软件分发的故障排除，到这里就结束了。在这里给大家一个建议，我通常会遇到软件内容都已经下载到本地了，但是还是安装不成功。请大家在分发软件的时候，一定要用命令的方式在测试机上运行一次，看自己的命令有没有问题。注意到execmgr.log中的commadn line了吗？其实，客户端就是按照你在配置包程序时候的命令来执行的。所以，一定要保证命令的正确。
SCCM的故障排除，虽然很繁琐，而且牵涉的日志文件也很多。大家要有细心和耐心。不要急躁，慢慢来随着自己的熟悉，会越来越快的。在SCCM的离线帮助文件中，包含了服务器和客户端的所有日志文件的作用，空了可以看看。
SCCM的故障排除是一个很有意思的过程，随着故障排除，你可以更深入的去了解SCCM的工作流程。更准确的判断出问题出在哪里，尤其是SCCM提供了丰富的日志文件记录。欢迎大家一起来探讨SCCM的troubeshooting。将日志文件贴出来，大家一起讨论。
本文转自zhaonaiqiu 51CTO博客，原文链接：http://blog.51cto.com/naima/823545，如需转载请自行联系原作者
