Deployment Solution 7.X / 8.X - DSTasks Log in Automation and how it interacts with the other logs
search cancel

Deployment Solution 7.X / 8.X - DSTasks Log in Automation and how it interacts with the other logs

book

Article ID: 181699

calendar_today

Updated On:

Products

Deployment Solution

Issue/Introduction

In DS 8.X significant changes were made to the product and processes that make troubleshooting a very new experience, even for experienced professionals.  One of the newest logs is called DSTasks.LOG. This log was originally created in 7.1 and used for verbose debug logging.  However, in 7.5 and later we now create this by default in nearly all environments to track all DS Task related activities.  Knowing how to read it and use it in conjunction with the other logs is critical for good troubleshooting.

In this article, we will be looking primarily at the DSTasks.LOG file created in Automation.  No consideration will be made for other versions of the log file created elsewhere (e.g. on Site Servers or production agents).  Other logs in Automation will be considered mostly as they relate to this one.  This is to assist an administrator or engineer in reviewing the Tasks that DS runs to see where failures occur, and help determine how to find solutions.

Environment

Deployment Solution 7.x, 8.x

Resolution

1) WHAT is the DSTasks.LOG, and HOW does it relate to other logs?

Location: X:\Program Files\Symantec\Deployment\Logs (while in automation)

It will be copied to the following path in production on the client being imaged,
If you run a "reboot to" task to production under the agent.

                         C:\Program Files\Altiris\Altiris Agent\Agents\Deployment\PreOS_Task_Logs.

DSTasks.LOG is just what it looks like, and no more.  Any DS related task is tracked verbosely through this log file.  Anything that is NOT executed as a DS task is NOT tracked in this log.  For instance, if you send a script task in Automation, that is captured only slightly by the SMP log (which is the same as the Agent log in production) but no mention of it will be in the DSTasks.LOG.  If you send a Deploy Image task, details of everything this task does is captured in DSTasks, but only the execution of the task is captured in the SMP.log.

As a very brief review of the logs, the following table may be of use:

Log File Purpose Relation to DSTasks.LOG
DSTasks Tracking all DS Tasks executed in Automation.  Always set to verbose. Same / Self
SMP Tracks all Agent activity (PECTAgent in Automation)  This is the same as the Agent.LOG files in Production Tracks only incoming tasks and outgoing statuses of those tasks.  Task will first be logged here, THEN in DSTasks.  All final statuses of tasks are captured before sending back to the SMP.
PECTAgent Tracks the initialization of the PECTAgent in Automation.  This is unique from the Agent.LOG in that PECTAgent has to do some custom actions in Automation not required in production. Almost no interaction at all with DSTasks.  Once initialized, process is handed to the SMP Logging, and DSTasks only comes in AFTER that point.
DA_Logs_date Tracks all DA related activity, depending on log level selected. DSTasks will show calling DA, but DA logs it's own activities and returns results to DSTasks.  This is similar to how SMP shows calling a DS related task, but DSTasks shows the activities of that task.
Drivers_List List of detected drivers that need to be copied to the system. DSTasks will show this log being used by DriverManager, IF DeployAnywhere successfully created it during it's /Eval run.
act_wnd Active Windows Partition information collected/created by GHConfig DSTasks will never have mention of this log, but every time you see DSTasks with GHConfiig running, it creates one of these.

2) What does the DSTasks.LOG look like and how do we read it?


The following log output shows a successful image deployment via Ghost:

