BART WARNING: xlog-method is not supported, ignored

[Davy_Machado]

Hi guys,

on a server, BART (2.0.1 or 2.1) is not doing backups with stream xlog method.

In the log we can see a WARNING ("xlog-method is not supported, ignored") and the pg_basebackup execution with -x option (fetch, not stream).

/usr/edb/bart2.0/bin/bart --debug -c /usr/edb/bart2.0/etc/bart.cfg BACKUP -Fp -s teste
DEBUG: Exec Command: set -o pipefail; /usr/ppas-9.5/bin/pg_basebackup --version
WARNING: xlog-method is not supported, ignored
INFO: creating backup for server 'teste'
INFO: backup identifier: '1526571574311'
DEBUG: internal backup Command to be execute: '/usr/ppas-9.5/bin/pg_basebackup -D /tmp/backups/teste/1526571574311/base -x -P -Fp -h 127.0.0.1 -p 5432 -U enterprisedb'
DEBUG: prepared for backup: 36 msecs
71047/71047 kB (100%), 1/1 tablespace

INFO: backup completed successfully
DEBUG: executed backup command: 371 msecs
DEBUG: start time: 1526571574, stop time: 1526571574, duration: 0
DEBUG: wrote backupinfo: 150 msecs
DEBUG: released lock file: 0 msecs
DEBUG: full backup complete: 557 msecs
INFO: 
BACKUP DETAILS:
BACKUP STATUS: active
BACKUP IDENTIFIER: 1526571574311
BACKUP NAME: none
BACKUP PARENT: none
BACKUP LOCATION: /tmp/backups/teste/1526571574311
BACKUP SIZE: 68.64 MB
BACKUP FORMAT: plain
BACKUP TIMEZONE: America/Maceio
XLOG METHOD: stream
BACKUP CHECKSUM(s): 0
TABLESPACE(s): 0
START WAL LOCATION: 000000010000000000000061
BACKUP METHOD: streamed
BACKUP FROM: master
START TIME: 2018-05-17 12:39:34 -03
STOP TIME: 2018-05-17 12:39:34 -03
TOTAL DURATION: 0 sec(s)

Follows bart.cfg:

[BART]
bart_host = enterprisedb@127.0.0.1
backup_path = /tmp/backups
pg_basebackup_path = /usr/ppas-9.5/bin/pg_basebackup
logfile = /tmp/bart2.0.log
scanner_logfile = /tmp/bart2.0_scanner.log
xlog_method = stream

[TESTE]
host = 127.0.0.1
port = 5432
user = enterprisedb
cluster_owner = enterprisedb
description = "Test Server"

We are using:

- CentOS Linux release 7.3.1611

- EnterpriseDB 9.5.13.19 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-4), 64-bit

Note that bart and pg_basebackup paths is right.

We have the same situation with BART 2.0.1 or 2.1, or with EDB PPAS 9.5 or EDB PAS 9.6. The problem just does not occur with EDB PAS 10.

In this server, bart CHECK-CONFIG returns version 9.00000:

-bash-4.2$ /usr/edb/bart2.0/bin/bart --debug CHECK-CONFIG
INFO:  Verifying that pg_basebackup is executable
DEBUG: Exec Command: set -o pipefail; /usr/ppas-9.5/bin/pg_basebackup --version
INFO:  success - pg_basebackup(/usr/ppas-9.5/bin/pg_basebackup) returns version 9,000000

-bash-4.2$ /usr/ppas-9.5/bin/pg_basebackup --version
pg_basebackup (PostgreSQL) 9.5.12.18

But, in other server, where we don't have this problem with the same versions, the bart CHECK-CONFIG returns version 9.50000:

[postgres@vm-edb-03 ~]$ /usr/edb/bart2.0/bin/bart --debug CHECK-CONFIG
INFO:  Verifying that pg_basebackup is executable
DEBUG: Exec Command: set -o pipefail; /usr/ppas-9.5/bin/pg_basebackup --version
INFO:  success - pg_basebackup(/usr/ppas-9.5/bin/pg_basebackup) returns version 9.500000

[postgres@vm-edb-03 ~]$ /usr/ppas-9.5/bin/pg_basebackup --version
pg_basebackup (PostgreSQL) 9.5.12.18

Maybe this can be a tip to solve the problem.

Anyone has access to BART (2.0.1 or 2.1) source code to verify why this WARNING is returned?

I appreciated any help.

Thanks,

Davy Machado

[richyen]

Hi Davy,

Thank you for your inquiry.  The reason why the xlog-method is not supported, ignored message appears is because getPGBaseBackupVersion() in our code retrieved a value less than or equal to 9.2.  So the real problem lies in why CHECK-CONFIG returned an incorrect pg_basebackup version of 9,000000 instead of 9.500000 (I am also suspicious of the comma as well).  I am investigating this and will update you when I get a better idea.

In the meantime, could you share your output of rpm -aq | grep -i bart on both servers?  And do you happen to have a non-9.5 version of Postgres installed on the problematic host?

Regards,

--Richard

[Davy_Machado]

Hi Richard,

Thanks for reply.

In the meantime, could you share your output of rpm -aq | grep -i bart on both servers?

Normal host:

[postgres@vm-edb-03 ~]$ rpm -aq | grep -i bart
edb-bart20-2.0.1-1.rhel7.x86_64

Problematic host:

-bash-4.2$ rpm -aq | grep -i bart
edb-bart20-2.0.1-1.rhel7.x86_64
edb-bart-2.1.0-1.rhel7.x86_64

On the problematic host, bart 2.1 was installed to verify that the problem occurred in the latest version.

