Troubleshooting SCCM OSD Part 2

Once the client boots to PXE  (which we have explained in Part I ) the clients goes to the management point and get the list of policy.
If any Mandatory (required) deployment then it will go ahead with that else if it is available deployment it will show you the List of advertisement.
 From the WindowsPE and  before HDD format the sequence of events is logged in SMSTS.log in the location   x:\windows\temp\smstslog\smsts.log


 The snippet below shows which policy are retrieved which policy is downloaded and from where.  SMSTS.log are usually pretty big.
I will be pointing only the required lines rest I will attach in a ZIP file which you can look in detail.
Preparing Policy Assignment Request. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Setting transport. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Setting site code = LAB. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Setting client ID = 0496841d-c8ba-4215-bc34-94da8ad4cd12. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
   Setting site signing Certificate. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Setting SiteSigningCertificateContext TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Executing Policy Assignment Request. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Sending RequestAssignments TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Setting message signatures. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Setting the authenticator. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
CLibSMSMessageWinHttpTransport::Send: URL: CM2012SP1.sudilab.com:80  CCM_POST /ccm_system/request TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Request was succesful. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
::DecompressBuffer(65536) TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Decompression (zlib) succeeded: original size 25716, uncompressed size 120828. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Request client ID: 0496841d-c8ba-4215-bc34-94da8ad4cd12 TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Response client ID: 0496841d-c8ba-4215-bc34-94da8ad4cd12 TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Retrieving Policy Assignments: TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Processing Policy Assignment {42a5d36c-1a04-4171-a34a-7d1ba6896d49}. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Processing Policy Assignment {6d4fd9bd-f9a8-4225-bd76-84e25e99ea39}. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Processing Policy Assignment {4bf211e4-461e-495c-aae1-cf47a73b95b2}. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
   
     ...........................
     ..............................    
    Processing Policy Assignment {adcfd522-f142-4aad-becc-a591eea01bd1}. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Processing Policy Assignment LAB20000-LAB00003-3B5BFFE2. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Processing Policy Assignment SRC10000. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Processing Policy Assignment DEP-LAB20002-LAB00002-6F6BCC28. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Processing Policy Assignment DEP-LAB20002-LAB00004-6F6BCC28. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Processing Policy Assignment DEP-LAB20002-LAB0000A-6F6BCC28. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Successfully read 43 policy assignments. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Downloading policy body LAB20002-LAB0000B-6F6BCC28. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Preparing Policy Body Request. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Setting transport. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
    Setting policy location = http:///SMS_MP/.sms_pol?LAB20002-LAB0000B-6F6BCC28.1_00. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Executing Policy Body Request. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
CLibSMSMessageWinHttpTransport::Send: URL: CM2012SP1.sudilab.com:80  GET /SMS_MP/.sms_pol?LAB20002-LAB0000B-6F6BCC28.1_00 TSPxe 20-09-2013 18:53:22 1244 (0x04DC)
Request was succesful. TSPxe 20-09-2013 18:53:22 1244 (0x04DC)

 You would also see the Network account policy which will be used to contact DP also being downloaded and evaluated

Reading Policy Body. TSPxe 20-09-2013 19:01:48 1336 (0x0538)
Parsing Policy Body. TSPxe 20-09-2013 19:01:48 1336 (0x0538)
Found NetworkAccessUsername/NetworkAccessPassword from NAAConfig CCM_NetworkAccessAccount TSPxe 20-09-2013 19:01:48 1336 (0x0538)
Network Access Account has a non-empty value TSPxe 20-09-2013 19:01:48 1336 (0x0538)
Getting local network information. TSPxe 20-09-2013 19:01:48 1336 (0x0538)
It will then check for all the content location for reference package you would find multiple occurrence of location request as below related to content reply .
If any issues with content lookup the TS would fail here and in such situations you would need to check the packages\application\boot images\OS image etc is distributed the DP which the client is assigned to.
 Request was succesful. TSPxe 20-09-2013 19:01:48 1336 (0x0538)
::DecompressBuffer(65536) TSPxe 20-09-2013 19:01:48 1336 (0x0538)
Decompression (zlib) succeeded: original size 547, uncompressed size 1690. TSPxe 20-09-2013 19:01:48 1336 (0x0538)
Location Reply: http://CM2012SP1.sudilab.com/SMS_DP_SMSPKG$/LAB00004

" Signature="http://CM2012SP1.sudilab.com/SMS_DP_SMSSIG$/LAB00004"/> Name="Default-First-Site-Name"/>7804>CM2012SP1.sudilab.comSERVERLOCAL TSPxe 20-09-2013 19:01:48 1336 (0x0538)
MCS server:  TSPxe 20-09-2013 19:01:48 1336 (0x0538)
Found location: http://CM2012SP1.sudilab.com/SMS_DP_SMSPKG$/LAB00004 TSPxe 20-09-2013 19:01:48 1336 (0x0538)Till this time TSPxe will be component in questions and once this is completed the Tasksequence is then read and parsed.
Then the Tasksequence starts performing one by one. Here on TSMager component will come in to action. This is the TS I have used which is a very basic one

Parsing group node: Install Operating System TSManager 20-09-2013 19:01:48 732 (0x02DC)
Parsing step node: Restart in Windows PE TSManager 20-09-2013 19:01:48 732 (0x02DC)
Parsing step node: Partition Disk 0 - BIOS TSManager 20-09-2013 19:01:48 732 (0x02DC)
Parsing step node: Partition Disk 0 - UEFI TSManager 20-09-2013 19:01:48 732 (0x02DC)
Parsing step node: Pre-provision BitLocker TSManager 20-09-2013 19:01:48 732 (0x02DC)
Parsing step node: Apply Operating System TSManager 20-09-2013 19:01:48 732 (0x02DC)
Parsing step node: Apply Windows Settings TSManager 20-09-2013 19:01:48 732 (0x02DC)
 Then you see the Tasksequence steps being executed

