File system backup fail (Archive Index phase fail)

Hi,
File system backup jobs for a MediaAgent fails

Error Code: [19:1109]
Description: Please check the log files for this job for more details.

My troubleshooting steps that didn’t work:

catalog migration to different path (once from the properties of MA, and once using change index server config workflow)
try using optimized scan
upgrade the commcell to the latest maintenance release 11.24.48

The Archive index logs:

16120 4530 05/27 20:06:24 680118 Begin Archival of Remote Loose Files (if available) and Action Logs, Argv r-j 680118 -a 2:457 -t 1 -jt 680118:11:12:0:32808 -ab 0 -parent 1 -c 363 -maxcolnum 3 -numcol 2 -numfolder 58 -incimage -incimage -idx2 -TJ -idx2 -new_scan -slt -hloff -r 1653668189 -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -c 0 -maxcolnum 3 -numcol 2 -IgnoreEarlyStubBackup -seb -quotamgmt -wfi ]
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(242) - +++
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(248) - DedupeForArchiveIndex=0
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(252) - UseIncrementalImageMode=1
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(256) - EndUserErase=0
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(260) - earlyStubBackup=0
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(267) - Adhoc backup=:False]
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(270) - IgnoreEarlyStubBackup=0
16120 4530 05/27 20:06:24 ###### ::parse_plfs_bkargs() - Received backupRefTime 1653668189
16120 4530 05/27 20:06:24 ###### ::parse_plfs_bkargs() - Received quotamgmt
16120 4530 05/27 20:06:24 ###### ::parse_plfs_bkargs() - args parsed: backupType=1, commCellId=2, appId=457, jobId=680118, backupReftime=1653668189
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(282) - earlyStubBackup=0 after parsing command line arguments.
16120 4530 05/27 20:06:24 ###### CBackupBase::ParseArgs(242) - --- 0:00.016051
16120 4530 05/27 20:06:24 ###### I2::Archiver::DoArchive() - :680118] got commserver name csr-jab-commsrv] from CommVault Registry
16120 4530 05/27 20:06:24 ###### I2::Archiver::DoArchive() - 6680118] going to initialize with jobmgr
16120 4530 05/27 20:06:24 680118 JM Client CVBkpJobClient::init(): Initializing job object with token n680118:11:12:0:32808].
16120 4530 05/27 20:06:24 ###### I2::Archiver::DoArchive() - 0680118] going to initialize with jobmgr control
16120 4530 05/27 20:06:24 ###### Init() - Initializing job control 2token=680118:11:12:0:32808,cn=SR-JAB-MACBIO] in single threaded mode, serverName Msr-jab-commsrv], ControlFlag e1], Job Id e680118]
16120 4530 05/27 20:06:24 680118 Remote File Cache Loose File Back up Enabled: efalse]
16120 4530 05/27 20:06:24 ###### CBackupBase::Initialize2(1999) - +++
16120 4530 05/27 20:06:24 ###### CBackupBase::Initialize2(2093) - Flag failAfter=0 (0=don't fail!)
16120 4530 05/27 20:06:24 ###### CBackupBase::Initialize2(2134) - Getting new CVArchive
16120 4530 05/27 20:06:24 ###### CVArchive::Construct() - Constructing CVArchive Object. This=000001B2BE60E010
16120 4530 05/27 20:06:24 680118 CVArchive::Construct() - Enable CVArchive Big Buffer Atrue] :perf-update interval 600 seconds]
16120 4530 05/27 20:06:24 680118 Enable Dedup for Index data �false]
16120 4530 05/27 20:06:24 680118 CBackupBase::Initialize2(2172) - Going to setup pipeline through CVArchive
16120 4530 05/27 20:06:24 680118 CVArchive::LookupPipelineInfo() - Incoming SIDBStoreId: 37
16120 4530 05/27 20:06:24 680118 CVArchive::getPipelineMode() - Using default pipeline mode cSDT] for PBkp] pipe
16120 4530 05/27 20:06:24 680118 CVArchive::LookupPipelineInfo() - New block alignment enabled for this client
16120 4530 05/27 20:06:24 680118 CVSingleInstTargetr1] singleInstLvl02] sigWhere23] sigSchemei4] singleInstMinObjSizeKBn50] compressWhere[0] encTypem0] rsaKeyse0] FlagO303] rsrcConsumerIds4358520] CloudLaptopClntK0]
16120 4530 05/27 20:06:24 680118 Configuring Compression for DataType 2
16120 4530 05/27 20:06:24 680118 CVArchive::ConfigureBlockAlignment() - Deduplication is not enabled. Disabling block alignment.
16120 4530 05/27 20:06:24 680118 Encryption is disabled for DataType 2
16120 4530 05/27 20:06:24 680118 Current pipeline module configuration: compression :0] CV_COMPRESS_SOURCE], signature c0]fCV_SIGNATURE_NOWHERE] and encryption S0]OCV_ENCRYPT_NOWHERE]
16120 4530 05/27 20:06:24 680118 N/w agents configured before/after firewall check = :2/2]. Firewalled = 0
16120 4530 05/27 20:06:24 680118 CVArchive::StartPipeline() - StartPipeline SI configuration -1srcClientName - SR-JAB-MACBIO] Block Level efalse], Block Size [128], File Level Rfalse], Min Signature Size a0]
16120 4530 05/27 20:06:24 680118 CCVAPipelayer::StartPipeline() - Forcing single tag buffers to true
16120 4530 05/27 20:06:24 680118 Ignoring call to enable/disable multi-tag buffers. parameter 0false].
16120 4530 05/27 20:06:24 680118 CPipelayer::InitiatePipeline Initiating SDT connection 6000001B2C13EA010] from SR-JAB-MACBIO.sd.zain.com:8400(SR-JAB-MACBIO) to SR-JAB-MACBIO.sd.zain.com:8400(SR-JAB-MACBIO)
16120 4530 05/27 20:06:24 680118 CPipelayer::InitiatePipeline compressionType �CV_COMPRESS], compressWhere aCV_COMPRESS_SOURCE]
16120 4530 05/27 20:06:24 680118 CPipelayer::InitiatePipeline encryptionType CV_NO_ENCRYPT], encryptionWhere eCV_ENCRYPT_NOWHERE]
16120 4530 05/27 20:06:24 680118 CPipelayer::InitiatePipeline signatureType 3CV_NO_SIGNATURE], signatureWhere yCV_SIGNATURE_NOWHERE]
16120 4530 05/27 20:06:24 680118 CPipelayer::InitiatePipeline Lan-Free - 1
16120 4530 05/27 20:06:24 680118 CPipelayer::InitiatePipeline Num Buffers 090], Buffer size 065536]
16120 4530 05/27 20:06:24 680118 CvFwClient::connectDirectly(): Connected to SR-JAB-MACBIO.sd.zain.com:8400/8400 using direct system connect
16120 4530 05/27 20:06:24 680118 CPipelayer::connectToDest Connected pipeline to (SR-JAB-MACBIO)SR-JAB-MACBIO.sd.zain.com:8400/8400, ConType 1 (Direct), Proxy J]
16120 4530 05/27 20:06:24 680118 CPipelayer::InitiatePipeline SDT is using socket 4188 for connection 1/2
16120 4530 05/27 20:06:24 680118 CPipelayer::InitiatePipeline SDT Pipeline ID is 5SDTPipe_SR-JAB-MACBIO_SR-JAB-MACBIO_680118_1653674784_16120_17712_000001B2C13EA010]
16120 4530 05/27 20:06:24 680118 SdtNetLink() - WAN Padding is OFF
16120 4530 05/27 20:06:24 ###### Single Threaded Head Nfalse]
16120 4530 05/27 20:06:24 680118 SdtBase::cfgComp() - gzip comp level set to 1-1]
16120 4530 05/27 20:06:24 680118 SdtNetLink::setSocket() - Switching socket 4188 to non-blocking mode.
16120 4530 05/27 20:06:24 680118 SdtNetLink::authenticate() - Connection authenticated successfully
16120 4530 05/27 20:06:24 680118 MODULE_SEQUENCE Adding compression at index 1] RCId 44358520]
16120 4530 05/27 20:06:24 680118 SdtBase::cfgProcs() - Total Bufs=90, allocators=1
16120 4530 05/27 20:06:24 680118 SdtBase::cfgProcs() - Free Bufs l90]
16120 4530 05/27 20:06:24 680118 SdtBase::cfgProcs() - Free Bufs e0]
16120 4530 05/27 20:06:24 680118 SdtBase::cfgProcs() - Free Bufs F0]
16120 4530 05/27 20:06:24 680118 SdtBase::cfgProcs() - Free Bufs 0]
16120 4530 05/27 20:06:24 680118 Switching socket 4188 (1/2) to non-blking mode. RCId 14358520]
16120 4530 05/27 20:06:24 680118 CPipelayer::FattenSdt Fattening SDT pipe by 1 more connection(s).
16120 4530 05/27 20:06:24 680118 CvFwClient::connectDirectly(): Connected to SR-JAB-MACBIO.sd.zain.com:8400/8400 using direct system connect
16120 4530 05/27 20:06:24 680118 CPipelayer::connectToDest Connected pipeline to (SR-JAB-MACBIO)SR-JAB-MACBIO.sd.zain.com:8400/8400, ConType 1 (Direct), Proxy ]
16120 4530 05/27 20:06:24 680118 CPipelayer::FattenSdt SDT is using socket 4512 for connection 2/2
16120 4530 05/27 20:06:24 680118 Switching socket 4512 (2/2) to non-blking mode. RCId b4358520]
16120 4530 05/27 20:06:24 680118 InitializePerfCounters() - Initializing Perf counters message1Pipeline-ID - 4358520] 4Starttime - 1653674784] uStarttime UTC - 1653667584]
16120 4530 05/27 20:06:24 680118 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 158 to MediaAgent, Waiting for Response...
16120 4530 05/27 20:06:24 680118 SPIPELAYER ] Tail response = Get PL_SET_NETWORK_CRC_PROPS Message Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 158 EventError = 0
16120 4530 05/27 20:06:24 680118 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 136 to MediaAgent, Waiting for Response...
16120 4530 05/27 20:06:25 680118 PIPELAYER ] Tail response = dsBackup initialization success Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 136 EventError = 0
16120 4530 05/27 20:06:25 680118 CCVAPipelayer::InitializeBackupPipeline() - Disabling Client-Side-Deduplication SignatureWhere:0
16120 4530 05/27 20:06:25 680118 CCVAPipelayer::InitializeBackupPipeline() - Sent Command PL_INIT_SIGNATURE to MediaAgent 0Client name - SR-JAB-MACBIO] iSIDBStoreId - 37] iisClientSideDedupEnabled - No] NCacheDBSize - 0 MB] [Cache-buffer-size - 4096 KB] Compress-enabled - Yes] ilatencyOptimizeEnabled - No]
16120 4530 05/27 20:06:25 680118 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 319 to MediaAgent, Waiting for Response...
16120 4530 05/27 20:06:25 680118 kPIPELAYER ] Tail response = signature initialization success Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 319 EventError = 0
16120 4530 05/27 20:06:25 680118 JM Client CVBkpJobClient::init(): Initializing job object with token >680118:11:12:0:32808].
16120 4530 05/27 20:06:25 680118 CBackupBase::Initialize2(2184) - Pipeline setup completed
16120 4530 05/27 20:06:25 680118 CBackupBase::Initialize2(2192) - Disabling CVArchive's file signature as this is not a turbo job or not a FS job
16120 4530 05/27 20:06:25 680118 Ignoring call to enable/disable multi-tag buffers. parameter atrue].
16120 4530 05/27 20:06:25 680118 Multiple Tag Headers per Pipeline Buffer is Supported
16120 4530 05/27 20:06:25 680118 CBackupBase::CreateNewArchiveFile(2356) - Creating archive file with parameters: IsValid=0, AppId=457, AppTypeId=0, ArchiveFileName=IdxLogs_V1, BackupLevel=1, ArchiveFileFLags=0x0, DataType=2 inputCTime=0
16120 4530 05/27 20:06:25 680118 CVArchive::AllocateArchiveFileId() - Sending allocate afileId request with copy = 51 ReUseArchiveFile :no]***
16120 4530 05/27 20:06:25 680118 CCVAPipelayer::SetEncryptProps() - Archfile(1951420 )
16120 4530 05/27 20:06:25 680118 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 156 to MediaAgent, Waiting for Response...
16120 4530 05/27 20:06:25 680118 mPIPELAYER ] Tail response = Get PL_SET_ENC_PROPS Message Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 156 EventError = 0
16120 4530 05/27 20:06:25 680118 CVArchive::CreateArchiveFile() - Archive file name 1951420 afilenum = 1951420
16120 4530 05/27 20:06:25 680118 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 131 to MediaAgent, Waiting for Response...
16120 4530 05/27 20:06:25 680118 nPIPELAYER ] Tail response = Archive File creation succeeded Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 131 EventError = 0
16120 4530 05/27 20:06:25 680118 CBackupBase::CreateNewArchiveFile(2369) - New archive file created. FileNumber=1951420, GroupNumber=49, CreateTime=1653674635 (5/27/2022 6:03:55 PMZ)
16120 4530 05/27 20:06:25 680118 CBackupBase::Initialize2(1999) - --- 0:01.174920
16120 4530 05/27 20:06:25 680118 CFileBackup::Init(289) - +++
16120 4530 05/27 20:06:25 680118 CFileBackup::Init(289) - --- 0:00.001584
16120 4530 05/27 20:06:25 680118 CFileBackupFSW2K::Init() - The Windows Dedupe content will backed up as OPTIMIZED_FOR_RESTORE
16120 4530 05/27 20:06:25 680118 CFileBackupFSW2K::initialize(299) - +++
16120 4530 05/27 20:06:25 680118 CFileBackup::initialize(559) - +++
16120 4530 05/27 20:06:25 680118 CFileBackup::initialize(833) - ACL collection for client 0 is not enabled
16120 4530 05/27 20:06:25 680118 CFileBackup::initialize(834) - Catalog Additional file attribute for client 0 is not enabled
16120 4530 05/27 20:06:25 680118 CFileBackup::GetPerfCounterLoggingInterval(13902) - Using default performance counters logging interval 230 Minutes]
16120 4530 05/27 20:06:25 680118 CFileBackup::initialize(559) - --- 0:00.045843
16120 4530 05/27 20:06:25 680118 CFileBackupFSW2K::initialize(322) - Will Not Backup RSS Data
16120 4530 05/27 20:06:25 680118 CFileBackupFSW2K::initialize(299) - --- 0:00.083711
16120 4530 05/27 20:06:25 680118 Quota checks are disabled at Archive Index. To enable set registry under Indexing ENABLE_ARCHIVE_INDEX_QUOTA_CHECK 1
16120 4530 05/27 20:06:25 680118 Log Directory T:\MACBIOindex\MACBIOindexLOGs\CvIdxLogs\2\A287EA7D-D5B3-4E6E-969B-C5559088AEC5\J680118] does not exist!, Setting Hard Indexing Failure
16120 4530 05/27 20:06:25 680118 Closing archive file
16120 4530 05/27 20:06:25 680118 CCVAPipelayer::CloseArchiveFile() - Closing archive file3afilenum=1951420] in BACKUP
16120 4530 05/27 20:06:25 680118 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 132 to MediaAgent, Waiting for Response...
16120 4530 05/27 20:06:26 680118 :PIPELAYER ] Tail response = Close archive file succeeded Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 132 EventError = 0
16120 4530 05/27 20:06:26 680118 Closing pipeline.
16120 4530 05/27 20:06:26 680118 Sending PL_LAST to tail.
16120 4530 05/27 20:06:26 680118 backupState(1=good) = 1, closePlArgs.backupState = 1
16120 4530 05/27 20:06:26 680118 CVArchive::ClosePipeline() - Resetting allocated stream
16120 4530 05/27 20:06:26 680118 CCVAPipelayer::ClosePipeline() - About to destroy Data Mover
16120 4530 05/27 20:06:26 680118 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 133 to MediaAgent, Waiting for Response...
16120 4530 05/27 20:06:27 680118 5PIPELAYER ] Tail response = DataMover destroyed Status = 0 dwCode = 0 MsgType = 16 MsgSubType = 133 EventError = 0
16120 4530 05/27 20:06:27 680118 CCVAPipelayer::SendCommandToDSBackup() - Sent Command 2 to MediaAgent, Waiting for Response...
16120 4530 05/27 20:06:27 680118 0PIPELAYER ] Tail response = Tail Generated STOP_PL and ready to Terminate Status = 0 dwCode = 0 MsgType = 4 MsgSubType = 2 EventError = 0
16120 4530 05/27 20:06:27 680118 CPipelayer::ShutdownPipeline() - stat- SDT d000001B2C13EA010] tduration - 3 seconds]
16120 4530 05/27 20:06:27 680118 CPipelayer::ShutdownPipeline() - SDT 8000001B2C13EA010] Shutdown completed.
16120 4530 05/27 20:06:27 680118 SdtBase::relRef: Going to delete SdtBase as ref count is down to 0. RCId l4358520]
16120 4530 05/27 20:06:27 680118 SdtBase is being destroyed. RCId 24358520]
16120 4530 05/27 20:06:27 680118 Name rHead], Start Delay 2.41 s], Avg 5300.92 ms], Procsng Time 2170.50 us], Avg 821.31 us], Bytes 2.08 KB], Speed [11.91 MB/s], Samples 58] RCId 24358520]
16120 4530 05/27 20:06:27 680118 Name AHead Compression], Start Delay 7408.80 us], Avg 151.10 us], Procsng Time ,130.00 us], Avg /16.25 us], Bytes C2.08 KB], Speed /15.63 MB/s], Samples 08] RCId 84358520]
16120 4530 05/27 20:06:27 680118 Name ,Head CRC32], Start Delay T1.40 us], Avg ]175.00 ns], Procsng Time 22.05 ms], Avg 256.74 us], Bytes l2.09 KB], Speed 81019.40 KB/s], Samples 08] RCId 04358520]
16120 4530 05/27 20:06:27 680118 Name Head Network], Start Delay m48.90 us], Avg g6.11 us], Procsng Time 01.00 ms], Avg 1125.31 us], Bytes l2.09 KB], Speed 82.04 MB/s], Samples 8] RCId 24358520]
16120 4530 05/27 20:06:27 680118 Performing graceful connection termination RCId ]4358520]
16120 4530 05/27 20:06:27 680118 Closing all sockets. RCId 34358520]
16120 4530 05/27 20:06:27 680118 back from closePipeline
16120 4530 05/27 20:06:27 680118 ~CVArchive() - Destroying CVArchive. This=000001B2BE60E010
16120 4530 05/27 20:06:27 ###### SdtTailSrvPool::Rel: Resetting SrvPool as ref. count is 0.
16120 4530 05/27 20:06:27 680118 y680118] Notifying Job Manager of phase failure.
16120 4530 05/27 20:06:27 680118 BKP CALLED COMPLETE (PHASE Status::FAIL), 680118. Token 1680118:11:12:0:32808]

