Troubleshooting SCCM Part VI ..........Software Distribution
Software Distribution
The Microsoft System Center Configuration Manager 2007 software distribution feature provides a set of tools and resources that help you create and manage packages and advertisements used to distribute software to client resources within your enterprise.
For more details please check the following link
https://technet.microsoft.com/en-us/library/bb632640.aspx
Troubleshooting Software Distribution
Server Side
Once you create a package then you need to check the status messages to see if the package has been created you will have the following entries
Status ID : 30000 => User "Domain\User" created a package named " Test Package " (LAB00003).
Status ID : 2301 => SMS Distribution Manager successfully processed package "Test Package" (package ID = LAB00003).
Also you will have 2300 and 2311 for starting and creation of the packages Once you add the distribution point you then have to see if the following status messages are displayed.
Status ID : 30125 User "Domain\User" added new distribution points to a package named " Test Package " (LAB00003).
Severity Type Site code Date / Time System Component Message ID Description Thread ID Process ID
Information Milestone LAB 4/26/2010 10:28:51 PM SCCM SMS_DISTRIBUTION_MANAGER 2330 SMS Distribution Manager successfully distributed package "LAB00003" to distribution point "["Display=\\SCCM\"]MSWNET:["SMS_SITE=LAB"]\\SCCM\". 4412 3040
Information Milestone LAB 4/26/2010 10:28:51 PM SCCM SMS_DISTRIBUTION_MANAGER 2329 SMS Distribution Manager copied package "LAB00003" from "C:\SOFTDUMP\" to "MSWNET:["SMS_SITE=LAB"]\\SCCM\SMSPKGC$\LAB00003\". 4412 3040
Information Milestone LAB 4/26/2010 10:28:29 PM SCCM SMS_DISTRIBUTION_MANAGER 2342 SMS Distribution Manager is starting to distribute package "Test Package" to distribution point "["Display=\\SCCM\"]MSWNET:["SMS_SITE=LAB"]\\SCCM\". 4412 3040
If you see the errors you can check the distmgr.log for the same. The distmgr.log will have the following entries
STATMSG: ID=2300 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_DISTRIBUTION_MANAGER" SYS=SCCM SITE=LAB PID=3040 TID=3276 GMTDATE=Mon Apr 26 16:59:00.772 2010 ISTR0="Test Package" ISTR1="LAB00003" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=1 AID0=400 AVAL0="LAB00003" SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:00 PM 3276 (0x0CCC)
No action specified for the package LAB00003. SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:00 PM 3276 (0x0CCC)
No action specified for the package on server ["Display=\\SCCM\"]MSWNET:["SMS_SITE=LAB"]\\SCCM\. SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:00 PM 3276 (0x0CCC)
Updating package info for package LAB00003 SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:00 PM 3276 (0x0CCC)
Package LAB00003 does not have a preferred sender. SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:00 PM 3276 (0x0CCC)
The package and/or program properties for package LAB00003 have not changed, need to determine which site(s) need updated package info. SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:00 PM 3276 (0x0CCC)
StoredPkgVersion (0) of package LAB00003. StoredPkgVersion in database is 0. SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:00 PM 3276 (0x0CCC)
SourceVersion (1) of package LAB00003. SourceVersion in database is 1. SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:00 PM 3276 (0x0CCC)
STATMSG: ID=2301 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_DISTRIBUTION_MANAGER" SYS=SCCM SITE=LAB PID=3040 TID=3276 GMTDATE=Mon Apr 26 16:59:01.073 2010 ISTR0="Test Package" ISTR1="LAB00003" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=1 AID0=400 AVAL0="LAB00003" SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:01 PM 3276 (0x0CCC)
Exiting package processing thread. SMS_DISTRIBUTION_MANAGER 4/26/2010 10:29:01 PM 3276 (0x0CCC)
In case you see errors please make sure that the following
· There is no network issue between the server and the and the DP server
· Make sure that the SMSPKG<DriveLettre>$ share has been created and that has the folder with the package ID
· There is no DNS resolution issue.
· Make sure that the share has the require permission to write the data.
Once this is verified the next step is to check if the advertisement is created .These are the following status which will give you an idea on the creation
Information Milestone LAB 4/26/2010 10:44:36 PM SCCM SMS_OFFER_MANAGER 3900 SMS Offer Manager successfully processed new advertisement Test Advr.
Information Audit LAB 4/26/2010 10:44:24 PM SCCM Microsoft.ConfigurationManagement.dll 30006 User "MYLAB\Administrator" created an advertisement named "Test Advr" (LAB20000) advertising program "Test Program".
Once the advertisement is received by the client you will have the following status messages
Severity Type Site code Date / Time System Component Message ID Description
Information Milestone LAB 4/26/2010 10:44:36 PM SCCM SMS_OFFER_MANAGER 3900 SMS Offer Manager successfully processed new advertisement Test Advr.
Information Audit LAB 4/26/2010 10:44:24 PM SCCM Microsoft.ConfigurationManagement.dll 30006 User "MYLAB\Administrator" created an advertisement named "Test Advr" (LAB20000) advertising program "Test Program".
Now on you need to check the client logs.
Client Side
Once the agent refreshes the policy according the policy refresh interval you will have the policy downloaded and evaluated.
Policyagnet.log
Download of policy CCM_Policy_Policy4.PolicyID="LAB20000-LAB00003-9785047B",PolicySource="SMS:LAB",PolicyVersion="1.00" completed (DTS Job ID: {231E2AE2-7ED2-4AA3-84F4-81CA1712217E}) PolicyAgent_PolicyDownload 4/26/2010 10:47:12 PM 1944 (0x0798)
Raising event:
instance of CCM_PolicyAgent_PolicyDownloadSucceeded
{
ClientID = "GUID:76B6D180-F0B6-4689-B294-6CCE9033D7EB";
DateTime = "20100426171712.258000+000";
DownloadMethod = "BITS";
DownloadSource = "https://SCCM.MYLAB.IN/SMS_MP/.sms_pol?LAB20000-LAB00003-9785047B.1_00";
PolicyNamespace = "\\\\SQL\\ROOT\\ccm\\Policy\\Machine\\RequestedConfig";
PolicyPath = "CCM_Policy_Policy4.PolicyID=\"LAB20000-LAB00003-9785047B\",PolicySource=\"SMS:LAB\",PolicyVersion=\"1.00\"";
ProcessID = 3568;
ThreadID = 1944;
};
PolicyAgent_PolicyDownload 4/26/2010 10:47:12 PM 1944 (0x0798)
Policy Evaluvator.log
Raising event:
instance of CCM_PolicyAgent_PolicyEvaluationComplete
{
ClientID = "GUID:76B6D180-F0B6-4689-B294-6CCE9033D7EB";
DateTime = "20100426171716.924000+000";
PolicyNamespace = "\\\\SQL\\ROOT\\ccm\\Policy\\Machine\\RequestedConfig";
PolicyPath = "CCM_Policy_Policy4.PolicyID=\"LAB20000-LAB00003-9785047B\",PolicySource=\"SMS:LAB\",PolicyVersion=\"1.00\"";
ProcessID = 3568;
ThreadID = 1944;
};
PolicyAgent_PolicyEvaluator 4/26/2010 10:47:16 PM 1944 (0x0798)
Policy state for [CCM_Policy_Policy4.PolicyID="LAB20000-LAB00003-9785047B",PolicyVersion="1.00",PolicySource="SMS:LAB"] is currently [Active] PolicyAgent_PolicyEvaluator 4/26/2010 10:47:16 PM 3488 (0x0DA0)
Updating settings in \\sql\root\ccm\policy\machine\actualconfig PolicyAgent_PolicyEvaluator 4/26/2010 10:47:16 PM 3488 (0x0DA0)
Raising event:
instance of CCM_PolicyAgent_SettingsEvaluationComplete
{
ClientID = "GUID:76B6D180-F0B6-4689-B294-6CCE9033D7EB";
DateTime = "20100426171718.827000+000";
PolicyNamespace = "\\\\sql\\root\\ccm\\policy\\machine\\actualconfig";
ProcessID = 3568;
ThreadID = 3488;
};
PolicyAgent_PolicyEvaluator 4/26/2010 10:47:18 PM 3488 (0x0DA0)
On the execution manager you will have the following entry
Execmgr.log
Policy arrived for parent package LAB00003 program Test Program execmgr 4/26/2010 10:47:19 PM 2004 (0x07D4)
Raising event:
[SMS_CodePage(437), SMS_LocaleID(1033)]
instance of SoftDistProgramOfferReceivedEvent
{
AdvertisementId = "LAB20000";
ClientID = "GUID:76B6D180-F0B6-4689-B294-6CCE9033D7EB";
DateTime = "20100426171720.299000+000";
MachineName = "SQL";
ProcessID = 3568;
SiteCode = "LAB";
ThreadID = 2004;
};
execmgr 4/26/2010 10:47:20 PM 2004 (0x07D4)
Requesting content from CAS for package LAB00003 version 1 execmgr 4/26/2010 10:47:25 PM 1944 (0x0798)
Successfully created a content request handle {80539F34-D400-4978-95F2-9D26151C9BF8} for the package LAB00003 version 1 execmgr 4/26/2010 10:47:29 PM 1944 (0x0798)
Then you will see the download in the datatransferservices.log
DatatransferServices.log
UpdateURLWithTransportSettings(): OLD URL - https://SCCM.MYLAB.IN/SMS\_MP/.sms\_pol?LAB20000-LAB00003-9785047B.1\_00 DataTransferService 4/26/2010 10:47:06 PM 3208 (0x0C88)
UpdateURLWithTransportSettings(): NEW URL - https://SCCM.MYLAB.IN:80/SMS\_MP/.sms\_pol?LAB20000-LAB00003-9785047B.1\_00 DataTransferService 4/26/2010 10:47:06 PM 3208 (0x0C88)
DTSJob {231E2AE2-7ED2-4AA3-84F4-81CA1712217E} created to download from 'https://SCCM.MYLAB.IN/SMS_MP/.sms_pol?LAB20000-LAB00003-9785047B.1_00' to 'C:\WINDOWS\system32\CCM\Temp\{55C3178E-C27D-4C29-AC2D-439C6E87D53D}.tmp'. DataTransferService 4/26/2010 10:47:06 PM 3208 (0x0C88)
DTSJob {231E2AE2-7ED2-4AA3-84F4-81CA1712217E} in state 'PendingDownload'. DataTransferService 4/26/2010 10:47:06 PM 1944 (0x0798)
DTS::AddTransportSecurityOptionsToBITSJob - Failed to QueryInterface for IBackgroundCopyJobHttpOptions. BITS 2.5+ may not be installed properly. DataTransferService 4/26/2010 10:47:09 PM 1944 (0x0798)
DTSJob {231E2AE2-7ED2-4AA3-84F4-81CA1712217E} in state 'DownloadingData'. DataTransferService 4/26/2010 10:47:09 PM 1944 (0x0798)
DTSJob {231E2AE2-7ED2-4AA3-84F4-81CA1712217E} in state 'RetrievedData'. DataTransferService 4/26/2010 10:47:11 PM 2004 (0x07D4)
DTSJob {B40BBB03-0BA0-460A-B822-3DB2535AFCF1} successfully completed download. DataTransferService 4/26/2010 10:48:10 PM 3208 (0x0C88)
DTSJob {B40BBB03-0BA0-460A-B822-3DB2535AFCF1} in state 'NotifiedComplete'. DataTransferService 4/26/2010 10:48:11 PM 3488 (0x0DA0)
DTS job {B40BBB03-0BA0-460A-B822-3DB2535AFCF1} has completed:
Status : SUCCESS
Start time : 04/26/2010 22:48:07
Completion time : 04/26/2010 22:48:10
Elapsed time : 3 seconds DataTransferService 4/26/2010 10:48:11 PM 3488 (0x0DA0)
Then you will see the downloaded progress and completed with the execution of the process. If it is failing make sure that the DP is available and also that the BITS is working fine.
Execmgr.log
Program Test Program change to state STATE_ADVANCED_DOWNLOAD content in progress execmgr 4/26/2010 10:47:29 PM 1944 (0x0798)
Execution Request for package LAB00003 program Test Program state change from NotExist to AdvancedDownload execmgr 4/26/2010 10:47:29 PM 1944 (0x0798)
Mandatory execution requested for program Test Program and advertisement LAB20000 execmgr 4/26/2010 10:47:29 PM 3208 (0x0C88)
Creating mandatory request for advert LAB20000, program Test Program, package LAB00003 execmgr 4/26/2010 10:47:29 PM 3208 (0x0C88)
Raising event:
[SMS_CodePage(437), SMS_LocaleID(1033)]
instance of SoftDistWaitingContentEvent
{
AdvertisementId = "LAB20000";
ClientID = "GUID:76B6D180-F0B6-4689-B294-6CCE9033D7EB";
DateTime = "20100426171731.545000+000";
MachineName = "SQL";
PackageName = "LAB00003";
PackageVersion = "1";
ProcessID = 3568;
ProgramName = "Test Program";
SiteCode = "LAB";
ThreadID = 3208;
};
execmgr 4/26/2010 10:47:31 PM 3208 (0x0C88)
Successfully raised SoftDistWaitingContentEvent event for program Test Program execmgr 4/26/2010 10:47:31 PM 3208 (0x0C88)
Execution Request for package LAB00003 program Test Program state change from WaitingDependency to WaitingContent execmgr 4/26/2010 10:47:31 PM 3208 (0x0C88)
Content is available for program Test Program. execmgr 4/26/2010 10:48:18 PM 3488 (0x0DA0)
CExecutionRequest::Service Windows Manager has allowed us to run. execmgr 4/26/2010 10:48:18 PM 3488 (0x0DA0)
Execution Request for package LAB00003 program Test Program state change from WaitingContent to NotifyExecution execmgr 4/26/2010 10:48:18 PM 3488 (0x0DA0)
Notify user mandatory program Test Program is about to run execmgr 4/26/2010 10:48:18 PM 3488 (0x0DA0)
Execution Manager timer has been fired. execmgr 4/26/2010 10:53:18 PM 2184 (0x0888)
Executing program test.bat in Admin context execmgr 4/26/2010 10:53:19 PM 2184 (0x0888)
Execution Manager timer has been fired. execmgr 4/26/2010 10:53:19 PM 3752 (0x0EA8)
Execution Request for package LAB00003 program Test Program state change from Running to NotifyExecution execmgr 4/26/2010 10:53:19 PM 2184 (0x0888)
Checking content location C:\WINDOWS\system32\CCM\Cache\LAB00003.1.System for use execmgr 4/26/2010 10:53:19 PM 2184 (0x0888)
Successfully selected content location C:\WINDOWS\system32\CCM\Cache\LAB00003.1.System execmgr 4/26/2010 10:53:19 PM 2184 (0x0888)
Executing program as a script execmgr 4/26/2010 10:53:19 PM 2184 (0x0888)
Successfully prepared command line "C:\WINDOWS\system32\CCM\Cache\LAB00003.1.System\test.bat" execmgr 4/26/2010 10:53:19 PM 2184 (0x0888)
Command line = "C:\WINDOWS\system32\CCM\Cache\LAB00003.1.System\test.bat", Working Directory = C:\WINDOWS\system32\CCM\Cache\LAB00003.1.System\ execmgr 4/26/2010 10:53:19 PM 2184 (0x0888)
Created Process for the passed command line execmgr 4/26/2010 10:53:20 PM 2184 (0x0888)
Raising event:
[SMS_CodePage(437), SMS_LocaleID(1033)]
instance of SoftDistProgramStartedEvent
{
AdvertisementId = "LAB20000";
ClientID = "GUID:76B6D180-F0B6-4689-B294-6CCE9033D7EB";
CommandLine = "\"C:\\WINDOWS\\system32\\CCM\\Cache\\LAB00003.1.System\\test.bat\"";
DateTime = "20100426172320.000000+000";
MachineName = "SQL";
PackageName = "LAB00003";
ProcessID = 3568;
ProgramName = "Test Program";
SiteCode = "LAB";
ThreadID = 2184;
UserContext = "NT AUTHORITY\\SYSTEM";
WorkingDirectory = "C:\\WINDOWS\\system32\\CCM\\Cache\\LAB00003.1.System\\";
};
execmgr 4/26/2010 10:53:20 PM 2184 (0x0888)
Raised Program Started Event for Ad:LAB20000, Package:LAB00003, Program: Test Program execmgr 4/26/2010 10:53:20 PM 2184 (0x0888)
Program exit code 0 execmgr 4/26/2010 10:53:24 PM 3752 (0x0EA8)
Looking for MIF file to get program status execmgr 4/26/2010 10:53:24 PM 3752 (0x0EA8)
Script for Package:LAB00003, Program: Test Program succeeded with exit code 0 execmgr 4/26/2010 10:53:24 PM 3752 (0x0EA8)
Raising event:
[SMS_CodePage(437), SMS_LocaleID(1033)]
instance of SoftDistProgramCompletedSuccessfullyEvent
{
AdvertisementId = "LAB20000";
ClientID = "GUID:76B6D180-F0B6-4689-B294-6CCE9033D7EB";
DateTime = "20100426172324.741000+000";
MachineName = "SQL";
PackageName = "LAB00003";
ProcessID = 3568;
ProgramName = "Test Program";
SiteCode = "LAB";
ThreadID = 3752;
UserContext = "NT AUTHORITY\\SYSTEM";
};
execmgr 4/26/2010 10:53:24 PM 3752 (0x0EA8)
Raised Program Success Event for Ad:LAB20000, Package:LAB00003, Program: Test Program execmgr 4/26/2010 10:53:24 PM 3752 (0x0EA8)
Execution is complete for program Test Program. The exit code is 0, the execution status is Success execmgr 4/26/2010 10:53:24 PM 2184 (0x0888)
Execution Manager timer has been fired. execmgr 4/26/2010 10:55:29 PM 2184 (0x0888)
If there are errors here you need to check the program command line and check if you can execute this command manually in your system. Please note that in SCCM software distribution is a just a command carrier and it will carry the command which you have requested with the set of files required so if there is any execution error you need to troubleshoot the same differently.
For more details please see the following link
https://technet.microsoft.com/en-us/library/bb632640.aspx Software Distribution in Configuration Manager
https://technet.microsoft.com/en-us/library/bb892792.aspx : Troubleshooting Software Distribution Issues
https://technet.microsoft.com/en-us/library/bb932214.aspx : Software Distribution Troubleshooting Flowcharts
https://technet.microsoft.com/en-us/library/bb735865.aspx : Troubleshooting Software Distribution Using Custom Error Codes
Comments
Anonymous
October 18, 2011
I set up an ad to run an install and out of 862 machines, one installed the software as soon as the user logged off. I checked the Schedule in Client Center and it shows the right schedule but yet the install ran prematurely. The clock on the machine is correct. Why would one machine run the install before the appointed time? I don't want these production machines running the install prematurely - obviously. Any ideas or feedback is much appreciated.Anonymous
June 12, 2012
Hi Sudheesh, The description is so good. However, I couldn't find any log file name at the start of the description. Could you please post similar articles with the sequential process and also any associated inbox folders.Anonymous
March 29, 2014
Sudheesh, nice to see your blog. Hope you remember me...