Sunday 11 March 2012

SCCM Troubleshooting ------- 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
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 = "http://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 - http://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 - http://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 'http://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

http://technet.microsoft.com/en-us/library/bb632640.aspx Software Distribution in Configuration Manager
http://technet.microsoft.com/en-us/library/bb892792.aspx : Troubleshooting Software Distribution Issues
http://technet.microsoft.com/en-us/library/bb932214.aspx : Software Distribution Troubleshooting Flowcharts
http://technet.microsoft.com/en-us/library/bb735865.aspx : Troubleshooting Software Distribution Using Custom Error Codes

No comments:

Post a Comment