Client Automation - Logs to follow the transfer of SD package for SD Agent in NOS Less mode

Products

• CA Client Automation - IT Client Manager
• CA Client Automation
• CA Client Automation - Software Delivery
• CA Client Automation - Patch Manager

Issue/Introduction

In which logs we could see the sending of SD Package from Scalability Server to SD Agent in NOS Less mode ?

Environment

Client Automation - All Versions.

Resolution

Here are the process and logs to check when SD Agent receives a SD package in NOSLess mode :

 

• Agent SD on machine starts and initialize the library of type 4 (NOSLess). We could see this in log TRC_USD_SDAGENT*.log :

280520-11:46:46.8385721L|001908|00001af8|SDAgent | |sdjecontainerif.cpp |000655|NOTIFY | Instantiating Library_1 as an internal nosless library (type=4)

280520-11:46:47.2837886L|001908|00001af8|SDAgent | |sdjecontainerif.cpp |001036|NOTIFY | RequestAccess succeeded for library 1

It receives the transfer request from cfftplugin of scalability server :

 

280520-11:46:48.4187547L|001908|00001af8|SDAgent | |sdjeasmlibraryif.cpp|000675|INFO | C:\Program Files (x86)\CA\DSM\SD\tmp\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.zip does not exist, downloading from the beginning

280520-11:46:48.5561101L|001908|00001af8|SDAgent |cfFTClientAPI | |000000|INFO | StartFileTransfer() - filename:C:\Program Files (x86)\CA\DSM\SD\tmp\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.zip

280520-11:46:48.5561306L|001908|00001af8|SDAgent |cfFTClientAPI | |000000|INFO | StartFileTransfer() - guid:A338D67E-BB91-4F24-83F5-911DC12AE76C

280520-11:46:48.5942600L|001908|00001af8|SDAgent |cfFTClientAPI | |000000|INFO | StartFileTransfer() - file is a download

 

Download starts and agent receives each parcel of size 131072 bytes :

280520-11:46:48.8377658L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|INFO | CFNetBufferRecvd - header complete, size=0x0000000003EE250A

280520-11:46:48.8380858L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|INFO | m_fileSize=0x0000000003EE250A

280520-11:46:48.8381375L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|INFO | m_BytesLeft=0x0000000003EE250A

280520-11:46:48.8381540L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | Setting the encryption=1 and throttle=-1 on the Networker for transfer={A338D67E-BB91-4F24-83F5-911DC12AE76C}

280520-11:46:48.8381719L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|INFO | CFNetBufferRecvd - this is a download

280520-11:46:48.8381935L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|INFO | Client received 0 bytes

 

280520-11:46:48.8397845L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | CFTClientNotifier::Notify - Received CFNetBufferRecvd notification!

280520-11:46:48.8399818L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | CFNetBufferRecvd - m_bReadyForData==true

280520-11:46:48.8400037L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | Client received 131072 bytes

280520-11:46:48.8421842L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | m_BytesLeft before decrementing=0x0000000003EE250A

 

280520-11:46:48.8429294L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | CFTClientNotifier::Notify - Received CFNetBufferRecvd notification!

280520-11:46:48.8430051L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | CFNetBufferRecvd - m_bReadyForData==true

280520-11:46:48.8430209L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | Client received 131072 bytes

...

280520-11:46:49.7804941L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | CFTClientNotifier::Notify - Received CFNetBufferRecvd notification!

280520-11:46:49.7805400L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | CFNetBufferRecvd - m_bReadyForData==true

280520-11:46:49.7806134L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | Client received 131072 bytes

280520-11:46:49.7807946L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | m_BytesLeft before decrementing=0x000000000002250A

 

280520-11:46:49.7811319L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | CFTClientNotifier::Notify - Received CFNetBufferRecvd notification!

280520-11:46:49.7811591L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | CFNetBufferRecvd - m_bReadyForData==true

280520-11:46:49.7811742L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | Client received 9482 bytes

280520-11:46:49.7812083L|001908|00001b28|SDAgent |cfFTClientAPI | |000000|DETAIL | m_BytesLeft before decrementing=0x000000000000250A

 

 

When download is finished the zip file is put in directory   C:\Program Files (x86)\CA\DSM\SD\tmp\activate

280520-11:46:49.7835422L|001908|00001af8|SDAgent |cfFTClientAPI | |000000|INFO | StartFileTransfer() returning 0

280520-11:46:49.7848961L|001908|00001af8|SDAgent |cfFTClientAPI | |000000|DETAIL | File Transfer Attempt 1 completed. Return code 0. Total Retries 1.

280520-11:46:49.7849279L|001908|00001af8|SDAgent |SDAgent |sdjobclientif.cpp |003711|INFO | Got zip C:\Program Files (x86)\CA\DSM\SD\tmp\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.zip

zip is uncompressed and job could be executed :

280520-11:46:50.4230373L|001908|00001af8|SDAgent | |sdjecontainerif.cpp |004305|NOTIFY | Library type=4

280520-11:46:50.4258065L|001908|00001af8|SDAgent | |sdjecontainerif.cpp |001232|NOTIFY | Running SD job 1: CMD inst 3.0

280520-11:46:50.5494747L|001908|00001af8|SDAgent | |sdjesdprocedureexecu|000475|INFO | Current directory is C:\Program Files (x86)\CA\DSM\SD\tmp\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.itm\1.vol