[2014/05/13 13:37:16.761 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp@446 Process imaging XML
[2014/05/13 13:37:16.761 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp@566 =False
[2014/05/13 13:37:16.761 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp@576 Output @isHTTP=False
[2014/05/13 13:37:16.761 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp@693 =  -batch -sure -clone,MODE=restore,DST=1,SRC=@fullImagePath
[2014/05/13 13:37:16.761 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp@704 Input @TyepOfImage=1
[2014/05/13 13:37:16.761 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp@461 Launch Imaging Tools
[2014/05/13 13:37:16.761 708:1172 2] Function Name is util::CSMPPackage::getNearestPackageInfoXML(),file name is common\util\SMPPackage.cpp and Line no 318.Reuest XML is /Deployment/Agent/GetNearestPackageServerInfo.aspx?xml=packageserver{32211B72-9251-4F3C-92B0-0C5DCDECD0B4}192.168.1.31ce1a2294-7780-4782-88b1-b36b780d176b
[2014/05/13 13:37:17.261 708:1172 2] Function Name is util::CSMPPackage::getNearestPackageInfoXML(),file name is common\util\SMPPackage.cpp and Line no 328. Response of getNearestPackageInfoXML = falsesmpserver.example.com192.168.1.34d43d7a2-4620-4ba1-acae-2857c45fb47atrue\\smpserver.example.com\NSCap\bin\Deployment\Packages\Images\{ce1a2294-7780-4782-88b1-b36b780d176b}\cachehttp://smpserver.example.com/Altiris/PackageShare/pkggroup_n2sqcsl64ahkqdn2pieuhyejmyexes4k/cachehttps://smpserver.example.com/Altiris/PackageShare/pkggroup_n2sqcsl64ahkqdn2pieuhyejmyexes4k/cache
[2014/05/13 13:37:17.261 708:1172 2] Function Name is util::CSMPPackage::ParsePackageInfoXML(),file name is common\util\SMPPackage.cpp and Line no 343. Return XML is =falsesmpserver.example.com192.168.1.34d43d7a2-4620-4ba1-acae-2857c45fb47atrue\\smpserver.example.com\NSCap\bin\Deployment\Packages\Images\{ce1a2294-7780-4782-88b1-b36b780d176b}\cachehttp://smpserver.example.com/Altiris/PackageShare/pkggroup_n2sqcsl64ahkqdn2pieuhyejmyexes4k/cachehttps://smpserver.example.com/Altiris/PackageShare/pkggroup_n2sqcsl64ahkqdn2pieuhyejmyexes4k/cache
[2014/05/13 13:37:17.261 708:1172 2] Function:util::CSMPPackage::Initialiaze(),File:common\util\SMPPackage.cpp and Line:98.smpserver.example.com have selected as a PS
[2014/05/13 13:37:17.261 708:1172 2] Function Name is util::ExecuteClass::LogPath(),file name is common\util\ExecuteCommand.cpp and Line no 885. path is  is =http://*:*smpserver.example.com/altiris/packageshare/pkggroup_n2sqcsl64ahkqdn2pieuhyejmyexes4k/cache/win7_x64.gho
[2014/05/13 13:37:17.261 708:1172 1] ****** ExecuteClass:: In ExecuteCommandNoUser ******

[2014/05/13 13:37:17.261 708:1172 1] ExecuteClass::Module Name = X:\Program Files\Symantec\Deployment\Ghost\Ghost64.exe
[2014/05/13 13:37:17.261 708:1172 1] ExecuteClass:: Commandline contains the credentials hence hiding it...
[2014/05/13 13:37:17.261 708:1172 2] ExecuteCommand.cpp@1886 calling ExecuteClass::ExecuteCommandNoUser().
[2014/05/13 13:37:17.261 708:1172 2] ExecuteClass::@1919 Application Name is NOT NULL.
[2014/05/13 13:37:17.261 708:1172 2] ExecuteClass::@1932 Command line is NOT NULL.
[2014/05/13 13:37:17.261 708:1172 1] ExecuteCommandNoUser()Successfully created process. nResult =1
[2014/05/13 13:37:17.261 708:1172 1]  Calling ExecuteClass::ProcessAfterCreate()
[2014/05/13 13:41:03.182 708:1172 2] ExecuteCommand.cpp@2031 ProcessAfterCreate:: dwExitCode=0
[2014/05/13 13:41:03.182 708:1172 2] tcube::ClientImageDeploy::ExecuteCommand:1186 Result of excution of X:\Program Files\Symantec\Deployment\Ghost\Ghost64.exe
[2014/05/13 13:41:03.182 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp:1214 ImageDeploy Task, Execute, Process returned 0
[2014/05/13 13:41:03.182 708:1172 1] ****** ExecuteClass:: In ExecuteCommandNoUser ******
[2014/05/13 13:41:03.182 708:1172 1] ExecuteClass::Module Name = X:\Program Files\Symantec\Deployment\Ghost\GhConfig64.exe
[2014/05/13 13:41:03.182 708:1172 1] ExecuteClass::Commandline =  /findactivewindows
[2014/05/13 13:41:03.182 708:1172 2] ExecuteCommand.cpp@1886 calling ExecuteClass::ExecuteCommandNoUser().
[2014/05/13 13:41:03.182 708:1172 2] ExecuteClass::@1919 Application Name is NOT NULL.
[2014/05/13 13:41:03.182 708:1172 2] ExecuteClass::@1932 Command line is NOT NULL.
[2014/05/13 13:41:03.182 708:1172 1] ExecuteCommandNoUser()Successfully created process. nResult =1
[2014/05/13 13:41:03.182 708:1172 1]  Calling ExecuteClass::ProcessAfterCreate()
[2014/05/13 13:41:03.276 708:1172 2] ExecuteCommand.cpp@2031 ProcessAfterCreate:: dwExitCode=0
[2014/05/13 13:41:03.276 708:1172 1] ****** ExecuteClass:: In ExecuteCommandNoUser ******


 The following output shows a successful DeployAnywhere execution:

[2014/05/13 13:41:03.432 708:1172 1] ****** ExecuteClass:: In ExecuteCommandNoUser ******
[2014/05/13 13:41:03.432 708:1172 1] ExecuteClass::Module Name = X:\Program Files\Symantec\Deployment\Ghost\DeployAnywhere64.exe
[2014/05/13 13:41:03.432 708:1172 1] ExecuteClass::Commandline =  /target=C:\Windows  /reportNonCriticalDevices  /eval  /rad /exportDevicesIntoFile="X:\Program Files\Symantec\Deployment\Logs"
[2014/05/13 13:41:03.432 708:1172 2] ExecuteCommand.cpp@1886 calling ExecuteClass::ExecuteCommandNoUser().
[2014/05/13 13:41:03.432 708:1172 2] ExecuteClass::@1919 Application Name is NOT NULL.
[2014/05/13 13:41:03.432 708:1172 2] ExecuteClass::@1932 Command line is NOT NULL.
[2014/05/13 13:41:03.447 708:1172 1] ExecuteCommandNoUser()Successfully created process. nResult =1
[2014/05/13 13:41:03.447 708:1172 1]  Calling ExecuteClass::ProcessAfterCreate()
[2014/05/13 13:41:34.445 708:1172 2] ExecuteCommand.cpp@2031 ProcessAfterCreate:: dwExitCode=2

[2014/05/13 13:41:34.445 708:1172 2] tcube::ClientImageDeploy::ExecuteCommand:1186 Result of excution of X:\Program Files\Symantec\Deployment\Ghost\DeployAnywhere64.exe
[2014/05/13 13:41:34.445 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp:1214 ImageDeploy Task, Execute, Process returned 2
[2014/05/13 13:41:34.445 708:1172 2] Function Name is util::CSMPPackage::getNearestPackageInfoXML(),file name is common\util\SMPPackage.cpp and Line no 318.Reuest XML is /Deployment/Agent/GetNearestPackageServerInfo.aspx?xml=packageserver{32211B72-9251-4F3C-92B0-0C5DCDECD0B4}192.168.1.31{20827DDD-C698-49E8-B312-830DF1D935B2}
[2014/05/13 13:41:34.492 708:1172 2] Function Name is util::CSMPPackage::getNearestPackageInfoXML(),file name is common\util\SMPPackage.cpp and Line no 328. Response of getNearestPackageInfoXML = falsesmpserver.example.com192.168.1.34d43d7a2-4620-4ba1-acae-2857c45fb47atrue\\smpserver.example.com\NSCap\bin\Deployment\DriversDBhttp://smpserver.example.com/Altiris/PackageShare/pkggroup_t7neyodofi7svj3ttzhvdbn5gfsqjhxx/DriversDBhttps://smpserver.example.com/Altiris/PackageShare/pkggroup_t7neyodofi7svj3ttzhvdbn5gfsqjhxx/DriversDB
[2014/05/13 13:41:34.492 708:1172 2] Function Name is util::CSMPPackage::ParsePackageInfoXML(),file name is common\util\SMPPackage.cpp and Line no 343. Return XML is =falsesmpserver.example.com192.168.1.34d43d7a2-4620-4ba1-acae-2857c45fb47atrue\\smpserver.example.com\NSCap\bin\Deployment\DriversDBhttp://smpserver.example.com/Altiris/PackageShare/pkggroup_t7neyodofi7svj3ttzhvdbn5gfsqjhxx/DriversDBhttps://smpserver.example.com/Altiris/PackageShare/pkggroup_t7neyodofi7svj3ttzhvdbn5gfsqjhxx/DriversDB
[2014/05/13 13:41:34.492 708:1172 2] Function:util::CSMPPackage::Initialiaze(),File:common\util\SMPPackage.cpp and Line:98.smpserver.example.com have selected as a PS
[2014/05/13 13:41:34.601 708:1172 0] common\util\SMPPackage.cpp@595: GetFile SUCCESS return code =0
[2014/05/13 13:41:34.601 708:1172 1] ****** ExecuteClass:: In ExecuteCommandNoUser ******

[2014/05/13 13:41:34.601 708:1172 1] ExecuteClass::Module Name = X:\Program Files\Symantec\Deployment\Ghost\DriverManager64.exe
[2014/05/13 13:41:34.601 708:1172 1] ExecuteClass::Commandline =  /ddb="C:\Program Files\Symantec\Deployment\DriversDB" /list="X:\program files\Symantec\Deployment\driver_list.txt" /cout="C:\Program Files\Symantec\Deployment\DA_Eval_List.xml" /format=xml
[2014/05/13 13:41:34.601 708:1172 2] ExecuteCommand.cpp@1886 calling ExecuteClass::ExecuteCommandNoUser().
[2014/05/13 13:41:34.601 708:1172 2] ExecuteClass::@1919 Application Name is NOT NULL.
[2014/05/13 13:41:34.601 708:1172 2] ExecuteClass::@1932 Command line is NOT NULL.
[2014/05/13 13:41:34.616 708:1172 1] ExecuteCommandNoUser()Successfully created process. nResult =1
[2014/05/13 13:41:34.616 708:1172 1]  Calling ExecuteClass::ProcessAfterCreate()
[2014/05/13 13:41:34.710 708:1172 2] ExecuteCommand.cpp@2031 ProcessAfterCreate:: dwExitCode=0
[2014/05/13 13:41:34.710 708:1172 2] tcube::ClientImageDeploy::ExecuteCommand:1186 Result of excution of X:\Program Files\Symantec\Deployment\Ghost\DriverManager64.exe
[2014/05/13 13:41:34.710 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp:1214 ImageDeploy Task, Execute, Process returned 0
[2014/05/13 13:41:34.866 708:1172 1] ****** ExecuteClass:: In ExecuteCommandNoUser ******
[2014/05/13 13:41:34.866 708:1172 1] ExecuteClass::Module Name = X:\Program Files\Symantec\Deployment\Ghost\DeployAnywhere64.exe
[2014/05/13 13:41:34.866 708:1172 1] ExecuteClass::Commandline =  /target=C:\ /HandleNonCriticalDrivers=minisetup /ddb="C:\Program Files\Symantec\Deployment\DriversDB" /skipMissingCriticalDrivers /byPassDrvVali=All /loglevel=255
[2014/05/13 13:41:34.866 708:1172 2] ExecuteCommand.cpp@1886 calling ExecuteClass::ExecuteCommandNoUser().
[2014/05/13 13:41:34.866 708:1172 2] ExecuteClass::@1919 Application Name is NOT NULL.
[2014/05/13 13:41:34.866 708:1172 2] ExecuteClass::@1932 Command line is NOT NULL.
[2014/05/13 13:41:34.866 708:1172 1] ExecuteCommandNoUser()Successfully created process. nResult =1
[2014/05/13 13:41:34.866 708:1172 1]  Calling ExecuteClass::ProcessAfterCreate()
[2014/05/13 13:42:13.773 708:1172 2] ExecuteCommand.cpp@2031 ProcessAfterCreate:: dwExitCode=0
[2014/05/13 13:42:13.773 708:1172 2] tcube::ClientImageDeploy::ExecuteCommand:1186 Result of excution of X:\Program Files\Symantec\Deployment\Ghost\DeployAnywhere64.exe
[2014/05/13 13:42:13.773 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp:1214 ImageDeploy Task, Execute, Process returned 0
[2014/05/13 13:42:13.773 708:1172 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp@1235::CopyIniFileToProduction()
[2014/05/13 13:42:13.788 708:1172 2] common\util\ExecuteCommand.cpp:util::ExecuteClass::SetResult():4356. Value of nResult(@ReturnValue) = 0, Value of bResult(@Success) = 1
[2014/05/13 13:42:13.788 708:1172 2] common\util\ExecuteCommand.cpp@4380 Task have completed. Successful return.


3) How do we troubleshoot the DSTasks.LOG?

Because the log is dynamic - that is, what is in it really depends on what you ask your agent system to do, troubleshooting is not very cut and dry.  In essence you will:

  • Understand the information above
  • Look for errors upside-down
  • Test where possible the step that failed.

An Example:

For example, let's say you have a job that is supposed to capture an image but it's failing.  The job has a Prepare for Image Capture, Capture Image, and Reboot to Production.  Simple.  How do you use DSTasks to help troubleshoot this?

  • First, you need to not reboot to production, so you can see what is happening and not loose the logs.
  • Second, you need to be sure not to use up all of your REARM counts for Windows 8/7/Vista, so you probably don't want to "prepare for image capture." either.

What we recommend is that you boot to Automation manually (or with a task) and just stop there doing nothing.  Then you assign a capture image task (backup or regular disk image doesn't matter) and run it only.  Immediately after it completes you look at the DSTasks.LOG to see what happened.

Looking for errors "upside-down."

Once you've seen one of these logs, you've seen more than enough, so unless you really want to, you don't need to read it from top to bottom.

Instead, start at the bottom and look for errors.  Actually - you're looking for where errors stop and success begins.  Literally, you're looking for the last successful "thing" to happen, and the first failure logged.  Often, later messages are misleading, so you want what came first.  Here's an example:

From the bottom, here's the first failure I see in a DSTasks.LOG file:

Error Description is "Child Process returned an error". The exit code from process is 3. Value of Windows error code = 183 and message is " Cannot create a file when that file already exists."

This message, however, is generic and means nothing.  So I keep looking up.  I see several messages, but finally I see what I'm looking for - success!:

[2014/02/12 14:09:13.395 1788:240 2] tcube::ClientImageDeploy::ExecuteCommand:1185 Result of excution of X:\Program Files\Symantec\Deployment\Ghost\DriverManager.exe
[2014/02/12 14:09:13.395 1788:240 2] apps\DeploymentClient\ClientImageDeploy\Tcube_ClientImageDeploy.cpp:1213 ImageDeploy Task, Execute, Process returned 0

Now, I look at the very next chunk of code - this is what is failing, but the code execution and failure message are SEVERAL lines apart:

[2014/02/12 14:09:16.50 1788:240 1] ExecuteClass::Module Name = X:\Program Files\Symantec\Deployment\Ghost\DeployAnywhere.exe
[2014/02/12 14:09:16.50 1788:240 1] ExecuteClass::Commandline = /target=D:\ /HandleNonCriticalDrivers=minisetup /ddb="D:\Program Files\Symantec\Deployment\DriversDB" /loglevel=255
[2014/02/12 14:09:16.50 1788:240 2] ExecuteCommand.cpp@1885 calling ExecuteClass::ExecuteCommandNoUser().
[2014/02/12 14:09:16.50 1788:240 2] ExecuteClass::@1918 Application Name is NOT NULL.
[2014/02/12 14:09:16.50 1788:240 2] ExecuteClass::@1931 Command line is NOT NULL.
[2014/02/12 14:09:16.50 1788:240 1] ExecuteCommandNoUser()Successfully created process. nResult =1
[2014/02/12 14:09:16.50 1788:240 1] Calling ExecuteClass::ProcessAfterCreate()
[2014/02/12 14:10:14.425 1788:240 2] ExecuteCommand.cpp@2030 ProcessAfterCreate:: dwExitCode=3 

Testing where possible.

From the text above, I can see that DeployAnywhere (DA) failed with an exit code of 3.  I don't know what this means, but I CAN see what it tried to do, and since I'm in automation, I can try it!  Here's the whole command line made up of gluing 2 lines together:

X:\Program Files\Symantec\Deployment\Ghost\DeployAnywhere.exe /target=D:\ /HandleNonCriticalDrivers=minisetup /ddb="D:\Program Files\Symantec\Deployment\DriversDB" /loglevel=255

The good news is that X is the RAM drive, and available.  D is used 2 times, and is the newly deployed production drive, and thus available.  I can actually run this from a Command Prompt here in WinPE and see what happens, or if miraculously it works!

Whether or not it works, I go fully armed to Support with logs, errors, AND testing results!

Remember, the goal of any troubleshooting process is to either find the problem, OR to find clues to the problem for a faster resolution.  In this case, you know the process, you know where it failed, and if possible, you've done additional testing.

Finally, capture ALL the logs in that LOGS folder, and have them zipped up and ready to send to support!

Powered by Wolken Software