Solved

Problem with AuxCopy job to qnap


Badge +4

Hello community!

I’m running into issue with AuxCopy job for one of my Plans in Commvault.

This job is a selective secondary copy, which should copy weekly friday fulls into Qnap repository.

The destination library is a Qnap library, which was added using uncpath (\\qnap.dns.name\commvault\) and dedicated user with full access permissions for this share.

I have configured a MCSS Cloud library also, and create the same secondary selective copy, with the same configuration - and for cloud storage everything is working fine.

Qnap firmware is the newest possible (we have updated it few days ago, believing this would solve the problem). We also disconnected every other shares from QNAP (now it is dedicated storage for commvault, for keeping additional copies of backup).

The job ends in copy as Partially Copied, when I manually run another AuxCopy job it actually completes without any issues and make a copy job status as “Available”- but it’s not a solution to run an additional aux copy job manually (or scheduled) - I would like to solve a source issue :)

These are the errors from Commcell Console job details window:

Error Code: [13:138] Description: Error occurred while processing chunk [6849] in media [V_371], at the time of error in library [CV_DiskLib1] and mount path [[cvcs] G:\CV_MP2], for storage policy [PROD_Oracle_Full@01:00_ArchiveLog@15min] copy [Secondary_QNAP] MediaAgent [cvcs]: Backup Job [1721]. Unable to send the stop data transfer control message to the tail. . 
Source: cvcs, Process: CVJobReplicatorODS

Error occurred while processing chunk [6836] in media [V_384], at the time of error in library [CV_DiskLib1] and mount path [[cvcs] I:\CV_MP4], for storage policy [PROD_Oracle_Full@01:00_ArchiveLog@15min] copy [Secondary_QNAP] MediaAgent [cvcs]: Backup Job [1721]. Unable to send the stop data transfer control message to the tail. .
Source: cvcs, Process: CVJobReplicatorODS

Error occurred while processing chunk [6813] in media [V_371], at the time of error in library [CV_DiskLib1] and mount path [[cvcs] G:\CV_MP2], for storage policy [PROD_Oracle_Full@01:00_ArchiveLog@15min] copy [Secondary_QNAP] MediaAgent [cvcs]: Ba

Here are the full CVJobReplicatorODS logs:

