Solved

PostgreSQL First full backup issue

2 years ago
21 May 2021
8 replies
3740 views

Userlevel 4

Kamil
138 replies

Hello Commvault Community,

Today I have a problem with the first full PostgreSQL Client backup.

Our client has configured client PostgreSQL ver. 12.5 on the Centos 7 system. The client seems to be correctly configured - the connection to the base is there.

The first backup full, unfortunately stops with the pending status and an error:

Error Code: [19: 599]

Description: Loss of control process PostGresBackup.exe. Possible causes:

1. The control process has unexpectedly died. Check crash dump or core file.

2. The communication to the control process machine xyz might have gone down due to network errors.

3. If the machine xyz is a cluster, it may have failed over.

4. The machine xyz may have rebooted. Source: commserve, Process: JobManager

After analyzing the logs, I can see that during the time when the error occurred during the backup task, it loops: (screen1-2)

-PostGresBackupParent.log
8150 1fd6 05/17 13:31:53 422980 DumpFileList() - DirPath = [/var/lib/pgsql/12/data] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
8150 1fd6 05/17 13:31:53 422980 DumpFileList() - DirPath = [/var/lib/pgsql/12/data] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
8150 1fd6 05/17 13:31:53 422980 DumpFileList() - DirPath = [/var/lib/pgsql/12/data] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
8150 1fd6 05/17 13:31:53 422980 DumpFileList() - DirPath = [/var/lib/pgsql/12/data] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]

-cvlaunched.log

129459 1fd5 05/17 13:32:03 ### acceptThread() - /opt/commvault/iDataAgent/PostGresBackup (pid=8150) terminated due to signal 11
129459 1fd5 05/17 13:32:03 ### acceptThread() - Socket send failed: Broken pipe

Software Version: 11 SP20.36

What could be causing the problem and how to fix it.
Thank you for your help.

Regards,
Kamil

icon

Best answer by Meera 24 May 2021, 11:22

View original

8 replies

Userlevel 4

Edd Rimmer
Vaulter
58 replies
2 years ago
21 May 2021

Hi Kamil,

It’s very difficult to identify what is happening here - however can see it’s being killed (I assume because it looks like its not making any progress).

You’d have to increase the logging level of the PostGresBackupParent module and see what it’s up to at this point:

Ideally though, a support case should probably be raised for this as a job should either progress or fail - not get stuck :)

Userlevel 3

Meera
Vaulter
61 replies
2 years ago
21 May 2021

Hi Kamil,

Do you have any user tablespace created inside data directory? If yes, please move it out and retry backup. Please see this case for details https://documentation.commvault.com/commvault/v11/article?p=21723.htm#o21753

Regards,

Meera

Userlevel 4

Kamil
Author
138 replies
2 years ago
21 May 2021

Hello,

I checked during the session with the client, the logs behave the same as in the case of the killed job.

@Meera

I sent this documentation at the very beginning, the database administrator claims that there is no problem. Additionally, please note that the access path is not the same.

At the client's: DirPath = DirPath = [/ var / lib / pgsql / 12 / data]: WalDir [/ pg_arch]: ClusterDir_m = [/ var / lib / pgsql / 12 / data]

In the documentation: DirPath = [/ var / lib / pgsql / data / pg_tblspc]: WalDir [/largevol/8.4/wal]: ClusterDir_m = [/ var / lib / pgsql / data]

I heard from the client that they have other PostgreSQL databases in version 9.6 on the environment and everything works fine. With version 12.5 they having problems, maybe version 12.5 is buggy and causing problems?

Regards,
Kamil

Userlevel 3

Meera
Vaulter
61 replies
2 years ago
21 May 2021

Hi Kamil,

Please check for any symlink inside data directory with below command.

ls -l /var/lib/pgsql/12/data/

Regards,

Meera

Userlevel 4

Kamil
Author
138 replies
2 years ago
24 May 2021

Hello,

I asked the client to do what you suggested @Meera .

The client did an analysis with the database admin and so:
- there were no links to userspace
- but there was a link in pg_wal in the data directory - admin deleted it

After that, the backup started but stops at 75%. (screens)

Below, I am sending the entire task record from the PostGreBackupParent.log for easier problem analysis. If you need information from a different log, please tell me.