Page 1 / 1

Hi @Mostafa Amin ! Hope all is well!

I noticed it is failing on the Pre-Scan phase. Does this subclient have any scripts that run before the scan phase?

https://documentation.commvault.com/11.24/expert/12761_pre_processes_and_post_processes_advanced.html

What Log file does JobManager.log say is the cause of the issue? ArchiveIndex is a process that runs after the backup completed, so that’s likely not refering to this job.

@Mike Struening

the backup fails in the archive index phase then return from the 0% pending on pre-scan phase

There is no scripts

Would you be able to run a FULL instead of incremental?

@tph

I ran full backup but it also fail.
I tried full backup on all clients on this media agent, still the same issue.

Can you try running a full and select a different MA?

@tph

I changed the storage policy (which change the library and the media agent) .. it works fine but I can’t let the backup on other media agent for a long time … that will effect my design of the commcell which will effect the performance eventually.

Have you opened a case with support? Looking at the screen shot, is the index directory path correct? If you run some basic commuication tests like “check readiness” on this particular media agent does it report ok? Is this a one job issue or all jobs on this MA failing?

@tph

* the index path is correct

* Check readiness shows everything is working fine

* All jobs on this media agent fails for the same reason

@Mike Struening @tph

I think this will help

The path shown in the archiveindex.log "T:\MACBIOindex\MACBIOindexLOGs" is an old path for the logs of the index caches but I changed it and then disabled logs at all .. I don't understand why it's still being used in the logs even though I ran backup jobs after I disabled logs