9576  4d8c  05/21 06:48:21 1856 [PIPELAYER  ] Waiting for pipeline buf. SndIdx [0/2], RCId [5344]
9576 4818 05/21 06:49:05 1856 Waiting for n/w send to complete. BytesToSend [48], Free Bufs [18/90] RCId [5347]
9576 238 05/21 06:49:05 1856 Waiting for n/w send to complete. BytesToSend [48], Free Bufs [18/90] RCId [5348]
9576 48b0 05/21 06:49:06 1856 Waiting for n/w send to complete. BytesToSend [48], Free Bufs [18/90] RCId [5346]
9576 42e0 05/21 06:49:11 1856 Waiting for n/w send to complete. BytesToSend [48], Free Bufs [18/90] RCId [5344]
9576 4178 05/21 06:49:30 1856 Waiting for n/w send to complete. BytesToSend [48], Free Bufs [18/90] RCId [5345]
9576 37c4 05/21 06:49:50 1856 [Coordinator] ==================== Coordinator Current State =======================
9576 37c4 05/21 06:49:50 1856 [Coordinator] Coordinator State : (COORDINATOR_RUNNING)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Stream List:(ReaderId,State,Agent)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Stream Info[1]: (12,STREAM_RECEIVED_BY_AGENT,cvcs)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Stream Info[2]: (13,STREAM_RECEIVED_BY_AGENT,cvcs)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Stream Info[3]: (14,STREAM_RECEIVED_BY_AGENT,cvcs)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Stream Info[4]: (15,STREAM_RECEIVED_BY_AGENT,cvcs)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Stream Info[5]: (16,STREAM_RECEIVED_BY_AGENT,cvcs)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Agent List:(Agent,State)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Agent Info[1]: (cvcs,REPL_AGENT_RUNNING)
9576 37c4 05/21 06:49:50 1856 [Coordinator] Co-ordinator is Waiting for [5] Readers to be processed
9576 37c4 05/21 06:49:50 1856 [Coordinator] =========================================================================
9576 45b8 05/21 06:50:42 1856 [Controller] ==================== Controller Current State =======================
9576 45b8 05/21 06:50:42 1856 [Controller] Controller is Waiting for [5] Readers to be processed. Pending Readers List:[16,15,14,13,12]
9576 45b8 05/21 06:50:42 1856 [Controller] =====================================================================
9576 b98 05/21 06:52:59 1856 CPipelayer::SendPipelineBuffer() - Tail has reported error [97][The destination encountered an error while processing the data from the source.]. Cannot continue.
9576 b98 05/21 06:52:59 1856 [PIPELAYER ] Error in flushing the current buffer.
9576 b98 05/21 06:52:59 1856 [Reader_13] Failed to write the data to the pipeline
9576 b98 05/21 06:52:59 1856 [Reader_13] Cannot process data for the chunk.
9576 b98 05/21 06:52:59 1856 [DM_BASE ] removeAllArchFilesMap(): Removing all the archive file ids from archive file map.
9576 b98 05/21 06:52:59 1856 [Reader_13] Discarding queued chunk list
9576 b98 05/21 06:52:59 1856 CVArchive::StopRawDataTransferOverPipeLine() - Sending message to pipeline that data transfer will stop over the pipeline
9576 b98 05/21 06:52:59 1856 [PIPELAYER ] Data Pipe Is Down
9576 b98 05/21 06:52:59 1856 CCVAPipelayer::SendCommandToDSBackup() - Failed to allocate a command buffer
9576 b98 05/21 06:52:59 1856 CCVAPipelayer::StopRawDataTransferOverPipeLine() - Unable to send StopDataTransfer Command Buffer or DSBackup reported failure
9576 b98 05/21 06:52:59 1856 CVArchive::StopRawDataTransferOverPipeLine() - Error sending message to pipeline that data transfer will stop over the pipeline
9576 b98 05/21 06:52:59 1856 [Reader_13] Cannot signal stop data transfer for archive group [11] copy [26] stream [3]
9576 b98 05/21 06:52:59 1856 [Reader_13] Cannot signal stop data transfer.
9576 b98 05/21 06:52:59 1856 [Reader_13] ProcessTime : [2740]
9576 b98 05/21 06:52:59 1856 [Reader_13] ChunkArray Len [1] [1]
9576 b98 05/21 06:52:59 1856 [Reader_13] ReportStatus Chunk [6811] type [fail]
9576 b98 05/21 06:52:59 1856 [Reader_13] ReportStatus Params Copy/Stream:[16]/[0] Error:[0], MMErrorCode:[0] MA:[cvcs] errorString []
9576 b98 05/21 06:52:59 1856 [Reader_13] ReportStatus Params Copy/Stream:[26]/[3] Error:[3], MMErrorCode:[123] MA:[cvcs] errorString [Unable to send the stop data transfer control message to the tail. ]
9576 b98 05/21 06:52:59 1856 [Reader_13] ReportStatus is successful
9576 b98 05/21 06:52:59 1856 [Reader_13] Report Status Response Type: [2]
9576 b98 05/21 06:52:59 1856 [Reader_13] Report Status Response error Code: [3]
9576 b98 05/21 06:52:59 1856 [Reader_13] Setting JPR for Chunk [6811] Copy[Secondary_QNAP] rcId[5345] MediaType[10001] Error[3] mmError[123] jobStr[ Backup Job [1721]] ErrStr[Unable to send the stop data transfer control message to the tail. ] HardFailure[0]
9576 b98 05/21 06:52:59 1856 [Reader_13] Error handler: ContinueStream set to [False], ContinueOnError set to [False].
9576 b98 05/21 06:52:59 1856 CVArchive::ClosePipeline() - Resetting allocated stream
9576 b98 05/21 06:52:59 1856 [PIPELAYER ] Data Pipe Is Down
9576 b98 05/21 06:52:59 1856 CCVAPipelayer::SendPerfCountersToDSBackup() - Failed to allocate Perf-counters command buffer
9576 b98 05/21 06:52:59 1856 CCVAPipelayer::ClosePipeline() - About to destroy Data Mover
9576 b98 05/21 06:52:59 1856 [PIPELAYER ] Data Pipe Is Down
9576 b98 05/21 06:52:59 1856 CCVAPipelayer::SendCommandToDSBackup() - Failed to allocate a command buffer
9576 b98 05/21 06:52:59 1856 CCVAPipelayer::ClosePipeline() - Failure sending datamover destroy
9576 b98 05/21 06:52:59 1856 CPipelayer::ShutdownPipeline() - stat- SDT [00000155057F7B60] [duration - 2740 seconds]
9576 b98 05/21 06:52:59 1856 CPipelayer::ShutdownPipeline() - pipeline has already been shutdown
9576 b98 05/21 06:52:59 1856 [Reader_13] CVArchive::closePipeline() Failed with return code [-1] for dest copy [26], stream [3].
9576 b98 05/21 06:52:59 1856 ~CVArchive() - Destroying CVArchive. This=000001557E452850
9576 b98 05/21 06:52:59 1856 CPipelayer::ShutdownPipeline() - pipeline has already been shutdown
9576 b98 05/21 06:52:59 1856 SdtBase::relRef: Going to delete SdtBase as ref count is down to 0. RCId [5345]
9576 b98 05/21 06:52:59 1856 SdtBase is being destroyed. RCId [5345]
9576 b98 05/21 06:52:59 1856 Signature processing speed: Type [SHA512], [1469.111379] GB/Hr, Bytes [35207300479], Time [80.349029] Sec(s)
9576 b98 05/21 06:52:59 1856 Name [Head], Start Delay [2343.46 s], Avg [3.49 ms], Procsng Time [61.30 s], Avg [91.38 us], Bytes [33.04 GB], Speed [551.86 MB/s], Samples [670826] RCId [5345]
9576 b98 05/21 06:52:59 1856 Name [Head Signature], Start Delay [1930.67 s], Avg [2.88 ms], Procsng Time [82.87 s], Avg [123.53 us], Bytes [33.04 GB], Speed [408.22 MB/s], Samples [670826] RCId [5345]
9576 b98 05/21 06:52:59 1856 Name [Head CRC32], Start Delay [187.13 s], Avg [278.95 us], Procsng Time [30.37 s], Avg [45.28 us], Bytes [33.10 GB], Speed [1.09 GB/s], Samples [670826] RCId [5345]
9576 b98 05/21 06:52:59 1856 Name [Head Network], Start Delay [189892.98 s], Avg [283.07 ms], Procsng Time [2713.65 s], Avg [4.05 ms], Bytes [33.10 GB], Speed [12.49 MB/s], Samples [670826] RCId [5345]
9576 b98 05/21 06:52:59 1856 Performing graceful connection termination RCId [5345]
9576 b98 05/21 06:52:59 1856 Closing all sockets. RCId [5345]
9576 b98 05/21 06:52:59 1856 [Reader_13] Sent Stream Status [STREAM_COMPLETED_FAILURE] to coordinator.
9576 431c 05/21 06:52:59 #### [REPL_APP]() - Received XML MsgType (3) from Session Handle (16), TagID (183943520) TagName(MediaManager_JobReplStreamStatusReq).
9576 b98 05/21 06:52:59 1856 [Reader_13] Discarding queued chunk list
9576 431c 05/21 06:52:59 #### [REPL_APP]() - Received default XML msg from session Handle: [16], SessionPtr: [0x000001555CFECAA0], type [3], TagID [183943520] TagName[MediaManager_JobReplStreamStatusReq] RemoteClientName [cvcs].
9576 b98 05/21 06:52:59 1856 [Reader_13] Worker Thread cleanup before exit
9576 37c4 05/21 06:52:59 1856 [Coordinator] Received JobReplStreamStatusReq from Agent:cvcs
9576 b98 05/21 06:52:59 1856 [Reader_13] Destorying reader specifics
9576 b98 05/21 06:52:59 1856 [Reader_13] Going to close the media handle of the source media
9576 37c4 05/21 06:52:59 1856 [Coordinator] Stream ReaderId [13] from Agent [cvcs] Status : [STREAM_FAILED]
9576 b98 05/21 06:52:59 1856 [DM_BASE ] Stopping LA thread [0000015562C61D50] loop. Reason [4]
9576 37c4 05/21 06:52:59 #### STREAM COMPLETE CALLED for RCID [5345] 1856
9576 b98 05/21 06:52:59 1856 [DM_BASE ] Stopped LA thread [0000015562C61D50] loop
9576 b98 05/21 06:52:59 1856 [DM_BASE ] CloseChunkSpecific: [Total Physical bytes read - 36648592424] Number Of Links Sent in this chunk [12860], Total bytes [1216179627] saved
9576 b98 05/21 06:52:59 1856 [DM_BASE ] LookAheadCtrs: Links (CacheHit/Exp/UnExp/Total): 0/391002/12860/403865
9576 37c4 05/21 06:52:59 1856 JM Client Freeing rcid [5345]
9576 b98 05/21 06:52:59 1856 [DM_BASE ] SfileRdrCtrs: Blks read [980137], Runs [18022], Run Len [34704912.00] KB (33891.52 MB), Random Pcnt [64.27%], Async Reads [288364], MPIds [4], Files: Hits/Opened [7984/2294 (W:2294+NO:0+O:0+I:0)]
9576 b98 05/21 06:52:59 1856 [DM_BASE ] SfileRdrCtrs: [Open File] Exp Avg [0.00], Total Avg [0.00], Total Time [5.31], Total Count [2294]
9576 b98 05/21 06:52:59 1856 [DM_BASE ] Releasing the volume and drive reservation on the media manager
9576 b98 05/21 06:52:59 1856 [DM_BASE ] LookAheadCtrs: Links (CacheHit/Exp/UnExp/Total): 0/391002/12860/403865
9576 b98 05/21 06:52:59 1856 [DM_BASE ] SfileRdrCtrs: Blks read [980137], Runs [18022], Run Len [34704912.00] KB (33891.52 MB), Random Pcnt [64.27%], Async Reads [288364], MPIds [4], Files: Hits/Opened [7984/2294 (W:2294+NO:0+O:0+I:0)]
9576 b98 05/21 06:52:59 1856 [DM_BASE ] SfileRdrCtrs: [Open File] Exp Avg [0.00], Total Avg [0.00], Total Time [5.31], Total Count [2294]
9576 2c80 05/21 06:52:59 1856 [DM_BASE ] ReadAhead: Received exit command.
9576 2c80 05/21 06:52:59 1856 [DM_BASE ] ReadAhead: LookAhead thread exiting.
9576 b98 05/21 06:52:59 1856 [DM_BASE ] CSfileRdr::DeInit: Sfile Cached Info size is [0 + 2]
9576 b98 05/21 06:52:59 1856 [DM_BASE ] Lookahead MPBlkInfo MPId:Blks {5:406, 6:966099, 7:7075, 8:6557, }
9576 b98 05/21 06:52:59 1856 stat- ID [Avg Open File Recvry], Samples [2294], Time [5.309955] Sec(s), Average [0.002315] Sec/Sample
9576 b98 05/21 06:52:59 #### stat- ID [Grp [00] Avg QueryPrimary], Samples [202182], Time [30.769009] Sec(s), Average [0.000152] Sec/Sample
9576 b98 05/21 06:52:59 #### stat- ID [Grp [01] Avg QueryPrimary], Samples [201681], Time [30.595806] Sec(s), Average [0.000152] Sec/Sample
9576 b98 05/21 06:52:59 1856 [DM_BASE ] Destroyed DataMoverBase for MediaGroupId=[0]
9576 b98 05/21 06:52:59 1856 stat- ID [DMBaseChunkClose], Samples [2], Time [0.014013] Sec(s), Average [0.007007] Sec/Sample
9576 b98 05/21 06:52:59 1856 [Reader_13] Worker Thread is exiting
9576 37c4 05/21 06:52:59 1856 [Coordinator] Freed rcid [5345] for CopyId:[26]
9576 45b8 05/21 06:53:00 1856 [Controller] Reporting status for reader [13] on exit. Worker count [5].
9576 45b8 05/21 06:53:00 1856 [Reader_13] Inside destructor of ReplicatorBae Object
9576 45b8 05/21 06:53:00 1856 stat- ID [Media Read Speed], Job Id [1856], Bytes [35436322237], Time [55.937871] Sec(s), Average Speed [604.147242] MB/Sec
9576 45b8 05/21 06:53:00 1856 stat- ID [Next chunk recv times], Job Id [1856], Samples [1], Time [0.024801] Sec(s), Average [0.024801] Sec/Sample
9576 45b8 05/21 06:53:00 1856 stat- ID [Media Open Times], Job Id [1856], Samples [1], Time [2.355210] Sec(s), Average [2.355210] Sec/Sample
9576 45b8 05/21 06:53:00 1856 stat- ID [PL Alloc Times], Job Id [1856], Samples [670818], Time [2669.740044] Sec(s), Average [0.003980] Sec/Sample
9576 45b8 05/21 06:53:00 1856 [Reader_13] Destorying JobRepl Thread Args
9576 45b8 05/21 06:53:00 1856 [Reader_13] Destorying shared members.
9576 45b8 05/21 06:53:00 1856 [Reader_13] Destorying reader specifics
9576 37c4 05/21 06:53:34 1856 [JobCtrl] Asking for [5] additional reservation resources.
9576 37c4 05/21 06:53:34 1856 JM Client Request to allocate additiona streams [5], noRunningStreams[false]
9576 37c4 05/21 06:53:34 1856 JM Client CVJobClient::allocateGenericResource(), The resource request identifier is [Global\1856_9576_1653111809_WAIT$Global\1856_9576_1653120756_SHM]
9576 37c4 05/21 06:53:34 1856 JM Client CVJobClient::allocateGenericResource() - The resource allocation request for job returned ErrorCode[2], ErrorMessage[]
9576 37c4 05/21 06:53:34 1856 [JobCtrl] return value from Allocate Request: [2]..
9576 37c4 05/21 06:53:34 1856 [Coordinator] Reservation Status: No new readers can be allocated, check for additional streams after [900] seconds, pending streams [4]
9576 1678 05/21 06:54:28 1856 CPipelayer::SendPipelineBuffer() - Tail has reported error [97][The destination encountered an error while processing the data from the source.]. Cannot continue.
9576 1678 05/21 06:54:28 1856 [PIPELAYER ] Error in flushing the current buffer.
9576 1678 05/21 06:54:28 1856 [Reader_16] Failed to write the data to the pipeline
9576 1678 05/21 06:54:28 1856 [Reader_16] Cannot process data for the chunk.
9576 1678 05/21 06:54:28 1856 [DM_BASE ] removeAllArchFilesMap(): Removing all the archive file ids from archive file map.
9576 1678 05/21 06:54:28 1856 [Reader_16] Discarding queued chunk list
9576 1678 05/21 06:54:28 1856 CVArchive::StopRawDataTransferOverPipeLine() - Sending message to pipeline that data transfer will stop over the pipeline
9576 1678 05/21 06:54:28 1856 [PIPELAYER ] Data Pipe Is Down
9576 1678 05/21 06:54:28 1856 CCVAPipelayer::SendCommandToDSBackup() - Failed to allocate a command buffer
9576 1678 05/21 06:54:28 1856 CCVAPipelayer::StopRawDataTransferOverPipeLine() - Unable to send StopDataTransfer Command Buffer or DSBackup reported failure
9576 1678 05/21 06:54:28 1856 CVArchive::StopRawDataTransferOverPipeLine() - Error sending message to pipeline that data transfer will stop over the pipeline
9576 1678 05/21 06:54:28 1856 [Reader_16] Cannot signal stop data transfer for archive group [11] copy [26] stream [6]
9576 1678 05/21 06:54:28 1856 [Reader_16] Cannot signal stop data transfer.
9576 1678 05/21 06:54:28 1856 [Reader_16] ProcessTime : [2829]
9576 1678 05/21 06:54:28 1856 [Reader_16] ChunkArray Len [1] [1]
9576 1678 05/21 06:54:28 1856 [Reader_16] ReportStatus Chunk [6835] type [fail]
9576 1678 05/21 06:54:28 1856 [Reader_16] ReportStatus Params Copy/Stream:[16]/[0] Error:[0], MMErrorCode:[0] MA:[cvcs] errorString []
9576 1678 05/21 06:54:28 1856 [Reader_16] ReportStatus Params Copy/Stream:[26]/[6] Error:[3], MMErrorCode:[123] MA:[cvcs] errorString [Unable to send the stop data transfer control message to the tail. ]
9576 1678 05/21 06:54:28 1856 [Reader_16] ReportStatus is successful
9576 1678 05/21 06:54:28 1856 [Reader_16] Report Status Response Type: [2]
9576 1678 05/21 06:54:28 1856 [Reader_16] Report Status Response error Code: [3]
9576 1678 05/21 06:54:28 1856 [Reader_16] Setting JPR for Chunk [6835] Copy[Secondary_QNAP] rcId[5348] MediaType[10001] Error[3] mmError[123] jobStr[ Backup Job [1721]] ErrStr[Unable to send the stop data transfer control message to the tail. ] HardFailure[0]
9576 1678 05/21 06:54:28 1856 [Reader_16] Error handler: ContinueStream set to [False], ContinueOnError set to [False].
9576 1678 05/21 06:54:28 1856 CVArchive::ClosePipeline() - Resetting allocated stream
9576 1678 05/21 06:54:28 1856 [PIPELAYER ] Data Pipe Is Down
9576 1678 05/21 06:54:28 1856 CCVAPipelayer::SendPerfCountersToDSBackup() - Failed to allocate Perf-counters command buffer
9576 1678 05/21 06:54:28 1856 CCVAPipelayer::ClosePipeline() - About to destroy Data Mover
9576 1678 05/21 06:54:28 1856 [PIPELAYER ] Data Pipe Is Down
9576 1678 05/21 06:54:28 1856 CCVAPipelayer::SendCommandToDSBackup() - Failed to allocate a command buffer
9576 1678 05/21 06:54:28 1856 CCVAPipelayer::ClosePipeline() - Failure sending datamover destroy
9576 1678 05/21 06:54:28 1856 CPipelayer::ShutdownPipeline() - stat- SDT [000001555CE14650] [duration - 2829 seconds]
9576 1678 05/21 06:54:28 1856 CPipelayer::ShutdownPipeline() - pipeline has already been shutdown
9576 1678 05/21 06:54:28 1856 [Reader_16] CVArchive::closePipeline() Failed with return code [-1] for dest copy [26], stream [6].
9576 1678 05/21 06:54:28 1856 ~CVArchive() - Destroying CVArchive. This=000001557E453760
9576 1678 05/21 06:54:28 1856 CPipelayer::ShutdownPipeline() - pipeline has already been shutdown
9576 1678 05/21 06:54:28 1856 SdtBase::relRef: Going to delete SdtBase as ref count is down to 0. RCId [5348]
9576 1678 05/21 06:54:28 1856 SdtBase is being destroyed. RCId [5348]
9576 1678 05/21 06:54:28 1856 Signature processing speed: Type [SHA512], [890.899724] GB/Hr, Bytes [8489060155], Time [31.947245] Sec(s)
9576 1678 05/21 06:54:28 1856 Name [Head], Start Delay [788.02 s], Avg [5.01 ms], Procsng Time [20.54 s], Avg [130.66 us], Bytes [7.97 GB], Speed [397.33 MB/s], Samples [157235] RCId [5348]
9576 1678 05/21 06:54:28 1856 Name [Head Signature], Start Delay [241.40 s], Avg [1.54 ms], Procsng Time [33.04 s], Avg [210.14 us], Bytes [7.97 GB], Speed [247.05 MB/s], Samples [157235] RCId [5348]
9576 1678 05/21 06:54:28 1856 Name [Head CRC32], Start Delay [8.21 s], Avg [52.20 us], Procsng Time [12.16 s], Avg [77.33 us], Bytes [7.99 GB], Speed [672.89 MB/s], Samples [157235] RCId [5348]
9576 1678 05/21 06:54:28 1856 Name [Head Network], Start Delay [199721.30 s], Avg [1.27 s], Procsng Time [2821.11 s], Avg [17.94 ms], Bytes [7.99 GB], Speed [2.90 MB/s], Samples [157235] RCId [5348]
9576 1678 05/21 06:54:28 1856 Performing graceful connection termination RCId [5348]
9576 1678 05/21 06:54:28 1856 Closing all sockets. RCId [5348]
9576 1678 05/21 06:54:28 1856 [Reader_16] Sent Stream Status [STREAM_COMPLETED_FAILURE] to coordinator.
9576 431c 05/21 06:54:28 #### [REPL_APP]() - Received XML MsgType (3) from Session Handle (16), TagID (183943520) TagName(MediaManager_JobReplStreamStatusReq).
9576 1678 05/21 06:54:28 1856 [Reader_16] Discarding queued chunk list
9576 1678 05/21 06:54:28 1856 [Reader_16] Worker Thread cleanup before exit
9576 431c 05/21 06:54:28 #### [REPL_APP]() - Received default XML msg from session Handle: [16], SessionPtr: [0x000001555CFECAA0], type [3], TagID [183943520] TagName[MediaManager_JobReplStreamStatusReq] RemoteClientName [cvcs].
9576 1678 05/21 06:54:28 1856 [Reader_16] Destorying reader specifics
9576 37c4 05/21 06:54:28 1856 [Coordinator] Received JobReplStreamStatusReq from Agent:cvcs
9576 1678 05/21 06:54:28 1856 [Reader_16] Going to close the media handle of the source media
9576 1678 05/21 06:54:28 1856 [DM_BASE ] Stopping LA thread [0000015562C5BEA0] loop. Reason [4]
9576 37c4 05/21 06:54:28 1856 [Coordinator] Stream ReaderId [16] from Agent [cvcs] Status : [STREAM_FAILED]
9576 1678 05/21 06:54:28 1856 [DM_BASE ] Stopped LA thread [0000015562C5BEA0] loop
9576 1678 05/21 06:54:28 1856 [DM_BASE ] CloseChunkSpecific: [Total Physical bytes read - 2996998830] Number Of Links Sent in this chunk [0], Total bytes [0] saved
9576 1678 05/21 06:54:28 1856 [DM_BASE ] LookAheadCtrs: Links (CacheHit/Exp/UnExp/Total): 0/106327/2291/108621
9576 1678 05/21 06:54:28 1856 [DM_BASE ] SfileRdrCtrs: Blks read [138218], Runs [5038], Run Len [8390677.00] KB (8194.02 MB), Random Pcnt [30.29%], Async Reads [70389], MPIds [4], Files: Hits/Opened [3616/538 (W:538+NO:0+O:0+I:0)]
9576 1678 05/21 06:54:28 1856 [DM_BASE ] SfileRdrCtrs: [Open File] Exp Avg [0.00], Total Avg [0.00], Total Time [0.19], Total Count [538]
9576 37c4 05/21 06:54:28 #### STREAM COMPLETE CALLED for RCID [5348] 1856
9576 37c4 05/21 06:54:28 1856 JM Client Freeing rcid [5348]
9576 1678 05/21 06:54:28 1856 [DM_BASE ] Releasing the volume and drive reservation on the media manager
9576 1678 05/21 06:54:28 1856 [DM_BASE ] LookAheadCtrs: Links (CacheHit/Exp/UnExp/Total): 0/106327/2291/108621
9576 1678 05/21 06:54:28 1856 [DM_BASE ] SfileRdrCtrs: Blks read [138218], Runs [5038], Run Len [8390677.00] KB (8194.02 MB), Random Pcnt [30.29%], Async Reads [70389], MPIds [4], Files: Hits/Opened [3616/538 (W:538+NO:0+O:0+I:0)]
9576 1678 05/21 06:54:28 1856 [DM_BASE ] SfileRdrCtrs: [Open File] Exp Avg [0.00], Total Avg [0.00], Total Time [0.19], Total Count [538]
9576 2a40 05/21 06:54:28 1856 [DM_BASE ] ReadAhead: Received exit command.
9576 2a40 05/21 06:54:28 1856 [DM_BASE ] ReadAhead: LookAhead thread exiting.
9576 1678 05/21 06:54:28 1856 [DM_BASE ] CSfileRdr::DeInit: Sfile Cached Info size is [0 + 2]
9576 1678 05/21 06:54:28 1856 [DM_BASE ] Lookahead MPBlkInfo MPId:Blks {5:8028, 6:100188, 7:29978, 8:24, }
9576 1678 05/21 06:54:28 1856 stat- ID [Avg Open File Recvry], Samples [538], Time [0.189906] Sec(s), Average [0.000353] Sec/Sample
9576 1678 05/21 06:54:28 #### stat- ID [Grp [00] Avg QueryPrimary], Samples [54488], Time [5.185335] Sec(s), Average [0.000095] Sec/Sample
9576 1678 05/21 06:54:28 #### stat- ID [Grp [01] Avg QueryPrimary], Samples [54132], Time [5.276213] Sec(s), Average [0.000097] Sec/Sample
9576 1678 05/21 06:54:28 1856 [DM_BASE ] Destroyed DataMoverBase for MediaGroupId=[0]
9576 1678 05/21 06:54:28 1856 stat- ID [DMBaseChunkClose], Samples [3], Time [0.057198] Sec(s), Average [0.019066] Sec/Sample
9576 1678 05/21 06:54:28 1856 [Reader_16] Worker Thread is exiting
9576 37c4 05/21 06:54:28 1856 [Coordinator] Freed rcid [5348] for CopyId:[26]
9576 45b8 05/21 06:54:32 1856 [Controller] Reporting status for reader [16] on exit. Worker count [4].
9576 45b8 05/21 06:54:32 1856 [Reader_16] Inside destructor of ReplicatorBae Object
9576 45b8 05/21 06:54:32 1856 stat- ID [Media Read Speed], Job Id [1856], Bytes [8550904375], Time [18.386810] Sec(s), Average Speed [443.512371] MB/Sec
9576 45b8 05/21 06:54:32 1856 stat- ID [Next chunk recv times], Job Id [1856], Samples [1], Time [0.059166] Sec(s), Average [0.059166] Sec/Sample
9576 45b8 05/21 06:54:32 1856 stat- ID [Media Open Times], Job Id [1856], Samples [2], Time [1.862827] Sec(s), Average [0.931413] Sec/Sample
9576 45b8 05/21 06:54:32 1856 stat- ID [PL Alloc Times], Job Id [1856], Samples [157226], Time [2798.285562] Sec(s), Average [0.017798] Sec/Sample
9576 45b8 05/21 06:54:32 1856 [Reader_16] Destorying JobRepl Thread Args
9576 45b8 05/21 06:54:32 1856 [Reader_16] Destorying shared members.
9576 45b8 05/21 06:54:32 1856 [Reader_16] Destorying reader specifics
9576 465c 05/21 06:54:54 1856 [DM_BASE ] ReadAheadLinks: Reached MD EOF. ChunkMD#=91, LinksRd=548534
9576 465c 05/21 06:54:54 1856 [DM_BASE ] ReadAheadLinks: Reached MD EOF. ChunkMD#=91, LinksRd=548641
9576 8f4 05/21 06:54:56 1856 [DM_BASE ] Completed Reading the chunk
9576 8f4 05/21 06:54:56 1856 [Reader_14] Reached EndOfChunk for copy
9576 8f4 05/21 06:54:56 1856 ChunkIndex:[2] , chunkArray_len:[9]
9576 8f4 05/21 06:54:56 1856 [Reader_14] +++ JobReplicator Thread Params +++
9576 8f4 05/21 06:54:56 1856 [Reader_14] Storage Policy [PROD_Oracle_Full@01:00_ArchiveLog@15min] ID [11]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Source Copy [Primary] ID [16] Is Dedup Copy [1]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Soruce Stream [0] MediaGroup ID [0]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Source DrivePool ID [2] Type [10001]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Target Copy [Secondary_QNAP] ID [26] Is Dedup Copy [1]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Target Stream [4] MediaGroup ID [2257]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Target DrivePool ID [4] Type [10001]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Target RC ID [5346] Source RC ID [0]
9576 8f4 05/21 06:54:56 1856 [Reader_14] +++ Source Chunk Info +++
9576 8f4 05/21 06:54:56 1856 [Reader_14] Source ChunkId [6816]
9576 8f4 05/21 06:54:56 1856 [Reader_14] CommCellId [2]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Source VolumeId [383]
9576 8f4 05/21 06:54:56 1856 [Reader_14] File Marker Number [5]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Chunk Physical Size [4269052010]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Chunk Logical Size [13102481408]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Number of ArchFiles [1]
9576 8f4 05/21 06:54:56 1856 [Reader_14] isSDM [0]
9576 8f4 05/21 06:54:56 1856 [Reader_14] +++ Archive File Info +++
9576 8f4 05/21 06:54:56 1856 [Reader_14] 1. Archive File ID [3437]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Backup JobId [1721] ClientId [0] iDATypeId [0] AppId [55]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Logical Size [13102481408] offset [143822946304]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Physical Size [4269052010] offset [46110987128]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Chunk Number [3] Last Chunk Number [9]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Encrypted [0] SI [1] CV SI [1] CV SI WEB [0] Flags [23] Extra Flags [0]
9576 8f4 05/21 06:54:56 1856 [Reader_14] 1. Target Copy ID [26]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Encryption Type [0] Key Len [0]
9576 8f4 05/21 06:54:56 1856 [Reader_14] Physical ReadStartoffset [0] Logical ReadStartoffset [0]
9576 8f4 05/21 06:54:56 1856 [Reader_14] %% Use Regular AUX COPY %%
9576 8f4 05/21 06:54:56 1856 [Reader_14] DataReader is already initialised. No need to initialize again.
9576 8f4 05/21 06:54:56 1856 [Reader_14] Setup pipeline completed.
9576 8f4 05/21 06:54:56 1856 [Reader_14] Ready to send data over the pipeline.
9576 8f4 05/21 06:54:56 1856 [DM_BASE ] CloseChunkSpecific: [Total Physical bytes read - 4268381507] Number Of Links Sent in this chunk [0], Total bytes [0] saved
9576 8f4 05/21 06:54:56 1856 [DM_CHUNK ] Got new Chunk Info. ChunkId [6816], CommcellId [2], CopyId[16], VolumeId [383], FileNumber [5], NumberOfArchFiles [1]
9576 8f4 05/21 06:54:56 1856 [DM_BASE ] Opening the Chunk =6816, ArchFileId = 3437, FileMarker=5, ArchFilePhysSizeInChunk=4269052010 VolId=383
9576 8f4 05/21 06:54:56 1856 CCVAPipelayer::SetEncryptProps() - Archfile(3437 )
9576 8f4 05/21 06:54:56 1856 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 156 to MediaAgent, Waiting for Response...
9576 8f4 05/21 06:54:56 1856 [PIPELAYER ] Tail response = Get PL_SET_ENC_PROPS Message Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 156 EventError = 0
9576 8f4 05/21 06:54:56 1856 [Reader_14] Successfully opened the archive files on the media...going to read data.
9576 8f4 05/21 06:54:56 1856 [DM_BASE ] Starting read ahead. MDChunkId [6816], OffQInUse [0], AfId [3437], Offset [Af:46110987128, Md:65536, Fs:-1], ChunkOff [46110987128-50380039138], CloudLaptop [0]
9576 465c 05/21 06:54:56 1856 [DM_BASE ] Started LA loop. Batches=16, Links=436466/112175/548641, Offset:65536
9576 45b8 05/21 06:55:43 1856 [Controller] ==================== Controller Current State =======================
9576 45b8 05/21 06:55:43 1856 [Controller] Controller is Waiting for [3] Readers to be processed. Pending Readers List:[15,14,12]
9576 45b8 05/21 06:55:43 1856 [Controller] =====================================================================
9576 462c 05/21 06:56:46 1856 CPipelayer::SendPipelineBuffer() - Tail has reported error [97][The destination encountered an error while processing the data from the source.]. Cannot continue.
9576 462c 05/21 06:56:46 1856 [PIPELAYER ] Error in flushing the current buffer.
9576 462c 05/21 06:56:46 1856 [Reader_15] Failed to write the data to the pipeline
9576 462c 05/21 06:56:46 1856 [Reader_15] Cannot process data for the chunk.
9576 462c 05/21 06:56:46 1856 [DM_BASE ] removeAllArchFilesMap(): Removing all the archive file ids from archive file map.
9576 462c 05/21 06:56:46 1856 [Reader_15] Discarding queued chunk list
9576 462c 05/21 06:56:46 1856 CVArchive::StopRawDataTransferOverPipeLine() - Sending message to pipeline that data transfer will stop over the pipeline
9576 462c 05/21 06:56:46 1856 [PIPELAYER ] Data Pipe Is Down
9576 462c 05/21 06:56:46 1856 CCVAPipelayer::SendCommandToDSBackup() - Failed to allocate a command buffer
9576 462c 05/21 06:56:46 1856 CCVAPipelayer::StopRawDataTransferOverPipeLine() - Unable to send StopDataTransfer Command Buffer or DSBackup reported failure
9576 462c 05/21 06:56:46 1856 CVArchive::StopRawDataTransferOverPipeLine() - Error sending message to pipeline that data transfer will stop over the pipeline
9576 462c 05/21 06:56:46 1856 [Reader_15] Cannot signal stop data transfer for archive group [11] copy [26] stream [5]
9576 462c 05/21 06:56:46 1856 [Reader_15] Cannot signal stop data transfer.
9576 462c 05/21 06:56:46 1856 [Reader_15] ProcessTime : [2967]
9576 462c 05/21 06:56:46 1856 [Reader_15] ChunkArray Len [1] [1]
9576 462c 05/21 06:56:46 1856 [Reader_15] ReportStatus Chunk [6813] type [fail]
9576 462c 05/21 06:56:46 1856 [Reader_15] ReportStatus Params Copy/Stream:[16]/[0] Error:[0], MMErrorCode:[0] MA:[cvcs] errorString []
9576 462c 05/21 06:56:46 1856 [Reader_15] ReportStatus Params Copy/Stream:[26]/[5] Error:[3], MMErrorCode:[123] MA:[cvcs] errorString [Unable to send the stop data transfer control message to the tail. ]
9576 462c 05/21 06:56:46 1856 [Reader_15] ReportStatus is successful
9576 462c 05/21 06:56:46 1856 [Reader_15] Report Status Response Type: [2]
9576 462c 05/21 06:56:46 1856 [Reader_15] Report Status Response error Code: [3]
9576 462c 05/21 06:56:46 1856 [Reader_15] Setting JPR for Chunk [6813] Copy[Secondary_QNAP] rcId[5347] MediaType[10001] Error[3] mmError[123] jobStr[ Backup Job [1721]] ErrStr[Unable to send the stop data transfer control message to the tail. ] HardFailure[0]
9576 462c 05/21 06:56:46 1856 [Reader_15] Error handler: ContinueStream set to [False], ContinueOnError set to [False].
9576 462c 05/21 06:56:46 1856 CVArchive::ClosePipeline() - Resetting allocated stream
9576 462c 05/21 06:56:46 1856 [PIPELAYER ] Data Pipe Is Down
9576 462c 05/21 06:56:46 1856 CCVAPipelayer::SendPerfCountersToDSBackup() - Failed to allocate Perf-counters command buffer
9576 462c 05/21 06:56:46 1856 CCVAPipelayer::ClosePipeline() - About to destroy Data Mover
9576 462c 05/21 06:56:46 1856 [PIPELAYER ] Data Pipe Is Down
9576 462c 05/21 06:56:46 1856 CCVAPipelayer::SendCommandToDSBackup() - Failed to allocate a command buffer
9576 462c 05/21 06:56:46 1856 CCVAPipelayer::ClosePipeline() - Failure sending datamover destroy
9576 462c 05/21 06:56:46 1856 CPipelayer::ShutdownPipeline() - stat- SDT [00000155266D3C90] [duration - 2967 seconds]
9576 462c 05/21 06:56:46 1856 CPipelayer::ShutdownPipeline() - pipeline has already been shutdown
9576 462c 05/21 06:56:46 1856 [Reader_15] CVArchive::closePipeline() Failed with return code [-1] for dest copy [26], stream [5].
9576 462c 05/21 06:56:46 1856 ~CVArchive() - Destroying CVArchive. This=000001557E456490
9576 462c 05/21 06:56:46 1856 CPipelayer::ShutdownPipeline() - pipeline has already been shutdown
9576 462c 05/21 06:56:46 1856 SdtBase::relRef: Going to delete SdtBase as ref count is down to 0. RCId [5347]
9576 462c 05/21 06:56:46 1856 SdtBase is being destroyed. RCId [5347]
9576 462c 05/21 06:56:46 1856 Signature processing speed: Type [SHA512], [864.476321] GB/Hr, Bytes [9823266052], Time [38.098286] Sec(s)
9576 462c 05/21 06:56:46 1856 Name [Head], Start Delay [506.92 s], Avg [2.70 ms], Procsng Time [24.59 s], Avg [130.85 us], Bytes [9.22 GB], Speed [384.15 MB/s], Samples [187888] RCId [5347]
9576 462c 05/21 06:56:46 1856 Name [Head Signature], Start Delay [276.05 s], Avg [1.47 ms], Procsng Time [39.33 s], Avg [209.32 us], Bytes [9.22 GB], Speed [240.14 MB/s], Samples [187888] RCId [5347]
9576 462c 05/21 06:56:46 1856 Name [Head CRC32], Start Delay [9.84 s], Avg [52.37 us], Procsng Time [14.32 s], Avg [76.24 us], Bytes [9.24 GB], Speed [660.74 MB/s], Samples [187888] RCId [5347]
9576 462c 05/21 06:56:46 1856 Name [Head Network], Start Delay [209791.08 s], Avg [1.12 s], Procsng Time [2963.33 s], Avg [15.77 ms], Bytes [9.24 GB], Speed [3.19 MB/s], Samples [187888] RCId [5347]
9576 462c 05/21 06:56:46 1856 Performing graceful connection termination RCId [5347]
9576 462c 05/21 06:56:46 1856 Closing all sockets. RCId [5347]
9576 462c 05/21 06:56:46 1856 [Reader_15] Sent Stream Status [STREAM_COMPLETED_FAILURE] to coordinator.
9576 462c 05/21 06:56:46 1856 [Reader_15] Discarding queued chunk list
9576 462c 05/21 06:56:46 1856 [Reader_15] Worker Thread cleanup before exit
9576 462c 05/21 06:56:46 1856 [Reader_15] Destorying reader specifics
9576 462c 05/21 06:56:46 1856 [Reader_15] Going to close the media handle of the source media
9576 462c 05/21 06:56:46 1856 [DM_BASE ] Stopping LA thread [0000015562C5C4F0] loop. Reason [4]
9576 37c4 05/21 06:56:46 1856 [Coordinator] Received JobReplStreamStatusReq from Agent:cvcs
9576 37c4 05/21 06:56:46 1856 [Coordinator] Stream ReaderId [15] from Agent [cvcs] Status : [STREAM_FAILED]
9576 462c 05/21 06:56:46 1856 [DM_BASE ] Stopped LA thread [0000015562C5C4F0] loop
9576 462c 05/21 06:56:46 1856 [DM_BASE ] CloseChunkSpecific: [Total Physical bytes read - 10928569805] Number Of Links Sent in this chunk [11920], Total bytes [1039023721] saved
9576 462c 05/21 06:56:46 1856 [DM_BASE ] LookAheadCtrs: Links (CacheHit/Exp/UnExp/Total): 0/115219/11920/127177
9576 37c4 05/21 06:56:46 #### STREAM COMPLETE CALLED for RCID [5347] 1856
9576 462c 05/21 06:56:46 1856 [DM_BASE ] SfileRdrCtrs: Blks read [242204], Runs [8106], Run Len [9706121.00] KB (9478.63 MB), Random Pcnt [52.35%], Async Reads [83705], MPIds [3], Files: Hits/Opened [4989/775 (W:775+NO:0+O:0+I:0)]
9576 37c4 05/21 06:56:46 1856 JM Client Freeing rcid [5347]
9576 462c 05/21 06:56:46 1856 [DM_BASE ] SfileRdrCtrs: [Open File] Exp Avg [0.00], Total Avg [0.00], Total Time [0.28], Total Count [775]
9576 462c 05/21 06:56:46 1856 [DM_BASE ] Releasing the volume and drive reservation on the media manager
9576 462c 05/21 06:56:46 1856 [DM_BASE ] LookAheadCtrs: Links (CacheHit/Exp/UnExp/Total): 0/115219/11920/127177
9576 462c 05/21 06:56:46 1856 [DM_BASE ] SfileRdrCtrs: Blks read [242204], Runs [8106], Run Len [9706121.00] KB (9478.63 MB), Random Pcnt [52.35%], Async Reads [83705], MPIds [3], Files: Hits/Opened [4989/775 (W:775+NO:0+O:0+I:0)]
9576 462c 05/21 06:56:46 1856 [DM_BASE ] SfileRdrCtrs: [Open File] Exp Avg [0.00], Total Avg [0.00], Total Time [0.28], Total Count [775]
9576 40c8 05/21 06:56:46 1856 [DM_BASE ] ReadAhead: Received exit command.
9576 40c8 05/21 06:56:46 1856 [DM_BASE ] ReadAhead: LookAhead thread exiting.
9576 462c 05/21 06:56:46 1856 [DM_BASE ] CSfileRdr::DeInit: Sfile Cached Info size is [0 + 3]
9576 462c 05/21 06:56:46 1856 [DM_BASE ] Lookahead MPBlkInfo MPId:Blks {5:229419, 6:12730, 7:55, }
9576 462c 05/21 06:56:46 1856 stat- ID [Avg Open File Recvry], Samples [775], Time [0.283983] Sec(s), Average [0.000366] Sec/Sample
9576 462c 05/21 06:56:46 #### stat- ID [Grp [00] Avg QueryPrimary], Samples [63665], Time [6.220294] Sec(s), Average [0.000098] Sec/Sample
9576 462c 05/21 06:56:46 #### stat- ID [Grp [01] Avg QueryPrimary], Samples [63498], Time [6.299021] Sec(s), Average [0.000099] Sec/Sample
9576 462c 05/21 06:56:46 1856 [DM_BASE ] Destroyed DataMoverBase for MediaGroupId=[0]
9576 462c 05/21 06:56:46 1856 stat- ID [DMBaseChunkClose], Samples [2], Time [0.024192] Sec(s), Average [0.012096] Sec/Sample
9576 462c 05/21 06:56:46 1856 [Reader_15] Worker Thread is exiting
9576 37c4 05/21 06:56:47 1856 [Coordinator] Freed rcid [5347] for CopyId:[26]
9576 45b8 05/21 06:56:49 1856 [Controller] Reporting status for reader [15] on exit. Worker count [3].
9576 45b8 05/21 06:56:49 1856 [Reader_15] Inside destructor of ReplicatorBae Object
9576 45b8 05/21 06:56:49 1856 stat- ID [Media Read Speed], Job Id [1856], Bytes [9893169764], Time [22.071123] Sec(s), Average Speed [427.475386] MB/Sec
9576 45b8 05/21 06:56:49 1856 stat- ID [Next chunk recv times], Job Id [1856], Samples [1], Time [0.021419] Sec(s), Average [0.021419] Sec/Sample
9576 45b8 05/21 06:56:49 1856 stat- ID [Media Open Times], Job Id [1856], Samples [1], Time [2.006591] Sec(s), Average [2.006591] Sec/Sample
9576 45b8 05/21 06:56:49 1856 stat- ID [PL Alloc Times], Job Id [1856], Samples [187880], Time [2937.957991] Sec(s), Average [0.015637] Sec/Sample
9576 45b8 05/21 06:56:49 1856 [Reader_15] Destorying JobRepl Thread Args
9576 45b8 05/21 06:56:49 1856 [Reader_15] Destorying shared members.
9576 45b8 05/21 06:56:49 1856 [Reader_15] Destorying reader specifics
9576 465c 05/21 06:57:30 1856 [DM_BASE ] ReadAheadLinks: Reached MD EOF. ChunkMD#=92, LinksRd=598613
9576 465c 05/21 06:57:30 1856 [DM_BASE ] ReadAheadLinks: Reached MD EOF. ChunkMD#=92, LinksRd=598623
9576 8f4 05/21 06:57:30 1856 [DM_BASE ] Completed Reading the chunk
9576 8f4 05/21 06:57:30 1856 [Reader_14] Reached EndOfChunk for copy
9576 8f4 05/21 06:57:30 1856 ChunkIndex:[3] , chunkArray_len:[9]
9576 8f4 05/21 06:57:30 1856 [Reader_14] +++ JobReplicator Thread Params +++
9576 8f4 05/21 06:57:30 1856 [Reader_14] Storage Policy [PROD_Oracle_Full@01:00_ArchiveLog@15min] ID [11]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Source Copy [Primary] ID [16] Is Dedup Copy [1]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Soruce Stream [0] MediaGroup ID [0]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Source DrivePool ID [2] Type [10001]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Target Copy [Secondary_QNAP] ID [26] Is Dedup Copy [1]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Target Stream [4] MediaGroup ID [2257]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Target DrivePool ID [4] Type [10001]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Target RC ID [5346] Source RC ID [0]
9576 8f4 05/21 06:57:30 1856 [Reader_14] +++ Source Chunk Info +++
9576 8f4 05/21 06:57:30 1856 [Reader_14] Source ChunkId [6822]
9576 8f4 05/21 06:57:30 1856 [Reader_14] CommCellId [2]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Source VolumeId [383]
9576 8f4 05/21 06:57:30 1856 [Reader_14] File Marker Number [7]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Chunk Physical Size [4269200157]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Chunk Logical Size [13059489792]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Number of ArchFiles [1]
9576 8f4 05/21 06:57:30 1856 [Reader_14] isSDM [0]
9576 8f4 05/21 06:57:30 1856 [Reader_14] +++ Archive File Info +++
9576 8f4 05/21 06:57:30 1856 [Reader_14] 1. Archive File ID [3437]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Backup JobId [1721] ClientId [0] iDATypeId [0] AppId [55]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Logical Size [13059489792] offset [156925427712]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Physical Size [4269200157] offset [50380039138]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Chunk Number [4] Last Chunk Number [9]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Encrypted [0] SI [1] CV SI [1] CV SI WEB [0] Flags [23] Extra Flags [0]
9576 8f4 05/21 06:57:30 1856 [Reader_14] 1. Target Copy ID [26]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Encryption Type [0] Key Len [0]
9576 8f4 05/21 06:57:30 1856 [Reader_14] Physical ReadStartoffset [0] Logical ReadStartoffset [0]
9576 8f4 05/21 06:57:30 1856 [Reader_14] %% Use Regular AUX COPY %%
9576 8f4 05/21 06:57:30 1856 [Reader_14] DataReader is already initialised. No need to initialize again.
9576 8f4 05/21 06:57:30 1856 [Reader_14] Setup pipeline completed.

