BART: bart incremental from a remote server

[Polem]

Hi,

I have a setup with a BART server central. When I try to execute a backup full plain no problem but when I try an incremental:

[bartuser@paulemscl95 ~]$ bart show-backups -s edb95
SERVER NAME   BACKUP ID       BACKUP NAME                 BACKUP PARENT   BACKUP TIME               BACKUP SIZE   WAL(s) SIZE   WAL FILES   STATUS

edb95         1547103465787   full_edb95                  none            2019-01-10 07:58:04 CET   4.32 GB       80.00 MB      5           active
edb95         1547021898673   edb95_2019-01-09T09:18:18   none            2019-01-09 09:23:30 CET   336.14 MB     48.00 MB      3           active
edb95         1545375232521   edb95_2018-12-21T07:53:52   none            2018-12-21 07:54:19 CET   211.71 MB     112.00 MB     7           active
edb95         1545316108205   edb95_2018-12-20T15:28:28   none            2018-12-20 15:28:54 CET   207.65 MB     48.00 MB      3           active

[bartuser@paulemscl95 ~]$ bart show-servers -s edb95
SERVER NAME         : edb95
BACKUP FRIENDLY NAME: edb95_%year-%month-%dayT%hour:%minute:%second
HOST NAME           : 10.27.105.7
USER NAME           : repuser
PORT                : 5432
REMOTE HOST         : enterprisedb@10.27.105.7
RETENTION POLICY    : 2019-01-07 08:12:50 CET
DISK UTILIZATION    : 5.34 GB
NUMBER OF ARCHIVES  : 18
ARCHIVE PATH        : /dstpol/backup/bart/edb95/archived_wals
ARCHIVE COMMAND     : rsync -av -z %p bartuser@10.27.105.12:/dstpol/backup/bart/edb95/archived_wals/%f
XLOG METHOD         : fetch
WAL COMPRESSION     : disabled
TABLESPACE PATH(s)  :
INCREMENTAL BACKUP  : ENABLED
DESCRIPTION         : "EDB 95 Server KITERICEDB95"

[bartuser@paulemscl95 ~]$ bart backup -s edb95 --backup-name=incr_edb95 --format=p --parent=full_edb95
INFO:  checking mbm files /dstpol/backup/bart/edb95/archived_wals
NOTICE:  pg_stop_backup complete, all required WAL segments have been archived
ERROR: backup failed for server 'edb95'
bart-scanner is not running, please check
[bartuser@paulemscl95 ~]$

[Ranjan]

Hi Polem,

We are looking into your issue and will update you soon.

[ajinkya]

Hi Polem,

In order to take the incremental backup we need to make few changes like:

• Disable wal_compression (if applicable)
• Enable allow_incremental_backups parameter in bart.cfg
• Start bart_scanner (It determines from the WAL files which blocks have been modified and records the information in a file called the modified block map (MBM) file, stored at bart archived_wals location) 

Command for bart scanner:

        bart-scanner -c <path_of_bart.cfg>

Kindly make these changes and check if the bart increment backup is working.

Please feel free to reach us if you have any queries.

--

Regards

Ajinkya Bangale

[Polem]

Hi,

I restart bart-scanner. It was scanning WAL at the start then stop.

So I get other when I try backup:

[bartuser@paulemscl95 tmp]$ bart backup -s edb95 --backup-name=incr_edb95 --format=p --parent=full_edb95
INFO:  checking mbm files /dstpol/backup/bart/edb95/archived_wals
WARNING: WAL file '/dstpol/backup/bart/edb95/archived_wals/00000001000000000000003B' must be scanned
WARNING: WAL file '/dstpol/backup/bart/edb95/archived_wals/00000001000000000000003C' must be scanned
NOTICE:  pg_stop_backup complete, all required WAL segments have been archived
ERROR: backup failed for server 'edb95'
waiting for WAL files to be archived; currently waiting for '00000001000000000000003C'
[bartuser@paulemscl95 tmp]$