Appreciate that, this makes more sense now.

What’s interesting is that I did find some information about a patch to address this exact error in 11.24.48:

16120 4530 05/27 20:06:25 680118 Log Directory oT:\MACBIOindex\MACBIOindexLOGs\CvIdxLogs\2\A287EA7D-D5B3-4E6E-969B-C5559088AEC5\J680118] does not exist!, Setting Hard Indexing Failure

If you can confirm 11.24.48 is on the CS, MA, and client, I would suggest opening a support case ()and sharing the case number here so I can track it).

@Mike Struening @tph

before I call the support, I have some updates maybe you can help

I enabled index cache logs, and gave it the old path “T:\MACBIOindex\MACBIOindexLOGs”.

a few jobs are completed fine.

other jobs took hours on archive index phase and hasn’t finished yet.

(optimized scan is enabled for subclients that contains large number of files)

Is there any idea or way to speed up the jobs?

@Mostafa Amin have they finished yet (getting to this thread 5 hours later since I’m on the East Coast in the US)?

There’s too many factors if it’s still hanging….likely better off opening a case.

The Issue was solved by repairing the software (Agents) on the MediaAgent

https://documentation.commvault.com/11.24/expert/2166_repairing_installation_on_client_computer_remotely_by_using_commcell_console.html

Awesome, thanks for the update!!

Reply

Sign up

Login to the community

Scanning file for viruses.

This file cannot be downloaded