Maybe some of you had similar problem with Qnap as secondary repository?

I have tried reducing the network traffic for this secondary copy to 250000MB/HR, I have also tried to change “Disk Optimized Copy” to “Network Optimized Copy” in Dash Copy Deduplication advanced options.

Thanks in advance for your help :)

Wish you a good weekend !

Regards,

Mateusz

icon

Best answer by Robert Horowski 8 July 2022, 15:37

View original

13 replies

Userlevel 7
Badge +16

Are there errors in cvd.log on source and target during the aux copy?

Based on logs I would first check if there are specific connection errors shown in that log.

Edit: after re-reading I see that cvcs is the media agent for both targets, is that correct?

Badge +4

Yes, there are some failed rows in cvd.log for this job also. Here is a log:

 

5420  42d4  05/21 09:11:39 1856 5423-3220 [MEDIAFS    ] stat- ID [SI-FS Write Speed] Curr Avg [0.055543] MB/Sec, Bytes [34078991]; Total Avg [24.297144] MB/Sec, Bytes [30768507250], Time [1207.68] Secs
5420 57c 05/21 09:11:50 1856 SdtTail::logStats: Clnt [cvcs], PId [18984], Cnt - BsyProcsg/Allocs [468512/562456]; Time - Procsg/NwRecv/Total [1272/1152/2424] secs, Bytes recvd [30692740316] RCId [5423]
5420 3d1c 05/21 09:13:00 1856 5420-3217 [MEDIAFS ] SiFS::WrtToFileInt: Cannot write to sfile file. Input Size [983548], Bytes written [0], SysErr=54, Err=0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}
5420 3d1c 05/21 09:13:00 1856 5420-3217 [MEDIAFS ] The operation failed. errorno [1205]
5420 3d1c 05/21 09:13:00 1856 5420-3217 [MEDIAFS ] SiFS::WrtToFile: [ERROR] WriteToCache failed. Ret=[-1]
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_BASE ] WriteDedupBlock [9453]: Cannot empty scratch buffer to the data file. Size [115256].
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_BASE ] WaitInsertQueue [9327]: WriteDedupBlock failed. iRet [-1]
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_BASE ] WaitAndProcessHeadBlock [9361]: Unable to wait for insert queue. iRet [-1]
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_BASE ] AllocDataBlock [9618]: Unable to wait for the head data block to get processed. iRet [-1]
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_BASE ] SubmitAndAllocDataBlock [9673]: AllocBlock failed. iRet [-1]
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_BASE ] ERROR: OnPlFsSignature failed to insert the SIDB record. Error = -1, Unknown
5420 3d1c 05/21 09:13:00 #### ** *MM ErrorCode -1 without translation* **
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_BASE ] WriteATagHdrDataPairForCVSIDevice:1709 Cannot process the signature buffer.
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_RECEIVER] DataReceiver::WritePipelineBufCS: Error: DataWriter Write Failed
5420 3d1c 05/21 09:13:00 #### [DSBACKUP ] Failed to process the pipeline buffer
5420 3d1c 05/21 09:13:00 #### [DM_WRITEMAP] DATAWRITER MAP CONTENTS - Total:4, [MediaGroup, UseCount][ {2255,1} {2256,1} {2258,0} {2259,1}])
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_RECEIVER] USE COUNT for media group [2258] is [0]
5420 3d1c 05/21 09:13:00 1856 5420-3217 [DM_RECEIVER] Destroying the DataWriter for media group [2258]. and removing from the map
5420 1ec8 05/21 09:13:13 1856 SdtTail::logStats: Clnt [cvcs], PId [18984], Cnt - BsyProcsg/Allocs [141570/146069]; Time - Procsg/NwRecv/Total [2481/27/2508] secs, Bytes recvd [8005046204] RCId [5421]
5420 d4c 05/21 09:13:14 1856 SdtTail::logStats: Clnt [cvcs], PId [18984], Cnt - BsyProcsg/Allocs [143056/147691]; Time - Procsg/NwRecv/Total [2482/26/2508] secs, Bytes recvd [8023998408] RCId [5422]
5420 3d1c 05/21 09:13:14 #### Flush time [0.014671 Sec], Change [0], Aligned [1]
5420 3d1c 05/21 09:13:14 1856 5420-3217 [MEDIAFS ] stat- ID [SI-FS Write Speed] Curr Avg [0.032835] MB/Sec, Bytes [3432428]; Total Avg [23.134438] MB/Sec, Bytes [31498319043], Time [1298.46] Secs
5420 3d1c 05/21 09:13:14 1856 5420-3217 [DM_BASE ] UnReserving the backup volume 471
5420 3054 05/21 09:13:14 1856 5421-3218 [MEDIAFS ] stat- ID [SI-FS Write Speed] Curr Avg [0.063765] MB/Sec, Bytes [1572864]; Total Avg [58.075946] MB/Sec, Bytes [8019260367], Time [131.69] Secs
5420 3d1c 05/21 09:13:18 #### stat- ID [Grp [00] Avg Add Reference], Samples [8186], Time [0.368995] Sec(s), Average [0.000045] Sec/Sample
5420 3d1c 05/21 09:13:18 #### stat- ID [Grp [00] Avg QueryInsert], Samples [175254], Time [13.643745] Sec(s), Average [0.000078] Sec/Sample
5420 3d1c 05/21 09:13:18 #### stat- ID [Grp [01] Avg Add Reference], Samples [8198], Time [0.372564] Sec(s), Average [0.000045] Sec/Sample
5420 3d1c 05/21 09:13:18 #### stat- ID [Grp [01] Avg QueryInsert], Samples [175334], Time [12.538087] Sec(s), Average [0.000072] Sec/Sample
5420 3d1c 05/21 09:13:18 1856 5420-# [DM_BASE ] Destroyed DataMoverBase for MediaGroupId=[2258]
5420 3d1c 05/21 09:13:18 1856 stat- ID [DMBaseCreate], Samples [1], Time [0.126687] Sec(s), Average [0.126687] Sec/Sample
5420 3d1c 05/21 09:13:18 1856 stat- ID [DMBaseChunkCreate], Samples [7], Time [0.324999] Sec(s), Average [0.046428] Sec/Sample
5420 3d1c 05/21 09:13:18 1856 stat- ID [DMBaseChunkClose], Samples [7], Time [2.526559] Sec(s), Average [0.360937] Sec/Sample
5420 3d1c 05/21 09:13:18 1856 SdtTail::onProcDataCompleted: Client [SDTPipe_cvcs_cvcs_1856_1653114675_18984_9588_0000026606630080], Id [8380], Cannot process the SDT buffer. Error [-1] RCId [5420]
5420 3d1c 05/21 09:13:18 1856 SdtBase::setLastErr: Setting last err [97][The destination encountered an error while processing the data from the source.] RCId [5420]
5420 3d1c 05/21 09:13:18 1856 SdtTail::onError: Going to wakeup the select thread, so that it can drop the connection. RCId [5420]
5420 139c 05/21 09:13:18 1856 SdtTailSrv::DropClientWorker: Removing Client [SDTPipe_cvcs_cvcs_1856_1653114675_18984_9588_0000026606630080], Id [8380] from the list. RCId [5420]
5420 139c 05/21 09:13:18 1856 SdtTail::onDisconnect: Sending error [97][The destination encountered an error while processing the data from the source.] to the head. RCId [5420]
5420 3d1c 05/21 09:13:18 1856 SdtTailSrv::AddToReadMask: Error flag set for client [SDTPipe_cvcs_cvcs_1856_1653114675_18984_9588_0000026606630080], Id [8380] RCId [5420]
5420 3d1c 05/21 09:13:18 1856 SdtTail::onFreeBufferAvailable: Cannot add the client [SDTPipe_cvcs_cvcs_1856_1653114675_18984_9588_0000026606630080], Id [8380] to the select mask. RCId [5420]
5420 139c 05/21 09:13:18 1856 SdtTail::onDisconnect: Sent error code to the head RCId [5420]
5420 3d1c 05/21 09:13:18 1856 SdtTail::onError: Going to wakeup the select thread, so that it can drop the connection. RCId [5420]
5420 139c 05/21 09:13:18 #### deinitializeSDTpipeline CALLED for pipelineID [SDTPipe_cvcs_cvcs_1856_1653114675_18984_9588_0000026606630080] 1856
5420 139c 05/21 09:13:18 1856 SdtTailSrv::DropClientWorker: Size of selected list [0] RCId [5420]
5420 139c 05/21 09:13:18 1856 SdtTailSrv::DropClientWorker: Draining away incoming data... RCId [5420]
5420 139c 05/21 09:13:18 1856 SdtTailSrv::DropClientWorker: Have drained away incoming data... Cnt [0] RCId [5420]
5420 139c 05/21 09:13:18 1856 SdtBase::relRef: Going to delete SdtBase as ref count is down to 0. RCId [5420]
5420 139c 05/21 09:13:18 #### [DSBACKUP ] CVMABackup object destroyed..
5420 139c 05/21 09:13:18 #### 1856-5420-dsBackup-MediaWrite: Bytes [5.53 MB, 29.24 GB], IO Rate [53.02 KB/s, 21.19 MB/s] IO Size [52.91 KB, 52.54 KB]. Time [997.82 ms/op, 2.42 ms/op], Rate [1.00 op/s, 413.08 op/s], Tot Time [106.77 s, 1412.70 s], Tot Samples [107, 583551]
5420 139c 05/21 09:13:18 1856 5420-# [DM_RECEIVER] Destroyed DataReceiverBase. MediaGroupId=[2258], AFId=[0]
5420 139c 05/21 09:13:18 1856 SdtTail::logStats:Final Clnt [cvcs], PId [18984], Cnt - BsyProcsg/Allocs [490019/583649]; Time - Procsg/NwRecv/Total [1375/1148/2523] secs, Bytes recvd [31424100448] RCId [5420]
5420 139c 05/21 09:13:18 1856 SdtBase is being destroyed. RCId [5420]
5420 139c 05/21 09:13:18 1856 Name [Tail Network], Start Delay [93622.73 s], Avg [160.41 ms], Procsng Time [1148.89 s], Avg [1.97 ms], Bytes [29.27 GB], Speed [26.08 MB/s], Samples [583649] RCId [5420]
5420 139c 05/21 09:13:18 1856 Name [Tail End], Start Delay [121389.78 s], Avg [208.02 ms], Procsng Time [1418.99 s], Avg [2.43 ms], Bytes [29.26 GB], Speed [21.12 MB/s], Samples [583559] RCId [5420]
5420 139c 05/21 09:13:18 1856 Performing graceful connection termination RCId [5420]
5420 139c 05/21 09:13:18 1856 Closing all sockets. RCId [5420]
5420 3f44 05/21 09:13:36 #### [DSBACKUP ] PL_SET_ENC_PROPS Archfile(3443 )
5420 3f44 05/21 09:13:36 #### [DSBACKUP ] Get PL_SET_ENC_PROPS Message Type: 16 SubType: 156 Status: 0 EventErrorCode: 0
5420 3f44 05/21 09:13:36 #### [DSBACKUP ] Get PL_SET_ENC_PROPS Message Has been Sent
5420 24e8 05/21 09:13:36 1856 5422-3219 [MEDIAFS ] stat- ID [SI-FS Write Speed] Curr Avg [6.175050] MB/Sec, Bytes [69075180]; Total Avg [64.215753] MB/Sec, Bytes [8105809108], Time [120.38] Secs
5420 350c 05/21 09:13:42 1856 5423-3220 [DM_BASE ] FlushAndUpdateDDB [6724]: Going to commit info in DDB. PriIds [0], Recs [0], PriCommitData [16384] ChunkSize [1342802632]
5420 139c 05/21 09:14:29 #### [DSBACKUP ] PL_SET_ENC_PROPS Archfile(3794 )
5420 139c 05/21 09:14:29 #### [DSBACKUP ] Get PL_SET_ENC_PROPS Message Type: 16 SubType: 156 Status: 0 EventErrorCode: 0
5420 139c 05/21 09:14:29 #### [DSBACKUP ] Get PL_SET_ENC_PROPS Message Has been Sent
5420 e84 05/21 09:14:31 #### [DSBACKUP ] PL_SET_ENC_PROPS Archfile(3795 )
5420 e84 05/21 09:14:31 #### [DSBACKUP ] Get PL_SET_ENC_PROPS Message Type: 16 SubType: 156 Status: 0 EventErrorCode: 0
5420 e84 05/21 09:14:31 #### [DSBACKUP ] Get PL_SET_ENC_PROPS Message Has been Sent
5420 3f44 05/21 09:14:31 #### [DSBACKUP ] Creating an Archive File <3795> UsedIndexing <0>
5420 64c 05/21 09:14:33 #### CCVPerfManager::Initialize: System Resource Monitor Initialization succeeded ( LogFilesDirectory [C:\Program Files\Commvault\ContentStore\Log Files\ResourceMonitor] [Max-log-File size - 10 MB] [Max-Log-File Count - 10]
5420 64c 05/21 09:14:33 #### [DSBACKUP ] PL_FS_DESTROY Destroying Data Mover
5420 64c 05/21 09:14:33 #### [DSBACKUP ] Destroying Data Mover
5420 64c 05/21 09:14:33 #### [DM_WRITEMAP] DATAWRITER MAP CONTENTS - Total:4, [MediaGroup, UseCount][ {1308,0} {2255,1} {2256,1} {2259,1}])
5420 2f78 05/21 09:14:39 #### Flush time [0.040158 Sec], Change [0], Aligned [1]
5420 2f78 05/21 09:14:39 1856 5423-3220 [DM_BASE ] FlushAndUpdateDDB [6724]: Going to commit info in DDB. PriIds [0], Recs [0], PriCommitData [16384] ChunkSize [2721877492]
5420 43a8 05/21 09:15:30 1856 5423-3220 [DM_BASE ] FlushAndUpdateDDB [6724]: Going to commit info in DDB. PriIds [0], Recs [0], PriCommitData [16384] ChunkSize [3958241981]
5420 9d8 05/21 09:15:42 1856 5423-3220 [DM_BASE ] CloseChunkSpecific: Entered. CVSIDevice [true], IsSIData [false]
5420 9d8 05/21 09:15:42 1856 5423-3220 [DM_BASE ] CloseChunkSpecific: Container metadata index [0]. SFile container index size [3019432]
5420 9d8 05/21 09:15:42 #### Flush time [0.009726 Sec], Change [0], Aligned [1]
5420 9d8 05/21 09:15:42 1856 5423-3220 [DM_BASE ] FlushAndUpdateDDB [6724]: Going to commit info in DDB. PriIds [0], Recs [0], PriCommitData [3915] ChunkSize [4267941589]
5420 9d8 05/21 09:15:42 1856 5423-3220 [DM_BASE ] [DEBUG] chunk physical size [4267941589] chunk media size [4294328357]
5420 9d8 05/21 09:15:42 1856 5423-3220 [MEDIAFS ] Size 34357787291 write time =1002
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_BASE ] Successfully closed chunk on Media for archive file id =3443, VolumeId = 453
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_CHUNK ] Split [0], SubStore [7], Primary [26798], Secondary [0]
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_CHUNK ] Split [1], SubStore [8], Primary [26269], Secondary [0]
5420 9d8 05/21 09:15:43 1856 5423-3220 [MEDIAFS ] Size 34357918363 write time =0
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_CHUNK ] Split [0], SubStore [7], Primary [26798], Secondary [0]
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_CHUNK ] Split [1], SubStore [8], Primary [26269], Secondary [0]
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_CHUNK ] [CloseChunkInfo] ArchFileId [3443], JobId [1856], chunkSeqNumber[8], PhysicalOffset [35362767491], logicalOffset [111438987264], physicalSize [4267941589], logicalSize[13911195648], uncompSize[13911195648], primaryObjects [53067], primaryObjSize [4267941589], primaryMetaDataSize[29340664], secondaryObjects [0], secondaryObjSize [0], secondaryMetaDataSize[0], isSingleDataInstance [1], isCVSingleInstanced [1], isCVSIWebStorage [0], isSoftwareCompressed [1], isNRS [0], isLastChunk [0] JobId:[1856] JobToken[1856:1:3:0:0:32808].
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_CHUNK ] [CloseChunkInfo] ArchFileId [3443], Primary Objects [53067], Size [4267941589], Metadata Size [29340664]Secondary Objects [0], Size [0], Metadata Size [0]
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_CHUNK ] [CloseChunkInfo] Current Chunk Info : Chunk Id 7845 CommcellId [2], CopyId[26], VolumeId [453], FileNumber [59], Total No. of ArchFiles in Chunk [1], No. of ArchFiles with NonZero size [1],Total amount data size in the chunk [4267941589], HwEncrypted [N], EncKeySharedOnMedia [N]
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_BASE ] Closed the chunk with Id 7845. Got New Chunk Id 7852 from ArMgr
5420 9d8 05/21 09:15:43 1856 5423-3220 [DM_BASE ] Creating new chunk id 7852 VolId= 453
5420 9d8 05/21 09:15:43 1856 5423-3220 [MEDIAFS ] SingleInstancer_FS Created [\\qnap4.dns.name\commvault\WRNHW6_05.11.2022_06.32\CV_MAGNETIC\V_453\CHUNK_7852] Chunk Directory
5420 9d8 05/21 09:15:43 #### [DSBACKUP ] 1. m_pCommittedRestartInfo = &m_prevRestartInfo
5420 9d8 05/21 09:15:43 #### [DSBACKUP ] Updating the Job Manager that the chunk has been committed
5420 3054 05/21 09:16:05 1856 5421-3218 [DM_BASE ] CloseChunkSpecific: Entered. CVSIDevice [true], IsSIData [false]
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] CloseChunkSpecific: Container metadata index [0]. SFile container index size [2678328]
5420 3054 05/21 09:16:06 #### WritePage:559 Failed to write [32768] bytes for page [0]. Written [-1]. Error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 3054 05/21 09:16:06 #### ApplyChanges:2253: Failed to write to page 0. Error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 3054 05/21 09:16:06 #### Flush:2127 Failed to apply changes.
5420 3054 05/21 09:16:06 1856 5421-3218 [MEDIAFS ] Failed to flush the data index file, error=0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] [FlushDataFileBuffer()] Cannot flush the the data file for file [\\qnap4.dns.name\commvault\WRNHW6_05.11.2022_06.32\CV_MAGNETIC\V_469\CHUNK_7839\SFILE_CONTAINER_184]. Error [1205]
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] **ERROR** Failed to Flush data buffer File to Media. ChunkId= 7839
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] FlushAndUpdateDDB [6693]: Failed to Flush metadata buffer to Media. File [\\qnap4.dns.name\commvault\WRNHW6_05.11.2022_06.32\CV_MAGNETIC\V_469\CHUNK_7839\SFILE_CONTAINER_184]. iRet [-1]
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] CloseChunkSpecific: FlushAndCommitPrimaryIds failed. iRet [-1]
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] Failed to close specific for ChunkId= 7839. Line [622]
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] Failed to close chunk for the ArchiveFile=3436 MediaGroup=2256
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] checkMediaSpaceAndSpan failed. ret [-1]
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_RECEIVER] DataReceiver::WritePipelineBufCS: Error: DataWriter Write Failed
5420 3054 05/21 09:16:06 #### [DSBACKUP ] Failed to process the pipeline buffer
5420 3054 05/21 09:16:06 #### [DM_WRITEMAP] DATAWRITER MAP CONTENTS - Total:3, [MediaGroup, UseCount][ {2255,1} {2256,0} {2259,1}])
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_RECEIVER] USE COUNT for media group [2256] is [0]
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_RECEIVER] Destroying the DataWriter for media group [2256]. and removing from the map
5420 3054 05/21 09:16:06 #### WritePage:559 Failed to write [32768] bytes for page [0]. Written [0]. Error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 3054 05/21 09:16:06 #### ApplyChanges:2253: Failed to write to page 0. Error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 3054 05/21 09:16:06 #### Flush:2127 Failed to apply changes.
5420 3054 05/21 09:16:06 #### CIndexFile::Close:2637 Unable to flush the file. error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 3054 05/21 09:16:06 1856 5421-3218 [MEDIAFS ] CloseSpecific: Cannot close the data index file [\\qnap4.dns.name\commvault\WRNHW6_05.11.2022_06.32\CV_MAGNETIC\V_469\CHUNK_7839\SFILE_CONTAINER.idx], error=0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}
5420 3054 05/21 09:16:06 1856 5421-3218 [MEDIAFS ] stat- ID [SI-FS Write Speed] Curr Avg [46.881945] MB/Sec, Bytes [570060278]; Total Avg [57.169984] MB/Sec, Bytes [8589320645], Time [143.28] Secs
5420 3054 05/21 09:16:06 1856 5421-3218 [DM_BASE ] UnReserving the backup volume 469
5420 3054 05/21 09:16:07 #### stat- ID [Grp [00] Avg Add Reference], Samples [8192], Time [1.082321] Sec(s), Average [0.000132] Sec/Sample
5420 3054 05/21 09:16:07 #### stat- ID [Grp [00] Avg QueryInsert], Samples [48612], Time [5.411888] Sec(s), Average [0.000111] Sec/Sample
5420 3054 05/21 09:16:07 #### stat- ID [Grp [01] Avg Add Reference], Samples [8192], Time [0.954764] Sec(s), Average [0.000117] Sec/Sample
5420 3054 05/21 09:16:07 #### stat- ID [Grp [01] Avg QueryInsert], Samples [48908], Time [4.949717] Sec(s), Average [0.000101] Sec/Sample
5420 3054 05/21 09:16:07 1856 5421-# [DM_BASE ] Destroyed DataMoverBase for MediaGroupId=[2256]
5420 3054 05/21 09:16:07 1856 stat- ID [DMBaseCreate], Samples [1], Time [0.228495] Sec(s), Average [0.228495] Sec/Sample
5420 3054 05/21 09:16:07 1856 stat- ID [DMBaseChunkCreate], Samples [1], Time [0.032619] Sec(s), Average [0.032619] Sec/Sample
5420 3054 05/21 09:16:07 1856 stat- ID [DMBaseChunkClose], Samples [1], Time [0.301078] Sec(s), Average [0.301078] Sec/Sample
5420 3054 05/21 09:16:07 1856 SdtTail::onProcDataCompleted: Client [SDTPipe_cvcs_cvcs_1856_1653114685_18984_19804_000002660C3128E0], Id [12148], Cannot process the SDT buffer. Error [-1] RCId [5421]
5420 3054 05/21 09:16:07 1856 SdtBase::setLastErr: Setting last err [97][The destination encountered an error while processing the data from the source.] RCId [5421]
5420 3054 05/21 09:16:07 1856 SdtTail::onError: Going to wakeup the select thread, so that it can drop the connection. RCId [5421]
5420 3054 05/21 09:16:07 1856 SdtTailSrv::AddToReadMask: Error flag set for client [SDTPipe_cvcs_cvcs_1856_1653114685_18984_19804_000002660C3128E0], Id [12148] RCId [5421]
5420 3054 05/21 09:16:07 1856 SdtTail::onFreeBufferAvailable: Cannot add the client [SDTPipe_cvcs_cvcs_1856_1653114685_18984_19804_000002660C3128E0], Id [12148] to the select mask. RCId [5421]
5420 3054 05/21 09:16:07 1856 SdtTail::onError: Going to wakeup the select thread, so that it can drop the connection. RCId [5421]
5420 2a6c 05/21 09:16:07 1856 SdtTailSrv::DropClientWorker: Removing Client [SDTPipe_cvcs_cvcs_1856_1653114685_18984_19804_000002660C3128E0], Id [12148] from the list. RCId [5421]
5420 2a6c 05/21 09:16:07 1856 SdtTail::onDisconnect: Sending error [97][The destination encountered an error while processing the data from the source.] to the head. RCId [5421]
5420 2a6c 05/21 09:16:07 1856 SdtTail::onDisconnect: Sent error code to the head RCId [5421]
5420 2a6c 05/21 09:16:07 #### deinitializeSDTpipeline CALLED for pipelineID [SDTPipe_cvcs_cvcs_1856_1653114685_18984_19804_000002660C3128E0] 1856
5420 2a6c 05/21 09:16:07 1856 SdtTailSrv::DropClientWorker: Size of selected list [0] RCId [5421]
5420 2a6c 05/21 09:16:07 1856 SdtTailSrv::DropClientWorker: Draining away incoming data... RCId [5421]
5420 2a6c 05/21 09:16:07 1856 SdtTailSrv::DropClientWorker: Have drained away incoming data... Cnt [0] RCId [5421]
5420 2a6c 05/21 09:16:07 1856 SdtBase::relRef: Going to delete SdtBase as ref count is down to 0. RCId [5421]
5420 2a6c 05/21 09:16:07 #### [DSBACKUP ] CVMABackup object destroyed..
5420 2a6c 05/21 09:16:07 #### 1856-5421-dsBackup-MediaWrite: Bytes [120.00 MB, 7.97 GB], IO Rate [3.23 MB/s, 3.06 MB/s] IO Size [53.92 KB, 53.42 KB]. Time [16.28 ms/op, 17.03 ms/op], Rate [61.42 op/s, 58.71 op/s], Tot Time [37.11 s, 2664.98 s], Tot Samples [2279, 156471]
5420 2a6c 05/21 09:16:07 1856 5421-# [DM_RECEIVER] Destroyed DataReceiverBase. MediaGroupId=[2256], AFId=[0]
5420 2a6c 05/21 09:16:07 1856 SdtTail::logStats:Final Clnt [cvcs], PId [18984], Cnt - BsyProcsg/Allocs [151852/156572]; Time - Procsg/NwRecv/Total [2654/28/2682] secs, Bytes recvd [8572088844] RCId [5421]
5420 2a6c 05/21 09:16:07 1856 SdtBase is being destroyed. RCId [5421]
5420 2a6c 05/21 09:16:07 1856 Name [Tail Network], Start Delay [404.77 s], Avg [2.59 ms], Procsng Time [28.64 s], Avg [182.93 us], Bytes [7.98 GB], Speed [285.43 MB/s], Samples [156572] RCId [5421]
5420 2a6c 05/21 09:16:07 1856 Name [Tail End], Start Delay [238039.31 s], Avg [1.52 s], Procsng Time [2668.25 s], Avg [17.05 ms], Bytes [7.98 GB], Speed [3.06 MB/s], Samples [156482] RCId [5421]
5420 2a6c 05/21 09:16:07 1856 Performing graceful connection termination RCId [5421]
5420 2a6c 05/21 09:16:07 1856 Closing all sockets. RCId [5421]
5420 24e8 05/21 09:16:13 #### WritePage:559 Failed to write [32768] bytes for page [0]. Written [-1]. Error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 24e8 05/21 09:16:13 #### ApplyChanges:2253: Failed to write to page 0. Error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 24e8 05/21 09:16:13 #### Flush:2127 Failed to apply changes.
5420 24e8 05/21 09:16:13 1856 5422-3219 [MEDIAFS ] Failed to flush the data index file, error=0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] [FlushDataFileBuffer()] Cannot flush the the data file for file [\\qnap4.dns.name\commvault\WRNHW6_05.11.2022_06.32\CV_MAGNETIC\V_472\CHUNK_7837\SFILE_CONTAINER_192]. Error [1205]
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] **ERROR** Failed to Flush data buffer File to Media. ChunkId= 7837
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] FlushAndUpdateDDB [6693]: Failed to Flush metadata buffer to Media. File [\\qnap4.dns.name\commvault\WRNHW6_05.11.2022_06.32\CV_MAGNETIC\V_472\CHUNK_7837\SFILE_CONTAINER_192]. iRet [-1]
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] OnDedupBlock [9548]: FlushAndCommitPrimaryIds failed. iRet [-1]
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] ProcessCompletedBlocks [9285]: Unable to process a dedup block. iRet [-1]
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] WaitAndProcessHeadBlock [9384]: Unable to process completed blocks. iRet [-1]
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] AllocDataBlock [9618]: Unable to wait for the head data block to get processed. iRet [-1]
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] SubmitAndAllocDataBlock [9673]: AllocBlock failed. iRet [-1]
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] ERROR: OnPlFsSignature failed to insert the SIDB record. Error = -1, Unknown
5420 24e8 05/21 09:16:13 #### ** *MM ErrorCode -1 without translation* **
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] WriteATagHdrDataPairForCVSIDevice:1709 Cannot process the signature buffer.
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_RECEIVER] DataReceiver::WritePipelineBufCS: Error: DataWriter Write Failed
5420 24e8 05/21 09:16:13 #### [DSBACKUP ] Failed to process the pipeline buffer
5420 24e8 05/21 09:16:13 #### [DM_WRITEMAP] DATAWRITER MAP CONTENTS - Total:2, [MediaGroup, UseCount][ {2255,1} {2259,0}])
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_RECEIVER] USE COUNT for media group [2259] is [0]
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_RECEIVER] Destroying the DataWriter for media group [2259]. and removing from the map
5420 24e8 05/21 09:16:13 #### WritePage:559 Failed to write [32768] bytes for page [0]. Written [0]. Error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 24e8 05/21 09:16:13 #### ApplyChanges:2253: Failed to write to page 0. Error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 24e8 05/21 09:16:13 #### Flush:2127 Failed to apply changes.
5420 24e8 05/21 09:16:13 #### CIndexFile::Close:2637 Unable to flush the file. error [0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}]
5420 24e8 05/21 09:16:13 1856 5422-3219 [MEDIAFS ] CloseSpecific: Cannot close the data index file [\\qnap4.dns.name\commvault\WRNHW6_05.11.2022_06.32\CV_MAGNETIC\V_472\CHUNK_7837\SFILE_CONTAINER.idx], error=0xECCC0016:{CQiFile::Write(225)/ErrNo.22.(Invalid argument)}
5420 24e8 05/21 09:16:13 1856 5422-3219 [MEDIAFS ] stat- ID [SI-FS Write Speed] Curr Avg [48.515406] MB/Sec, Bytes [442323780]; Total Avg [63.158137] MB/Sec, Bytes [8548132888], Time [129.07] Secs
5420 24e8 05/21 09:16:13 1856 5422-3219 [DM_BASE ] UnReserving the backup volume 472
5420 24e8 05/21 09:16:19 #### stat- ID [Grp [00] Avg Add Reference], Samples [8242], Time [0.700691] Sec(s), Average [0.000085] Sec/Sample
5420 24e8 05/21 09:16:19 #### stat- ID [Grp [00] Avg QueryInsert], Samples [48944], Time [5.449031] Sec(s), Average [0.000111] Sec/Sample
5420 24e8 05/21 09:16:19 #### stat- ID [Grp [01] Avg Add Reference], Samples [8142], Time [0.660661] Sec(s), Average [0.000081] Sec/Sample
5420 24e8 05/21 09:16:19 #### stat- ID [Grp [01] Avg QueryInsert], Samples [49010], Time [5.015531] Sec(s), Average [0.000102] Sec/Sample
5420 24e8 05/21 09:16:19 1856 5422-# [DM_BASE ] Destroyed DataMoverBase for MediaGroupId=[2259]
5420 24e8 05/21 09:16:19 1856 stat- ID [DMBaseCreate], Samples [1], Time [0.214065] Sec(s), Average [0.214065] Sec/Sample
5420 24e8 05/21 09:16:19 1856 stat- ID [DMBaseChunkCreate], Samples [1], Time [0.094332] Sec(s), Average [0.094332] Sec/Sample
5420 24e8 05/21 09:16:19 1856 stat- ID [DMBaseChunkClose], Samples [1], Time [0.776802] Sec(s), Average [0.776802] Sec/Sample
5420 24e8 05/21 09:16:19 1856 SdtTail::onProcDataCompleted: Client [SDTPipe_cvcs_cvcs_1856_1653114686_18984_10520_000002660C946D20], Id [4056], Cannot process the SDT buffer. Error [-1] RCId [5422]
5420 24e8 05/21 09:16:19 1856 SdtBase::setLastErr: Setting last err [97][The destination encountered an error while processing the data from the source.] RCId [5422]
5420 24e8 05/21 09:16:19 1856 SdtTail::onError: Going to wakeup the select thread, so that it can drop the connection. RCId [5422]
5420 24e8 05/21 09:16:19 1856 SdtTailSrv::AddToReadMask: Error flag set for client [SDTPipe_cvcs_cvcs_1856_1653114686_18984_10520_000002660C946D20], Id [4056] RCId [5422]
5420 24e8 05/21 09:16:19 1856 SdtTail::onFreeBufferAvailable: Cannot add the client [SDTPipe_cvcs_cvcs_1856_1653114686_18984_10520_000002660C946D20], Id [4056] to the select mask. RCId [5422]
5420 24e8 05/21 09:16:19 1856 SdtTail::onError: Going to wakeup the select thread, so that it can drop the connection. RCId [5422]
5420 2f78 05/21 09:16:19 1856 SdtTailSrv::DropClientWorker: Removing Client [SDTPipe_cvcs_cvcs_1856_1653114686_18984_10520_000002660C946D20], Id [4056] from the list. RCId [5422]
5420 2f78 05/21 09:16:19 1856 SdtTail::onDisconnect: Sending error [97][The destination encountered an error while processing the data from the source.] to the head. RCId [5422]
5420 2f78 05/21 09:16:19 1856 SdtTail::onDisconnect: Sent error code to the head RCId [5422]
5420 2f78 05/21 09:16:19 #### deinitializeSDTpipeline CALLED for pipelineID [SDTPipe_cvcs_cvcs_1856_1653114686_18984_10520_000002660C946D20] 1856

 