tail from /tmp/bart_scanner.log
5539:2019-01-11 08:04:55 CET  INFO:  process created for server 'scl96', pid = 5543
5540:2019-01-11 08:04:55 CET  INFO:  parsing WAL backlog
5540:2019-01-11 08:04:55 CET  INFO:  WAL file to be processed: 000000010000000000000037
5542:2019-01-11 08:04:55 CET  INFO:  parsing WAL backlog
5540:2019-01-11 08:04:55 CET  INFO:  WAL file to be processed: 000000010000000000000038
5540:2019-01-11 08:04:55 CET  INFO:  WAL file to be processed: 000000010000000000000039
5540:2019-01-11 08:04:55 CET  INFO:  WAL file to be processed: 00000001000000000000003A
5541:2019-01-11 08:04:55 CET  INFO:  parsing WAL backlog
5543:2019-01-11 08:04:55 CET  INFO:  parsing WAL backlog
5542:2019-01-11 08:04:55 CET  INFO:  WAL file to be processed: 00000001000000010000000A

But files are present:
ls -lrt from archived_wals directory
-rw------- 1 bartuser bartuser 16777216 Jan 11 08:07 00000001000000000000003B
-rw------- 1 bartuser bartuser 16777216 Jan 11 08:07 00000001000000000000003C
-rw------- 1 bartuser bartuser 16777216 Jan 11 08:08 00000001000000000000003D
-rw------- 1 bartuser bartuser      292 Jan 11 08:08 00000001000000000000003C.00000028.backup

[ajinkya]

Hi Polem,

Please make sure that the bart-scanner is not stopped (ps -ef | grep bart-scanner). It should be running in background.

use:

    bart-scanner --daemon -c <bart.cfg>

[Polem]

Hi,

I check bart-scanner:

[root@paulemscl95 ~][0]#  ps -fe | grep bart-scanner
bartuser  5539     1  0 08:04 ?        00:00:00 bart-scanner --daemon
bartuser  5540  5539  0 08:04 ?        00:00:00 bart-scanner --daemon
bartuser  5541  5539  0 08:04 ?        00:00:00 bart-scanner --daemon
bartuser  5542  5539  0 08:04 ?        00:00:00 bart-scanner --daemon
bartuser  5543  5539  0 08:04 ?        00:00:00 bart-scanner --daemon
root     20817 20658  0 10:35 pts/1    00:00:00 grep --color=auto bart-scanner
[root@paulemscl95 ~][0]#

And find below bart.log

8110:2019-01-09 09:22:48 CET  INFO:  new backup identifier generated 1547021898673
8110:2019-01-09 09:22:48 CET  INFO:  creating 5 harvester threads
8110:2019-01-09 09:23:30 CET  INFO:  backup completed successfully
8110:2019-01-09 09:23:30 CET  INFO:  
BART VERSION: 2.2.0
BACKUP DETAILS:
BACKUP STATUS: active
BACKUP IDENTIFIER: 1547021898673
BACKUP NAME: edb95_2019-01-09T09:18:18
BACKUP PARENT: none
BACKUP LOCATION: /dstpol/backup/bart/edb95/1547021898673
BACKUP SIZE: 336.14 MB
BACKUP FORMAT: tar.gz
BACKUP TIMEZONE: Europe/Brussels
XLOG METHOD: fetch
BACKUP CHECKSUM(s): 0
TABLESPACE(s): 0
START WAL LOCATION: 00000001000000000000002C
STOP WAL LOCATION: 00000001000000000000002D
BACKUP METHOD: pg_start_backup
BACKUP FROM: master
START TIME: 2019-01-09 09:22:48 CET
STOP TIME: 2019-01-09 09:23:29 CET
TOTAL DURATION: 41 sec(s)

8110:2019-01-09 09:23:33 CET  INFO:  connection to the server failed: could not connect to server: No route to host
	Is the server running on host "10.27.105.8" and accepting
	TCP/IP connections on port 5432?

