CVO Netapp intellisnap backup goes to pendng state.

Hi ​@neerajnen ,

Could you please share the "FileScan.log" from the iagicvop02cv07 server? Additionally, I would appreciate it if you could provide the job ID associated with it.

Regards,

Wasim

​@Wasim   : can you check on this , few of the sub clients are failing, few are getting success. 
7812  bc0   08/12 14:57:09 52380734 CVLibCurl::CVLibCurlSendHttpReqInternal() - failed to send http request
7812  bc0   08/12 14:57:09 52380734 CVLibCurl::CVLibCurlSendHttpReqInternal() - curl-err:[No error] http-resp:[409] url:[https://10.108.164.4/api/storage/volumes/be25b5a4-02ed-11f0-9dae-000d3ae9851f/snapdiff/sessions?return_records=true] server-resp:[{
7812  bc0   08/12 14:57:09 52380734 OntapRestAPI::sendReq() - Error while sending the request. URL[https://10.108.164.4/api/storage/volumes/be25b5a4-02ed-11f0-9dae-000d3ae9851f/snapdiff/sessions?return_records=true] Body[{ "application": { "name": "Commvault", "type": "backup" }, "base_snapshot": {"name": "SP_2_52340140_922944_1754888428" }, "diff_snapshot": { "name": "SP_2_52380711_923149_1755009064" }, "access_time": false, "report_file_attributes": true, "checkpoint_enabled": false, "file_access_protocol": "cifs", "max_diffs": 4096} ].
7812  bc0   08/12 14:57:09 52380734 OntapRestAPI::sendReq() - * Got 409 HTTP response. Number of retries left [2]. Will retry after [30] secs ...
7812  bc0   08/12 14:57:39 52380734 CVLibCurl::CVLibCurlSendHttpReqInternal() - failed to send http request
7812  bc0   08/12 14:57:39 52380734 CVLibCurl::CVLibCurlSendHttpReqInternal() - curl-err:[No error] http-resp:[409] url:[https://10.108.164.4/api/storage/volumes/be25b5a4-02ed-11f0-9dae-000d3ae9851f/snapdiff/sessions?return_records=true] server-resp:[{
7812  bc0   08/12 14:57:39 52380734 OntapRestAPI::sendReq() - Error while sending the request. URL[https://10.108.164.4/api/storage/volumes/be25b5a4-02ed-11f0-9dae-000d3ae9851f/snapdiff/sessions?return_records=true] Body[{ "application": { "name": "Commvault", "type": "backup" }, "base_snapshot": {"name": "SP_2_52340140_922944_1754888428" }, "diff_snapshot": { "name": "SP_2_52380711_923149_1755009064" }, "access_time": false, "report_file_attributes": true, "checkpoint_enabled": false, "file_access_protocol": "cifs", "max_diffs": 4096} ].
7812  bc0   08/12 14:57:39 52380734 OntapRestAPI::sendReq() - * Got 409 HTTP response. Number of retries left [1]. Will retry after [30] secs ...
7812  bc0   08/12 14:58:09 52380734 CVLibCurl::CVLibCurlSendHttpReqInternal() - failed to send http request
7812  bc0   08/12 14:58:09 52380734 CVLibCurl::CVLibCurlSendHttpReqInternal() - curl-err:[No error] http-resp:[409] url:[https://10.108.164.4/api/storage/volumes/be25b5a4-02ed-11f0-9dae-000d3ae9851f/snapdiff/sessions?return_records=true] server-resp:[{
7812  bc0   08/12 14:58:09 52380734 OntapRestAPI::sendReq() - Error while sending the request. URL[https://10.108.164.4/api/storage/volumes/be25b5a4-02ed-11f0-9dae-000d3ae9851f/snapdiff/sessions?return_records=true] Body[{ "application": { "name": "Commvault", "type": "backup" }, "base_snapshot": {"name": "SP_2_52340140_922944_1754888428" }, "diff_snapshot": { "name": "SP_2_52380711_923149_1755009064" }, "access_time": false, "report_file_attributes": true, "checkpoint_enabled": false, "file_access_protocol": "cifs", "max_diffs": 4096} ].
7812  bc0   08/12 14:58:09 52380734 SnapDiffV3: Could not start a SnapDiff session. Error code [15073282] message [Failed to create a snapdiff session for Volume with UUID "be25b5a4-02ed-11f0-9dae-000d3ae9851f". Reason: Could not connect to network interface.].
7812  bc0   08/12 14:58:09 52380734 SnapDiffV3: Please check if RPC is enabled and if there is a data network interface configured for NFS on vserver [SVA0656A].
7812  bc0   08/12 14:58:09 52380734 SnapDiffV3: Unable to start a SnapDiff V3 session. Falling back to V2.
7812  bc0   08/12 14:58:09 52380734 SnapDiffV2: Cannot connect to vserver [SVA0656A] on address [10.108.164.21]. Please verify that SnapDiff RPC is enabled on vserver [SVA0656A]. Falling back to V1.
7812  bc0   08/12 14:58:09 52380734 Starting SnapDiff V1. FileServer:[SVA0656A] Volume:[/SVA0656A/ORG005] SnapOne:[SP_2_52340140_922944_1754888428] SnapTwo:[SP_2_52380711_923149_1755009064] Format:[cifs] Items In Each Iteration [4096]
7812  bc0   08/12 14:58:09 52380734 ManageOntap connection established to FileServer:[10.108.164.4] ConnectMethod:[HTTPS] FileServerVersion:[NetApp Release 9.15.0P1: Fri Apr 19 14:49:05 UTC 2024]
7812  bc0   08/12 14:58:09 52380734 ManageONTAP::SetVserverForTunneling() - Using SVM[SVA0656A] for tunneling
7812  bc0   08/12 14:58:09 52380734 ManageONTAP::OpenConnection() - SVM connection with tunneling
7812  bc0   08/12 14:58:09 52380734 File-access-protocol support:[true] version check:[true]
7812  bc0   08/12 14:58:09 52380734 atime support:[true] version check:[true]
7812  bc0   08/12 14:58:09 52380734 End-of-diff support: [true]
7812  bc0   08/12 14:58:10 52380734 Successfully kicked off SnapDiff. Session ID:[c30f890a-778c-11f0-970f-000d3ae9851f:7a317bbb-43aa-11ef-ad16-000d3ae9851f]
7812  bc0   08/12 14:58:10 52380734 Waiting for session to become active. Session ID:[c30f890a-778c-11f0-970f-000d3ae9851f:7a317bbb-43aa-11ef-ad16-000d3ae9851f]
7812  bc0   08/12 14:58:10 52380734 Snapdiff status:[snapdiff_status_active]
7812  bc0   08/12 14:58:10 52380734 Session is active. Session ID:[c30f890a-778c-11f0-970f-000d3ae9851f:7a317bbb-43aa-11ef-ad16-000d3ae9851f]
7812  bc0   08/12 14:58:12 52380734 CWorkerAdvanced::SnapDiffVolumeNetApp(873) - SnapDiff first iteration has returned [256] items.
7812  bc0   08/12 14:58:39 52380734 SnapDiffNext Failed to get the next set of snapdiff items (snapdiff-iter-next). Error returned:[13001][Parsing error in results: Couldn't find end of Start Tag d
7812  bc0   08/12 14:58:39 52380734 CWorkerAdvanced::SnapDiffVolumeNetApp(849) - SnapDiffNext failed
7812  bc0   08/12 14:58:39 52380734 SnapDiff Iteration done.
7812  bc0   08/12 14:58:39 52380734 CWorkerAdvanced::SnapDiffVolumeNetApp(1180) - SnapDiff Files:[4608] ElapseSecs:[29] Total Files/Sec:[158] Interval Files/Sec:[158] Files added to collect:[4608]
7812  bc0   08/12 14:58:39 52380734 CWorkerAdvanced::SnapDiffVolumeNetApp(1186) - Total time for SnapDiff delete item DB insert: 0.408429
7812  bc0   08/12 14:58:39 52380734 CWorkerAdvanced::ProcessSnapDiffDeleteItems(2884) - Total time for SnapDiff delete item DB fetch: 0.001010
7812  bc0   08/12 14:58:39 52380734 CWorkerAdvanced::SnapDiffVolumeNetApp(1255) - Done Indexing; SnapDiff scan: Volume:[ORG005], Files scanned:[4608], Files added to collect:[4608]
7812  bc0   08/12 14:58:39 52380734 ManageONTAP::DeInit() - Calling na_shutdown...
7812  bc0   08/12 14:58:39 52380734 CWorkerAdvanced::ProcessPathsUsingSnapDiff(302) - --- 2:00.577612 1 paths to process
7812  bc0   08/12 14:58:39 52380734 CWorkerBasic::ProcessScan(4073) - --- 
7812  bc0   08/12 14:58:39 52380734 CWorkerThread::RunSynchronous(70) - Worker thread failed, error=0x80070306:{CWorkerBasic::Run(4053)} + {CWorkerBasic::ProcessScan(4089)} + {CWorkerBasic::TryScanners(4137)} + {CWorkerAdvanced::TryScanners_3(197)} + {CWorkerAdvanced::ProcessPathsUsingSnapDiff(363)/W32.774.(One or more errors occurred while processing the request. (ERROR_ERRORS_ENCOUNTERED.774))-SnapDiff failed, result=2}
7812  bc0   08/12 14:58:39 52380734 CWorkerGroup::Run(31) - --- 2:00.593045 
7812  bc0   08/12 14:58:39 52380734 CWorkerThread::RunStub(56) - Worker thread failed, error=0x80070306:{CWorkerGroup::Run(40)} + {CWorkerThread::RunSynchronous(75)} + {CWorkerBasic::Run(4053)} + {CWorkerBasic::ProcessScan(4089)} + {CWorkerBasic::TryScanners(4137)} + {CWorkerAdvanced::TryScanners_3(197)} + {CWorkerAdvanced::ProcessPathsUsingSnapDiff(363)/W32.774.(One or more errors occurred while processing the request. (ERROR_ERRORS_ENCOUNTERED.774))-SnapDiff failed, result=2}
7812  89c   08/12 14:58:39 52380734 CFind::ProcessJobDisposition(9909) - +++ Status=[1], FailJobFlag=[0]
7812  2600  08/12 14:58:39 52380734 CReportingThread::OnStop(57) - Stopping Reporting Thread. Final Reporting all tasks
7812  2600  08/12 14:58:39 52380734 CFileScanJMProgressReportTask::Execute(55) - Total Scanned items count did not change in last [150] seconds. Current Count: Folders [0] , Files [0] , Total [0] 
7812  2600  08/12 14:58:39 52380734 CFileScanAdvancedLogStatsTask::LogPeriodicCounters(60) - Total time for SnapDiff Scan: 2:00.577144, 1 samples, 2:00.577144 average, 0/second
7812  2600  08/12 14:58:39 52380734 IReportTask::Finalize(47) - [IFind JM Progress Report Task] Time Counter: 0:00.000942, 1 samples, 0:00.000942 average, 100/second .
7812  2600  08/12 14:58:39 52380734 IReportTask::Finalize(47) - [IFind Mark Job Alive Task] Time Counter: 0:00.000000, 0 samples, 0:00.000000 average, 0/second .
7812  2600  08/12 14:58:39 52380734 CContentPreprocessor::LogStatistics(62) - ExpandToVirtualStore=[0:00.002984, 16 samples, 0:00.000186 average, 1600/second]
7812  2600  08/12 14:58:39 52380734 CContentPreprocessor::LogStatistics(69) - ExpandContent5=[0:00.001532, 16 samples, 0:00.000095 average, 1600/second]
7812  2600  08/12 14:58:39 52380734 CContentPreprocessor::LogStatistics(76) - ExpandContent5 IsJunctionPoint=[0:00.001432, 20 samples, 0:00.000071 average, 2000/second]
7812  2600  08/12 14:58:39 52380734 CContentPreprocessor::LogStatistics(83) - ExpandContent5 SplitPaths=[0:00.000026, 14 samples, 0:00.000001 average, 1400/second]
7812  2600  08/12 14:58:39 52380734 CContentPreprocessor::LogStatistics(90) - ExpandContent5 SetLookup=[0:00.000027, 31 samples, 0:00.000000 average, 3100/second]
7812  2600  08/12 14:58:39 52380734 CContentPreprocessor::LogStatistics(97) - ExpandContent5 SetInsert=[0:00.000012, 6 samples, 0:00.000002 average, 600/second]
7812  2600  08/12 14:58:39 52380734 IReportTask::Finalize(47) - [IFind Log Performance Stats Task] Time Counter: 0:00.001057, 1 samples, 0:00.001057 average, 100/second .
7812  2600  08/12 14:58:39 52380734 CReportingThread::Run(23) - --- 2:01.015775 
7812  89c   08/12 14:58:39 52380734 JOBRESULTSTABLE(C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\2\0\5238 removing copy 'C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\2\0\52380734'
7812  89c   08/12 14:58:39 52380734 CFind::ProcessJobDisposition(9976) - Closing collect file, CollectFileName=[C:\Program Files\Commvault\ContentStore\iDataAgent\JobResults\CV_JobResults\iDataAgent\FileSystemAgent\2\12556\BC_12556\CollectInc.cvf]
7812  89c   08/12 14:58:39 52380734 BKP CALLED COMPLETE (PHASE Status::FAIL), 52380734. Token [52380734:8:2:0:0:22952]
7812  89c   08/12 14:58:40 52380734 CFind::ProcessJobDisposition(9909) - --- Status=[1], FailJobFlag=[0]
7812  89c   08/12 14:58:40 52380734 CFind::ProcessScanContent(5977) - --- 2:01.828813 
7812  89c   08/12 14:58:40 52380734 CFind::ProcessContent(5811) - --- 2:01.832320 
7812  89c   08/12 14:58:40 52380734 CFindAdvanced::ProcessContent(1633) - --- 2:01.833981 
7812  89c   08/12 14:58:40 52380734 CFind::ExecuteScan(5636) - --- 2:01.840556 
7812  89c   08/12 14:58:40 52380734 CFindAdvanced::ExecuteScan(1541) - --- 2:01.842088 
7812  89c   08/12 14:58:40 52380734 CFind::ProcessJobDisposition(9909) - +++ Status=[1], FailJobFlag=[0]
7812  89c   08/12 14:58:40 52380734 CFind::ProcessJobDisposition(9987) - JobDisposition has already been processed, ignoring this invocation
7812  89c   08/12 14:58:40 52380734 CFind::ProcessJobDisposition(9909) - --- Status=[1], FailJobFlag=[0]
7812  89c   08/12 14:58:40 52380734 CFind::ConfigureRunSequence(918) - JobDisposition handled, JobDisposition=[1], MessageId=[0 0xFFFFFFFF], Item=[CFind::PerformScanOperation], 

​@Wasim   : can you check on this urgent basis

Can any one assist here

Hi ​@neerajnen It's always better to provide the file rather than the log line specifically. 

Can you compare working and non-working subclient and under subclient properties > Intellisnap operations, are you using any specific proxy for non-working one's which is not present in the working one?

I would also suggest you raise a case with us if there is no difference between the sub clients observed. 

Best,

Rajiv Singal