Userlevel 7
Badge +16

Does the qnap have a default ipv4 network config, for example MTU 1500 or did the admin customize settings?

Is the source (cvcs) configured with similar network config? For example, that one side is using jumbo frames and the other is not?

What type of block size is used on qnap?

Any anti virus installed on cvcs which actively scans this traffic?

Is anti virus (ClamAV) active on qnap? If you use Security Counselor, this can tell you if this is so.

Seems that either there is a network issue or locks remain on the qnap filesystem which prevent write activity on files.

Badge +4

Hello Jos Meijer!

Yes, the qnap network settings are a default ipv4 settings. Qnap and commserve are in the same network, the traffic is allowed on every ports.

I cannot log in to qnap right now, but I found that the default block size for Qnap is 32KB (and I believe that this is current block size on this qnap - it was configured using default settings - not by me).

Our source disk library is formatted with 64KB block size (recommended for disk library by Commvault).

There is an antivirus installed on commserve (cvcs) - it is WithSecure Elements Agent (before F-Secure). We created an exclusions for every mount path, for every DDB directory, indexcache directory, software cache etc. This antivirus does not have firewall service activated - commserve is using default Windows Firewall.

Is it possible that different block size on qnap volume cause this AuxCopy problems ?

Thanks in advance ! :)

Userlevel 7
Badge +16