8110:2019-01-09 09:23:33 CET  ERROR: unable to execute query (SELECT pg_catalog.pg_is_in_recovery()): no connection to the server

19681:2019-01-09 14:09:51 CET  INFO:  restoring backup 'edb95_2019-01-09T09:18:18' of server 'edb95'
19681:2019-01-09 14:10:14 CET  INFO:  base backup restored
19681:2019-01-09 14:10:14 CET  INFO:  creating recovery.conf file
19681:2019-01-09 14:10:14 CET  INFO:  WAL file(s) will be streamed from the BART host
19681:2019-01-09 14:10:15 CET  INFO:  archiving is disabled
19681:2019-01-09 14:10:15 CET  INFO:  permissions set on $PGDATA
19681:2019-01-09 14:10:15 CET  INFO:  restore completed successfully
28052:2019-01-09 14:31:31 CET  INFO:  restoring backup 'edb95_2019-01-09T09:18:18' of server 'edb95'
28052:2019-01-09 14:31:55 CET  INFO:  base backup restored
28052:2019-01-09 14:31:55 CET  INFO:  creating recovery.conf file
28052:2019-01-09 14:31:55 CET  INFO:  WAL file(s) will be streamed from the BART host
28052:2019-01-09 14:31:56 CET  INFO:  archiving is disabled
28052:2019-01-09 14:31:56 CET  INFO:  permissions set on $PGDATA
28052:2019-01-09 14:31:56 CET  INFO:  restore completed successfully
28250:2019-01-09 14:33:09 CET  INFO:  restoring backup 'edb95_2018-12-21T07:53:52' of server 'edb95'
28250:2019-01-09 14:33:24 CET  INFO:  base backup restored
28250:2019-01-09 14:33:24 CET  INFO:  creating recovery.conf file
28250:2019-01-09 14:33:24 CET  INFO:  WAL file(s) will be streamed from the BART host
28250:2019-01-09 14:33:24 CET  INFO:  archiving is disabled
28250:2019-01-09 14:33:25 CET  INFO:  permissions set on $PGDATA
28250:2019-01-09 14:33:25 CET  INFO:  restore completed successfully
29547:2019-01-09 14:38:49 CET  INFO:  restoring backup 'edb95_2018-12-21T07:53:52' of server 'edb95'
29547:2019-01-09 14:39:04 CET  INFO:  base backup restored
29547:2019-01-09 14:39:04 CET  INFO:  creating recovery.conf file
29547:2019-01-09 14:39:04 CET  INFO:  WAL file(s) will be streamed from the BART host
29547:2019-01-09 14:39:05 CET  INFO:  archiving is disabled
29547:2019-01-09 14:39:05 CET  INFO:  permissions set on $PGDATA
29547:2019-01-09 14:39:05 CET  INFO:  restore completed successfully
1515:2019-01-10 07:57:45 CET  INFO:  new backup identifier generated 1547103465787
1515:2019-01-10 07:57:46 CET  INFO:  creating 5 harvester threads
1515:2019-01-10 07:58:06 CET  INFO:  backup completed successfully
1515:2019-01-10 07:58:06 CET  INFO:  
BART VERSION: 2.2.0
BACKUP DETAILS:
BACKUP STATUS: active
BACKUP IDENTIFIER: 1547103465787
BACKUP NAME: full_edb95
BACKUP PARENT: none
BACKUP LOCATION: /dstpol/backup/bart/edb95/1547103465787
BACKUP SIZE: 4.32 GB
BACKUP FORMAT: plain
BACKUP TIMEZONE: Europe/Brussels
XLOG METHOD: fetch
BACKUP CHECKSUM(s): 0
TABLESPACE(s): 0
START WAL LOCATION: 00000001000000000000002F
STOP WAL LOCATION: 000000010000000000000030
BACKUP METHOD: pg_start_backup
BACKUP FROM: master
START TIME: 2019-01-10 07:57:45 CET
STOP TIME: 2019-01-10 07:58:04 CET
TOTAL DURATION: 19 sec(s)

