Solved

Problem with AuxCopy job to qnap

2 years ago
May 21, 2022
13 replies
2416 views

Mateusz Slezak
Byte

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

Best answer by Robert Horowski

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.

View original

Did this answer your question?

+17

Jos Meijer
Commvault Certified Expert
2 years ago
May 21, 2022

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?

Mateusz Slezak
Byte
2 years ago
May 21, 2022

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

+17

Jos Meijer
Commvault Certified Expert
2 years ago
May 21, 2022

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.

Mateusz Slezak
Byte
2 years ago
May 21, 2022

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 ! :)

+17

Jos Meijer
Commvault Certified Expert
2 years ago
May 21, 2022

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.

Mateusz Slezak
Byte
2 years ago
May 28, 2022

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).

+23

Mike Struening
Vaulter
2 years ago
July 7, 2022

@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).

https://www.linkedin.com/in/michael-struening

+13

Robert Horowski
Commvault Certified Expert
2 years ago
July 8, 2022

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.

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

+23

Mike Struening
Vaulter
2 years ago
July 8, 2022

@Robert Horowski , you are amazing, great insight!

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

https://www.linkedin.com/in/michael-struening

Shane
Commvault Certified Expert
2 years ago
November 23, 2022

Robert Horowski wrote:

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.

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...

+23

Mike Struening
Vaulter
2 years ago
November 28, 2022

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

https://www.linkedin.com/in/michael-struening

+13

Robert Horowski
Commvault Certified Expert
2 years ago
November 29, 2022

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!

Shane
Commvault Certified Expert
2 years ago
November 29, 2022

Robert Horowski wrote:

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

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

Cookie policy

We use cookies to enhance and personalize your experience. If you accept you agree to our full cookie policy. Learn more about our cookies.

Cookie settings

We use 3 different kinds of cookies. You can choose which cookies you want to accept. We need basic cookies to make this site work, therefore these are the minimum you can select. Learn more about our cookies.

Basic
Functional

Normal
Functional + analytics

Complete
Functional + analytics + social media + embedded videos

Reply

Related topics

ZTE MC801A softan päivitys ei onnistuicon

ZTE MC801A ohjelmistopäivitys ei toimiicon

Zte Mc801a

ZTE MC801A päivitys MC801A_Elisa3_B22

5G Kotinetti jumittaaicon

Most helpful members this week

Sign up

Login to the community

Scanning file for viruses.

This file cannot be downloaded

Cookie policy

Cookie settings