Sounds all good, except for the unknown qnap anti virus config that could still cause issues. Advice is to check this first.

The block size won't cause this error, but it will slow your transfer speed.

Badge +4

We disabled AntiVirus on QNAP - and nothing changed. This errors occurs again and jobs are Partially copied in the QNAP copy.

This QNAP aux jobs are running very very slow. We have another secondary copy to MCSS (metallic), and this copy have a mirror configuration as QNAP copy (copying the same jobs). And copy to mcss takes around 2hours (to transfer data through WAN) but copy to QNAP takes around 8hours (qnap is accessed locally - through LAN). I think this problem when occurs - stops the job - waiting for some time - and then resumes the jobs. I think when we fix the problem with this errors above - then copy to QNAP will take a lot less time then today.

Today I reported this problem to commvault support - but in few requests before they was not that helpful as they should be :( - thats why i decided to try Community first :)

 

In few hours I will have an administrative access to this QNAP. I will look into network settings (if they are default or maybe not).

Userlevel 7
Badge +23

@Mateusz Slezak , following up on this one.  Were you able to find anything else in the network settings?

If not, I would suggest opening a support case (and sharing the case number here).

Userlevel 4
Badge +13

Hi @Mike Struening 

@Mateusz Slezak is actually my colleague from work and I have advised him to switch from SMB to iSCSI protocol on QNAP device.

