@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Machine : spiderman File : CVD.log @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4396 66c 09/16 13:57:00 2391 ArMgrCS::getPipelineInfo Input: appId [6] archGroupId [106] copyId [110] jobType [5] dataType [1] backupLevel [0] archiveFileId [4236] commCellId [2] 4396 66c 09/16 13:57:00 2391 ArMgrCS::getPipelineInfo BackupRestoreParams: archGroupId [106] copyId [110] 4396 66c 09/16 13:57:00 2391 ArMgrCS::getPipelineInfo archGroupId[106] copyId[110] signatureScheme[0] signatureModuleWhere[0] singleInstMinObjSizeKB[0] singleInstanceLevel [0] SIBlockSizeKB [128] isClientSideDedupEnabled[0] clientSideCacheDBSizeMB[0] clientSideCacheBufferSizeKB[0] isVSAEnabled[0]numNWAgents[2] compressWhere[0] writeSpeed[0] chunkSizeMB[4096] jobUpdateInterval[300] encryptionType[0] rsaKeysPresent[0] 4396 66c 09/16 13:57:00 #### ArMgrCS::getRestoreMediaAgent(): The first volume id needed for archive file[4236] is 17 4396 66c 09/16 13:57:00 2391 MOUNT [17] DATAPATH SELECTED = , DRIVEPOOL <2> LIBRARY 4396 66c 09/16 13:57:00 2391 ArMgrCS::getPipelineInfo Get parameters for RESTORE to destination client [spiderman]: Library [2] MediaGroup [1160] MediaAgent [spiderman.hrt.hr] HWcompress [78] SIDBForceSingleTagBuffer[0] isCVSingleInstanceTarget[0] useSimpleDataTransfer[0] 4396 66c 09/16 13:57:00 2391 ArchiveManagerCS::logOpenArchiveFileEvent() - EnableRestoreDataAgeTracking event is not enabled. 4396 66c 09/16 13:57:00 2391 ArMgrCS::getPipelineInfo Source Interface [spiderman.hrt.hr] Destination Interface [spiderman.hrt.hr] pipelineSrcClientName {spiderman] pipelineDestClientName [spiderman] pipelineSrcCvdPort [8400] pipelineSrcEvmgrCPort [8402] pipelineDestCvdPort [8400] pipelineDestEvmgrCPort [8402] 4396 1588 09/16 13:57:00 2391 [FSRESTHEAD ] Did not find regkey FillMediaOffset 4396 1588 09/16 13:57:00 2391 [FSRESTHEAD ] Going to set up socket connectivity with the tail. 4396 2554 09/16 13:57:00 2391 CArchFileKeys::Init() - Max archive file key map size set to 25 4396 1588 09/16 13:57:00 2391 [FSRESTHEAD ] plutil.cpp:getTailSockFD Bind succeeded. port numbers are 65366 0 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] head sending init buffer 24110000 Head = spiderman(spiderman.hrt.hr) Tail = spiderman(spiderman.hrt.hr) port_v4 = 65366 port_v6 = 0 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] After accept: tail Sock = 5632 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::initialize]: Unique Restore Head Name = FSR_HEAD_5512 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Ctrl Msg Sending type=0x90 - Shall flush BUFFER=0x0000000000000000 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Sent buffer type [90] to the tail 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] Using Accept timeout as 120 4396 1588 09/16 13:57:01 #### [DM_READER ] DATAREADER Constructor Invoked ... 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::initialize]: msgProcessor thread started. 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] nFsRestoreHeadCountersLogInterval is set to [300] seconds 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] Pipeline Restore Head started 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] Entered [FsRestoreHead::acceptSession] 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::acceptSession]: session accepted. 4396 1588 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::clListener]: Entered. 4396 2eb0 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: Processing FSR_MSG_SET_OPTIONS 4396 2eb0 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::HandleSetOptionsMsg]: Processing FSR_MSG_SET_OPTION 4396 2eb0 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::HandleSetOptionsMsg]: Enabling Flush Buffer After Seek 4396 2eb0 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: Processing FSR_SEQNUM_INIT 4396 2eb0 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::HandleSequenceInitMsg]: Processing FSR_SEQNUM_INIT message 4396 2eb0 09/16 13:57:01 #### [DM_READER ] Sequence Number is 4436701240229 4396 2eb0 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: Processing FSR_MSG_OPEN_ARCHIVE 4396 2eb0 09/16 13:57:01 2391 [FSRESTHEAD ] [FsRestoreHead::HandleOpenArchiveFile]: Processing FSR_MSG_OPEN_ARCHIVE 4396 2eb0 09/16 13:57:01 2391 1-# [DM_READER ] DataReader::Open: Opening ARCHIVE FILE ID [4236], COPY ID[110] CommCellId[2], StoragePolicyId[106] 4396 2eb0 09/16 13:57:02 2391 ArMgrDS::getAfileInfo Returns afcFlags [32] encType [0] encKeyLen [0] needPassPhrase [0] drToolAccess [0] dataMoverType [1] 4396 2eb0 09/16 13:57:02 2391 1-# [DM_BASE ] Chunk response caching is enabled. 4396 2eb0 09/16 13:57:02 2391 1-# [DM_BASE ] Initialising DataMoverBase for MediaGroupId = 0 ... 4396 2eb0 09/16 13:57:02 2391 1-# [DM_BASE ] Disabling CRC32 checking on the media. Host attributes [37] 4396 2eb0 09/16 13:57:02 2391 1-# [DM_BASE ] Disabling CRC32 checking on the network. Host attributes [37] 4396 2eb0 09/16 13:57:02 2391 1-# [DM_BASE ] Maximum Mount retry value during read is 0 4396 2eb0 09/16 13:57:02 2391 1-# [DM_BASE ] DataMoverMaxMountRetryValue [0] DataMoverMaxMountRetrySleepTime [0] DataMoverMaxReadRetryValue [0] DataMoverWaitTimeBeforeChunkCloseInSec [0] DataMoverCloseChunkImmediately [0] 4396 2eb0 09/16 13:57:02 2391 1-# [DM_BASE ] DataMoverMonitorThreadRetryValue [5], DataMoverMonitorThreadSleepValueMins[10] 4396 2eb0 09/16 13:57:02 2391 1-# [DM_BASE ] DMEnableDirectSeek registry key is set to true 4396 2eb0 09/16 13:57:03 2391 1-# [DM_BASE ] Resetting the current chunk and setting the chunk id to zero 4396 2eb0 09/16 13:57:03 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Ctrl Msg Sending type=0x9C - Shall flush BUFFER=0x0000000000000000 4396 2eb0 09/16 13:57:03 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Sent buffer type [9c] to the tail 4396 2eb0 09/16 13:57:03 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Ctrl Msg Sending type=0x121 - Shall flush BUFFER=0x0000000000000000 4396 2eb0 09/16 13:57:03 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Sent buffer type [121] to the tail 4396 2eb0 09/16 13:57:35 2391 1-# [DM_BASE ] Added chunk [] to cache. 4396 2eb0 09/16 13:57:35 #### [DM_CHUNK ] Got new Chunk Info. ChunkId [10214], CommcellId [2], CopyId[110], VolumeId [17], FileNumber [1574], NumberOfArchFiles [1] 4396 2eb0 09/16 13:57:35 #### [DM_CHUNK ] New Chunk Info: archiveFileId [4236], PhysicalSizeInCurrChunk [4293912480], LogicalSizeInCurrChunk [4280221824], PhysicalStartOffset [0], LogicalStartOffset [0] 4396 2eb0 09/16 13:57:35 2391 1-# [DM_BASE ] Loading the VolId=17 hostname=spiderman.hrt.hr 4396 2eb0 09/16 13:57:36 2391 1-# [DM_BASE ] **ERROR** reserveMountVol Failed VolumeId = 17 MA - spiderman.hrt.hrMediaManager returned error [803], errorString [The media is already reserved by some other job[s].] 4396 2eb0 09/16 13:57:36 2391 1-# [DM_BASE ] Going to check whether the mount should be retried for the above mediamanager error 4396 2eb0 09/16 13:57:36 2391 1-# [DM_BASE ] The mount will be retried for the MediaManager error [803] after sleeping for [120] seconds. 4396 2eb0 09/16 13:57:36 2391 1-# [DM_BASE ] Setting the Job Id to the mounting job 4396 2eb0 09/16 13:57:36 2391 1-# [DM_BASE ] Setting the job state to waiting 4396 2eb0 09/16 13:59:36 2391 1-# [DM_BASE ] Setting the Job Id to the mounting job 4396 2eb0 09/16 13:59:36 2391 1-# [DM_BASE ] Setting the job state to running 4396 2eb0 09/16 13:59:36 2391 1-# [DM_BASE ] Going to retry the Restore Mount. 4396 2eb0 09/16 13:59:36 2391 1-3145 [DM_BASE ] Succesfully mounted Volume 17 for Reading. Reservation id [3145] 4396 2eb0 09/16 13:59:36 2391 1-3145 [MEDIAFS ] mediatype [2004], mountpath [\\.\Tape2] 4396 2eb0 09/16 13:59:36 2391 1-3145 [MEDIAFS ] The volume will be recorded with the block size [64] KB 4396 2eb0 09/16 13:59:36 2391 1-3145 [MEDIAFS ] The option to mark the drives as cleaning when CRC errors has NOT been selected 4396 2eb0 09/16 13:59:36 2391 1-3145 [MEDIAFS ] Serial number HUJ5233W99 for drive, access path- \\.\Tape2 Matched succesfully. 4396 2eb0 09/16 13:59:36 2391 1-3145 [MEDIAFS ] Succesfully completed SCSI2 reservations for drive accespath \\.\Tape2. 4396 2eb0 09/16 13:59:36 #### [DM_MONITOR ] Going to start monitoring thread. Check period set to [10] minutes 4396 2eb0 09/16 13:59:36 2391 1-3145 [DM_BASE ] Registered RID [3145] with the monitoring thread. 4396 2eb0 09/16 13:59:36 2391 1-3145 [DM_BASE ] Opening the Chunk =10214, ArchFileId = 4236, FileMarker=1574, ArchFilePhysSizeInChunk=4293912480 VolId=17 4396 2eb0 09/16 13:59:36 2391 1-3145 [MEDIAFS ] Trying to go forward by one filemarker. Read Cached filemarker [2238] 4396 2eb0 09/16 13:59:48 2391 1-3145 [MEDIAFS ] Successfully fowarded to the next filemarker.. Now going to read the chunkmap trailer from this location on the tape 4396 2eb0 09/16 13:59:48 2391 1-3145 [MEDIAFS ] Setting the block size for the volume 17 to [65536] 4396 2eb0 09/16 13:59:48 2391 1-3145 [MEDIAFS ] Succesfully validated filemark and media using Chunk map. Currently the tape is postioned after the filemarker [2238] 4396 2eb0 09/16 13:59:48 2391 1-3145 [MEDIAFS ] Successfully validated the filemarker position on the media.. continuing to position to the required filemarker 4396 2eb0 09/16 13:59:48 2391 1-3145 [MEDIAFS ] Moving back by 666 on the Tape volId=17 4396 2eb0 09/16 14:00:43 2391 1-3145 [MEDIAFS ] Ready to read from tape volId=17 4396 2eb0 09/16 14:00:44 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: Processing FSR_MSG_READ_ALL 4396 2eb0 09/16 14:00:44 2391 [FSRESTHEAD ] [FsRestoreHead::HandleReadAllMsg]: Processing FSR_MSG_READ_ALL 4396 1588 09/16 14:00:45 2391 [FSRESTHEAD ] [FsRestoreHead::clListener]: Received FSR_MSG_ABORT_READ_ALL 4396 2eb0 09/16 14:00:45 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: received FSR_MSG_ABORT_READ_ALL from FclRestore object 4396 2eb0 09/16 14:00:45 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Ctrl Msg Sending type=0x94 - Shall flush BUFFER=0x0000000000000000 4396 2eb0 09/16 14:00:45 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Sent buffer type [94] to the tail 4396 2eb0 09/16 14:00:45 2391 1-3145 [DM_BASE ] Added chunk [] to cache. 4396 2eb0 09/16 14:00:45 #### [DM_CHUNK ] Got new Chunk Info. ChunkId [10546], CommcellId [2], CopyId[110], VolumeId [17], FileNumber [2238], NumberOfArchFiles [1] 4396 2eb0 09/16 14:00:45 #### [DM_CHUNK ] New Chunk Info: archiveFileId [4236], PhysicalSizeInCurrChunk [4293892128], LogicalSizeInCurrChunk [4280202240], PhysicalStartOffset [1425574119680], LogicalStartOffset [1421029515392] 4396 2eb0 09/16 14:00:45 2391 1-3145 [DM_BASE ] Opening the Chunk =10546, ArchFileId = 4236, FileMarker=2238, ArchFilePhysSizeInChunk=4293892128 VolId=17 4396 2eb0 09/16 14:00:45 2391 1-3145 [MEDIAFS ] Forwarding by fileMarker=664 on the Tape volId=17 4396 2eb0 09/16 14:01:50 2391 1-3145 [MEDIAFS ] Ready to read from tape volId=17 4396 2eb0 09/16 14:01:50 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: Processing FSR_MSG_READ_ALL 4396 2eb0 09/16 14:01:50 2391 [FSRESTHEAD ] [FsRestoreHead::HandleReadAllMsg]: Processing FSR_MSG_READ_ALL 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::clListener]: Received FSR_MSG_ABORT_READ_ALL 4396 2eb0 09/16 14:03:28 2391 stat- ID [FsRestoreHead Allocate Buffer Time], Job Id [2391], Samples [50389], Time [93.796575] Sec(s), Average [0.001861] Sec/Sample 4396 2eb0 09/16 14:03:28 2391 stat- ID [FsRestoreHead Media Read Speed], Job Id [2391], Bytes [1516663904], Time [5.776432] Sec(s), Average Speed [250.397385] MB/Sec 4396 2eb0 09/16 14:03:28 2391 stat- ID [FsRestoreHead Read From Media Time], Job Id [2391], Samples [50389], Time [5.826625] Sec(s), Average [0.000116] Sec/Sample 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: received FSR_MSG_ABORT_READ_ALL from FclRestore object 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Ctrl Msg Sending type=0x94 - Shall flush BUFFER=0x0000000000000000 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Sent buffer type [94] to the tail 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: Processing FSR_MSG_CLOSE_ARCHIVE 4396 2eb0 09/16 14:03:28 2391 1-# [DM_READER ] DataReader::Close: Closing the ARCHIVE FILE [4236] COPY [110] 4396 2eb0 09/16 14:03:28 2391 1-3145 [DM_BASE ] Going to close chunk for archive File [4236] The current size of the chunk is [4293892128 ] 4396 2eb0 09/16 14:03:28 2391 1-3145 [DM_BASE ] Resurrecting the Datamover for MediaGroupId = 0 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Ctrl Msg Sending type=0x84 - Shall flush BUFFER=0x0000000000000000 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Sent buffer type [84] to the tail 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: received FSR_MSG_DESTROY from FclRestore object 4396 2eb0 09/16 14:03:28 2391 1-3145 [DM_BASE ] Going to unregister from the monitoring thread as the datawriter is going down 4396 2eb0 09/16 14:03:28 #### [DM_MONITOR ] Going to ask reservation monitoring thread to beat it. 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::clListener]: Received CVS_PM_DISCONNECT_REQ 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::clListener]: Exited 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] Entered [FsRestoreHead::acceptSession] 4396 2eb0 09/16 14:03:28 2391 1-3145 [DM_BASE ] Successfully unregistered from the monitoring thread 4396 2eb0 09/16 14:03:28 2391 1-3145 [MEDIAFS ] Closing and deleting the SCSITapeDrive object 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Ctrl Msg Sending type=0x90 - Shall flush BUFFER=0x0000000000000000 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Sent buffer type [90] to the tail 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::acceptSession]: clListener has already exited.. 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [::fsRestoreHead]: error from acceptSession 4396 1588 09/16 14:03:28 #### [CVD ] Sending STOP_PL with plid = spiderman.hrt.hr_1442404620_11600_7416 (FsRestoreHead exiting gracefully) 4396 1588 09/16 14:03:28 #### [CVD ] Setting Control message event for [spiderman.hrt.hr_1442404620_11600_7416] 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [::fsRestoreHead]: Waiting for message processor to exit 4396 2eb0 09/16 14:03:28 2391 1-3145 [DM_BASE ] Releasing the volume and drive reservation on the media manager 4396 2eb0 09/16 14:03:28 2391 1-# [DM_BASE ] Destroyed DataMoverBase for MediaGroupId=[0] 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Ctrl Msg Sending type=0x85 - Shall flush BUFFER=0x0000000000000000 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::sendCtrlBuffer]: Sent buffer type [85] to the tail 4396 2eb0 09/16 14:03:28 2391 [FSRESTHEAD ] [FsRestoreHead::msgProcessor]: Request _clListenerThread termination. 4396 1588 09/16 14:03:28 2391 [FSRESTHEAD ] [::fsRestoreHead]: Message processor has exited gracefully 4396 1588 09/16 14:03:28 2391 stat- ID [FsRestoreHead Read From Media Time], Job Id [2391], Samples [50389], Time [5.826625] Sec(s), Average [0.000116] Sec/Sample 4396 1588 09/16 14:03:28 2391 stat- ID [FsRestoreHead Allocate Buffer Time], Job Id [2391], Samples [50389], Time [93.796575] Sec(s), Average [0.001861] Sec/Sample 4396 1588 09/16 14:03:28 2391 stat- ID [FsRestoreHead Media Read Speed], Job Id [2391], Bytes [1516664928], Time [5.776724] Sec(s), Average Speed [250.384871] MB/Sec 4396 2554 09/16 14:03:33 #### [CVD ] STOP_PL Control Message Received 1 (FsRestoreHead exiting gracefully) 4396 2554 09/16 14:03:33 2391 [DECRYPT ] Received STOP_PL while receiving a buffer 4396 23c0 09/16 14:03:33 2391 [UNCOMPRESS ] Received STOP_PL while receiving a buffer @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Machine : spiderman File : CVNdmpRemoteServer.log @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 11600 1cf8 09/16 13:56:55 2391 main() - ============================================ 11600 1cf8 09/16 13:56:55 2391 main() - ----------------- STARTED ----------------- 11600 1cf8 09/16 13:56:55 2391 main() - ============================================ 11600 1cf8 09/16 13:56:55 2391 main() - CVNdmpRemoteServer.exe -l ndmp -p 39b87acfec63e189d0906fb4cabcb115b06a64ae3ac14aa86 -j 2391 -cn spiderman -RstDestClientId 1005 -cn spiderman cvshost:spiderman.hrt.hr*spiderman cvsport:65346:0 cvsmyplatform:2 cvsremoteplatform:2 -vm Instance001 11600 1cf8 09/16 13:56:55 2391 Init() - Initializing job control [token=,cn=spiderman], serverName [spiderman.hrt.hr], ControlFlag [4], Job Id [2391] 11600 1cf8 09/16 13:56:56 2391 Cvcl::init() - CVCL: Running in FIPS Mode 11600 1cf8 09/16 13:56:56 2391 CVJobCtrlLog::registerProcess(): successfully created file [C:\Program Files\NetApp\SnapProtect\Base\JobControl\11.600] 11600 1cf8 09/16 13:56:56 2391 CompleteStartup() - Process was created using IPv4. 11600 1cf8 09/16 13:56:56 2391 CompleteStartup() - Going to listen on host:[spiderman.hrt.hr]. Listening on all IPv4 interfaces. 11600 1cf8 09/16 13:56:56 2391 CompleteStartup() - Going to listen on socket [580] port [65351]. 11600 1cf8 09/16 13:56:56 2391 CompleteStartup() - Send to NAS iDA NDMP port [65351] binded to socket 11600 1cf8 09/16 13:56:56 2391 ** CVSession::disconnect (void) 11600 1cf8 09/16 13:56:56 2391 ndmp.cpp 3513 NOTIFY_CONNECTED: protocol_version[4] 11600 1cf8 09/16 13:56:56 2391 ndmp.cpp 3521 NOTIFY_CONNECTED: successful 11600 1cf8 09/16 13:56:56 2391 ndmp.cpp 3480 NDMP_CONNECT_OPEN reply 11600 1cf8 09/16 13:56:56 2391 ndmp.cpp 3491 NDMP_CONNECT_OPEN reply: successful 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4300 NDMP_CONFIG_GET_SERVER_INFO reply: Vendor[CommVault Systems] Product[Galaxy] Revision[10.0.0(BUILD116)] Auth:[2] 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4329 NDMP_CONFIG_GET_SERVER_INFO reply: successful 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4073 NDMP_CONFIG_GET_AUTH_ATTR reply: Error[0] AuthType[2] 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4095 NDMP_CONFIG_GET_AUTH_ATTR reply: successful 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4157 NDMP_CONNECT_CLIENT_AUTH reply: Error[0] 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4177 NDMP_CONNECT_CLIENT_AUTH reply: successful 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4054 AUTHENTICATION successful 11600 1cf8 09/16 13:56:56 2391 >: Logger: Set Debug Level 1 (Normal) 11600 1cf8 09/16 13:56:56 2391 >: Registering callbacks for NRS 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4352 NDMP_CONFIG_GET_HOST_INFO reply: Host[spiderman.hrt.hr] OsType[Windows Server x64] Version[6.2Build 9200: ] ID:[A01503A] 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4378 NDMP_CONFIG_GET_HOST_INFO reply: successful 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4300 NDMP_CONFIG_GET_SERVER_INFO reply: Vendor[CommVault Systems] Product[Galaxy] Revision[10.0.0(BUILD116)] Auth:[2] 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4329 NDMP_CONFIG_GET_SERVER_INFO reply: successful 11600 1cf8 09/16 13:56:56 2391 ************ GET_EXTENSION_LIST ************ 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4231 NDMP_CONFIG_GET_EXT_LIST reply 11600 1cf8 09/16 13:56:56 2391 ndmp_v4.cpp 4276 NDMP_CONFIG_GET_EXT_LIST reply: successful 11600 1cf8 09/16 13:56:56 2391 ************ GET_EXTENSION_LIST[0] ************ 11600 1cf8 09/16 13:56:57 2391 >: ************ TAPE OPEN ************ 11600 1cf8 09/16 13:56:57 2391 CVArchive::Construct() - Constructing CVArchive Object 11600 1cf8 09/16 13:56:58 2391 CVArchive::Construct() - Enable CVArchive Big Buffer [true] 11600 1cf8 09/16 13:56:58 2391 >: MediaAdapter: OPEN ARCHIVE WITH PARAMETERS: 11600 1cf8 09/16 13:56:58 2391 >: Level[0] JobId[2391] AfileId[4236] AgroupId[106] MediaGroupId[0] Stream[1] CopyId[0] CommCell[2] ClientId[3] SubClientId[6] Appid[6] AppType[13] SeqNum[4436701240229] DestRcid[0] SrcCopyId[0] 11600 1cf8 09/16 13:56:58 2391 >: Set CvArchive option FLUSH_BUFFER_AFTER_SEEK for restore 11600 1cf8 09/16 13:56:58 2391 >: MediaAdapter::Open opening archive... 11600 1cf8 09/16 13:56:58 2391 CVArchive::SetupPipeline() - Enter setupPipeline 11600 1cf8 09/16 13:56:58 2391 CVArchive::LookupPipelineInfo() - Enter LookupPipelineInfo 11600 1cf8 09/16 13:56:59 2391 CVArchive::LookupPipelineInfo() - Successfully translated archFileId 4236 (commCellId 2) to client name "hrtcluster.hrt.hr" 11600 1cf8 09/16 13:57:00 2391 isCVSingleInstanceTarget[0] singleInstanceLevel[0] signatureModuleWhere[0] signatureScheme[0] singleInstMinObjSizeKB[0] compressWhere[0] encryptionType[0] rsaKeysPresent[0] 11600 1cf8 09/16 13:57:00 2391 Network agents configured before firewall check = 2 11600 1cf8 09/16 13:57:00 2391 Network agents configured after firewall check = 2 11600 1cf8 09/16 13:57:00 2391 CVArchive::StartPipeline() - StartPipeline SI configuration -[srcClientName - spiderman] Block Level [false], Block Size [128], File Level [false], Min Signature Size [0] 11600 1cf8 09/16 13:57:00 2391 CVArchive::StartPipeline() - Starting pipeline 11600 1cf8 09/16 13:57:00 2391 CPipelayer::InitiatePipeline() - Initiating Pipeline [5e8f1d0] from spiderman.hrt.hr:8400(spiderman) to spiderman.hrt.hr:8400(spiderman) 11600 1cf8 09/16 13:57:00 2391 [PIPELAYER ] PipeLine will Not be Extended 11600 1cf8 09/16 13:57:00 2391 [PIPELAYER ] Waiting for pipeline [spiderman.hrt.hr_1442404620_11600_7416] to initialize 11600 1cf8 09/16 13:57:00 2391 [PIPELAYER ] Completed waiting for pipeline [spiderman.hrt.hr_1442404620_11600_7416]. 11600 1cf8 09/16 13:57:00 2391 [PIPELAYER ] Got Fill Ident response on 896 11600 1cf8 09/16 13:57:00 2391 [PIPELAYER ] Calling InitIpc, path = spiderman.hrt.hr_1442404620_11600_7416_Instance001 11600 1cf8 09/16 13:57:00 2391 [CVD ] initIpc: Called path = spiderman.hrt.hr_1442404620_11600_7416_Instance001 ipcptr = 5e8f248 NumNWAgents = 2 NumModules =4 PosId =3 11600 1cf8 09/16 13:57:00 2391 [CVD ] initIpc: MapViewOfFile () err 5, size 2360352 11600 1cf8 09/16 13:57:00 2391 [CVD ] Retrying with corrected size as 2229280 11600 1cf8 09/16 13:57:01 2391 [PIPELAYER ] Received ReGPqptr response: reply = 0 11600 1cf8 09/16 13:57:01 2391 CPipelayer::AttachPipeline() - Keep Alive Messages will be sent every 30 minutes 11600 1cf8 09/16 13:57:01 2391 [PIPELAYER ] getHeadSockFd(): Going to wait for init buffer from head. 11600 1cf8 09/16 13:57:01 2391 [CVD ] Auto Starting CVDAliveChecking 11600 1cf8 09/16 13:57:01 2391 [CVD ] Starting CVDAliveChecking 11600 1cf8 09/16 13:57:01 2391 [PIPELAYER ] getHeadSockFd(): Received init buffer from head. 11600 1cf8 09/16 13:57:01 2391 [PIPELAYER ] Connecting to Head on spiderman(spiderman.hrt.hr):65366/0 11600 2c24 09/16 13:57:01 2391 [CVD ] CVDAliveChecking Thread Started 11600 1cf8 09/16 13:57:01 2391 Received Head Name: FSR_HEAD_5512 with ports [65368/0] 11600 1cf8 09/16 13:57:01 2391 Initializing a session with pipeline head [FSR_HEAD_5512:65368:0] on [spiderman.hrt.hr]... 11600 1cf8 09/16 13:57:01 2391 CVArchive::OpenArchiveFile() - Sending OpenArchive message to FSRestoreHead 11600 1cf8 09/16 13:57:01 2391 Invalid input client name. Use physical machine name. 11600 1cf8 09/16 13:57:02 2391 ArMgrDS::getAfileInfo Returns afcFlags [32] encType [0] encKeyLen [0] needPassPhrase [0] drToolAccess [0] dataMoverType [1] 11600 1cf8 09/16 13:57:02 2391 >: Compression setting is:[OFF] Dedup:[OFF] for archive file [4236] and copy id [110]. 11600 1cf8 09/16 13:57:03 2391 >: ** PIPELINE SETUP, ARCHIVE CREATION COMPLETED: 11600 1cf8 09/16 13:57:03 2391 Invalid input client name. Use physical machine name. 11600 1cf8 09/16 13:57:04 2391 ArMgrDS::getAfileInfo Returns afcFlags [32] encType [0] encKeyLen [0] needPassPhrase [0] drToolAccess [0] dataMoverType [1] 11600 1cf8 09/16 13:57:04 2391 >: Compression setting is:[OFF] Dedup:[OFF] for archive file [4236] and copy id [110]. 11600 1cf8 09/16 13:57:05 2391 ndmp_v4.cpp 5281 NDMP_TAPE_OPEN reply: Error[0] 11600 1cf8 09/16 13:57:05 2391 ndmp_v4.cpp 5301 NDMP_TAPE_OPEN reply: successful 11600 1cf8 09/16 13:57:05 2391 >: ************ TAPE OPEN[0] ************ 11600 1cf8 09/16 13:57:05 2391 >: ************ MOVER_SET_WINDOW ************ 11600 1cf8 09/16 13:57:05 2391 >: SetWindow Offset: 0 Length: 1557968040960 11600 1cf8 09/16 13:57:05 2391 ndmp_v4.cpp 5542 NDMP_MOVER_SET_WINDOW reply: Error[0] 11600 1cf8 09/16 13:57:05 2391 ndmp_v4.cpp 5562 NDMP_MOVER_SET_WINDOW reply: successful 11600 1cf8 09/16 13:57:05 2391 >: ************ MOVER_SET_WINDOW[0] ************ 11600 1cf8 09/16 13:57:05 2391 >: ************ MOVER LISTEN ************ 11600 1cf8 09/16 13:57:05 2391 >: Listen mode: WRITE 11600 1cf8 09/16 13:57:05 2391 >: Using destination client-id: 1005 11600 1cf8 09/16 13:57:06 2391 >: NrsSocket: NrsSocket::Bind: Binding to interface name [spiderman.hrt.hr] for incoming data connection from client [1005] 11600 1cf8 09/16 13:57:11 2391 >: NrsSocket: Going to listen on IP:[10.1.128.99] IP:[10.1.80.58] Port:[65378] 11600 1cf8 09/16 13:57:11 2391 >: NrsSocket: Socket is listening. 11600 1cf8 09/16 13:57:11 2391 >: NrsSocket: Set socket option SO_LINGER 11600 1cf8 09/16 13:57:11 2391 >: NrsSocket: Set socket buffer sizes 11600 1cf8 09/16 13:57:11 2391 >: NrsSocket: NrsSocket::Options: Send buffer size is [65536]. Changing to [65536] 11600 1cf8 09/16 13:57:11 2391 >: NrsSocket: NrsSocket::Options: Recv buffer size is [65536], Changing to [65536]. 11600 1cf8 09/16 13:57:11 2391 >: NrsSocket: socket Options is done 11600 1cf8 09/16 13:57:11 2391 >: Data socket is binded to addr:[10.1.128.99] Port:[65378] addr:[10.1.80.58] Port:[65378] 11600 1cf8 09/16 13:57:11 2391 >: Create Data thread 11600 1cf8 09/16 13:57:11 2391 >: Wait for Data Thread Starts listening... 11600 1cf8 09/16 13:57:11 2391 >: WaitFor with timeout: 30 sec... 11600 2518 09/16 13:57:11 2391 >: Data Thread started 11600 1cf8 09/16 13:57:11 2391 >: WaitFor successful 11600 1cf8 09/16 13:57:11 2391 >: Change State from IDLE to LISTEN in request: Listen 11600 1cf8 09/16 13:57:11 2391 >: Send mover_listen_reply. 11600 1cf8 09/16 13:57:11 2391 ndmp_v4.cpp 5317 NDMP_MOVER_LISTEN reply. 11600 1cf8 09/16 13:57:11 2391 ndmp_v4.cpp 5339 --- address[0xa018063] port[65378] 11600 1cf8 09/16 13:57:11 2391 ndmp_v4.cpp 5339 --- address[0xa01503a] port[65378] 11600 1cf8 09/16 13:57:11 2391 ndmp_v4.cpp 5362 NDMP_MOVER_LISTEN reply: successful 11600 1cf8 09/16 13:57:11 2391 >: ************ MOVER LISTEN[0] ************ 11600 2518 09/16 13:57:32 2391 >: Change State from LISTEN to ACTIVE in request: Data Client Connected 11600 2518 09/16 13:57:32 2391 >: **** Restore Loop ***** 11600 2518 09/16 13:57:32 2391 >: DEBUGLOG: Read Socket Timeout value is [86400]. Default is [86400]. Use dword registry nREADSOCKETTIMEOUT to set. 11600 1cf8 09/16 13:57:34 2391 ndmp_v4.cpp 5176 NDMP_MOVER_READ reply: Error[0] 11600 1cf8 09/16 13:57:34 2391 ndmp_v4.cpp 5196 NDMP_MOVER_READ reply: successful 11600 2518 09/16 13:57:34 2391 >: Got Read Request from the Queue: Offset: 0 Size: 4194304 11600 2518 09/16 13:57:34 2391 >: Reading Archive metadata Header... 11600 2518 09/16 13:57:34 2391 CVArchive::ReadBuffer() - PL_SET_ENC_PROPS(2, 106, 4236) 11600 2518 09/16 13:57:34 2391 CVArchive::ReadBuffer() - PL_FS_OPEN_AFILE(2, 106, 4236) 11600 2518 09/16 13:57:34 2391 >: Read loop: got PL_FS_OPEN_AFILE block - continuing 11600 2518 09/16 14:00:43 2391 >: Read loop: got PL_NRS_METADATA 11600 2518 09/16 14:00:43 2391 >: MediaAdapter::cv_read_metaheader (MetaData struct size 128): Read block type 157 Size: 128 *** Meta Header Found: magic: 5730569652246480705 appVersion: 2 appSubversion: 1 appType: 1 blockSize: 32768 logicalSize: 0 physicalSize: 0 metaDataVersion: 1 metaDataSubVersion: 1Archive Format detected: 2 11600 2518 09/16 14:00:44 2391 >: MediaAdapter::GetChunkOffset: Afile:[4236] ChunkLogSize:[4280221696] ChunkLogOffset:[0] ChunkPhyOffset:[0] 11600 2518 09/16 14:00:44 2391 >: MediaAdapter::cv_seekall() Sending FSR_MSG_READ_ALL. 11600 1cf8 09/16 14:00:44 2391 ndmp_v4.cpp 5176 NDMP_MOVER_READ reply: Error[0] 11600 1cf8 09/16 14:00:44 2391 ndmp_v4.cpp 5196 NDMP_MOVER_READ reply: successful 11600 2518 09/16 14:00:44 2391 >: Got Read Request from the Queue: Offset: 1422527511552 Size: 4194304 11600 2518 09/16 14:00:45 2391 >: MediaAdapter::GetChunkOffset: Afile:[4236] ChunkLogSize:[4280202240] ChunkLogOffset:[1421029515264] ChunkPhyOffset:[1425574119680] 11600 2518 09/16 14:00:45 2391 >: MediaAdapter::SeekChunkDar Seeking Current:[4174848] ToChunk:[1421029515264] ToChunkPhyOffset:[1425574119680] ReadRequest:[1422527511552] 11600 2518 09/16 14:00:45 2391 >: MediaAdapter: AbortReadAll... 11600 2518 09/16 14:00:45 2391 CCVAPipelayer::discardTransitBuffers()() - Read All has been aborted 11600 2518 09/16 14:00:45 2391 >: MediaAdapter: AbortReadAll successful 11600 2518 09/16 14:01:50 2391 >: MediaAdapter::cv_seekall() Sending FSR_MSG_READ_ALL. 11600 1cf8 09/16 14:01:57 2391 ndmp_v4.cpp 5176 NDMP_MOVER_READ reply: Error[0] 11600 1cf8 09/16 14:01:57 2391 ndmp_v4.cpp 5196 NDMP_MOVER_READ reply: successful 11600 2518 09/16 14:01:57 2391 >: Got Read Request from the Queue: Offset: 1422531705856 Size: 4194304 11600 1cf8 09/16 14:03:27 2391 >: ************ MOVER_ABORT ************ 11600 1cf8 09/16 14:03:27 2391 >: TapeServer::Abort. Bytes processed:[12582912] 11600 1cf8 09/16 14:03:27 2391 >: Abort Data Thread... 11600 1cf8 09/16 14:03:27 2391 >: WaitFor with timeout: 30 sec... 11600 2518 09/16 14:03:27 2391 >: Restore loop is aborted 11600 2518 09/16 14:03:27 2391 >: Set Halted Reason: 2 11600 2518 09/16 14:03:27 2391 >: Closing Data connection... 11600 2518 09/16 14:03:27 2391 >: ========== TapeServer: State Snapshot: ======= 11600 2518 09/16 14:03:27 2391 >: State: 3 11600 2518 09/16 14:03:27 2391 >: Mode: 1 11600 2518 09/16 14:03:27 2391 >: Bytes processed: 12582912 11600 2518 09/16 14:03:27 2391 >: Data Addr: 0.0.0.0 11600 2518 09/16 14:03:27 2391 >: Data Port: 0 11600 2518 09/16 14:03:27 2391 >: Error: 0 11600 2518 09/16 14:03:27 2391 >: Change State from ACTIVE to HALTED in request: Data Thread halts server on exit 11600 2518 09/16 14:03:27 2391 >: run callback 11600 2518 09/16 14:03:27 2391 >: ************ TapeServer CallBack ************ 11600 2518 09/16 14:03:27 2391 >: ************ NOTIFY_HALTED ************ 11600 2518 09/16 14:03:27 2391 ndmp_v4.cpp 4581 NDMP_NOTIFY_MOVER_HALTED: Reason:[2=NDMP_MOVER_HALT_ABORTED] 11600 2518 09/16 14:03:27 2391 ndmp_v4.cpp 4594 NDMP_NOTIFY_MOVER_HALTED: successful 11600 2518 09/16 14:03:27 2391 >: ************ NotifyHalted ************ 11600 2518 09/16 14:03:27 2391 >: TapeServer Callback returned true 11600 2518 09/16 14:03:27 2391 >: Data thread exits 11600 1cf8 09/16 14:03:28 2391 >: WaitFor successful 11600 1cf8 09/16 14:03:28 2391 >: Stop read Queue... 11600 1cf8 09/16 14:03:28 2391 >: Abort MediaAdaper... 11600 1cf8 09/16 14:03:28 2391 >: MediaAdapter Abort successful 11600 1cf8 09/16 14:03:28 2391 >: WaitFor successful 11600 1cf8 09/16 14:03:28 2391 ndmp_v4.cpp 5211 NDMP_MOVER_ABORT reply: Error[0] 11600 1cf8 09/16 14:03:28 2391 ndmp_v4.cpp 5231 NDMP_MOVER_ABORT reply: successful 11600 1cf8 09/16 14:03:28 2391 >: ************ MOVER ABORT[0] ************ 11600 1cf8 09/16 14:03:28 2391 >: ************ MOVER_STOP ************ 11600 1cf8 09/16 14:03:28 2391 >: TapeServer: Stop 11600 1cf8 09/16 14:03:28 2391 >: TapeServer::Stop. Bytes processed:[12582912] 11600 1cf8 09/16 14:03:28 2391 >: WaitFor successful 11600 1cf8 09/16 14:03:28 2391 >: Change State from HALTED to IDLE in request: Stop 11600 1cf8 09/16 14:03:28 2391 ndmp_v4.cpp 5246 NDMP_MOVER_STOP reply: Error[0] 11600 1cf8 09/16 14:03:28 2391 ndmp_v4.cpp 5266 NDMP_MOVER_STOP reply: successful 11600 1cf8 09/16 14:03:28 2391 >: ************ MOVER STOP[0] ************ 11600 1cf8 09/16 14:03:28 2391 >: ************ TAPE CLOSE ************ 11600 1cf8 09/16 14:03:28 2391 >: MediaAdapter::Close: bytes processed: 12582912 11600 1cf8 09/16 14:03:28 2391 >NRS_Warning: MediaAdapter::Close: Pipeline active when closing. Aborting current read. 11600 1cf8 09/16 14:03:28 2391 >: MediaAdapter: AbortReadAll... 11600 1cf8 09/16 14:03:28 2391 [PIPELAYER ] Attempt to receive a pipeline buffer when the current buffer is still set 11600 1cf8 09/16 14:03:28 2391 CCVAPipelayer::discardTransitBuffers()() - Read All has been aborted 11600 1cf8 09/16 14:03:28 2391 >: MediaAdapter: AbortReadAll successful 11600 1cf8 09/16 14:03:28 2391 >: ** CLOSE ARCHIVE WITH PARAMETERS: 11600 1cf8 09/16 14:03:28 2391 >: AfileId[4236] AgroupId[106] AfileSize[0] Operation[RESTORE] CopyId[0] CommCell[2] 11600 1cf8 09/16 14:03:28 2391 >: ** CLOSE PIPELINE WITH PARAMETERS: Operation[RESTORE] State[SUCCESS] 11600 1cf8 09/16 14:03:28 2391 CVArchive::ClosePipeline() - Closing Pipeline 11600 1cf8 09/16 14:03:28 2391 CVArchive::ClosePipeline() - Shutting down head session 11600 1cf8 09/16 14:03:28 2391 CCVAPipelayer::discardTransitBuffers()() - Archive file has been closed 11600 1cf8 09/16 14:03:28 2391 CCVAPipelayer::ClosePipeline() - About to shut down RESTORE pipeline 11600 1cf8 09/16 14:03:28 2391 CPipelayer::ShutdownPipeline() - stat- Pipeline [5e8f1d0] [duration - 388 seconds] 11600 1cf8 09/16 14:03:28 2391 CPipelayer::ShutdownPipeline() - Sending STOP_PL when Shutting down pipeline 11600 1cf8 09/16 14:03:28 2391 [CVD ] Sending STOP_PL with plid = spiderman.hrt.hr_1442404620_11600_7416 (Shutting down pipeline) 11600 1cf8 09/16 14:03:28 2391 [CVD ] Setting Control message event for [spiderman.hrt.hr_1442404620_11600_7416] 11600 1cf8 09/16 14:03:28 2391 CPipelayer::ShutdownPipeline() - Waiting for STOP_PL message 11600 1cf8 09/16 14:03:28 2391 [PIPELAYER ] Pipeline already received STOP_PL 11600 1cf8 09/16 14:03:28 2391 [PIPELAYER ] Returning from waiting for pipeline shutdown because the pipeline is no longer running 11600 1cf8 09/16 14:03:28 2391 CPipelayer::ShutdownPipeline() - pipeline [5e8f1d0] Shutdown completed. 11600 1cf8 09/16 14:03:28 2391 [CVD ] Stopping CVDAliveChecking 11600 2c24 09/16 14:03:28 2391 [CVD ] CVD Alive Check Quit Event Signaled 11600 2c24 09/16 14:03:28 2391 [CVD ] CVDAliveChecking Thread Stopping 11600 1cf8 09/16 14:03:28 2391 >: TapeServer::TapeClose. Bytes processed:[0] 11600 1cf8 09/16 14:03:28 2391 ndmp_v4.cpp 5439 NDMP_TAPE_CLOSE reply: Error[0] 11600 1cf8 09/16 14:03:28 2391 ndmp_v4.cpp 5459 NDMP_TAPE_CLOSE reply: successful 11600 1cf8 09/16 14:03:28 2391 >: ************ TAPE CLOSE[0] ************ 11600 1cf8 09/16 14:03:28 2391 >: ************ NDMP_CONNECT_CLOSE ************ 11600 1cf8 09/16 14:03:28 2391 ndmp.cpp 1038 NDMP_CONNECT_CLOSE [] 11600 1cf8 09/16 14:03:28 2391 >: ************ NDMP_CONNECT_CLOSE [0] ************ 11600 1cf8 09/16 14:03:28 2391 >: Shutdown TapeServer... 11600 1cf8 09/16 14:03:28 2391 >: Abort Data Thread... 11600 1cf8 09/16 14:03:28 2391 >: WaitFor successful 11600 1cf8 09/16 14:03:28 2391 >: Stop read Queue... 11600 1cf8 09/16 14:03:28 2391 >: WaitFor successful 11600 1cf8 09/16 14:03:28 2391 >: Shutdown TapeServer is completed 11600 1cf8 09/16 14:03:28 2391 CVJobCtrlLog::unregisterProcess(): successfully removed file [C:\Program Files\NetApp\SnapProtect\Base\JobControl\11.600] 11600 1cf8 09/16 14:03:28 2391 main() - ============================================ 11600 1cf8 09/16 14:03:28 2391 main() - ----------------- STOPPED ----------------- 11600 1cf8 09/16 14:03:28 2391 main() - ============================================ @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Machine : spiderman File : fsIndexedRestore.log @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 9516 2f90 09/16 13:56:32 2391 setIndexingAfiles() - Latest Backup was found. CCell=2, appId=6, Copy=0, Time=2147483647. Returned afile=(2,106,4238) copy=110 created=1442370632. 9516 2f90 09/16 13:56:33 2391 setIndexingAfiles() - LastInCycle Backup was found. CCell=2, appId=6, Copy=0, Time=1442370632. Returned afile=(2,106,4238) copy=110 created=1442370632. 9516 2f90 09/16 13:56:34 2391 setIndexingAfiles() - Exact Backup was found. CCell=2, appId=6, Copy=0, Time=1442370632. Returned afile=(2,106,4238) copy=110 created=1442370632. 9516 2f90 09/16 13:56:39 2391 RESTOREIDX restore accessing index 'D:\NetappIndexCache\CV_Index\2\6\1442370632' 9516 2f90 09/16 13:56:39 2391 RESTOREIDX Continue with checking CS for presence of erase masks for timestamp [0] 9516 2f90 09/16 13:56:39 2391 SDVERSION no indexing subclient for client 3, appType 13 9516 2f90 09/16 13:56:39 2391 RESTORE open directory [D:\NetappIndexCache\CV_Index\2\6\1442370632] to check for metadata collection flag 9516 2f90 09/16 13:56:39 2391 NASOPTIMIZER optimizer limit dNASOPTIMLIMIT not found in MediaAgent registry folder, defaults to infinite 9516 2f90 09/16 13:56:39 2391 RESTORE NAS Recurse optimization check is [false] for client [vmvcenter] 9516 2f90 09/16 13:56:40 2391 MediaAgent Interface name spiderman.hrt.hr mangles to spiderman.hrt.hr*spiderman*8400*8402 9516 2f90 09/16 13:56:41 2391 CVRestoreFiles::createRestoreProcess() - remote executable = nasRestore.exe, commandline args = -commcellid 2 -appid 6 -port 8400 -host spiderman.hrt.hr -ptype 2 -destClientId 1005 -maHostName -rawdatapart 1 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::acceptSession() - Client Session will be kept alive 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::acceptSession() - Keep Alive Messages will be sent every 1800 minutes 9516 2f90 09/16 13:56:42 2391 Init() - Initializing job control [token=No Token,cn=spiderman], serverName [spiderman.hrt.hr], ControlFlag [3], Job Id [2391] 9516 2f90 09/16 13:56:42 2391 CVJobCtrlLog::registerProcess(): successfully created file [C:\Program Files\NetApp\SnapProtect\Base\JobControl\9.516] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - Sending initialization data: 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - seqNum = [4436701240229] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - appNumber = [6] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - appType = [13] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - commCellId = [2] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - copyId = [0] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - jobId = [2391] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - subClient = [Orabckp] 9516 2988 09/16 13:56:42 2391 CVRestoreFiles::jobCtrlThreadProcMember() - Thread jobCtrlThreadProc started. 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - numFiles = [1] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - srcClient = [hrtcluster.hrt.hr] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - destClient = [vmvcenter] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - userName = [NULL] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - password = [NULL] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - initRestartNumber = [0] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - noLossRestore = [0] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - mountDbsAfterRestore = [0] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - Sent message FSR_MSG_INIT_DATA 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - Client version is [15] 9516 2f90 09/16 13:56:42 2391 CVRestoreFiles::sendInitData() - Sent message FSR_MSG_INIT_DATA_VER2 9516 2f90 09/16 13:56:43 2391 CVRestoreFiles::init() - Initialization of client [vmvcenter] subclient [Orabckp] completed. 9516 2f90 09/16 13:56:43 2391 CVRestoreFiles::setRestoreParameters() - Sending restore parameters: 9516 2f90 09/16 13:56:43 2391 CVRestoreFiles::setRestoreParameters() - options = [100047c] 9516 2f90 09/16 13:56:43 2391 CVRestoreFiles::setRestoreParameters() - destDir = [C:\tmp] 9516 2f90 09/16 13:56:43 2391 CVRestoreFiles::setRestoreParameters() - numSrcPaths = [1] 9516 2f90 09/16 13:56:43 2391 CVRestoreFiles::setRestoreParameters() - Sending [1] pathnames to be restored 9516 2f90 09/16 13:56:43 2391 CVRestoreFiles::setRestoreParameters() - pathname [0]: [/svm01/vol_orabckp/expdp/pris/expdp_export_cumulative.log] 9516 2f90 09/16 13:56:43 2391 RESTORETABLE Rebuilding index for restore vector table 9516 2f90 09/16 13:56:44 2391 RESTORETABLE restore vector index rebuilt 9516 2f90 09/16 13:56:44 2391 RESTORETABLE Start processing of items with type 0 9516 2f90 09/16 13:56:44 2391 CVRestoreFiles::restoreFile() - Sending FSR_MSG_OPEN_ARCHIVE (2,106,4236) 9516 2f90 09/16 13:56:48 2391 CVRestoreFiles::restoreFile() - Launching feedbackThreadProc thread... 9516 2158 09/16 13:56:48 2391 CVRestoreFiles::feedbackThreadProcMember() - Thread feedbackThreadProc started. 9516 2f90 09/16 13:56:48 2391 CVRestoreFiles::waitForCompletion() - Sending FSR_MSG_CLOSE_ARCHIVE 9516 2f90 09/16 13:56:48 2391 CVRestoreFiles::waitForCompletion() - Sending FSR_MSG_WAIT_ARCHIVE_CLOSED 9516 2f90 09/16 13:56:48 2391 CVRestoreFiles::waitForCompletion() - Waiting for feedbackThreadProc to terminate... 9516 2158 09/16 14:03:54 2391 CVRestoreFiles::feedbackThreadProcMember() - Received FSR_MSG_WAIT_ARCHIVE_CLOSED 9516 2158 09/16 14:03:54 2391 CVRestoreFiles::feedbackThreadProcMember() - Feedback Thread is done... 9516 2f90 09/16 14:03:54 2391 CVRestoreFiles::finalize() - Waiting for Job Control Thread to finish... 9516 2988 09/16 14:03:55 2391 CVRestoreFiles::jobCtrlThreadProcMember() - Job Control Thread is done... 9516 2f90 09/16 14:03:55 2391 CVRestoreFiles::finalize() - Launching feedbackThreadProc thread... 9516 2f90 09/16 14:03:55 2391 CVRestoreFiles::finalize() - MSG_RESTORE_END sent to client 9516 2f90 09/16 14:03:55 2391 CVRestoreFiles::finalize() - Waiting for feedbackThreadProc to terminate... 9516 12c0 09/16 14:03:55 2391 CVRestoreFiles::feedbackThreadProcMember() - Thread feedbackThreadProc started. 9516 12c0 09/16 14:03:55 2391 CVRestoreFiles::feedbackThreadProcMember() - Received FSR_MSG_RESTORE_END 9516 12c0 09/16 14:03:56 2391 CVRestoreFiles::feedbackThreadProcMember() - Received CVS_PM_DISCONNECT_REQ 9516 12c0 09/16 14:03:56 2391 CVRestoreFiles::SetExtentRestoreStatus() - Setting the status 9516 12c0 09/16 14:03:56 2391 CVRestoreFiles::feedbackThreadProcMember() - Feedback Thread is done... 9516 2f90 09/16 14:03:56 2391 CVRestoreFiles::finalize() - Sending FSR_MSG_RESTORE_END to fsStartRestore 9516 2f90 09/16 14:03:56 2391 CVJobCtrlLog::unregisterProcess(): successfully removed file [C:\Program Files\NetApp\SnapProtect\Base\JobControl\9.516] 9516 2f90 09/16 14:03:56 2391 CVRestoreFiles::restartNeeded() - restartNeeded: _fatalError=0, _stopRequest=0 9516 2f90 09/16 14:03:56 2391 RESTORE 1 files restored 9516 2f90 09/16 14:03:56 2391 FsIndexedRestore::run() - COMPLETED ::restore(). 9516 2f90 09/16 14:04:06 2391 ::main() - Sending disconnect to FSStartRestore 9516 2f90 09/16 14:04:07 2391 ::main() - Received disconnect reply 9516 2f90 09/16 14:04:07 2391 ::main() - Exiting... 9516 2f90 09/16 14:04:07 2391 ** CVSession::sendBytes(...) iSocketMember=792 send failed, err=0x8007276D:{QiSocket.cpp[CQiSocket::Send(397)]/W32.10093.(Either the application has not called WSAStartup, or WSAStartup failed.)}. 9516 2f90 09/16 14:04:07 2391 ** CVSession::disconnect (void) 9516 2f90 09/16 14:04:07 2391 ** CVSession::sendBytes(...) iSocketMember=816 send failed, err=0x8007276D:{QiSocket.cpp[CQiSocket::Send(397)]/W32.10093.(Either the application has not called WSAStartup, or WSAStartup failed.)}. 9516 2f90 09/16 14:04:07 2391 ** CVSession::disconnect (void) @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Machine : spiderman File : JobManager.log @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 7080 2bb0 09/16 13:56:26 2391 Servant [---- IMMEDIATE RESTORE REQUEST ----] Task id [2391] Clnt[hrtcluster.hrt.hr] AppType[NAS][13] 7080 d64 09/16 13:56:28 2391 Scheduler Restore request successfuly sent 7080 d64 09/16 13:56:28 2391 Scheduler Phase [2-Restore] (0,0) started on [spiderman.hrt.hr] in [0] second(s) - startRestore.exe 2391 2391 7080 2688 09/16 13:56:28 2391 Servant Reg [Control] received. Client [spiderman] plattype = 1 7080 2688 09/16 13:56:42 2391 Servant Reg [IndexRestore] received. Client [spiderman] plattype = 2 7080 2688 09/16 13:56:43 2391 Servant Reg [NotControl] received. Client [spiderman] plattype = 4 7080 2688 09/16 13:56:54 2391 Servant Reg [NotControl] received. Client [vmvcenter] plattype = 4 7080 2688 09/16 13:56:56 2391 Servant Reg [NotControl] received. Client [spiderman] plattype = 2 7080 c40 09/16 13:57:36 2391 Scheduler Set pending cause [The media is already reserved by some other job[s].]::Client [spiderman] Application [MediaManager] Message Id [1040187740] RCID [0] ReservationId [-1]. Level [0] flags [0] id [0] overwrite [0] append [0] CustId[0]. 7080 134 09/16 13:59:36 2391 Scheduler Reset pending cause received for RCID [0], ReservationId [0] from client [spiderman] and application [MediaManager]. Level [0] flags [0] id [0] overwrite [0] append [0] CustId[0]. 7080 134 09/16 14:04:08 2391 Scheduler Job [Completed] message received from [spiderman.hrt.hr] Module [StartRestore] Token [] restartPhase [0] 7080 134 09/16 14:04:08 #### CvResourceManager::releaseJobStreamsNoRetry() - :RM_TRACE[2391]:CvResourceManager.cpp:10424: No reservation exists for Job 2391 7080 134 09/16 14:04:08 2391 JobSvr Obj Phase [2-Restore] has succeeded along with the WHOLE job. 7080 134 09/16 14:04:08 2391 Scheduler -> COMPLETED <- Restore; Restore job [2391] completed. Client [vmvcenter], Agent Type [NAS], Duration [00:07:42]. @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Machine : spiderman File : MediaManager.log @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 7104 1dbc 09/16 13:56:55 2391 MOUNT [17] DATAPATH SELECTED = , DRIVEPOOL <2> LIBRARY 7104 1dc0 09/16 13:57:35 2391 MOUNT [ ] MOUNT REQUEST from [spiderman] : JOB 2391 7104 1dc0 09/16 13:57:35 2391 MOUNT [17] DATAPATH SELECTED = , DRIVEPOOL <2> LIBRARY 7104 1dc0 09/16 13:57:35 2391 MOUNT [17] RESERVE VOL 17 AND DRIVE IN DRIVEPOOL 2 7104 1dc0 09/16 13:57:36 #### MLMDriveInfo::fillDriveInfoForDM() - :MLMDriveInfo.cpp:2973: Failed to get Drivectrl info for drvctrlId [-1] due to error [261]. 7104 1dc0 09/16 13:57:36 2391 MOUNT [17] ERROR:(reservation failed) DUE TO ** [The media is already reserved by some other job[s].](803) ** FUNC[(MLMReserveMountVol::reserveMountForDrive)(MLMReserveMountVol.cpp:5062)] PARAMETERS: LIBRARY [(2):Library2(FUJITSU ETERNUS LT S2)] DRIVE [(-1):()] MEDIA [(17):AEM394L6]MEDIAGRP[1160] DRIVEPOOL [2] DRIVEHOST [0] LIBRARYHOST [2] LMS [LmsLibrary2_2] DMS [] 7104 1dbc 09/16 13:59:36 2391 MOUNT [ ] MOUNT REQUEST from [spiderman] : JOB 2391 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] DATAPATH SELECTED = , DRIVEPOOL <2> LIBRARY 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] RESERVE VOL 17 AND DRIVE IN DRIVEPOOL 2 7104 1dbc 09/16 13:59:36 #### MOUNT [0 ] RESERVED RESERVATION ID [3145],RESOURCE USER [151], SP [], COPY [(ID:0)], MEDIAGROUP [1160], VOLUME [17], MEDIA [AEM394L6(ID:17)], DRIVE [HP Ultrium 6-SCSI_2(ID:2)], DRIVEPOOL [DrivePool(spiderman)2(ID:2)], LIBRARY [FUJITSU ETERNUS LT S2], HOST[spiderman] 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] JOB [2391] SUCCEEDED IN RESERVATION 7104 1dbc 09/16 13:59:36 #### EvEvent::setMsgEventArguments() - MsgId[0x00000000]: Catalog does not exist or Args table does not exist. 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] USING RESERVATION ID [3145], DRIVE ID [2] 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] MOUNT PARAMS - JOB [2391] TOKEN [] 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] MEDIA INFO : BARCODE [AEM394L6], VOLUME [17], MEDIAID [17] 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] LIBRARY INFO : NAME [FUJITSU ETERNUS LT S2] 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] LIBRARY BLIND : FALSE 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] MNT TYPE: MOUNT_VOL_IN_ANY_DRIVEPOOL 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] DRIVE POOL ID: 2, TYPE: Regular 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] LIBRARY HOST ID: 2 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] DRIVE HOST: spiderman.hrt.hr 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] JOB [2391] IS A RESTORE JOB 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] REUSE CACHEMOUNT 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] REUSE VOLUME [17], BARCODE [AEM394L6] MOUNTED IN DRIVE [Lib2_Drive2] IN LIBRARY [Library2] 7104 1dbc 09/16 13:59:36 2391 MOUNT [17] DRIVE ACCESSPATH : \\.\Tape2, DRIVEPOOL 2, HOST 2, SERIAL# , 7104 1dbc 09/16 14:03:28 2391 MOUNT [17] UNMOUNT PARAMS from [spiderman.hrt.hr] : JOB 2391, RESERVATION ID: 3145 RELEASE VOLUME : 1, RELEASE DRIVE : 1, LOGICAL UNMOUNT : 1, PHYSICAL UNMOUNT : 0, RESOURCE CONSUMER ID: 0 7104 1dbc 09/16 14:03:28 2391 MOUNT [17] Unreserved Vol 17 Drive -1, ReservationId 3145 7104 1dbc 09/16 14:03:28 2391 Resource Removed resource user 151 7104 1dbc 09/16 14:03:28 #### Resource Released reservation 3145 7104 1dbc 09/16 14:25:44 #### SERVICE [17] LCP UNMOUNT Host spiderman.hrt.hr, Library Library2, Slot slot 17<1017>, Drive Lib2_Drive2<2>, RID 50130/0/0 @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Machine : spiderman File : nasRestore.log @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 108 2714 09/16 13:56:43 2391 Init() - Initializing job control [token=No Token,cn=spiderman], serverName [spiderman.hrt.hr], ControlFlag [4], Job Id [2391] 108 2714 09/16 13:56:43 2391 CVJobCtrlLog::registerProcess(): successfully created file [C:\Program Files\NetApp\SnapProtect\Base\JobControl\0.108] 108 2714 09/16 13:56:43 2391 FclRestore::initialize2() - Skip and continue on seek Failure option NOT selected, restore would fail if seek failures happen. 108 2714 09/16 13:56:43 2391 FclRestore::initialize2() - No user id found in the registry [VMName = spiderman]. Trying getting it from the CS 108 2714 09/16 13:56:43 2391 CVArchive::Construct() - Constructing CVArchive Object 108 2714 09/16 13:56:43 2391 CVArchive::Construct() - Enable CVArchive Big Buffer [true] 108 2714 09/16 13:56:43 2391 FclRestore::initialize2() - GUI progress updates will be sent every [300] secs 108 2714 09/16 13:56:43 2391 FclRestore::initialize2() - Keep Alive Messages will be sent every 30 minutes 108 14fc 09/16 13:56:43 2391 FClRestore::processRestoreMsgs() - This is NOT a WOW64 system state restore 108 14fc 09/16 13:56:43 2391 Multiple Tag Headers per Pipeline Buffer is Supported 108 2714 09/16 13:56:43 2391 NasMedia::initialize() - Using data mover max mount retry registry key value [0] 108 2714 09/16 13:56:43 2391 NasMedia::initialize() - Using data mover max mount retry sleep time registry key value [0] minutes. 108 2714 09/16 13:56:43 2391 NasRestore::initializeNasRestore() - Restore from copy precedence [0] 108 2714 09/16 13:56:43 2391 NasRestore::initializeNasRestore() - Init data: [#IcdPath="D:\NetappIndexCache\CV_Index\2\6\1442370632"] 108 14fc 09/16 13:56:43 2391 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_INIT_DATA_VER2 108 14fc 09/16 13:56:43 2391 FclRestore::OnMsgInitDataVer2() - This is not a file level snap restore from disk backup SnapRestore=[0] bkpType=[0] rstType=[0] 108 14fc 09/16 13:56:43 2391 CSyncRestorePathMapper::InitSyncRestore(265) - JobID=[2391] is not a SYNC_RESTORE 108 14fc 09/16 13:56:43 2391 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_SET_PARAMS 108 14fc 09/16 13:56:43 2391 FclRestore::OnMsgSetParams() - Options = 100047c 108 14fc 09/16 13:56:43 2391 FclRestore::OnMsgSetParams() - destDir supplied is [C:\tmp] 108 14fc 09/16 13:56:43 2391 NasRestore::isLocalFSTests() - Suppress local file system tests for NAS restore 108 14fc 09/16 13:56:43 2391 FclRestore::OnMsgSetParams() - Out of place restore selected to dir [C:\tmp] 108 14fc 09/16 13:56:43 2391 NasRestore::isLocalFSTests() - Suppress local file system tests for NAS restore 108 14fc 09/16 13:56:43 2391 JOBRESCACHEDIR: job 2391 creating 'C:\Program Files\NetApp\SnapProtect\iDataAgent\JobResults\CV_JobResults\2\0\2391' 108 14fc 09/16 13:56:44 2391 FclRestore::OnMsgSetParams() - compatabilityOptions set to - SEND_NO_RAW_DEVICE_DATA 108 14fc 09/16 13:56:44 2391 FclRestore::OnMsgSetParams() - This is not a ZIP folder download job 108 14fc 09/16 13:56:44 2391 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_SRC_PATH 108 14fc 09/16 13:56:44 2391 NasRestore::OnMsgSrcPath() - Source path: Strip level [4] index [0] path [/svm01/vol_orabckp/expdp/pris/expdp_export_cumulative.log] 108 14fc 09/16 13:56:44 2391 NasRestore::OnMsgSrcPath() - Option to update the web server DB is not set. 108 14fc 09/16 13:56:44 2391 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_OPEN_ARCHIVE 108 14fc 09/16 13:56:44 2391 MapFileRestoreSelected() - EvRstTask::getOptionString() returned empty path for map file. 108 14fc 09/16 13:56:44 2391 CVArchive::Construct() - Constructing CVArchive Object 108 14fc 09/16 13:56:44 2391 CVArchive::Construct() - Enable CVArchive Big Buffer [true] 108 14fc 09/16 13:56:44 2391 NasMedia::getCopyID() - FIREWALL: Calling open[arch]: pid = 108, thread = 5372 108 14fc 09/16 13:56:44 2391 NasMedia::getCopyID() - archive manager output copy ID [110] 108 14fc 09/16 13:56:45 2391 NasRestore::OnMsgOpenArchive() - calling ArchiveManagerDS::getAfileInfo() with parameters: 108 14fc 09/16 13:56:45 2391 NasRestore::OnMsgOpenArchive() - afileNumber = 4236 108 14fc 09/16 13:56:45 2391 NasRestore::OnMsgOpenArchive() - storagePolicyNumber = 106 108 14fc 09/16 13:56:45 2391 NasRestore::OnMsgOpenArchive() - commCellId = 2 108 14fc 09/16 13:56:45 2391 NasRestore::OnMsgOpenArchive() - copyId = 110 108 14fc 09/16 13:56:46 2391 ArMgrDS::getAfileInfo Returns afcFlags [32] encType [0] encKeyLen [0] needPassPhrase [0] drToolAccess [0] dataMoverType [1] 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - ArchiveManagerDS::getAfileInfo returned: 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - appNumber = 6 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - commCellId = 2 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - agroupNumber = 106 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - afileNumber = 4236 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - name = /svm01/vol_orabckp 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - fileType = 1 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - backupTime = 1442361708 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - backupLevel = 2 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - objName1 = ACL_START=1557968033792;CV_FIRST_OFFSET=365568;BASE_DATE=14327177354;CV_BUTYPE=dump;CV_RECORDSIZE=65536;DEBUG=N;DUMP_DATE=18622231081;ENHANCED_DAR_ENABLED=T;HIST=Y;NDMP_VERSION=4;NO_ACLS=N;PATHNAME_SEPARATOR=/;TYPE=dump;UPDATE=Y;VERBOSE=N; 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - afc flags = 32 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - encryption type = 0 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - ArchiveManagerDS::listAfileInfo called with parameters: 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - appNumber = 6 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - commCellId = 2 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - fileType = 1 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - beforeDate = 1442361708 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - afileName = /svm01/vol_orabckp 108 14fc 09/16 13:56:46 2391 NasRestore::OnMsgOpenArchive() - jobId = 2376 108 14fc 09/16 13:56:48 2391 NasRestore::OnMsgOpenArchive() - ArchiveManagerDS::listAfileInfo archive selected for restore: 108 14fc 09/16 13:56:48 2391 NasRestore::OnMsgOpenArchive() - backupTime = 1442361708 108 14fc 09/16 13:56:48 2391 NasRestore::OnMsgOpenArchive() - backupLevel = 2 108 14fc 09/16 13:56:48 2391 NasRestore::OnMsgOpenArchive() - afileNumber = 4236 108 14fc 09/16 13:56:48 2391 NasRestore::OnMsgOpenArchive() - createJobId = 2376 108 14fc 09/16 13:56:48 2391 NasRestore::OnMsgOpenArchive() - name = /svm01/vol_orabckp 108 14fc 09/16 13:56:48 2391 NasRestore::OnMsgOpenArchive() - afileSize = 1557968041088 108 14fc 09/16 13:56:48 2391 NasRestore::OnMsgOpenArchive() - ------------------------------------ 108 14fc 09/16 13:56:49 2391 NasRestore::findStripLevel(): Source path [/svm01/vol_orabckp/expdp/pris/expdp_export_cumulative.log] matched with [/svm01/vol_orabckp/expdp/pris/expdp_export_cumulative.log]. 108 14fc 09/16 13:56:49 2391 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_CLOSE_ARCHIVE 108 14fc 09/16 13:56:49 2391 NasRestore::OnMsgCloseArchive() - NDMP data server [vmvcenter] not a file server, kicking off open systems restore. 108 14fc 09/16 13:56:49 2391 kickOffRemoteServer() - remote exec name is [CVNRDS.exe] with command line args [-l ndmp -p 39b87acfec63e189d0906fb4cabcb115b06a64ae3ac14aa86 -j 2391 -cn vmvcenter ] 108 14fc 09/16 13:56:54 2391 kickOffRemoteServer() - Received port number 51872(IPv flag 1) from remote NRS/NRDS process. 108 14fc 09/16 13:56:54 2391 CVArchive::Construct() - Constructing CVArchive Object 108 1fe4 09/16 13:56:54 2391 NasRestore::progressReport() - Starting progress-reporting thread... 108 14fc 09/16 13:56:54 2391 CVArchive::Construct() - Enable CVArchive Big Buffer [true] 108 14fc 09/16 13:56:54 2391 NasMedia::getCopyID() - FIREWALL: Calling open[arch]: pid = 108, thread = 5372 108 14fc 09/16 13:56:54 2391 NasMedia::getCopyID() - archive manager output copy ID [110] 108 14fc 09/16 13:56:55 2391 NasMedia::lookupAfileInfo() - GetNextChunk hostname set to [spiderman.hrt.hr] 108 14fc 09/16 13:56:55 2391 NasMedia::lookupAfileInfo() - Retrieved chunk [10214] for afile [4236] Logical size [4280221824] Physical Size [4293912480] 108 14fc 09/16 13:56:55 2391 NasMedia::setDrivePoolId() - destination client id set to [1005], destination client is [vmvcenter] 108 14fc 09/16 13:56:55 2391 NasMedia::setDrivePoolIdForDestClient() - set drive pool ID [2] 108 14fc 09/16 13:56:55 2391 kickOffRemoteServer() - remote exec name is [CVNdmpRemoteServer.exe] with command line args [-l ndmp -p 39b87acfec63e189d0906fb4cabcb115b06a64ae3ac14aa86 -j 2391 -cn spiderman -RstDestClientId 1005] 108 14fc 09/16 13:56:56 2391 kickOffRemoteServer() - Received port number 65351(IPv flag 1) from remote NRS/NRDS process. 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - Calling NdmpRestore constructor with parameters: 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - destMach = vmvcenter 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - dataServerLogin= ndmp 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - dataServerOS = 5 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - dataServerVers = 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - dataServerPort = 51872 108 14fc 09/16 13:56:56 2391 NasMedia::getTapeDevice() - CVMMreserveMount::getMntPnt failed. 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - tapeDeviceName = 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - tapeServer = spiderman.hrt.hr 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - moverLogin = ndmp 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - moverVersion = V2 - Galaxy 7.0 or later 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - moverPort = 65351 108 14fc 09/16 13:56:56 2391 NasMedia::getTapeDevice() - CVMMreserveMount::getMntPnt failed. 108 14fc 09/16 13:56:56 2391 NdmpRestore::NdmpRestore,2() - received NULL tape device. 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - Calling NdmpRestore::initialize with parameters: 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - destDir = C:\tmp 108 14fc 09/16 13:56:56 2391 NDMP Restore Initialization: 108 14fc 09/16 13:56:56 2391 destDir is -C:\tmp- 108 14fc 09/16 13:56:56 2391 restoreACLs = false 108 14fc 09/16 13:56:56 2391 DAR = ON 108 14fc 09/16 13:56:56 2391 Image = true 108 14fc 09/16 13:56:56 2391 CommVault Backup Env = -ACL_START=1557968033792;CV_FIRST_OFFSET=365568;BASE_DATE=14327177354;CV_BUTYPE=dump;CV_RECORDSIZE=65536;DEBUG=N;DUMP_DATE=18622231081;ENHANCED_DAR_ENABLED=T;HIST=Y;NDMP_VERSION=4;NO_ACLS=N;PATHNAME_SEPARATOR=/;TYPE=dump;UPDATE=Y;VERBOSE=N;- 108 14fc 09/16 13:56:56 2391 total size of all archive files in list [1557968041088] 108 14fc 09/16 13:56:56 2391 Data server listen port number is 51872 108 14fc 09/16 13:56:56 2391 Mover server listen port number is 65351 108 14fc 09/16 13:56:56 2391 m_bNRDSisDataServer is [1] 108 14fc 09/16 13:56:56 2391 extended options are [0x280] 108 14fc 09/16 13:56:56 2391 NAS options are [640] 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - NdmpRestore::restoreDump called with parameters: 108 14fc 09/16 13:56:56 2391 NasRestore::OnMsgCloseArchive() - dumpRoot = /svm01/vol_orabckp 108 14fc 09/16 13:56:56 2391 NAS RESTORE. 9.0 108 14fc 09/16 13:56:56 2391 ASCII to UTF8 Translation by this procss is [n]. NRDS is [true]. 108 14fc 09/16 13:56:56 2391 LOGIN TO CLIENT: NRDS[true] 108 14fc 09/16 13:56:56 2391 ndmp.cpp 3054 CONNECT: opening socket connection to host [vmvcenter] port [51872] family [IPv4] 108 14fc 09/16 13:56:56 2391 ndmp.cpp 3088 CONNECT successful: Now waiting for NOTIFY_CONNECTED message. 108 14fc 09/16 13:56:56 2391 ndmp.cpp 2749 NDMP_NOTIFY_CONNECTED: received ndmp_notify_connected. Version:[4], Reason:[0] Text:[Connected] 108 14fc 09/16 13:56:56 2391 ndmp.cpp 3137 NDMP_CONNECT_OPEN: protocol_version[4] 108 14fc 09/16 13:56:56 2391 ndmp.cpp 3152 NDMP_CONNECT_OPEN: successful 108 14fc 09/16 13:56:56 2391 ndmp.cpp 2804 NDMP_NOTIFY_CONNECTED: successful. Version is [4] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 873 NDMP_CONFIG_GET_SERVER_INFO: 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 905 NDMP_CONFIG_GET_SERVER_INFO: successful. Vendor[CommVault Systems] Product[Galaxy] Revision[10.0.0(BUILD116)] AuthType[2] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 787 NDMP_CONNECT_CLIENT_AUTH: login[ndmp] mode[2=NDMP_AUTH_MD5] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 807 NDMP_CONNECT_CLIENT_AUTH: successful 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 827 NDMP_CONFIG_GET_HOST_INFO: 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 849 NDMP_CONFIG_GET_HOST_INFO: successful. Host[vmvcenter] OsType[Windows Server x64] Version[6.1Build 7601: Service Pack 1] HostId[A014F14] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 873 NDMP_CONFIG_GET_SERVER_INFO: 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 905 NDMP_CONFIG_GET_SERVER_INFO: successful. Vendor[CommVault Systems] Product[Galaxy] Revision[10.0.0(BUILD116)] AuthType[2] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 1322 NDMP_CONFIG_GET_EXT_LIST: 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 1372 NDMP_CONFIG_GET_EXT_LIST: successful 108 14fc 09/16 13:56:56 2391 Data server connect complete. 108 14fc 09/16 13:56:56 2391 LOGIN TO MOVER 108 14fc 09/16 13:56:56 2391 ndmp.cpp 3054 CONNECT: opening socket connection to host [spiderman.hrt.hr] port [65351] family [IPv4] 108 14fc 09/16 13:56:56 2391 ndmp.cpp 3088 CONNECT successful: Now waiting for NOTIFY_CONNECTED message. 108 14fc 09/16 13:56:56 2391 ndmp.cpp 2749 NDMP_NOTIFY_CONNECTED: received ndmp_notify_connected. Version:[4], Reason:[0] Text:[Connected] 108 14fc 09/16 13:56:56 2391 ndmp.cpp 3137 NDMP_CONNECT_OPEN: protocol_version[4] 108 14fc 09/16 13:56:56 2391 ndmp.cpp 3152 NDMP_CONNECT_OPEN: successful 108 14fc 09/16 13:56:56 2391 ndmp.cpp 2804 NDMP_NOTIFY_CONNECTED: successful. Version is [4] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 873 NDMP_CONFIG_GET_SERVER_INFO: 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 905 NDMP_CONFIG_GET_SERVER_INFO: successful. Vendor[CommVault Systems] Product[Galaxy] Revision[10.0.0(BUILD116)] AuthType[2] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 787 NDMP_CONNECT_CLIENT_AUTH: login[ndmp] mode[2=NDMP_AUTH_MD5] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 807 NDMP_CONNECT_CLIENT_AUTH: successful 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 827 NDMP_CONFIG_GET_HOST_INFO: 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 849 NDMP_CONFIG_GET_HOST_INFO: successful. Host[spiderman.hrt.hr] OsType[Windows Server x64] Version[6.2Build 9200: ] HostId[A01503A] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 873 NDMP_CONFIG_GET_SERVER_INFO: 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 905 NDMP_CONFIG_GET_SERVER_INFO: successful. Vendor[CommVault Systems] Product[Galaxy] Revision[10.0.0(BUILD116)] AuthType[2] 108 14fc 09/16 13:56:56 2391 New NRS:[true] Version:[10.0.0(BUILD116)] 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 1322 NDMP_CONFIG_GET_EXT_LIST: 108 14fc 09/16 13:56:56 2391 ndmp_v4.cpp 1372 NDMP_CONFIG_GET_EXT_LIST: successful 108 14fc 09/16 13:56:56 2391 Data mover connect complete. 108 14fc 09/16 13:56:56 2391 Set NDMP Variables() - Back-up NDMP variable backup type set to [dump]. 108 14fc 09/16 13:56:56 2391 Set NDMP Variables() - Back-up record size set to [65536]. 108 14fc 09/16 13:56:56 2391 NDMP Variable Setup() - backup type is dump 108 14fc 09/16 13:56:56 2391 Set NDMP Variables() - NDMP server type is 5 108 14fc 09/16 13:56:57 2391 Opening tape for archive [4236]... 108 14fc 09/16 13:56:57 2391 Construct Open Device Name() - got subclientID 6 and clientID 3 108 14fc 09/16 13:56:57 2391 Construct Open Device Name() - constructed virtual tape name is R:0:2391:4236:106:0:1:0:2:3:6:6:13:4436701240229:0:0 108 14fc 09/16 13:56:57 2391 ndmp_v4.cpp 1686 NDMP_TAPE_OPEN [spiderman.hrt.hr]: Device[R:0:2391:4236:106:0:1:0:2:3:6:6:13:4436701240229:0:0] Mode[0] 108 14fc 09/16 13:57:03 2391 Log Message() - received NDMP_LOG_MESSAGE [spiderman.hrt.hr][CVNRS: Tape opened. AfileId=4236 CopyId=0 Stream=1] 108 14fc 09/16 13:57:03 2391 ndmp.cpp 2225 Message not replied to yet. 108 14fc 09/16 13:57:05 2391 ndmp_v4.cpp 1706 NDMP_TAPE_OPEN: successful 108 14fc 09/16 13:57:05 2391 Restore Request() - MAX Restore List Length set to [1048576]. 108 14fc 09/16 13:57:05 2391 ndmp_v4.cpp 2829 NDMP_MOVER_SET_WINDOW [spiderman.hrt.hr]: Offset[0] Length[1557968040960] 108 14fc 09/16 13:57:05 2391 ndmp_v4.cpp 2846 NDMP_MOVER_SET_WINDOW: successful 108 14fc 09/16 13:57:05 2391 ndmp_v4.cpp 2712 NDMP_MOVER_LISTEN [spiderman.hrt.hr]: mode[1] addr_type[1] 108 14fc 09/16 13:57:11 2391 ndmp_v4.cpp 2735 NDMP_MOVER_LISTEN: successful 108 14fc 09/16 13:57:11 2391 ndmp_v4.cpp 2742 --- address[0xa018063] port[65378] 108 14fc 09/16 13:57:11 2391 ndmp_v4.cpp 2742 --- address[0xa01503a] port[65378] 108 14fc 09/16 13:57:11 2391 ndmp_v4.cpp 2143 NDMP_DATA_CONNECT(tcp): 108 14fc 09/16 13:57:11 2391 ndmp_v4.cpp 2147 --- address[0xa018063] port[65378] 108 14fc 09/16 13:57:11 2391 ndmp_v4.cpp 2147 --- address[0xa01503a] port[65378] 108 14fc 09/16 13:57:32 2391 ndmp_v4.cpp 2192 NDMP_DATA_CONNECT: successful 108 14fc 09/16 13:57:32 2391 re-initialized tape server for next block of files. 108 14fc 09/16 13:57:33 2391 Successfully translated archFileId 4236 (commCellId 2) to client Id 3 108 14fc 09/16 13:57:34 2391 Back-up Vendor() - Source Client ID = 3, back-up vendor = 1 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2385 NDMP_DATA_START_RECOVER_CV: RestoreType[dump] BackupVendor[NetApp] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [ACL_START]=[1557968033792] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [BASE_DATE]=[14327177354] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [CV_FIRST_OFFSET]=[365568] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [DEBUG]=[N] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [DIRECT]=[Y] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [DUMP_DATE]=[18622231081] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [ENHANCED_DAR_ENABLED]=[T] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [FILESYSTEM]=[/svm01/vol_orabckp] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [HIST]=[N] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [NDMP_VERSION]=[4] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [NO_ACLS]=[N] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [PATHNAME_SEPARATOR]=[/] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [RECURSIVE]=[N] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [TYPE]=[dump] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [UPDATE]=[Y] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2395 ENV [VERBOSE]=[N] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2416 FILE Offset[1422527511552] Inode[20265] Mtime[1442342090] Size[5273444] [expdp/pris/expdp_export_cumulative.log] to [/C:\tmp/expdp_export_cumulative.log] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2448 NDMP_DATA_START_RECOVER_CV: successful 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2975 NDMP_MOVER_READ [spiderman.hrt.hr]: Offset[0] Length[4194304] 108 14fc 09/16 13:57:34 2391 ndmp_v4.cpp 2992 NDMP_MOVER_READ: successful 108 14fc 09/16 13:59:34 2391 ndmp_v4.cpp 2079 NDMP_DATA_GET_STATE: Timeout:[7200] 108 14fc 09/16 13:59:34 2391 ndmp_v4.cpp 2105 NDMP_DATA_GET_STATE: successful. Operation[2] State[0x1] HaltReason[0] BytesProcessed[0] EstBytesRemain[0] ReadOffset[0] ReadLength[4194304] 108 14fc 09/16 14:00:44 2391 ndmp_v4.cpp 2975 NDMP_MOVER_READ [spiderman.hrt.hr]: Offset[1422527511552] Length[4194304] 108 14fc 09/16 14:00:44 2391 ndmp_v4.cpp 2992 NDMP_MOVER_READ: successful 108 14fc 09/16 14:01:44 2391 ndmp_v4.cpp 2079 NDMP_DATA_GET_STATE: Timeout:[7200] 108 14fc 09/16 14:01:44 2391 ndmp_v4.cpp 2105 NDMP_DATA_GET_STATE: successful. Operation[2] State[0x1] HaltReason[0] BytesProcessed[0] EstBytesRemain[0] ReadOffset[1422527511552] ReadLength[4194304] 108 14fc 09/16 14:01:57 2391 ndmp_v4.cpp 2975 NDMP_MOVER_READ [spiderman.hrt.hr]: Offset[1422531705856] Length[4194304] 108 14fc 09/16 14:01:57 2391 ndmp_v4.cpp 2992 NDMP_MOVER_READ: successful 108 14fc 09/16 14:01:57 2391 Log Message() - received NDMP_LOG_MESSAGE [vmvcenter][Total number of files sent for recovery :: 1,Total number of files recovered successfully :: 1,Total number of files which skipped to be recovered :: 0,Total number of files which failed to be recovered ::0] 108 14fc 09/16 14:01:57 2391 Data Halted Notification() - received DATA_HALT with reason [NDMP_DATA_HALT_SUCCESSFUL] 108 14fc 09/16 14:01:57 2391 ndmp_v4.cpp 2079 NDMP_DATA_GET_STATE: Timeout:[7200] 108 14fc 09/16 14:01:57 2391 ndmp_v4.cpp 2105 NDMP_DATA_GET_STATE: successful. Operation[2] State[0x2] HaltReason[0] BytesProcessed[5273444] EstBytesRemain[0] ReadOffset[1422531705856] ReadLength[4194304] 108 14fc 09/16 14:03:27 2391 ndmp_v4.cpp 2900 NDMP_MOVER_ABORT [spiderman.hrt.hr]: 108 14fc 09/16 14:03:27 2391 Mover Halted Notification() - received NDMP_MOVER_HALTED reason [NDMP_MOVER_HALT_ABORTED] 108 14fc 09/16 14:03:27 2391 ndmp.cpp 2225 Message not replied to yet. 108 14fc 09/16 14:03:28 2391 ndmp_v4.cpp 2914 NDMP_MOVER_ABORT: successful 108 14fc 09/16 14:03:28 2391 ndmp_v4.cpp 2934 NDMP_MOVER_STOP [spiderman.hrt.hr]: 108 14fc 09/16 14:03:28 2391 ndmp_v4.cpp 2948 NDMP_MOVER_STOP: successful 108 14fc 09/16 14:03:28 2391 ndmp_v4.cpp 2551 NDMP_DATA_STOP: 108 14fc 09/16 14:03:28 2391 ndmp_v4.cpp 2565 NDMP_DATA_STOP: successful 108 14fc 09/16 14:03:28 2391 ndmp_v4.cpp 1735 NDMP_TAPE_CLOSE [spiderman.hrt.hr]: [R:0:2391:4236:106:0:1:0:2:3:6:6:13:4436701240229:0:0]. Timeout:[1200] 108 14fc 09/16 14:03:28 2391 ndmp_v4.cpp 1752 NDMP_TAPE_CLOSE: successful 108 14fc 09/16 14:03:28 2391 ndmp.cpp 1038 NDMP_CONNECT_CLOSE [spiderman.hrt.hr] 108 14fc 09/16 14:03:28 2391 ndmp.cpp 1038 NDMP_CONNECT_CLOSE [vmvcenter] 108 1fe4 09/16 14:03:54 2391 NasRestore::progressReport() - Exiting progress reporting thread... 108 14fc 09/16 14:03:54 2391 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_WAIT_ARCHIVE_CLOSED 108 14fc 09/16 14:03:55 2391 FClRestore::ProcessRestoreMessage() - Processing FSR_MSG_RESTORE_END 108 14fc 09/16 14:03:55 2391 FclRestore::OnMsgRestoreEnd() - Restore on client [spiderman.hrt.hr] subclient [Orabckp] completed... 108 14fc 09/16 14:03:55 2391 FclRestore::OnMsgRestoreEnd() - File Statistics: Total [1], Succeeded [1], Skipped [0] Failed [0] Need Reboot [0] 108 14fc 09/16 14:03:55 2391 FclRestore::OnMsgRestoreEnd() - Byte Statistics: Total [0], Succeeded [5273444], Skipped [0] Failed [0] 108 14fc 09/16 14:03:55 2391 FclRestore::OnMsgRestoreEnd() - The failed byte count does not include files that failed due to seek error 108 14fc 09/16 14:03:55 2391 FclRestore::OnMsgRestoreEnd() - sending FSR_MSG_RESTORE_END to FSRestoreHead 108 14fc 09/16 14:03:55 2391 FclRestore::sendMsgToRestoreHead() - Could not send FSR_MSG_RESTORE_END to Restore Head - not connected! 108 14fc 09/16 14:03:55 2391 FClRestore::processRestoreMsgs() - Exiting the thread... 108 2714 09/16 14:03:55 2391 FclRestore::receiveRestoreMsgs() - Waking up after FSR_MSG_RESTORE_END has been processed 108 2714 09/16 14:03:55 2391 FclRestore::SuspendRestoreMessageProcessor()() - Resuming Restore Message Processor 108 2714 09/16 14:03:55 2391 FclRestore::receiveRestoreMsgs() - Waiting for children threads to complete... 108 2714 09/16 14:03:55 2391 FclRestore::receiveRestoreMsgs() - Exiting the thread... 108 2714 09/16 14:03:55 2391 ::main() - Finished receiving messages. Shutting down. 108 2714 09/16 14:03:55 2391 NasRestore::finalize() - Files restored : [1], Files that failed or had errors during restore : [0] 108 2714 09/16 14:03:55 2391 NasMedia::cleanup() - setting the current tape position to 0 - will reset the tape position. 108 2714 09/16 14:03:55 2391 stat- ID [Job Progress Update], Samples [8], Time [0.000587] Sec(s), Average [0.000073] Sec/Sample 108 2714 09/16 14:03:55 2391 FclRestore::finalize() - Restore successful - sending FSR_MSG_RESTORE_END 108 2714 09/16 14:03:55 2391 Using default close pipeline args for a backup, backupState is not being set 108 2714 09/16 14:03:55 2391 CVJobCtrlLog::unregisterProcess(): successfully removed file [C:\Program Files\NetApp\SnapProtect\Base\JobControl\0.108] 108 2714 09/16 14:03:56 2391 ::main() - Exiting... 108 2714 09/16 14:03:56 2391 JOBRESULTSTABLE(C:\Program Files\NetApp\SnapProtect\iDataAgent\JobResults\CV_JobResults\2\0\2391\Job removing copy 'C:\Program Files\NetApp\SnapProtect\iDataAgent\JobResults\CV_JobResults\2\0\2391' 108 2714 09/16 14:03:56 2391 ** CVSession::sendBytes(...) iSocketMember=992 send failed, err=0x8007276D:{QiSocket.cpp[CQiSocket::Send(397)]/W32.10093.(Either the application has not called WSAStartup, or WSAStartup failed.)}. 108 2714 09/16 14:03:56 2391 ** CVSession::disconnect (void) @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Machine : spiderman File : StartRestore.log @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 11876 1540 09/16 13:56:28 2391 STARTRESTORE Resetting to time [0] to current time [1442404586] 11876 1540 09/16 13:56:28 2391 STARTRESTORE To time is changed from [1442404586] to archive file creation time [1442370632] returned by getArchFileByTime for backupset [5] reference time [1442404586] 11876 1540 09/16 13:56:28 2391 Init() - Initializing job control [token=No Token,cn=spiderman] in single threaded mode, serverName [Instance001], ControlFlag [1], Job Id [2391] 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE options - 0x8c0 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE Restore Options - ER_UNCONDITIONAL | ER_PRESERVE_LEVEL | ER_NONFULLREGISTRY 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE synthetic full - no 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE commcell - 2 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE source client - 3 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE dest client - 1005 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE apptype - 13 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE instance - 1 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE backupset = 5 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE subclient - 6 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE from time - 0 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE to time - 1442370632 2015/09/16 04:30:32 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE source path - [/svm01/vol_orabckp/expdp/pris/expdp_export_cumulative.log] 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE dest path - [C:\tmp] 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE copy - 0 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE em function - 0 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE em firstnode - 0 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE em skipnodes - 0 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE em page size - -1 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE skip errors and continue - [false] 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE checking whether super restore should be applied 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE filter browse XML string [] 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE converting restore job into a single subclient restore for subclient [6] 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE starting regular restore 11876 2cc0 09/16 13:56:29 2391 FSSubclientConf::load(857) - +++ 11876 2cc0 09/16 13:56:29 2391 FSSubclientConf::load(857) - --- 0:00.086676 11876 2cc0 09/16 13:56:29 2391 STARTRESTORE start operation on subclient id [6] name [Orabckp] backupset id [5] 11876 2cc0 09/16 13:56:30 2391 STARTRESTORE SECURITY: canRestore() returned true for subclientId (6). User (2), commCell (2), srcClientId (3), destClientId (1005), appTypeId (13), instance (1), backupSet (5), inPlace = (false) impersonateUser = (false) machineUId=(). 11876 2cc0 09/16 13:56:30 2391 STARTRESTORE filter browse XML string [] 11876 2cc0 09/16 13:56:30 2391 STARTRESTORE Non-snap restore for non-DB restore 11876 2cc0 09/16 13:56:30 2391 STARTRESTORE connecting to MediaAgent 'spiderman.hrt.hr*spiderman*8400*8402' 11876 2cc0 09/16 13:56:31 2391 STARTRESTORE Sending source path '/svm01/vol_orabckp/expdp/pris/expdp_export_cumulative.log' with strip level 4 11876 2cc0 09/16 13:56:31 2391 STARTRESTORE Sending destination path 'C:\tmp' 11876 2770 09/16 14:03:55 2391 STARTRESTORE File Statistics: Succeeded [1], Skipped [0] Failed [0] 11876 2770 09/16 14:03:56 2391 STARTRESTORE Received FSR_MSG_RESTORE_END 11876 29cc 09/16 14:04:07 2391 STARTRESTORE Received disconnect request 11876 29cc 09/16 14:04:07 2391 STARTRESTORE Disconnected MA session completed restore 11876 2cc0 09/16 14:04:08 2391 STARTRESTORE Success | Partial Success | Failure: Total files [1], Succeeded [1], Transferred [0], Skipped [0], Failed [0], MaAttach [true] 11876 2cc0 09/16 14:04:08 2391 Sending SUCCESS complete message to JM, 2391 @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Machine : vmvcenter File : CVNRDS.log @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 10784 4a7c 09/16 13:56:53 2391 main() - ============================================ 10784 4a7c 09/16 13:56:53 2391 main() - ----------------- STARTED ----------------- 10784 4a7c 09/16 13:56:53 2391 main() - ============================================ 10784 4a7c 09/16 13:56:53 2391 main() - CVNRDS.exe -l ndmp -p 39b87acfec63e189d0906fb4cabcb115b06a64ae3ac14aa86 -j 2391 -cn vmvcenter -cn vmvcenter cvshost:spiderman.hrt.hr*spiderman cvsport:65341:0 cvsmyplatform:4 cvsremoteplatform:2 -vm Instance001 10784 4a7c 09/16 13:56:53 2391 Init() - Initializing job control [token=,cn=vmvcenter], serverName [spiderman.hrt.hr], ControlFlag [4], Job Id [2391] 10784 4a7c 09/16 13:56:53 2391 Cvcl::init() - CVCL: Running in FIPS Mode 10784 4a7c 09/16 13:56:54 2391 CVJobCtrlLog::registerProcess(): successfully created file [C:\Program Files\NetApp\SnapProtect\Base\JobControl\10.784] 10784 4a7c 09/16 13:56:54 2391 CompleteStartup() - Process was created using IPv4. 10784 4a7c 09/16 13:56:54 2391 CompleteStartup() - Going to listen on host:[vmvcenter]. Listening on all IPv4 interfaces. 10784 4a7c 09/16 13:56:54 2391 CompleteStartup() - Going to listen on socket [548] port [51872]. 10784 4a7c 09/16 13:56:54 2391 CompleteStartup() - Send to NAS iDA NDMP port [51872] binded to socket 10784 4a7c 09/16 13:56:57 2391 ndmp.cpp 3513 NOTIFY_CONNECTED: protocol_version[4] 10784 4a7c 09/16 13:56:57 2391 ndmp.cpp 3521 NOTIFY_CONNECTED: successful 10784 4a7c 09/16 13:56:57 2391 ndmp.cpp 3480 NDMP_CONNECT_OPEN reply 10784 4a7c 09/16 13:56:57 2391 ndmp.cpp 3491 NDMP_CONNECT_OPEN reply: successful 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4300 NDMP_CONFIG_GET_SERVER_INFO reply: Vendor[CommVault Systems] Product[Galaxy] Revision[10.0.0(BUILD116)] Auth:[2] 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4329 NDMP_CONFIG_GET_SERVER_INFO reply: successful 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4073 NDMP_CONFIG_GET_AUTH_ATTR reply: Error[0] AuthType[2] 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4095 NDMP_CONFIG_GET_AUTH_ATTR reply: successful 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4157 NDMP_CONNECT_CLIENT_AUTH reply: Error[0] 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4177 NDMP_CONNECT_CLIENT_AUTH reply: successful 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4054 AUTHENTICATION successful 10784 4a7c 09/16 13:56:57 2391 NRDS debug level as given by registry key NDMP_API/\nNRDSLOGLEVEL is set to 1 10784 4a7c 09/16 13:56:57 2391 runMainLoop() - Registering call backs for NRDS 10784 4a7c 09/16 13:56:57 2391 Waiting for next NDMP message. TimeOut [9000] 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4352 NDMP_CONFIG_GET_HOST_INFO reply: Host[vmvcenter] OsType[Windows Server x64] Version[6.1Build 7601: Service Pack 1] ID:[A014F14] 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4378 NDMP_CONFIG_GET_HOST_INFO reply: successful 10784 4a7c 09/16 13:56:57 2391 Waiting for next NDMP message. TimeOut [9000] 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4300 NDMP_CONFIG_GET_SERVER_INFO reply: Vendor[CommVault Systems] Product[Galaxy] Revision[10.0.0(BUILD116)] Auth:[2] 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4329 NDMP_CONFIG_GET_SERVER_INFO reply: successful 10784 4a7c 09/16 13:56:57 2391 Waiting for next NDMP message. TimeOut [9000] 10784 4a7c 09/16 13:56:57 2391 ************ GET_EXTENSION_LIST ************ 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4231 NDMP_CONFIG_GET_EXT_LIST reply 10784 4a7c 09/16 13:56:57 2391 ndmp_v4.cpp 4276 NDMP_CONFIG_GET_EXT_LIST reply: successful 10784 4a7c 09/16 13:56:57 2391 ************ GET_EXTENSION_LIST[0] ************ 10784 4a7c 09/16 13:56:57 2391 Waiting for next NDMP message. TimeOut [9000] 10784 4a7c 09/16 13:57:12 2391 NdmpDataConnectHandler() - Creating socket to connect to tape server 10784 4a7c 09/16 13:57:12 2391 NdmpDataConnectHandler() - Attempting to connect to IP passed into NDMP_DATA_CONNECT. Using IPv4. 10784 4a7c 09/16 13:57:33 2391 NdmpDataConnectHandler() - NRDS_Error: NdmpDataConnectHandler: Failed to connect to remote tape server::error : 10784 4a7c 09/16 13:57:33 2391 NdmpDataConnectHandler() - NRDS_Error: NdmpDataConnectHandler: 0x8007274C:{QiSocket.cpp[CQiSocket::Connect(224)]/W32.10060.(A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.)} 10784 4a7c 09/16 13:57:33 2391 NdmpDataConnectHandler() - Successfully connected to ip address 10784 4a7c 09/16 13:57:33 2391 ndmp_v4.cpp 5859 NDMP_DATA_CONNECT reply: Error[0] 10784 4a7c 09/16 13:57:33 2391 ndmp_v4.cpp 5879 NDMP_DATA_CONNECT reply: successful 10784 4a7c 09/16 13:57:33 2391 Waiting for next NDMP message. TimeOut [9000] 10784 4a7c 09/16 13:57:35 2391 processStartRecoverRequest() - DAR restore requested 10784 4a7c 09/16 13:57:35 2391 ndmp_v4.cpp 5729 NDMP_DATA_START_RECOVER_CV reply: Error[0] 10784 4a7c 09/16 13:57:35 2391 ndmp_v4.cpp 5749 NDMP_DATA_START_RECOVER_CV reply: successful 10784 4a7c 09/16 13:57:35 2391 Waiting for next NDMP message. TimeOut [9000] 10784 3390 09/16 13:57:35 2391 processDumpData() - Printing the START_RECOVER request variables 10784 3390 09/16 13:57:35 2391 printStartRecoverRequest() - NDMP_DATA_START_RECOVER_CV 10784 3390 09/16 13:57:35 2391 #environmental vars: [16] 10784 3390 09/16 13:57:35 2391 environmental vars: 10784 3390 09/16 13:57:35 2391 var 1 : name = ACL_START , value = 1557968033792 10784 3390 09/16 13:57:35 2391 var 2 : name = BASE_DATE , value = 14327177354 10784 3390 09/16 13:57:35 2391 var 3 : name = CV_FIRST_OFFSET , value = 365568 10784 3390 09/16 13:57:35 2391 var 4 : name = DEBUG , value = N 10784 3390 09/16 13:57:35 2391 var 5 : name = DIRECT , value = Y 10784 3390 09/16 13:57:35 2391 var 6 : name = DUMP_DATE , value = 18622231081 10784 3390 09/16 13:57:35 2391 var 7 : name = ENHANCED_DAR_ENABLED , value = T 10784 3390 09/16 13:57:35 2391 var 8 : name = FILESYSTEM , value = /svm01/vol_orabckp 10784 3390 09/16 13:57:35 2391 var 9 : name = HIST , value = N 10784 3390 09/16 13:57:35 2391 var 10 : name = NDMP_VERSION , value = 4 10784 3390 09/16 13:57:35 2391 var 11 : name = NO_ACLS , value = N 10784 3390 09/16 13:57:35 2391 var 12 : name = PATHNAME_SEPARATOR , value = / 10784 3390 09/16 13:57:35 2391 var 13 : name = RECURSIVE , value = N 10784 3390 09/16 13:57:35 2391 var 14 : name = TYPE , value = dump 10784 3390 09/16 13:57:35 2391 var 15 : name = UPDATE , value = Y 10784 3390 09/16 13:57:35 2391 var 16 : name = VERBOSE , value = N 10784 3390 09/16 13:57:35 2391 #recover names: [1] 10784 3390 09/16 13:57:35 2391 recover names: NOT LOGGED. See NasRestore.log or CvNasSnapRestore.log 10784 3390 09/16 13:57:35 2391 options = RESTORE_OPTION_NOT_IN_PLACE | RESTORE_OPTION_UNCOND_OVERWRITE 10784 3390 09/16 13:57:35 2391 | RESTORE_OPTION_RECURSIVE | RESTORE_OPTION_NDMP_RESTORE 10784 3390 09/16 13:57:35 2391 preprocessRestorePaths() - Sorted source pathnames in ascending order 10784 3390 09/16 13:57:35 2391 ClientHives::ClientHives() - Skipping user hive [\Registry\User\S-1-5-21-809044434-1823356140-929701000-45724] from system state backup, it should be backed up with regular file system backups 10784 3390 09/16 13:57:35 2391 ClientHives::ClientHives() - Skipping user hive [\Registry\User\S-1-5-21-809044434-1823356140-929701000-45724_Classes] from system state backup, it should be backed up with regular file system backups 10784 3390 09/16 13:57:35 2391 Initializing the share monitor as this is not an Index cache restore 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## hal.dll found at C:\Windows\system32\hal.dll 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## ntoskrnl.exe found at C:\Windows\system32\ntoskrnl.exe 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## ntkrnlpa.exe found at C:\Windows\system32\ntkrnlpa.exe 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## kernel32.dll found at C:\Windows\system32\kernel32.dll 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## ntdll.dll found at C:\Windows\system32\ntdll.dll 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## win32k.sys found at C:\Windows\system32\win32k.sys 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## winsrv.dll found at C:\Windows\system32\winsrv.dll 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## bootvid.dll found at C:\Windows\system32\bootvid.dll 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - ## kdcom.dll found at C:\Windows\system32\kdcom.dll 10784 3390 09/16 13:57:35 2391 FsRestoreNTObjectsFactory::FsRestoreNTObjectsFactory() - Simpana currently installed at C:\Program Files\NetApp\SnapProtect 10784 3390 09/16 13:57:35 2391 preprocessRestorePaths() - Created the FsRestoreNTObjectsFactory factory successfully 10784 3390 09/16 13:57:35 2391 preprocessRestorePaths::Number of valid source paths: 1 10784 3390 09/16 13:57:35 2391 Creating the DumpParser & tape buffer for file server::NetApp 10784 3390 09/16 13:57:35 2391 fill_tape_buffer() - sending notify_data_read for offset [0], length [4194304] , chunk_offset [18446744073709551615], chunk_length [18446744073709551615] 10784 3390 09/16 13:57:35 2391 ndmp_v4.cpp 4697 NDMP_NOTIFY_DATA_READ: Offset:[0] Length:[4194304] 10784 3390 09/16 13:57:35 2391 ndmp_v4.cpp 4711 NDMP_NOTIFY_DATA_READ: successful 10784 4a7c 09/16 13:59:35 2391 ndmp_v4.cpp 5612 NDMP_DATA_GET_STATE reply: BytesProcessed:[0] ReadOffset:[0] ReadLen:[4194304] 10784 4a7c 09/16 13:59:35 2391 ndmp_v4.cpp 5644 NDMP_DATA_GET_STATE reply: successful 10784 4a7c 09/16 13:59:35 2391 Waiting for next NDMP message. TimeOut [9000] 10784 3390 09/16 14:00:44 2391 checkDumpHeader() - Dump is a NOT compressed dump 10784 3390 09/16 14:00:44 2391 Dump date: Wed Sep 16 02:04:57 2015 10784 3390 09/16 14:00:44 2391 checkDumpHeader() - Assume WIN32 block size equal to cluster size of 4096 bytes 10784 3390 09/16 14:00:44 2391 checkDumpHeader() - file system block size: 4096 bytes 10784 3390 09/16 14:00:44 2391 checkDumpHeader() - The longest permissible path length defined by Windows documentation: 1024 chars 10784 3390 09/16 14:00:44 2391 parseDumpStream() - Begin parsing file data ... 10784 3390 09/16 14:00:44 2391 parseDumpStream() - Restoring file [/expdp_export_cumulative.log] 10784 3390 09/16 14:00:44 2391 fill_tape_buffer() - sending notify_data_read for offset [1422527511552], length [4194304] , chunk_offset [18446744073709551615], chunk_length [18446744073709551615] 10784 3390 09/16 14:00:44 2391 ndmp_v4.cpp 4697 NDMP_NOTIFY_DATA_READ: Offset:[1422527511552] Length:[4194304] 10784 3390 09/16 14:00:44 2391 ndmp_v4.cpp 4711 NDMP_NOTIFY_DATA_READ: successful 10784 4a7c 09/16 14:01:44 2391 ndmp_v4.cpp 5612 NDMP_DATA_GET_STATE reply: BytesProcessed:[0] ReadOffset:[1422527511552] ReadLen:[4194304] 10784 4a7c 09/16 14:01:44 2391 ndmp_v4.cpp 5644 NDMP_DATA_GET_STATE reply: successful 10784 4a7c 09/16 14:01:44 2391 Waiting for next NDMP message. TimeOut [9000] 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B35474000] [1422528036864] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B354F4400] [1422528562176] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B35574800] [1422529087488] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B355F4C00] [1422529612800] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B35675000] [1422530138112] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B356F5400] [1422530663424] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B35775800] [1422531188736] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 fill_tape_buffer() - sending notify_data_read for offset [1422531705856], length [4194304] , chunk_offset [18446744073709551615], chunk_length [18446744073709551615] 10784 3390 09/16 14:01:57 2391 ndmp_v4.cpp 4697 NDMP_NOTIFY_DATA_READ: Offset:[1422531705856] Length:[4194304] 10784 3390 09/16 14:01:57 2391 ndmp_v4.cpp 4711 NDMP_NOTIFY_DATA_READ: successful 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B357F5C00] [1422531714048] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B35876000] [1422532239360] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 getfile() - Getting next file hdr at tape offset 0x[14B358F6400] [1422532764672] 10784 3390 09/16 14:01:57 2391 getfile() - Successfully read the next header for the same file. 10784 3390 09/16 14:01:57 2391 endOfFileRestore() - Finished restoring file [/expdp_export_cumulative.log] 10784 3390 09/16 14:01:57 2391 Sending the status of the restore to NasRestore 10784 3390 09/16 14:01:57 2391 processDumpData() - Finished parsing the dump stream, time taken [0]Hr:[4]Min:[22]Secs,total # bytes processed [5273444] 10784 3390 09/16 14:01:57 2391 Finished restoring data. NDMP error::0::NDMP_NO_ERR 10784 3390 09/16 14:01:57 2391 Halting the data task with reason 1 10784 3390 09/16 14:01:57 2391 haltDataTask() - Closing the data socket 10784 3390 09/16 14:01:57 2391 ndmp_v4.cpp 4669 NDMP_NOTIFY_DATA_HALTED: Reason:[1=NDMP_DATA_HALT_SUCCESSFUL] 10784 3390 09/16 14:01:57 2391 ndmp_v4.cpp 4682 NDMP_NOTIFY_DATA_HALTED: successful 10784 4a7c 09/16 14:01:57 2391 ndmp_v4.cpp 5612 NDMP_DATA_GET_STATE reply: BytesProcessed:[5273444] ReadOffset:[1422531705856] ReadLen:[4194304] 10784 4a7c 09/16 14:01:57 2391 ndmp_v4.cpp 5644 NDMP_DATA_GET_STATE reply: successful 10784 4a7c 09/16 14:01:57 2391 Waiting for next NDMP message. TimeOut [9000] 10784 4a7c 09/16 14:03:28 2391 ndmp_v4.cpp 5694 NDMP_DATA_STOP reply: Error[0] 10784 4a7c 09/16 14:03:28 2391 ndmp_v4.cpp 5714 NDMP_DATA_STOP reply: successful 10784 4a7c 09/16 14:03:28 2391 Waiting for next NDMP message. TimeOut [9000] 10784 4a7c 09/16 14:03:28 2391 ndmp.cpp 1038 NDMP_CONNECT_CLOSE [] 10784 4a7c 09/16 14:03:28 2391 Waiting for next NDMP message. TimeOut [9000] 10784 4a7c 09/16 14:03:28 2391 ndmp.cpp 1379 NDMP_CONNECTION_CLOSED 10784 4a7c 09/16 14:03:28 2391 runMainLoop() - MsgReceive returned [-1]. NDMP Message [654311549]==[NDMP_CONNECTION_CLOSED] 10784 4a7c 09/16 14:03:28 2391 runMainLoop() - Exiting.. 10784 4a7c 09/16 14:03:28 2391 ~CVNdmpTapeBuffer() - freed tape buffer 10784 4a7c 09/16 14:03:28 2391 ~CVNdmpTapeBuffer() - destructor called 10784 4a7c 09/16 14:03:28 2391 CVJobCtrlLog::unregisterProcess(): successfully removed file [C:\Program Files\NetApp\SnapProtect\Base\JobControl\10.784] 10784 4a7c 09/16 14:03:28 2391 main() - ============================================ 10784 4a7c 09/16 14:03:28 2391 main() - ----------------- STOPPED ----------------- 10784 4a7c 09/16 14:03:28 2391 main() - ============================================