Start executing the command line: osddiskpart.exe TSManager 20-09-2013 19:01:49 732 (0x02DC)
!--------------------------------------------------------------------------------------------! TSManager 20-09-2013 19:01:49 732 (0x02DC)
Expand a string: WinPE TSManager 20-09-2013 19:01:49 732 (0x02DC)
Executing command line: osddiskpart.exe TSManager 20-09-2013 19:01:49 732 (0x02DC)
==============================[ OSDDiskPart.exe ]============================== OSDDiskPart 20-09-2013 19:01:49 852 (0x0354)
Command line: "osddiskpart.exe" OSDDiskPart 20-09-2013 19:01:49 852 (0x0354)
Succeeded loading resource DLL 'X:\sms\bin\i386\1033\TSRES.DLL' OSDDiskPart 20-09-2013 19:01:49 852 (0x0354)
Reading partition size info for partition 0 OSDDiskPart 20-09-2013 19:01:49 852 (0x0354)
Remaining size before partition: 136358691840 OSDDiskPart 20-09-2013 19:01:49 852 (0x0354)
.............
............
OSDDiskPart.exe completed successfully OSDDiskPart 20-09-2013 19:02:04 852 (0x0354)
Process completed with exit code 0 TSManager 20-09-2013 19:02:04 732 (0x02DC)
!--------------------------------------------------------------------------------------------! TSManager 20-09-2013 19:02:04 732 (0x02DC)
Successfully completed the action (Partition Disk 0 - BIOS) with the exit win32 code 0 TSManager 20-09-2013 19:02:04 732 (0x02DC)

 If you filter with Successfully completed the action you can get which all completed and if any steps fails you could check the error accordingly and then troubleshoot.
Each step does different things to know in detail please check the article http://technet.microsoft.com/en-us/library/hh846237.aspx

Successfully completed the action (Partition Disk 0 - BIOS) with the exit win32 code 0 TSManager 20-09-2013 19:02:04 732 (0x02DC)
Successfully completed the action (Pre-provision BitLocker) with the exit win32 code 0 TSManager 20-09-2013 19:02:05 732 (0x02DC)
Successfully completed the action (Apply Operating System) with the exit win32 code 0 TSManager 20-09-2013 19:15:45 732 (0x02DC)
Successfully completed the action (Apply Windows Settings) with the exit win32 code 0 TSManager 20-09-2013 19:15:46 732 (0x02DC)
Successfully completed the action (Apply Network Settings) with the exit win32 code 0 TSManager 20-09-2013 19:15:46 732 (0x02DC)
Successfully completed the action (Apply Device Drivers) with the exit win32 code 0 TSManager 20-09-2013 19:18:15 732 (0x02DC)
Successfully completed the action (Setup Windows and Configuration Manager) with the exit win32 code 0 TSManager 20-09-2013 19:20:36 732 (0x02DC)


 Once these steps are completed the windows PE phase get finished and it will boot to OS which we had applied

Save the current environment block TSManager 20-09-2013 19:20:41 732 (0x02DC)
Expand a string: %_SMSTSMDataPath%\Logs TSManager 20-09-2013 19:20:41 732 (0x02DC)
Current operating system is Windows PE. Computer will automatically rebooted when the process exits. TSManager 20-09-2013 19:21:11 732 (0x02DC)
The action (Setup Windows and Configuration Manager) initiated a reboot request TSManager 20-09-2013 19:21:11 732 (0x02DC)


You will also find the information from windows PE load to format of the disk in the SMSTS.log located atx:\smstslog\smsts.log.
Now since we have drive created and OS applied c:\_SMSTaskSequence\ which will be used as a working directory for the Tasksequence and once it is completed this will be deleted. Presence of this folder after the Tasksequence itself is a indication that TS did not complete fine.
In the windowsPE phase what ever you have in X:\  drive smsts.log will also be there inc:\_SMSTaskSequence\Logs\Smstslog\smsts.log.
Once the system boot to complete OS the X:\ data will no longer be available so you would need to grab logs before the reboot.
You can use this http://blogs.technet.com/b/sudheesn/archive/2010/03/09/how-to-get-the-related-logs-for-troubleshooting-operating-system-deployment.aspx For 2012 only the change is the location in boot image properties rest everything is the same.

Now once the system boots to full OS it will configure the OS, drivers and then install the client. In winpe only download happens till the client is installed you will find the logs inc:\_SMSTaskSequence\Logs\Smstslog\smsts.log and then it will continue through the Tasksequence if any further steps are there.
Once the client is installed then you will find the logs in the :\windows\ccm\logs\smsts.log in 2012 and in 2007 :\windows\system32\ccm\logs\smsts.log  :\windows\sysWOW64\ccm\logs\smsts.log

As you can make TS of your choice and the failure can happen any where in this it is difficult to explain all possible issues. But if you can read the smsts.log most of the issue can be sorted out as failure of any step is given in detail in the logs. What is important is that you need to find the first step failed as in many cases I had seen people looking at the last error and get misled.
For OSD issues observation , probing and finding the first major failure is the key. Just what we need to understand that when these basic steps are in place then it is just how the Tasksequence was created can make issues. In various to isolate the issue different trial and error method like disabling few steps or deleting few will make a lot of sense.
If you think TS as a step by step command thrower and approach the issues things will be simpler. If you have failure when OS is being applied , driver injection etc the other OS logs will be of help.
This link has a good collection http://technet.microsoft.com/en-us/library/dd744583(v=ws.10).aspx
I am also attaching a ZIP file with the logs which was collected while preparing this doc. For more details you can refer this.

OSD.zip