Disaster Recovery Problem

[marcoantonio.vazquez]

I have a problem when I try to do a restore in a new CUCM

I registered my backup device and my CUCM saved it succesfully, but when I try to make my restore wizard my CUCM can´t find the restore file that I saved.

When I try with another CUCM I have no problems.

Im not sure If I´m doing something wrong, I have a litle bit of experience on this

I´m using CUCM 10.5.1

[Aman Soi]

Hi,

are u trying to restore the backup to another CUCM having exactly same version?

regds,

aman

[marcoantonio.vazquez]

Yes both CUCM are 10.5 

[Aman Soi]

Hi,

You can check the following:

a. make sure u do not have multiple windows open.

b. secondly, u do not have demo licneses working on CUCM.

The one on which u are able to see backup under restore, is it working on Permanent licenses.

regds,

aman

[marcoantonio.vazquez]

Hi

Exactly the CUCM when I can see the TAR files is working on permanent license and when I can´t it´s a new CUCM with only a demo license.

Can the licensing be the problem?

Regards.

[Aman Soi]

Hi,

I doubt Demo license could be the issue.

You can speak to licensing team to get temporary license and then, try to restore.

regds,

aman

[Clifford McGlamry]

I'm seeing what appears to be the exact same problem on the 10.5.2-11900 build. 

Good backup pulled from existing licensed system.  Existing system can backup and see its backups.

Built a new server on the same version and attempted a restore.  It can see the device, but the DRF process complains it can't find the files.

However, the log from the SFTP server tells a very different story.  The server DID find the files.  It didn't ask for anything that wasn't there.  Trace is below:

10-02-2015 19:37:25 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:25 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:25 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:25 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:25 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:26 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\2015-09-29-23-00-01_PUBLISHER_processnode.xml)
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp is downloading /cucma/2015-09-29-23-00-01_PUBLISHER_processnode.xml (D:\SFTPRoot\cucma\2015-09-29-23-00-01_PUBLISHER_processnode.xml)
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp transfer complete
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:26 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:26 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:26 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:27 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\2015-09-29-23-00-01_PUBLISHER_drfComponent.xml)
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp is downloading /cucma/2015-09-29-23-00-01_PUBLISHER_drfComponent.xml (D:\SFTPRoot\cucma\2015-09-29-23-00-01_PUBLISHER_drfComponent.xml)
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp transfer complete
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:27 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\)
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp disconnected
10-02-2015 19:37:27 IP 10.14.25.7 SFTP connection attempt
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp connected
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp is listing /cucma (D:\SFTPRoot\cucma\2015-09-29-23-00-01_PUBLISHER_processnode.xml)
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp is downloading /cucma/2015-09-29-23-00-01_PUBLISHER_processnode.xml (D:\SFTPRoot\cucma\2015-09-29-23-00-01_PUBLISHER_processnode.xml)
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp transfer complete
10-02-2015 19:37:27 IP 10.14.25.7 SFTP sftp disconnected

The GUI complains "Restore request is timing out.  Either master agent is down, or SFTP server is inaccessible or too slow to respond." 

Attempts to restore from the CLI also fail with a message:

Network request timed out
drfCliMsg: error occurred: tar file not found at given storage location

Problem with this is that the trace from the SFTP server indicates that's not remotely true.  And the master and local agents have been restarted, and the box has been rebooted. 

I've done this before and licensing has never been an issue in the past, but I will attempt to get some sort of license on there.  It's never been an issue when doing this in the past, so I'm somewhat puzzled. 

The last entry on this thread is two weeks old.  Any updates?

TIA

Cliff

[Clifford McGlamry]

Update on this:

Pulled the RTMT logs for the DRF Local and Master processes on the publisher.  Local showed nothing unusual.  But the DRF Master process on the pub actually shows the process functioning normally.  See below for the DRF Master log trace.  This has me wondering if it may possibly be a bug in the tomcat process, or something else....