• On scalabilty server we could see this in logs TRC_USD_SDSERVER*.log

SDServer starts the sending of zip file by using plugin cfftplugin :

280520-11:46:47.7365283L|005288|000017c4|SDServer |SDServer |SWPackageRequestHand|000531|INFO | GetZipForJob found C:\Program Files (x86)\CA\DSM\SD\ASM\LIBRARY\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.zip

 

280520-11:46:48.5439675L|005288|000019a4|SDServer |SDServer |SWPackageRequestHand|001053|DETAIL | Zip C:\Program Files (x86)\CA\DSM\SD\ASM\LIBRARY\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.zip exists. Setting up file transfer

 

280520-11:46:48.5440717L|005288|000019a4|SDServer |cfFTServerAPI | |000000|INFO | SetupFileTransfer() - uploadDirection==false

280520-11:46:48.5441505L|005288|000019a4|SDServer |cfFTServerAPI | |000000|INFO | File Transfer: guid=A338D67E-BB91-4F24-83F5-911DC12AE76C, filename=C:\Program Files (x86)\CA\DSM\SD\ASM\LIBRARY\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.zip, encryption=1, throttle=-1

 

When transfer is finished we could see this :

280520-11:46:48.5488299L|005288|000019a4|SDServer |SDServer |SWPackageRequestHand|001062|INFO | SWPackageRequestHandler::HandleSWDownloadRequest. SetupFileTransfer succeeded - guid=A338D67E-BB91-4F24-83F5-911DC12AE76C

 

 

 

• On scalability server we could see this in logs TRC_CF_FTPLUGIN*.log :

cfftplugin received the transfer file request from SDServer and put the request in a queue :

280520-11:46:48.5490969L|005596|00001600|cfFTPlugin|cfFTPlugin | |000000|INFO | Setting up file transfer, filename=C:\Program Files (x86)\CA\DSM\SD\ASM\LIBRARY\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.zip

280520-11:46:48.5491175L|005596|00001600|cfFTPlugin|cfFTPlugin | |000000|INFO | Setting up file transfer, guid=A338D67E-BB91-4F24-83F5-911DC12AE76C

280520-11:46:48.5491322L|005596|00001600|cfFTPlugin|cfFTPlugin | |000000|INFO | Setting up file transfer, upload direction=0, encryption=1, throttle=-1

280520-11:46:48.5492323L|005596|00001600|cfFTPlugin|cfFTPlugin | |000000|INFO | In CFTNotifierTransfer::AddTransferObject()

 

Next request is processed and parcels of 131072 bytes are sent to SD Agent :

280520-11:46:48.8482833L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | In CFTNotifierTransfer::FindTransferObject()

280520-11:46:48.8484211L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | Found the transfer object

280520-11:46:48.8484375L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | Server - CFNetBufferRecvd - found transfer item!

280520-11:46:48.8485077L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|DETAIL | Setting the encryption=1 and throttle=-1 on the Networker for transfer={A338D67E-BB91-4F24-83F5-911DC12AE76C}, File='C:\Program Files (x86)\CA\DSM\SD\ASM\LIBRARY\activate\477CD92C-BB35-443D-9D9C-D5F4369DA97A.zip'

280520-11:46:48.8485257L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | Server - filepos==0x0000000000000000

280520-11:46:48.8485385L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | Server - remoteFileSize==0x0000000000000000

280520-11:46:48.8485516L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | Server - remoteFileSize after subtracting filesize==0x0000000000000000

280520-11:46:48.8485639L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | Server - File is a download

280520-11:46:48.8490381L|005596|00000714|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::FileSendThread() - sending 131072 bytes

280520-11:46:48.8497106L|005596|00000714|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::FileSendThread() - sending 131072 bytes

280520-11:46:48.8500187L|005596|00000714|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::FileSendThread() - sending 131072 bytes

280520-11:46:48.8545709L|005596|00000714|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::FileSendThread() - sending 131072 bytes

280520-11:46:48.8546439L|005596|00000714|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::FileSendThread() - sending 131072 bytes

280520-11:46:48.8571305L|005596|00000714|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::FileSendThread() - sending 131072 bytes

...

280520-11:46:49.7874926L|005596|00000714|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::FileSendThread() - sending 131072 bytes

280520-11:46:49.7910987L|005596|00000714|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::FileSendThread() - sending 9482 bytes

 

At the end of transfer we could see this in the log TRC_CF_FTPLUGIN*.log :

280520-11:46:49.7943668L|005596|00000780|cfFTPlugin|tlsauthent |etpkiimp.cpp |001987|DETAIL | received ETPKI_E_SSOCK_SHUTDOWN in decrypt message
280520-11:46:49.7944731L|005596|00000780|cfFTPlugin|CCFSock::Recv |CCFSock.cpp |000617|INFO | Socket has been closed gracefully
280520-11:46:49.7944891L|005596|00000780|cfFTPlugin|cfNetwork |CCFNetAsyncConnectio|000721|DETAIL | DoCloseNotify: Notifying owner of graceful connection close
280520-11:46:49.7945067L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | CFTNotifierTransfer::Notify event - connectionClosed
280520-11:46:49.7945215L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | In CFTNotifierTransfer::DeleteTransferObject()
280520-11:46:49.7945371L|005596|00000780|cfFTPlugin|cfFTPlugin | |000000|INFO | erased the transfer object