And do you happen to have a non-9.5 version of Postgres installed on the problematic host?

Yeah, PAS 9.6 and PAS 10.3.8 was installed on this host to verify the problem too. The problem only does not happen with pg_basebackup (PostgreSQL) 10.3.8.

-bash-4.2$ /usr/edb/bart2.0/bin/bart -c /usr/edb/bart2.0/etc/bart.cfg --debug BACKUP -Fp -s teste                    
DEBUG: Exec Command: set -o pipefail; /usr/edb/as10/bin/pg_basebackup --version
INFO:  creating backup for server 'teste'
INFO:  backup identifier: '1526611249286'
DEBUG: internal backup Command to be execute: '/usr/edb/as10/bin/pg_basebackup -D /tmp/backups/teste/1526611249286/base -X stream -P  -Fp -d "host=127.0.0.1 port=5444 user=enterprisedb"  '
DEBUG: prepared for backup: 43 msecs
49380/49380 kB (100%), 1/1 tablespace

INFO:  backup completed successfully
DEBUG: executed backup command: 1498 msecs
DEBUG: start time: 1526611249, stop time: 1526611250, duration: 1
DEBUG: wrote backupinfo: 19 msecs
DEBUG: released lock file: 0 msecs
DEBUG: full backup complete: 1560 msecs
INFO:  
BACKUP DETAILS:
BACKUP STATUS: active
BACKUP IDENTIFIER: 1526611249286
BACKUP NAME: none
BACKUP PARENT: none
BACKUP LOCATION: /tmp/backups/teste/1526611249286
BACKUP SIZE: 63.40 MB
BACKUP FORMAT: plain
BACKUP TIMEZONE: America/Maceio
XLOG METHOD: stream
BACKUP CHECKSUM(s): 0
TABLESPACE(s): 0
START WAL LOCATION: 000000010000000000000014
BACKUP METHOD: streamed
BACKUP FROM: master
START TIME: 2018-05-17 23:40:49 -03
STOP TIME: 2018-05-17 23:40:50 -03
TOTAL DURATION: 1 sec(s)

-bash-4.2$ /usr/edb/bart2.0/bin/bart --debug CHECK-CONFIG       
INFO:  Verifying that pg_basebackup is executable
DEBUG: Exec Command: set -o pipefail; /usr/edb/as10/bin/pg_basebackup --version
INFO:  success - pg_basebackup(/usr/edb/as10/bin/pg_basebackup) returns version 10,000000

My friend Clailson uploaded the virtual disk image (vdi) of problematic host on Google Drive. If you want, create a new VM on VirtualBox with that vdi to replicate the problem.

Follow link below:

https://drive.google.com/open?id=1ABshoyaiONuOoSvWsLl3_HPtTU3h3ySo

Regards,

Davy Machado

[Clailson]

Hi.

Our client has the same issue, reporting the wrong version and not making the streaming backup. He is using PPAS9.5 and Bart 2.1.

/opt/PostgresPlus/9.5AS/bin/psql --version
psql (EnterpriseDB) 9.5.5.10

/opt/PostgresPlus/9.5AS/bin/pg_basebackup --version
pg_basebackup (PostgreSQL) 9.5.5.10

/usr/edb/bart/bin/bart -c /usr/edb/bart/etc/bart-9.5.cfg check-config
INFO:  Verifying that pg_basebackup is executable
INFO:  success - pg_basebackup(/opt/PostgresPlus/9.5AS /bin/pg_basebackup) returns version 9,000000

Regards,

Clailson de Almeida

[richyen]

Clailson and Davy,

Thank you for sharing the information with us--we're currently investigating and will provide an update at our earliest ability.

Cheers,

--Richard

[richyen]

Clailson and Davy,

It seems that this behavior is related to the LC_NUMERIC setting.  By changing LC_NUMERIC (or by simply setting LC_ALL), you will be able to get the correct output:

-bash-4.2$ /usr/edb/bart2.1/bin/bart --debug -c /usr/edb/bart2.1/etc/bart.cfg check-config
INFO:  Verifying that pg_basebackup is executable
DEBUG: Exec Command: set -o pipefail; /usr/ppas-9.5/bin/pg_basebackup --version
INFO:  success - pg_basebackup(/usr/ppas-9.5/bin/pg_basebackup) returns version 9,000000
-bash-4.2$ export LC_NUMERIC=C
-bash-4.2$ /usr/edb/bart2.1/bin/bart --debug -c /usr/edb/bart2.1/etc/bart.cfg check-config
INFO:  Verifying that pg_basebackup is executable
DEBUG: Exec Command: set -o pipefail; /usr/ppas-9.5/bin/pg_basebackup --version
INFO:  success - pg_basebackup(/usr/ppas-9.5/bin/pg_basebackup) returns version 9.500000

[Clailson]

Hi Richard.

It worked.

Now the question: Is it a bug or was it supposed to behave like this? I'm wondering why with version 10 of PG it was working (though it returned the wrong number too - 10,000000).

Thanks for your help.

Clailson

[richyen · Accepted solution]

@Clailson wrote:

Now the question: Is it a bug or was it supposed to behave like this? I'm wondering why with version 10 of PG it was working (though it returned the wrong number too - 10,000000).

Hi Clailson, we're treating this as a bug, and should be fixed soon.  The reason why it works for v10 despite the incorrect output is because the test is for $VERSION <= 9.2 -- as you can see, 9.5 becoming interpreted as 9,0 will cause xlog-method to get ignored, but 10.4 getting interpreted as 10,0 is not problematic, as 10,0 >= 9,2

Hope that helps,

--Richard

[Clailson]

Many thanks, Richard.
Your help was very important.

Clailson