2015-10-02 20:35:03,628 DEBUG [Thread-2] - ==============================
2015-10-02 20:35:03,629 DEBUG [Thread-2] - 5-16-4-77-0-0-0-0-0-0-0-0-0-0-5-0-
2015-10-02 20:35:03,630 DEBUG [Thread-2] - TotLen = 1296, MsgType = NCS_MESSAGE, UD1 = 0, UD2 = 0, Payload Length = 1280
2015-10-02 20:35:03,630 DEBUG [Thread-2] - Payload( 1280 bytes)
2015-10-02 20:35:03,630 DEBUG [Thread-2] - <msg><type>DBL</type><table>processnodeservice</table><tableid>262</tableid><action>U</action><user>dbserviceweb</user><time>1443832503</time><old><cdrserver>0</cdrserver><cdrtime>1443788836</cdrtime><pkid>7e02108c-9a5f-4184-8411-8bff04ceff00</pkid><fkprocessnode>88df2e72-3d39-4c33-abfd-bf574115c1bc</fkprocessnode><tkservice>29</tkservice><tracelevel>127</tracelevel><usercategories>0</usercategories><enable>t</enable><numfiles>15</numfiles><numlines>10000</numlines><numminutes>1440</numminutes><includenondevicetraces>f</includenondevicetraces><usexml>f</usexml><servername>myNewPub</servername><devicetypemonitorflag>f</devicetypemonitorflag><devicenamemonitorflag>f</devicenamemonitorflag><filetraceflag>t</filetraceflag><outputdebugstringflag>f</outputdebugstringflag><isactive>t</isactive><priority>0</priority><maxfilesize>1</maxfilesize><restrictserver>f</restrictserver><tracedrive>C</tracedrive><ifx_replcheck>6201025832949907458</ifx_replcheck></old><new><tracelevel>127</tracelevel><usercategories>7</usercategories><enable>t</enable><numfiles>200</numfiles><includenondevicetraces>f</includenondevicetraces><usexml>f</usexml><devicetypemonitorflag>t</devicetypemonitorflag><devicenamemonitorflag>f</devicenamemonitorflag><maxfilesize>2</maxfilesize></new></msg>
2015-10-02 20:35:03,630 DEBUG [Thread-2] - ==============================
2015-10-02 20:35:03,630 DEBUG [Thread-2] - NcsClient:com.cisco.ccm.serviceability.conf.TableChangeSubscriberImpl$MyNcsClient@26a0ba Sending notification to application.
2015-10-02 20:35:03,656 INFO [Thread-3] - TraceSetting: Prev - Level=DEBUG nFile=15 fSize=1048576 path=/var/log/active/platform/drf/trace/drfMA00003.log
2015-10-02 20:35:03,680 DEBUG [Thread-2] - ==============================
2015-10-02 20:35:03,699 DEBUG [Thread-2] - 5-16-4-77-0-0-0-0-0-0-0-0-0-0-5-0-
2015-10-02 20:35:03,699 DEBUG [Thread-2] - TotLen = 1296, MsgType = NCS_MESSAGE, UD1 = 0, UD2 = 0, Payload Length = 1280
2015-10-02 20:35:03,699 DEBUG [Thread-2] - Payload( 1280 bytes)
2015-10-02 20:35:03,700 DEBUG [Thread-2] - <msg><type>DBL</type><table>processnodeservice</table><tableid>262</tableid><action>U</action><user>dbserviceweb</user><time>1443832503</time><old><cdrserver>0</cdrserver><cdrtime>1443788836</cdrtime><pkid>7a5c0ffe-5682-4c07-924c-8c5da8f3b49e</pkid><fkprocessnode>88df2e72-3d39-4c33-abfd-bf574115c1bc</fkprocessnode><tkservice>30</tkservice><tracelevel>127</tracelevel><usercategories>0</usercategories><enable>t</enable><numfiles>15</numfiles><numlines>10000</numlines><numminutes>1440</numminutes><includenondevicetraces>f</includenondevicetraces><usexml>f</usexml><servername>myNewPub</servername><devicetypemonitorflag>f</devicetypemonitorflag><devicenamemonitorflag>f</devicenamemonitorflag><filetraceflag>t</filetraceflag><outputdebugstringflag>f</outputdebugstringflag><isactive>t</isactive><priority>0</priority><maxfilesize>1</maxfilesize><restrictserver>f</restrictserver><tracedrive>C</tracedrive><ifx_replcheck>6201025832949907458</ifx_replcheck></old><new><tracelevel>127</tracelevel><usercategories>7</usercategories><enable>t</enable><numfiles>200</numfiles><includenondevicetraces>f</includenondevicetraces><usexml>f</usexml><devicetypemonitorflag>t</devicetypemonitorflag><devicenamemonitorflag>f</devicenamemonitorflag><maxfilesize>2</maxfilesize></new></msg>
2015-10-02 20:35:03,700 DEBUG [Thread-2] - ==============================
2015-10-02 20:35:03,700 DEBUG [Thread-2] - NcsClient:com.cisco.ccm.serviceability.conf.TableChangeSubscriberImpl$MyNcsClient@26a0ba Sending notification to application.
2015-10-02 20:35:03,699 INFO [Thread-3] - TraceSetting: New - Level=DEBUG nFile=200 fSize=2097152 path=/var/log/active/platform/drf/trace/drfMA00003.log
2015-10-02 20:35:42,675 INFO [NetMessageDispatch] - drfMessageReceiver::HandleMessage: Message ID3100 has been validated successfully
2015-10-02 20:35:42,675 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowStatus: Received show status request
2015-10-02 20:35:42,677 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowStatus: Show status response sent
2015-10-02 20:35:42,769 INFO [NetMessageDispatch] - drfMessageReceiver::HandleMessage: Message ID2650 has been validated successfully
2015-10-02 20:35:42,769 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowDeviceList: Received show DeviceList request
2015-10-02 20:35:42,769 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowDeviceList: com.cisco.cpi.drf.msgSubShowDeviceList_REQ@1308a8d
2015-10-02 20:35:42,769 INFO [NetMessageDispatch] - drfUtils:ReadXMLObject: File: /usr/local/platform/conf/drfDevice.xml
2015-10-02 20:35:42,771 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowDeviceList: DeviceList retrieved 2 records
2015-10-02 20:35:42,772 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowDeviceList: DeviceList response sent
2015-10-02 20:35:50,732 INFO [NetMessageDispatch] - drfMessageReceiver::HandleMessage: Message ID2650 has been validated successfully
2015-10-02 20:35:50,732 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowDeviceList: Received show DeviceList request
2015-10-02 20:35:50,732 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowDeviceList: com.cisco.cpi.drf.msgSubShowDeviceList_REQ@a9b0b4
2015-10-02 20:35:50,732 INFO [NetMessageDispatch] - drfUtils:ReadXMLObject: File: /usr/local/platform/conf/drfDevice.xml
2015-10-02 20:35:50,735 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowDeviceList: DeviceList retrieved 2 records
2015-10-02 20:35:50,736 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowDeviceList: DeviceList response sent
2015-10-02 20:35:50,737 INFO [NetMessageDispatch] - drfMessageReceiver::HandleMessage: Message ID2620 has been validated successfully
2015-10-02 20:35:50,737 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowSelectedDestination: Device selected is : cdm
2015-10-02 20:35:50,738 DEBUG [NetMessageDispatch] - drfMessageHandler:HandleShowSelectedDestination: Show selected destination response sent
2015-10-02 20:35:52,552 DEBUG [NetMessageDispatch] - drfMessageValidator.validateMessage(): Starting introspection for Message ID = 2400 Message Body =
     ========== BEGIN msgSubListBackups_REQ ==========
     devicepath     : /cucma/
     devicetype      : NETWORK
     hostname  : 10.14.25.2
     m_iBackupSetCount : 2
     password : 6bd4c942b4763016051013c0b4408018fe2a5d7fc88b5fbb3404aa6eb191a755
     storagelocationname  :
     username   : sftp
     version : 1.0.0
     schedules : []
     operation :
     ========== END msgSubListBackups_REQ ==========