4453:2019-01-10 08:03:47 CET  INFO:  checking mbm files /dstpol/backup/bart/edb95/archived_wals
4453:2019-01-10 08:03:48 CET  ERROR: backup failed for server 'edb95'
bart-scanner is not running, please check
10042:2019-01-10 08:20:43 CET  INFO:  checking mbm files /dstpol/backup/bart/edb95/archived_wals
10042:2019-01-10 08:20:45 CET  ERROR: backup failed for server 'edb95'
bart-scanner is not running, please check
4870:2019-01-11 08:02:03 CET  INFO:  checking mbm files /dstpol/backup/bart/edb95/archived_wals
4870:2019-01-11 08:02:14 CET  WARNING: WAL file '/dstpol/backup/bart/edb95/archived_wals/000000010000000000000037' must be scanned
4870:2019-01-11 08:02:14 CET  WARNING: WAL file '/dstpol/backup/bart/edb95/archived_wals/000000010000000000000038' must be scanned
4870:2019-01-11 08:02:14 CET  WARNING: WAL file '/dstpol/backup/bart/edb95/archived_wals/000000010000000000000039' must be scanned
4870:2019-01-11 08:02:15 CET  ERROR: backup failed for server 'edb95'
waiting for WAL files to be archived; currently waiting for '000000010000000000000039'
5902:2019-01-11 08:07:55 CET  INFO:  checking mbm files /dstpol/backup/bart/edb95/archived_wals
5902:2019-01-11 08:08:05 CET  WARNING: WAL file '/dstpol/backup/bart/edb95/archived_wals/00000001000000000000003B' must be scanned
5902:2019-01-11 08:08:05 CET  WARNING: WAL file '/dstpol/backup/bart/edb95/archived_wals/00000001000000000000003C' must be scanned
5902:2019-01-11 08:08:07 CET  ERROR: backup failed for server 'edb95'
waiting for WAL files to be archived; currently waiting for '00000001000000000000003C'

[slonkar · Accepted solution]

Hi @Polem,

From the error it looks like, the WAL files which needs to be processed by the bart-scanner are not processed or bart-scanner is not running to do it.

Please refer below steps and try taking backup again :

1) Take a fresh full backup.

2) Keep the bart-scanner running in the background (daemon).

3) Initiate the incremental backup with above full backup as parent.

If this mbm files issue triggers error again, could you please change the archive_command which I can see is using rsync.

Use the scp instead of the rsync and try the backup again with above mentioned steps.

Please let us know if you face issue after doing the above suggestions. 

Regards,

Sudhir

[Polem]

Hi,

rsync in archive_command was the problem. Since I replace it by scp it's working fine.

Many thanks 

Kind regards,

Paul-Emmanuel

[Din2pg]

Hi

                What is the reason to change in rsync command,any problem in this command in archive_command.

               .Please tell me why, what problem is in this case...thanks

Regards

Din

[slonkar · Accepted solution]

Hi @Din2pg,

By default, if we tell rsync to copy a file named something like '00000000010000000000003F', rsync will create the file as '00000000010000000000003F.some-random-suffix' and, once the file transfer completes, rsync renames the complete file back to '00000000010000000000003F'.

We need to execute the bart-scanner first for the incremental backup, so it scans the archives and creates .mbm files.

The problem is that bart-scanner watches for *new* files and when it receives a notification that a new file has arrived, it examines the file name. If the file name doesn't look like a WAL file (a 24-character name made up of hex digits), bart-scanner ignores the new file.

Thats not the problem of rsync, by default it works like that, but our bart-scanner once it see the WAL file with some extension name it can't identify it and throws errors and will not continue further.

Hope this helps you.

Regards,

Sudhir

[Din2pg]

Hi @slonkar 

             Fantastic message from you @slonkar ,and am satisfied your post,very very interesting..thank for the information..Thanks a lot.

Regards

Diny