60315 eb9b 05/21 14:02:42 424776 ::main() - PostGresBackupParent
60315 eb9b 05/21 14:02:42 424776 ::main() - Backup on Postgres server
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::logBackupArgs(14841) - args parsed: currProg=</opt/commvault/iDataAgent/PostGresBackup>
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::logBackupArgs(14844) - args parsed: backupType=1, commCellId=2, appId=1673, jobId=424776, collectCount=9223372036854775807, numCol=1, maxCol=1
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::logBackupArgs(14845) - isParent=1 isChild=0 numStreamsReserved=1 fdRead=0, fdWrite=0
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::logBackupArgs(14847) - verifySyntheticFull=0, m_bEarlyStubBackup=0
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::logBackupArgs(14848) - bCatalogBkp:0 bSnap2TapeBkp:0
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::parent(2801) - Disabling optimized hard link backups
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::initPerfFlag(2523) - clBackup PERFORMANCE ANALYSIS will be turned OFF (FileSystemAgent/nPerfBackup not set)
60315 eb9b 05/21 14:02:42 424776 PostGresClBackupBase::Initialize() - FSflag:FALSE,logBackup:FALSE
60315 eb9b 05/21 14:02:42 424776 PostGresClBackupBase::Initialize() - Subclient GUID = [532E5C0D-07E3-4CED-A7AD-9A2854293795]
60315 eb9b 05/21 14:02:42 424776 useIndexingV2 [true]
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::Initialize(9157) - going to get commserver name for commclient from platform information
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::Initialize(9170) - got commserver name from platform information
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::Initialize(9190) - going to initialize with jobmgr
60315 eb9b 05/21 14:02:42 424776 JM Client CVBkpJobClient::init(): Initializing job object with token [424776:6:1:0:44709].
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::Initialize(9198) - going to initialize with jobmgr control
60315 eb9b 05/21 14:02:42 424776 Init() - Initializing job control [token=424776:6:1:0:44709,cn=500db1], serverName [Commserve.ANTARES.INT], ControlFlag [1], Job Id [424776]
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::subclientDir(9877) - reInitializing szJobStatusDir
60315 eb9b 05/21 14:02:42 424776 ::GetSubclientDirUsingClientName() - clientname is [500db1].
60315 eb9b 05/21 14:02:42 424776 ::GetSubclientDirUsingClientName() - GALAXY_INST is [Instance001].
60315 eb9b 05/21 14:02:42 424776 ::GetSubclientDirUsingClientName() - GALAXY_VM is [Instance001].
60315 eb9b 05/21 14:02:42 424776 ::GetSubclientDirUsingClientName() - The subclient directory is [/opt/commvault/iDataAgent/jobResults/2/1673].
60315 eb9b 05/21 14:02:42 424776 CvUCS::init_static() - Native charset="UTF-8".
60315 eb9b 05/21 14:02:42 424776 CvUCS::init_static() - Great! This system is using ISO/IEC 10646 character set for wchar_t. We will not be using iconv() API and will be converting between MBE and UTF/UCS using C MBR functions.
60315 eb9b 05/21 14:02:42 424776 CvUCS::init_static() - MBE happens to be UTF-8. Will use strcpy for MBE<=>UTF-8 conversion.
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::subclientDir(9984) - subclientDir = /opt/commvault/iDataAgent/jobResults/2/1673
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::subclientDir(9985) - collect = /opt/commvault/iDataAgent/jobResults/2/1673/CollectTot.cvf
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::subclientDir(9986) - dirchangeTmp = /opt/commvault/iDataAgent/jobResults/2/1673/DCTmp.cvf
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::subclientDir(9987) - dirchangeFull = /opt/commvault/iDataAgent/jobResults/2/1673/DCTot.cvf
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::subclientDir(9988) - dirchangeIncr = /opt/commvault/iDataAgent/jobResults/2/1673/DCInc.cvf
60315 eb9b 05/21 14:02:42 424776 ClBackupBase::subclientDir(9989) - subclient failure = /opt/commvault/iDataAgent/jobResults/2/1673/Failures.cvf
60315 eb9b 05/21 14:02:42 424776 PostGresClBackupBase::PostGresInitialize() - CommcellID 2, AppId 1673
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::Init() - autoDiscoveryFlag = 1
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::Init() - Got all the information from appmanager
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - archlogFile = /pg_arch
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - socketName =
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - unixUser = postgres
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - saUser = admin
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - postgresVersion = 12.5
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - binaryPath = /usr/pgsql-12/bin
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - datafilePath = /usr/pgsql-12/lib
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - configFile = postgres
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - ntUser =
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - uncUser =
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - HostAddr       =
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - Port   = 5433
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - autoDiscoveryFlag = 1
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - LastLogNumber =
60315 eb9b 05/21 14:02:42 424776 GetPostgresInfo::display() - Prune Logs = true
60315 eb9b 05/21 14:02:42 424776 SetEnv() - setenv [LD_LIBRARY_PATH] = [/usr/pgsql-12/lib]
60315 eb9b 05/21 14:02:42 424776 ::GetSubclientDir() - The subclient directory is [/opt/commvault/iDataAgent/jobResults/2/1673].
60315 eb9b 05/21 14:02:42 424776 PostGresClBackupBase::PostGresInitialize() - Jobresultsdir /opt/commvault/iDataAgent/jobResults/2/1673
60315 eb9b 05/21 14:02:42 424776 PostGresClBackupBase::Initialize() - FSflag :true
60315 eb9b 05/21 14:02:42 424776 PGCommon::GetPGLibraryPath(1290) - Cloudn't find library [/usr/pgsql-12/lib/libpq.so] , try to locate libpq.so.x version under library path.
60315 eb9b 05/21 14:02:42 424776 PGCommon::GetPGLibraryPath(1303) - found match [libpq.so.5]
60315 eb9b 05/21 14:02:42 424776 ConnectDb() - Connection Info string: port = '5433' dbname = 'postgres' user = 'admin' password = **********
60315 eb9b 05/21 14:02:42 424776 PostGresClBackupBase::Initialize() - PostGres FileSystem Backup
60315 eb9b 05/21 14:02:42 424776 PostGresClBackupBase::Initialize() - Jobresultsdir /opt/commvault/iDataAgent/jobResults/2/1673
60315 eb9b 05/21 14:02:42 424776 PGCommon::GetPGLibraryPath(1290) - Cloudn't find library [/usr/pgsql-12/lib/libpq.so] , try to locate libpq.so.x version under library path.
60315 eb9b 05/21 14:02:42 424776 PGCommon::GetPGLibraryPath(1303) - found match [libpq.so.5]
60315 eb9b 05/21 14:02:42 424776 ConnectDb() - Connection Info string: port = '5433' dbname = 'postgres' user = 'admin' password = **********
60315 eb9b 05/21 14:02:42 424776 PostgresHelperClass::GetDbDirs() - Got PostgreSQL version [12.5]
60315 eb9b 05/21 14:02:42 424776 PostGresClBackupBase::Initialize() - restart string is empty Starting interface
60315 eb9b 05/21 14:02:42 424776 PostGreFsBackupInterface() - Enter
60315 eb9b 05/21 14:02:42 424776 PGCommon::GetPGLibraryPath(1290) - Cloudn't find library [/usr/pgsql-12/lib/libpq.so] , try to locate libpq.so.x version under library path.
60315 eb9b 05/21 14:02:42 424776 PGCommon::GetPGLibraryPath(1303) - found match [libpq.so.5]
60315 eb9b 05/21 14:02:42 424776 ConnectDb() - Connection Info string: port = '5433' dbname = 'postgres' user = 'admin' password = **********
60315 eb9b 05/21 14:02:42 424776 PostGreFsBackupInterface() - Set DB in backup mode if its not standby system
60315 eb9b 05/21 14:06:24 424776 SetDBInBackupMode() - Cluster is in Backup mode now
60315 eb9b 05/21 14:06:24 424776 GenerateCollectFile() - JobResultsDir_m[/opt/commvault/iDataAgent/jobResults/2/1673]
60315 eb9b 05/21 14:06:24 424776 CollectFileManager::CollectFileManager() - JobResultsFolder_m[/opt/commvault/iDataAgent/jobResults/2/1673]
60315 eb9b 05/21 14:06:24 424776 CollectFileManager::CollectFileManager() - CollectFileMap_m size [33]
60315 eb9b 05/21 14:06:24 424776 ::getActualPath() - File postgresql.conf --- Dir /var/lib/pgsql/12/data
60315 eb9b 05/21 14:06:24 424776 ResetCurrentCollectFile() - fopen [/opt/commvault/iDataAgent/jobResults/2/1673/CollectTot1.cvf]
60315 eb9b 05/21 14:06:24 424776 ::getActualPath() - File pg_hba.conf --- Dir /var/lib/pgsql/12/data
60315 eb9b 05/21 14:06:24 424776 ::getActualPath() - File pg_ident.conf --- Dir /var/lib/pgsql/12/data
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_snapshots] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_dynshmem] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/log] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_logical] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_logical/mappings] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_logical/snapshots] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_twophase] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_commit_ts] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_tblspc] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_sl_i] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_sl_i/PG_12_201909212] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_sl_i/PG_12_201909212/16424] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_default] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_default/PG_12_201909212] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_default/PG_12_201909212/pgsql_tmp] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_default/PG_12_201909212/16424] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_temp/] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_temp//PG_12_201909212] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_temp//PG_12_201909212/pgsql_tmp] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_sl_d] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_sl_d/PG_12_201909212] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_sl_d/PG_12_201909212/16424] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_wnio_i] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_wnio_i/PG_12_201909212] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_wnio_i/PG_12_201909212/16424] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_wnio_d] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_wnio_d/PG_12_201909212] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_wnio_d/PG_12_201909212/16424] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_zal_d] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_zal_d/PG_12_201909212] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_zal_d/PG_12_201909212/16424] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_zal_i] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_zal_i/PG_12_201909212] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/tablespaces/ppsw1_zal_i/PG_12_201909212/16424] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_xact] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/archive_status] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_subtrans] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_multixact] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_multixact/offsets] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_multixact/members] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_serial] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_wal] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/global] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_stat] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_notify] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_stat_tmp] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/base] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/base/16408] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/base/27364847] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/base/14186] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/base/16409] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 DumpFileList() - DirPath = [/var/lib/pgsql/12/data/pg_replslot] : WalDir [/pg_arch]: ClusterDir_m = [/var/lib/pgsql/12/data]
60315 eb9b 05/21 14:06:24 424776 GenerateCollectFile() - Getting collectfile size
60315 eb9b 05/21 14:06:24 424776 CheckCollectFileSize() - Collect file [/opt/commvault/iDataAgent/jobResults/2/1673/CollectTot1.cvf] size [438272].
60315 eb9b 05/21 14:06:24 424776 GenerateCollectFile() - Getting collectfile count
60315 eb9b 05/21 14:06:24 424776 GenerateCollectFile() - Getting number of files to backup
60315 eb9b 05/21 14:06:24 424776 GenerateCollectFile() - Exit
60315 eb9b 05/21 14:06:24 424776 PostGreFsBackupInterface() - Exit
60315 eb9b 05/21 14:06:24 424776 PostGresClBackupBase::Initialize() - Interface started
60315 eb9b 05/21 14:06:24 424776 PostGresClBackupBase::Initialize() - NoOfCollectFiles = 1 ,NonOfFilesToBackup=7064
60315 eb9b 05/21 14:06:24 424776 PostGresClBackupBase::Initialize() - setting UnCompBytesToXfer [170674302234]
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::getCollectFileAttrib(8825) - collectFileDir=</opt/commvault/iDataAgent/jobResults/2/1673> collectFileName=<CollectTot> collectFileExtn=<cvf>
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::parent(2895) - m_dbArchive=0|incImageMode=0
60315 eb9b 05/21 14:06:24 424776 PostGresClBackupBase::doCreateIndex() - doCreateIndex
60315 eb9b 05/21 14:06:24 424776 PostGresClBackupBase::doCreateIndex() - PostGreFsBackupInterfaceGetMetaData done
60315 eb9b 05/21 14:06:24 424776 PostGresClBackupBase::doCreateIndex() - Writing to DBList file
60315 eb9b 05/21 14:06:24 424776 NoPrefix Heartbeat timeout is set to 1800
60315 eb9b 05/21 14:06:24 424776 *******************Using new Indexing layer*******************
60315 eb9b 05/21 14:06:24 424776 [::sendDirChange]: creating one line dirchange
60315 eb9b 05/21 14:06:24 424776 [::sendDirChange]: createindex will process dirchange [/opt/commvault/Base/Temp/Idx_60315_0]
60315 eb9b 05/21 14:06:24 424776 CreateIndex succeeded.
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::getCreateIndexFileName(16029) - CreateIndex flag file name set to '/opt/commvault/iDataAgent/jobResults/2/1673/CIdxDone.cvf'.
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::CreateIndexComplete(15948) - File CreateIndex flag created.
60315 eb9b 05/21 14:06:24 424776 PostGresClBackupBase::doCreateIndex() - subclient flag = 1
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::parent(2975) - FolderCount=[0], FileCount[7064], TotalCount=[7064]
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::getMultiStreamFactor(2646) - getDataBackupStreams = 1
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::getMultiStreamFactor(2679) - Multi Stream Factor=<1>; Resources Reserved by JobManager=<1>
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::getRestartInfo(6677) - Restart String is NULL; numCollectFilesRemaining=<1> restartListSize=<1>
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::parent(3613) - CXBF driver is not installed on this host. CV SNAP will be skipped.
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::parent(3675) - QSnap is not enabled.
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::startChild(5753) - Child Process=<63943> Started.
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::startChild(5788) - Sending bkArgs to the Child=<63943>
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::sendMappingInfo(16064) - ifDoSnap:0 bCatalogBkp:0 snapInfo.count:0 snapMap:0 DDBSubClient:0.
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::sendMappingInfo(16095) - Will sent 0 items in snapMap table.
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::getCollectFileName(17032) - ../../clBackup/clBackupBase.C:17032 num:1 buf '1'
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::getCollectFileName(17038) - '/opt/commvault/iDataAgent/jobResults/2/1673/CollectTot1.cvf'
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::sendNextCollectFile(6479) - Number of Collect Files remaining=<0> collectNum to send 1
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::startChild(5846) - Sending collectNum=<1> offset=<0> to the Child=<63943> for acrhcive ID <0>
60315 eb9b 05/21 14:06:24 424776 ClBackupBase::parent(3965) - Number of Child Process started=<1>
60315 f9c7 05/21 14:06:24 424776 ClBackupBase::startChild(5940) - CVPI_Focus::getFocusClientName() [ 500db1 ]
60315 f9c7 05/21 14:06:24 424776 ClBackupBase::startChild(5941) - m_ClientNamePassedToParent [ 500db1 ]
60315 f9c7 05/21 14:06:24 424776 ClBackupBase::startChild(6180) - Child Args - '/opt/commvault/iDataAgent/PostGresBackup -child 60315 -j 424776 -fdRead 10 -fdWrite 13 -a 2:1673 -jt 424776:6:1:0:44709 -numstreams 1 -cn 500db1 -hloff -idx2 '
60315 eb9b 05/21 14:06:30 424776 ClBackupBase::parent(4412) - Child=<63943> sent use the ResourceId=<1255833>
60315 eb9b 05/21 14:16:24 424776 ClBackupBase::parent(4212) - Child=<63943> processed collectNum=<1>; Requests next file
60315 eb9b 05/21 14:16:24 424776 ClBackupBase::parent(4363) - Sending collectNum=<0> offset=<0> to the Child=<63943>
60315 eb9b 05/21 14:16:34 424776 ClBackupBase::parent(4525) - Child=<63943> Stream Completed; numFiles=7064 totSize=170677988996
60315 eb9b 05/21 14:16:37 424776 ClBackupBase::parent(4758) - All Child Process Done - Ready to exit.
60315 eb9b 05/21 14:16:37 424776 ClBackupBase::parent(5181) - Exiting main collect processing loop...
60315 eb9b 05/21 14:16:37 424776 ClBackupBase::ShouldUseIdxMAOptionForV1Index(15916) - Using MA [MediaagentA.ANTARES.INT*mediaagenta*8400] for indexing connection
60315 eb9b 05/21 14:16:37 424776 ClBackupBase::parent(5389) - Successful completion of the Backup
60315 eb9b 05/21 14:16:37 424776 ClBackupBase::dumpStats(5606) - STATISTICS: 7064 files, 170677988996 bytes, 24161663 average size
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::Init() - autoDiscoveryFlag = 1
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::Init() - Got all the information from appmanager
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - archlogFile = /pg_arch
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - socketName =
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - unixUser = postgres
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - saUser = admin
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - postgresVersion = 12.5
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - binaryPath = /usr/pgsql-12/bin
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - datafilePath = /usr/pgsql-12/lib
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - configFile = postgres
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - ntUser =
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - uncUser =
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - HostAddr       =
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - Port   = 5433
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - autoDiscoveryFlag = 1
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - LastLogNumber =
60315 eb9b 05/21 14:16:37 424776 GetPostgresInfo::display() - Prune Logs = true
60315 eb9b 05/21 14:16:37 424776 PostGresClBackupBase::createMetadataIndex() - subclient flag = 1
60315 eb9b 05/21 14:16:37 424776 PGCommon::GetPGLibraryPath(1290) - Cloudn't find library [/usr/pgsql-12/lib/libpq.so] , try to locate libpq.so.x version under library path.
60315 eb9b 05/21 14:16:37 424776 PGCommon::GetPGLibraryPath(1303) - found match [libpq.so.5]
60315 eb9b 05/21 14:16:37 424776 ConnectDb() - Connection Info string: port = '5433' dbname = 'postgres' user = 'admin' password = **********
60315 eb9b 05/21 14:16:37 424776 PostgresHelperClass::GetDbDirs() - Got PostgreSQL version [12.5]
60315 eb9b 05/21 14:16:37 424776 PostGresClBackupBase::sendMetadataIndex() - mangled client name 500db1*500db1*8400*8402
60315 eb9b 05/21 14:16:37 424776 PostGresClBackupBase::sendMetadataIndex() - mangled media agent name = MediaagentA.ANTARES.INT*mediaagenta*8400
60315 eb9b 05/21 14:16:37 424776 PostGresClBackupBase::sendMetadataIndex() - Before calling m_idxUtil.addBrowseAblePath for extended metadata indexing
60315 eb9b 05/21 14:16:37 424776 IdxUtil::addBrowseAblePath() - Entering function
60315 eb9b 05/21 14:16:37 424776 IdxUtil::addBrowseAblePathIndV2() - Entering function
60315 eb9b 05/21 14:16:37 424776 IDXCONNECT *****************USING NEW INDEXING LAYER**************
60315 eb9b 05/21 14:16:37 424776 IDXCONNECT Stream Id not set, Generating it
60315 eb9b 05/21 14:16:37 424776 IDXCONNECT Initializing Indexing connection to client [mediaagenta] from [500db1], Setting log mode as offline
60315 eb9b 05/21 14:16:37 424776 CVArchive::ConnectSessionToArchiveManager() - Attaching to CommServer [Commserve.ANTARES.INT] from Platform Type 4
60315 eb9b 05/21 14:16:37 424776 CVArchive::ConnectSessionToArchiveManager() - Attached to CommServe
60315 eb9b 05/21 14:16:37 424776 IDXCONNECT starting afile (2,72,1486242)
60315 eb9b 05/21 14:16:37 424776 CVOnDemandSvcClient::SubmitTask() - On Demand service CVODS_logmanager_mediaagenta_1 launched at host MediaagentA.ANTARES.INT*mediaagenta*8400. Unique ID is 4CAACBB2-0570-405D-B7AA-443AF78C57C0
60315 eb9b 05/21 14:16:37 424776 Got ODS Guid [4CAACBB2-0570-405D-B7AA-443AF78C57C0] from server [LogManager] Host [MediaagentA.ANTARES.INT*mediaagenta*8400]
60315 eb9b 05/21 14:16:38 424776 IDXCONNECT entire afile (2,72,1486242) is valid
60315 eb9b 05/21 14:16:38 424776 CVOnDemandSvcClient::Attach() - Successfully attached to on Demand service CVODS_logmanager_mediaagenta_1 launched at host MediaagentA.ANTARES.INT*mediaagenta*8400. Unique ID is 4CAACBB2-0570-405D-B7AA-443AF78C57C0
60315 eb9b 05/21 14:16:38 424776 IdxUtil::addBrowseAblePathIndV2() - calling idx.backupDone(1)
60315 eb9b 05/21 14:16:38 424776 CVOnDemandSvcClient::Attach() - Successfully attached to on Demand service CVODS_logmanager_mediaagenta_1 launched at host MediaagentA.ANTARES.INT*mediaagenta*8400. Unique ID is 4CAACBB2-0570-405D-B7AA-443AF78C57C0
60315 eb9b 05/21 14:16:38 424776 PGPERFMONITOR::PGTimer::logSummary(433) - Function/query #of calls Elapsed Time(sec)
60315 eb9b 05/21 14:16:38 424776 PGPERFMONITOR::PGTimer::logSummary(436) - sendMetadataIndex 1 0.209101
60315 eb9b 05/21 14:16:38 424776 PostGresClBackupBase::exitHere() - DBG: sendDirChange with finalize called
60315 eb9b 05/21 14:16:38 424776 NoPrefix Heartbeat timeout is set to 1800
60315 eb9b 05/21 14:16:38 424776 *******************Using new Indexing layer*******************
60315 eb9b 05/21 14:16:38 424776 [::sendDirChange]: creating one line dirchange
60315 eb9b 05/21 14:16:38 424776 [::sendDirChange]: createindex will process dirchange [/opt/commvault/Base/Temp/Idx_60315_1]
60315 ebbb 05/21 14:54:04 424776 controlThread() - Quit flag set, operation 2 - waiting on semaphore 424776_60315