Skip to main content
commvault.com commvault.com
Solved

PostgreSQL First full backup issue

K
Byte

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

Best answer by Meera

Hi Kamil,

Since it is failing in transaction log backup phase, we need to check whether log archival to /pg_arch directory is happening fine or not. 

https://documentation.commvault.com/commvault/v11_sp20/article?p=21518.htm → Please do the test mentioned in last point here.

There is a related troubleshooting case also → ttps://documentation.commvault.com/commvault/v11_sp20/article?p=21723.htm#o21744 

 

Logging for this phase will be in PostGresLogBackupParent.log and PostGresLogBackupChild.log

 

Regards,

Meera

View original
Did this answer your question?

8 replies

Edd Rimmer
Vaulter
Forum|alt.badge.img+7
  • Edd RimmerVaulter
  • Vaulter
  • 58 replies
  • May 21, 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 :) 

Of all the things I've lost, I miss my mind the most
K
1 person likes this
  • K
    Kamil
Meera
Vaulter
Forum|alt.badge.img+7
  • MeeraVaulter
  • Vaulter
  • 70 replies
  • May 21, 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

Meera
K
1 person likes this
  • K
    Kamil
K
Byte
  • Kamil
  • Author
  • 143 replies
  • May 21, 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

Meera
Vaulter
Forum|alt.badge.img+7
  • MeeraVaulter
  • Vaulter
  • 70 replies
  • May 21, 2021

Hi Kamil,

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

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

 

Regards,

Meera

Meera
Mike Struening
K
2 people like this
  • Mike Struening
    Mike Struening
  • K
    Kamil
K
Byte
  • Kamil
  • Author
  • 143 replies
  • May 24, 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

 

 

I am asking you for help in analyzing the problem.

Thanks,
Kamil

3 Attachments
Meera
Vaulter
Forum|alt.badge.img+7
  • MeeraVaulter
  • Vaulter
  • 70 replies
  • Answer
  • May 24, 2021

Hi Kamil,

Since it is failing in transaction log backup phase, we need to check whether log archival to /pg_arch directory is happening fine or not. 

https://documentation.commvault.com/commvault/v11_sp20/article?p=21518.htm → Please do the test mentioned in last point here.

There is a related troubleshooting case also → ttps://documentation.commvault.com/commvault/v11_sp20/article?p=21723.htm#o21744 

 

Logging for this phase will be in PostGresLogBackupParent.log and PostGresLogBackupChild.log

 

Regards,

Meera

Meera
Mike Struening
K
2 people like this
  • Mike Struening
    Mike Struening
  • K
    Kamil
K
Byte
  • Kamil
  • Author
  • 143 replies
  • May 26, 2021

Hello,

 

Backup started after changing the settings, the client wants to wait a while to verify that everything is working properly.

Thanks
Kamil

Mike Struening
Meera
2 people like this
  • Mike Struening
    Mike Struening
  • Meera
    Meera
Mike Struening
Vaulter
Forum|alt.badge.img+23

SWEET!  Once you and the client are happy, feel free to mark the reply with the solution as the Best Answer :nerd:

https://www.linkedin.com/in/michael-struening
K
1 person likes this
  • K
    Kamil

Reply


Most helpful members this week

Terms & ConditionsCookie settings

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