2015-10-02 20:35:52,552 INFO [NetMessageDispatch] - drfMessageReceiver::HandleMessage: Message ID2400 has been validated successfully
2015-10-02 20:35:52,553 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: Received list backup request
     ========== BEGIN msgSubListBackups_REQ ==========
     devicepath     : /cucma/
     devicetype      : NETWORK
     hostname  : 10.14.25.2
     m_iBackupSetCount : 2
     password : 6bd4c942b4763016051013c0b4408018fe2a5d7fc88b5fbb3404aa6eb191a755
     storagelocationname  :
     username   : sftp
     version : 1.0.0
     schedules : []
     operation :
     ========== END msgSubListBackups_REQ ==========
2015-10-02 20:35:52,553 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:drfGetListOfBackups: filtering out the files by considering:_drfComponent.xml
2015-10-02 20:35:52,553 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:52,553 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:52,553 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:52,553 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:52,553 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:52,553 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpLsFiles-: Executing JSCH SFTP ls command for: User: sftpHostName: 10.14.25.2 from source :/cucma/ with pattern _drfComponent.xml
2015-10-02 20:35:52,553 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:52,553 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:52,902 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:52,970 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 14 files found at the given path
2015-10-02 20:35:52,970 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_drfComponent.xml
2015-10-02 20:35:52,970 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: Found 1 matching the search criteria.
2015-10-02 20:35:52,970 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:52,970 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:52,971 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:52,974 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:drfGetListOfBackups: filtering out the files by considering:myNewPub
2015-10-02 20:35:52,977 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:52,977 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:52,977 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:52,977 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:52,978 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:52,978 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpLsFiles-: Executing JSCH SFTP ls command for: User: sftpHostName: 10.14.25.2 from source :/cucma/ with pattern _myNewPub
2015-10-02 20:35:52,978 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:52,978 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:53,217 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:53,253 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 14 files found at the given path
2015-10-02 20:35:53,253 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_drfComponent.xml
2015-10-02 20:35:53,253 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:53,253 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_ANN.tar
2015-10-02 20:35:53,253 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_BAT.tar
2015-10-02 20:35:53,253 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_CCMDB.tar
2015-10-02 20:35:53,253 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_CCMPREFS.tar
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_CDPAGT.tar
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_CLM.tar
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_MOH.tar
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_PLATFORM.tar
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_SYSLOGAGT.tar
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_UCM_TCT.tar
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: Found 12 matching the search criteria.
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:53,254 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:53,254 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:drfGetListOfBackups: Adding the backup id after the _pubhostname filtering:2015-09-29-23-00-01
2015-10-02 20:35:53,255 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:53,255 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:53,255 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:53,255 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:53,256 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:53,256 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpLsFiles-: Executing JSCH SFTP ls command for: User: sftpHostName: 10.14.25.2 from source :/cucma/ with pattern _processnode.xml
2015-10-02 20:35:53,256 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:53,256 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:53,496 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:53,515 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 14 files found at the given path
2015-10-02 20:35:53,515 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:53,515 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: Found 1 matching the search criteria.
2015-10-02 20:35:53,515 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:53,515 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:53,515 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:53,519 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:drfGetListOfBackups: The number of the processnode.xml files in the sftp location is1
2015-10-02 20:35:53,519 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:drfGetListOfBackups: copying processnode.xml to /tmp/2015-09-29-23-00-01
2015-10-02 20:35:53,523 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:53,523 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:53,523 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:53,523 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:53,524 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:53,524 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:getFileNameFromBackupId: File to be searched :processnode.xml
2015-10-02 20:35:53,524 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpLsFiles-: Executing JSCH SFTP ls command for: User: sftpHostName: 10.14.25.2 from source :/cucma/ with pattern _processnode.xml
2015-10-02 20:35:53,524 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:53,524 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:53,782 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:53,805 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 14 files found at the given path
2015-10-02 20:35:53,805 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:53,805 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: Found 1 matching the search criteria.
2015-10-02 20:35:53,806 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:53,806 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:53,806 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:53,806 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: Number of files with backup id _processnode.xml format is :1
2015-10-02 20:35:53,806 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: File name with matching pub hostname is : 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:53,806 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: Exact file is found. File is : 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:53,806 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:makeDirectory: Creating directory: /tmp/2015-09-29-23-00-01
2015-10-02 20:35:53,808 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:makeDirectory: Successful in creating directory /tmp/2015-09-29-23-00-01
2015-10-02 20:35:53,808 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:53,808 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:53,809 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:53,809 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:53,809 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:53,809 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpGetFile-: Executing JSCH SFTP get command for: User: sftpHostName: 10.14.25.2 from source :/cucma/2015-09-29-23-00-01_myNewPub_processnode.xml to destination : /tmp/2015-09-29-23-00-01/processnode.xml
2015-10-02 20:35:53,809 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:53,809 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:54,050 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:54,064 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpGetFile: Transferring files from the server: 10.14.25.2 - /cucma/2015-09-29-23-00-01_myNewPub_processnode.xml to /tmp/2015-09-29-23-00-01/processnode.xml
2015-10-02 20:35:54,067 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: STARTING: 1 /cucma/2015-09-29-23-00-01_myNewPub_processnode.xml -> /tmp/2015-09-29-23-00-01/processnode.xml total: 1494
2015-10-02 20:35:54,071 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: ...Progressed data so far1494
2015-10-02 20:35:54,073 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: ...File Transfer Completed
2015-10-02 20:35:54,114 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils.sftpGetFile: Successfully transferred /cucma/2015-09-29-23-00-01_myNewPub_processnode.xml on the Server 10.14.25.2 to /tmp/2015-09-29-23-00-01/processnode.xml
2015-10-02 20:35:54,114 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:54,114 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:54,114 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:54,114 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: processnode.xml file exists
2015-10-02 20:35:54,114 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:54,114 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:54,114 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:54,115 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:54,115 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:54,115 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:54,115 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:54,115 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: Exception caught :java.lang.StringIndexOutOfBoundsException: String index out of range: -6
2015-10-02 20:35:54,115 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:drfGetListOfBackups: deleting processnode.xml from /tmp/2015-09-29-23-00-01
2015-10-02 20:35:54,115 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteFiles: Removing path: /tmp/2015-09-29-23-00-01
2015-10-02 20:35:54,115 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteFiles: Removing path: /tmp/2015-09-29-23-00-01/processnode.xml
2015-10-02 20:35:54,116 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteDir: Successfully deleted file: processnode.xml
2015-10-02 20:35:54,116 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:drfGetListOfBackups: The final backup id which got added to the list is2015-09-29-23-00-01
2015-10-02 20:35:54,116 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: Fetching list of backup ids having processnode.xml
2015-10-02 20:35:54,116 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:54,116 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:54,116 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:54,116 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:54,117 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:54,117 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpLsFiles-: Executing JSCH SFTP ls command for: User: sftpHostName: 10.14.25.2 from source :/cucma/ with pattern _processnode.xml
2015-10-02 20:35:54,117 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:54,117 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:54,349 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:54,370 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 14 files found at the given path
2015-10-02 20:35:54,370 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:54,370 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: Found 1 matching the search criteria.
2015-10-02 20:35:54,370 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:54,370 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:54,370 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:54,373 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:drfRestoreConfig: File to be searched :2015-09-29-23-00-01_drfComponent.xml
2015-10-02 20:35:54,375 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:54,375 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:54,376 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:54,376 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:54,376 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:54,376 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:getFileNameFromBackupId: File to be searched :drfComponent.xml
2015-10-02 20:35:54,376 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpLsFiles-: Executing JSCH SFTP ls command for: User: sftpHostName: 10.14.25.2 from source :/cucma/ with pattern _drfComponent.xml
2015-10-02 20:35:54,376 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:54,376 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:54,624 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:54,647 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 14 files found at the given path
2015-10-02 20:35:54,647 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_drfComponent.xml
2015-10-02 20:35:54,647 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: Found 1 matching the search criteria.
2015-10-02 20:35:54,647 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:54,648 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:54,648 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:54,648 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: Number of files with backup id _drfComponent.xml format is :1
2015-10-02 20:35:54,648 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: File name with matching pub hostname is : 2015-09-29-23-00-01_myNewPub_drfComponent.xml
2015-10-02 20:35:54,648 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: Exact file is found. File is : 2015-09-29-23-00-01_myNewPub_drfComponent.xml
2015-10-02 20:35:54,648 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:makeDirectory: Creating directory: /common/drf/2015-09-29-23-00-01
2015-10-02 20:35:54,648 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:makeDirectory: Successful in creating directory /common/drf/2015-09-29-23-00-01
2015-10-02 20:35:54,648 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:54,649 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:54,649 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:54,649 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:54,650 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:54,650 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpGetFile-: Executing JSCH SFTP get command for: User: sftpHostName: 10.14.25.2 from source :/cucma/2015-09-29-23-00-01_myNewPub_drfComponent.xml to destination : /common/drf/drfComponent.xml
2015-10-02 20:35:54,650 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:54,650 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:54,894 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:54,909 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpGetFile: Transferring files from the server: 10.14.25.2 - /cucma/2015-09-29-23-00-01_myNewPub_drfComponent.xml to /common/drf/drfComponent.xml
2015-10-02 20:35:54,911 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: STARTING: 1 /cucma/2015-09-29-23-00-01_myNewPub_drfComponent.xml -> /common/drf/drfComponent.xml total: 86968
2015-10-02 20:35:54,919 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: ...Progressed data so far32755
2015-10-02 20:35:54,925 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: ...Progressed data so far32755
2015-10-02 20:35:54,926 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: ...Progressed data so far21458
2015-10-02 20:35:54,968 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: ...File Transfer Completed
2015-10-02 20:35:55,010 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils.sftpGetFile: Successfully transferred /cucma/2015-09-29-23-00-01_myNewPub_drfComponent.xml on the Server 10.14.25.2 to /common/drf/drfComponent.xml
2015-10-02 20:35:55,010 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:55,011 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:55,011 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:55,011 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:moveFile: From: /common/drf/drfComponent.xml, To: /common/drf/2015-09-29-23-00-01/drfComponent.xml
2015-10-02 20:35:55,011 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:moveFile: Successfully moved  File/directory /common/drf/drfComponent.xml to /common/drf/2015-09-29-23-00-01/drfComponent.xml
2015-10-02 20:35:55,011 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: drfComponent.xml got copied to /common/drf
2015-10-02 20:35:55,018 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils.fnGetVersion():  the version which is being added to the arraylist:10.5.2.11900-3
2015-10-02 20:35:55,018 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: version list from drfComponent.xml created
2015-10-02 20:35:55,018 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:fnHasSuccessFeature: Checking /common/drf/2015-09-29-23-00-01/drfComponent.xml for failed features.
2015-10-02 20:35:55,023 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:fnHasSuccessFeature: Total number of features : 1
2015-10-02 20:35:55,023 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:fnHasSuccessFeature: Found at least one successful feature.
2015-10-02 20:35:55,023 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: drfComponent.xml has atleast one successful feature:true
2015-10-02 20:35:55,023 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups:  sProcessBackupList is not empty.
2015-10-02 20:35:55,023 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: backup id exists in sProcessBackupList
2015-10-02 20:35:55,023 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: copying processnode.xml to /tmp/2015-09-29-23-00-01
2015-10-02 20:35:55,025 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:55,025 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:55,025 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:55,025 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:55,026 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:55,026 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpManager:getFileNameFromBackupId: File to be searched :processnode.xml
2015-10-02 20:35:55,026 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpLsFiles-: Executing JSCH SFTP ls command for: User: sftpHostName: 10.14.25.2 from source :/cucma/ with pattern _processnode.xml
2015-10-02 20:35:55,026 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:55,026 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:55,276 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 14 files found at the given path
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfutils.sftpLsFiles-: Found 1 matching the search criteria.
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: Number of files with backup id _processnode.xml format is :1
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: File name with matching pub hostname is : 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:55,299 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - getFileNameFromBackupId: Exact file is found. File is : 2015-09-29-23-00-01_myNewPub_processnode.xml
2015-10-02 20:35:55,299 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:makeDirectory: Creating directory: /tmp/2015-09-29-23-00-01
2015-10-02 20:35:55,300 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:makeDirectory: Successful in creating directory /tmp/2015-09-29-23-00-01
2015-10-02 20:35:55,300 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Entering decryptPassword
2015-10-02 20:35:55,300 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Use Dkey to decrypt data
2015-10-02 20:35:55,301 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - CCMENC::ERROR : Dkey decryption failed. Use recovery mechanism to decrypt data.
2015-10-02 20:35:55,301 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - Using static key to decrypt data
2015-10-02 20:35:55,301 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - decryptPassword was successful
2015-10-02 20:35:55,301 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpGetFile-: Executing JSCH SFTP get command for: User: sftpHostName: 10.14.25.2 from source :/cucma/2015-09-29-23-00-01_myNewPub_processnode.xml to destination : /tmp/2015-09-29-23-00-01/processnode.xml
2015-10-02 20:35:55,301 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Trying to connect to the SFTP server.
2015-10-02 20:35:55,301 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Connecting SFTP server...
2015-10-02 20:35:55,566 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:establishSftpConnection: Authenctication Completed Successfully, connected to remote server. Now opening a SFTP channel.
2015-10-02 20:35:55,581 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:sftpGetFile: Transferring files from the server: 10.14.25.2 - /cucma/2015-09-29-23-00-01_myNewPub_processnode.xml to /tmp/2015-09-29-23-00-01/processnode.xml
2015-10-02 20:35:55,583 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: STARTING: 1 /cucma/2015-09-29-23-00-01_myNewPub_processnode.xml -> /tmp/2015-09-29-23-00-01/processnode.xml total: 1494
2015-10-02 20:35:55,587 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: ...Progressed data so far1494
2015-10-02 20:35:55,588 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfSftpProgressMonitor:: ...File Transfer Completed
2015-10-02 20:35:55,630 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils.sftpGetFile: Successfully transferred /cucma/2015-09-29-23-00-01_myNewPub_processnode.xml on the Server 10.14.25.2 to /tmp/2015-09-29-23-00-01/processnode.xml
2015-10-02 20:35:55,630 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing ChannelSftp...
2015-10-02 20:35:55,630 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Disconnecting Channel...
2015-10-02 20:35:55,630 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:closeSFTPConnections: Closing Session...
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: Reading processnode.xml file from /tmp/2015-09-29-23-00-01
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: processnode.xml file exists
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: saving role and hostname tag value in a map.
2015-10-02 20:35:55,631 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:ReadProcessNodeFile: Exception caught :java.lang.StringIndexOutOfBoundsException: String index out of range: -6
2015-10-02 20:35:55,632 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: Calling getClusterProductInfo method
2015-10-02 20:35:55,632 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): servers_VersionInfo is empty
2015-10-02 20:35:55,632 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): sRoleHostNameInfo is not null
2015-10-02 20:35:55,632 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): saving productId as callmanager
2015-10-02 20:35:55,632 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): Running the command: sudo -u root /usr/local/bin/base_scripts/icluster_impl getPeerDeploymentVersion 10.37.245.71
2015-10-02 20:38:02,355 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): the command output is:
2015-10-02 20:38:02,355 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): getPeerDeploymentVersion API could not return version info.
2015-10-02 20:38:02,355 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils.getCCMVersion(): Returning: 10.5.2.11900-3
2015-10-02 20:38:02,355 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): First node version and productId saved to hashmap: callmanager 10.5.2.11900-3
2015-10-02 20:38:02,355 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): saving productId as callmanager
2015-10-02 20:38:02,355 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): saving productId as callmanager
2015-10-02 20:38:02,356 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): saving productId as callmanager
2015-10-02 20:38:02,356 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): saving productId as callmanager
2015-10-02 20:38:02,356 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): saving productId as callmanager
2015-10-02 20:38:02,356 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:getClusterProductInfo(): saving productId as callmanager
2015-10-02 20:38:02,356 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: version is present in hashmap.
2015-10-02 20:38:02,356 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: Fetching HostName from drfComponent.xml of backed up files)
2015-10-02 20:38:02,356 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:xmlProcess:: Checking Metadata file from the path :/common/drf/2015-09-29-23-00-01/drfComponent.xml
2015-10-02 20:38:02,356 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:xmlProcess: File exists.
2015-10-02 20:38:02,360 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:processxml:: List has been created
2015-10-02 20:38:02,360 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: Fetching HostName from drfComponent.xml of cluster
2015-10-02 20:38:02,360 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:xmlProcess:: Checking Metadata file from the path :/usr/local/platform/conf/drfComponent.xml
2015-10-02 20:38:02,360 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:xmlProcess: File exists.
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:processxml:: List has been created
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: HostName fetched
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:compareHost:: Number of servers present in backedup drfComponent.xml are 7 & in metadatafile file are 1
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:compareHost:: Host lists are  Matching
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: version count is equal. Incrementing the tar file list.
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: Added in TarFilelist2015-09-29-23-00-01
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: Removing all /tmp/<backupId> files
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteFiles: Removing path: /tmp/2015-09-29-23-00-01
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteFiles: Removing path: /tmp/2015-09-29-23-00-01/processnode.xml
2015-10-02 20:38:02,362 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteDir: Successfully deleted file: processnode.xml
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteFiles: Removing path: /common/drf/2015-09-29-23-00-01
2015-10-02 20:38:02,362 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteFiles: Removing path: /common/drf/2015-09-29-23-00-01/drfComponent.xml
2015-10-02 20:38:02,362 INFO [drfMasterAgentMsgWorker, MessageID: 2400] - drfUtils:deleteDir: Successfully deleted file: drfComponent.xml
2015-10-02 20:38:02,363 DEBUG [drfMasterAgentMsgWorker, MessageID: 2400] - drfMasterAgentMsgWorker:HandleListBackups: [List backup] response sent