I remember that quite some time ago I read about broken SMB implementation in QNAP devices. This was in competition newsletter and since QNAP devices are pretty popular with their customers, they did some fine tuning to overcome QNAP implementation of SMB protocol.

Long story short, switching to iSCSI protocol made the problems go away and now Auxilary copies are running fine.

Userlevel 7
Badge +23

@Robert Horowski , you are amazing, great insight!

Thanks for the update, I’ll credit your reply as the Best Answer 😎

Userlevel 3
Badge +8

Hi @Mike Struening 

@Mateusz Slezak is actually my colleague from work and I have advised him to switch from SMB to iSCSI protocol on QNAP device.

I remember that quite some time ago I read about broken SMB implementation in QNAP devices. This was in competition newsletter and since QNAP devices are pretty popular with their customers, they did some fine tuning to overcome QNAP implementation of SMB protocol.

Long story short, switching to iSCSI protocol made the problems go away and now Auxilary copies are running fine.

Apologies for resurrecting this, but how does one go about switching from SMB to iSCSI?

I have a QNAP that performs ok during backups, but pruning is too slow.

Even worse, this is on Metallic, so my options are a little limited... 

Userlevel 7
Badge +23

Tagging @Robert Horowski to see if he can advise you, @Shane !

Userlevel 4
Badge +13

Thanks for tagging me @Mike Struening 

 

@Shane as far as I am aware there is no in-place options or checkbox you can check to convert from one to the other.

https://forum.qnap.com/viewtopic.php?t=40444

 

In this case switching means, create new iSCSI volume, map it to the mediaagent, move data path and remove the old SMB share. That is if you have required free space to do so. In our case it was a fresh installation and performance issues came up very early, so discarding everything and starting over on new volume was an option.

I hope this helps!

Userlevel 3
Badge +8

Thanks for tagging me @Mike Struening 

 

@Shane as far as I am aware there is no in-place options or checkbox you can check to convert from one to the other.

https://forum.qnap.com/viewtopic.php?t=40444

 

In this case switching means, create new iSCSI volume, map it to the mediaagent, move data path and remove the old SMB share. That is if you have required free space to do so. In our case it was a fresh installation and performance issues came up very early, so discarding everything and starting over on new volume was an option.

I hope this helps!

It helps, and doesn’t help at all :-P

I appreciate your input, thank you. I have a Metallic case open to try assist with the horrendous pruning performance on the SMB QNAP.

But I know for next time, thanks again.

Reply