[Clifford McGlamry]

Tomcat logs don't show anything helpful....

[Clifford McGlamry]

Did a full rebuild on the new server and created a new image.  Same problem....

Looked at the bug toolkit, but cannot find any related issues around this problem.

Guess it's time to call TAC...

[Clifford McGlamry · Accepted solution]

TAC was able to resolve this.  Here is the solution:

1.  My new publisher was a single server (i.e. it wasn't part of a cluster yet), and was not aware of any other subscribers.

2.  TAC had me remove all the files from the SFTP store EXCEPT for the drfComponent file and the files specific to the publisher. 

3.  once the above was completed, I was able to start the restore and proceed with no problems.

I think it likely there is a defect involved here, but that has not yet been confirmed by TAC.  If it is confirmed, I'll post that info here as well. 

[Clifford McGlamry]

So, here's the bug:

https://tools.cisco.com/bugsearch/bug/CSCus28201

Essentially, the problem is that earlier DRF backups did not have the processnode.xml file, so if it sees those backups and it's attempting to restore to a full cluster, it confuses the DRF system.

But if you have a single server that is NOT YET CLUSTER AWARE, or does not have ALL the subscribers installed and reachable, it will also fail.

For the single server recovery issue we are addressing in this thread, simply remove the processnode.xml files from the SFTP store *should* solve the problem. 

I'm going to test this theory in my lab, and will report back the results. 

[Clifford McGlamry]

In my lab, I took the backup from a 7 node cluster (Pub and 6 Subs), and attempted to restore it onto a newly built publisher that had no subscribers attached.  The restore attempt failed while attempting to retrieve the available backups.

I removed ONLY the processnode.xml file associated with the backup and attempted the restore attempt again.

With the processnode.xml file removed from the backup directory, the server was able to retrieve the available backups, and provide a list of available backups to chose to restore.  The fact that there are a large number of other files in the backup target directory (i.e. for the other subscribers) had zero impact.

I'm not sure what would happen if I attempted to use the single step restore process that makes the publisher aware and then restores everything (and I don't have the time to build this out just to test that), but at least this allows for a publisher restore when dealing with the single server. 

I'm also unclear what this processnode.xml file is really for (it wasn't there in earlier versions), and if it is really required or not.  Maybe someone from Cisco can weigh in on that. 

[Aman Soi]

[+5] for sharing the results.

regds,

aman

[Jaime Valencia]

Is the other CUCM that does show the TAR, the same version as the one that doesn't??