Postgresql 9.3.5 fails to start from recovered database

1,533 views

Skip to first unread message

patman

unread,

Aug 13, 2014, 5:36:34 AM8/13/14

to pgba...@googlegroups.com

Hi all,

I am a barman noob so please bare with me :)

After failing a few times with recovery I wanted to start 'clean' and record my steps for this post.
I have 2 VMs (CentOS 6.5, 64bit) both running postgresql 9.3.5

Hopefully I have provided all the required info for you to give me some hints.

main = my db server that is used by barman to backup from and recover back to.

According to barman check main , barman status main my setup looks correct.

Here goes:

...(deleted all previous backups with '# barman delete main oldest')
# barman list-backup all (no backup files remaining)
# barman check main
Server main:
    ssh: OK
    PostgreSQL: OK
    archive_mode: OK
    archive_command: OK
    directories: OK
    retention policy settings: OK
    compression settings: OK
    minimum redundancy requirements: OK (have 0 backups, expected at least 0)

# barman status main
Server main:
    Description: Main PostgreSQL Database
    PostgreSQL version: 9.3.5
    pgespresso extension: Not available
    PostgreSQL Data directory: /var/lib/pgsql/9.3/data
    PostgreSQL 'archive_command' setting: rsync -a %p bar...@opentunnel-db-standby.lan:/var/lib/barman/opentunnel-db-standby.lan/incoming/%f
    Archive status: last shipped WAL segment 000000010000000000000026
    Current WAL segment: 000000050000000000000027
    Retention policies: not enforced
    No. of available backups: 0
    First available backup: None
    Last available backup: None
    Minimum redundancy requirements: satisfied (0/0)

# barman diagnose
{
    "global": {
        "config": {
            "barman_home": "/var/lib/barman",
            "barman_user": "barman",
            "configuration_files_directory": "/etc/barman.d/",
            "log_file": "/var/log/barman/barman.log"
        },
        "system_info": {
            "kernel_ver": "Linux opentunnel-db-standby.lan 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux",
            "python_ver": "Python 2.6.6",
            "release": "RedHat Linux CentOS release 6.5 (Final)",
            "rsync_ver": "rsync version 3.0.6 protocol version 30",
            "ssh_ver": "OpenSSH_5.3p1, OpenSSL 1.0.1e-fips 11 Feb 2013"
        }
    },
    "servers": {
        "main": {
            "backups": {},
            "config": {
                "active": true,
                "backup_directory": "/var/lib/barman/main",
                "backup_options": "exclusive_backup",
                "bandwidth_limit": null,
                "barman_home": "/var/lib/barman",
                "basebackups_directory": "/var/lib/barman/main/base",
                "compression": null,
                "conninfo": "host=opentunnel-db.lan user=postgres",
                "custom_compression_filter": null,
                "custom_decompression_filter": null,
                "description": "Main PostgreSQL Database",
                "immediate_checkpoint": false,
                "incoming_wals_directory": "/var/lib/barman/main/incoming",
                "lock_file": "/var/lib/barman/main/main.lock",
                "minimum_redundancy": 0,
                "name": "main",
                "network_compression": false,
                "post_backup_script": null,
                "pre_backup_script": null,
                "retention_policy": null,
                "retention_policy_mode": "auto",
                "ssh_command": "ssh post...@opentunnel-db.lan",
                "tablespace_bandwidth_limit": null,
                "wal_retention_policy": "main",
                "wals_directory": "/var/lib/barman/main/wals"
            },
            "status": {
                "archive_command": "rsync -a %p bar...@opentunnel-db-standby.lan:/var/lib/barman/opentunnel-db-standby.lan/incoming/%f",
                "archive_mode": "on",
                "config_file": "/var/lib/pgsql/9.3/data/postgresql.conf",
                "current_xlog": "000000050000000000000027",
                "data_directory": "/var/lib/pgsql/9.3/data",
                "hba_file": "/var/lib/pgsql/9.3/data/pg_hba.conf",
                "ident_file": "/var/lib/pgsql/9.3/data/pg_ident.conf",
                "last_shipped_wal": "000000010000000000000026",
                "pgespresso_installed": false,
                "server_txt_version": "9.3.5"
            },
            "system_info": {
                "kernel_ver": "Linux opentunnel-db.lan 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux",
                "python_ver": "Python 2.6.6",
                "release": "RedHat Linux CentOS release 6.5 (Final)",
                "rsync_ver": "rsync version 3.0.6 protocol version 30",
                "ssh_ver": "OpenSSH_5.3p1, OpenSSL 1.0.1e-fips 11 Feb 2013"
            }
        }
    }
}

::: Starting new backup

# barman backup main
Starting backup for server main in /var/lib/barman/main/base/20140812T083134
Backup start at xlog location: 0/28000028 (000000050000000000000028, 00000028)
Copying files.
Copy done.
Asking PostgreSQL server to finalize the backup.
Backup end at xlog location: 0/280000B8 (000000050000000000000028, 000000B8)
Backup completed
#
(on main server)
    [root@opentunnel-db pg_xlog]# ls -ltr
    total 196632
    -rw-------. 1 postgres postgres 16777216 Aug 12 02:38 000000040000000000000029
    -rw-------. 1 postgres postgres 16777216 Aug 12 03:22 00000005000000000000002A
    -rw-------. 1 postgres postgres 16777216 Aug 12 03:22 000000010000000000000027
    -rw-------. 1 postgres postgres 16777216 Aug 12 03:22 000000010000000000000028
    -rw-------. 1 postgres postgres 16777216 Aug 12 03:38 000000010000000000000029
    -rw-------. 1 postgres postgres 16777216 Aug 12 03:38 00000001000000000000002A
    -rw-------. 1 postgres postgres 16777216 Aug 12 03:46 000000030000000000000027
    -rw------- 1 postgres postgres       42 Aug 12 03:46 00000002.history
    -rw------- 1 postgres postgres 16777216 Aug 12 03:47 000000040000000000000028
    -rw------- 1 postgres postgres       85 Aug 12 03:47 00000003.history
    -rw------- 1 postgres postgres 16777216 Aug 12 04:04 000000050000000000000029
    -rw------- 1 postgres postgres      128 Aug 12 04:04 00000004.history
    -rw------- 1 postgres postgres 16777216 Aug 12 04:04 000000040000000000000027
    -rw------- 1 postgres postgres      171 Aug 12 04:04 00000005.history
    -rw------- 1 postgres postgres 16777216 Aug 12 08:31 000000050000000000000027
    -rw------- 1 postgres postgres 16777216 Aug 12 08:31 000000050000000000000028
    -rw------- 1 postgres postgres      323 Aug 12 08:31 000000050000000000000028.00000028.backup
    drwx------. 2 postgres postgres     4096 Aug 12 08:31 archive_status
    [root@opentunnel-db pg_xlog]#

# barman list-backup main
main 20140812T083134 - Tue Aug 12 08:31:36 2014 - Size: 25.8 MiB - WAL Size: 0 B

So it looks like backup was succesful.

-------------------------------------------
Now the other important task, RECOVERY :)
-------------------------------------------

# barman recover --remote-ssh-command "ssh post...@opentunnel-db.lan" main 20140812T083134 /opt/restored-backup/
Starting remote restore for server main using backup 20140812T083134
Destination directory: /opt/restored-backup/
Copying the base backup.
Copying required wal segments.
The archive_command was set to 'false' to prevent data losses.

Your PostgreSQL server has been successfully prepared for recovery!

Please review network and archive related settings in the PostgreSQL
configuration file before starting the just recovered instance.


(content) #/opt/restored-backup/postgresql.conf
    archive_mode = on
    wal_level = 'archive' # For PostgreSQL >= 9.0
    #BARMAN# archive_command = 'rsync -a %p bar...@opentunnel-db-standby.lan:/var/lib/barman/opentunnel-db-standby.lan/incoming/%f'
    archive_command = false

OK, restore appears to be done alright as well.

Now change PGDATA on main server and restart postgresql...

    #PGDATA=/var/lib/pgsql/9.3/data
    PGDATA=/opt/restored-backup

[root@opentunnel-db data]# /etc/init.d/postgresql-9.3 start
Starting postgresql-9.3 service:                           [FAILED]

cat /opt/restored-backup/pg_log/postgresql-Wed.log

< 2014-08-13 11:21:33.655 CEST >LOG: database system was interrupted; last known up at 2014-08-12 08:31:34 CEST
< 2014-08-13 11:21:33.655 CEST >LOG: invalid checkpoint record
< 2014-08-13 11:21:33.655 CEST >FATAL: could not locate required checkpoint record
< 2014-08-13 11:21:33.655 CEST >HINT: If you are not restoring from a backup, try removing the file "/opt/restored-backup/backup_label".
< 2014-08-13 11:21:33.656 CEST >LOG: startup process (PID 9669) exited with exit code 1
< 2014-08-13 11:21:33.656 CEST >LOG: aborting startup due to startup process failure
< 2014-08-13 11:23:03.205 CEST >LOG: database system was interrupted; last known up at 2014-08-12 08:31:34 CEST
< 2014-08-13 11:23:03.205 CEST >LOG: invalid checkpoint record
< 2014-08-13 11:23:03.205 CEST >FATAL: could not locate required checkpoint record
< 2014-08-13 11:23:03.205 CEST >HINT: If you are not restoring from a backup, try removing the file "/opt/restored-backup/backup_label".
< 2014-08-13 11:23:03.205 CEST >LOG: startup process (PID 9797) exited with exit code 1
< 2014-08-13 11:23:03.205 CEST >LOG: aborting startup due to startup process failure
[root@opentunnel-db pg_log]#


I must be doing something wrong, but I cannot figure out what it is.
Do you have any hints?

Thank you.

MP

unread,

Aug 14, 2014, 6:26:38 AM8/14/14

to pgba...@googlegroups.com

copy PGDATA/barman_xlog to PGDATA/pg_xlog and start postgres.

Maybe ver 1.3.3 will copy xlog to pg_xlog instead barman_xlog?

Patrick Balm

unread,

Aug 14, 2014, 7:25:34 AM8/14/14

to pgba...@googlegroups.com

Thank you, I will give that a try and report back to the list.

On Aug 14, 2014 w3, at 12:26 , MP wrote:

copy PGDATA/barman_xlog to PGDATA/pg_xlog and start postgres.

Maybe ver 1.3.3 will copy xlog to pg_xlog instead barman_xlog?

--
--
You received this message because you are subscribed to the "Barman for PostgreSQL" group.
To post to this group, send email to pgba...@googlegroups.com
To unsubscribe from this group, send email to
pgbarman+u...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/pgbarman?hl=en?hl=en-GB

---
You received this message because you are subscribed to a topic in the Google Groups "Barman, Backup and Recovery Manager for PostgreSQL" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/pgbarman/YlxuheGZ7tg/unsubscribe.
To unsubscribe from this group and all its topics, send an email to pgbarman+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Gabriele Bartolini

unread,

Aug 14, 2014, 8:48:33 AM8/14/14

to pgba...@googlegroups.com

From the commands that Patrick provided, he did not activate Point In
Time Recovery. He should not have barman_xlog in the destination
directory (in that case, he'd just need the recovery.conf file - see
bug #45).

Could you please verify that 1.3.3-alpha.1 fixes it?

Thanks,
Gabriele
--
Gabriele Bartolini - 2ndQuadrant Italia
PostgreSQL Training, Services and Support
gabriele....@2ndQuadrant.it | www.2ndQuadrant.it

> You received this message because you are subscribed to the Google Groups

> "Barman, Backup and Recovery Manager for PostgreSQL" group.

> To unsubscribe from this group and stop receiving emails from it, send an

patman

unread,

Aug 15, 2014, 4:57:15 AM8/15/14

to pgba...@googlegroups.com

(grrr my previous post went bad so I am retyping it)

Btw 1.3.3-alpha.1 is downloaded as tarbal 1.3.2.tar.gz

After installing from source:

# barman -v

1.3.2

So I redid the backup

[root@opentunnel-db-standby barman-1.3.2]# barman backup main
Starting backup for server main in /var/lib/barman/main/base/20140815T095443
Backup start at xlog location: 0/2B000028 (00000005000000000000002B, 00000028)

Copying files.
Copy done.
Asking PostgreSQL server to finalize the backup.

Backup end at xlog location: 0/2B0000B8 (00000005000000000000002B, 000000B8)
Backup completed
[root@opentunnel-db-standby barman-1.3.2]# barman list-backup main
main 20140815T095443 - Fri Aug 15 09:54:46 2014 - Size: 25.8 MiB - WAL Size: 0 B

[root@opentunnel-db-standby tmp]# barman recover --remote-ssh-command "ssh post...@opentunnel-db.lan" main 20140815T095443 /opt/restored-backup/
Starting remote restore for server main using backup 20140815T095443

Destination directory: /opt/restored-backup/
Copying the base backup.
Copying required wal segments.
The archive_command was set to 'false' to prevent data losses.

Your PostgreSQL server has been successfully prepared for recovery!

Please review network and archive related settings in the PostgreSQL
configuration file before starting the just recovered instance.

On main server

I added recovery.conf to my original PGDATA

#postgresql.conf
...

archive_mode = on
wal_level = 'archive' # For PostgreSQL >= 9.0

#archive_command = 'rsync -a %p bar...@opentunnel-db-standby.lan:/var/lib/barman/opentunnel-db-standby.lan/incoming/%f'
archive_command = false

# recovery.conf
restore_command ='rsync -a /opt/restored-backup/%f "%p"'

then I restarted postgresql again to kick off the recovery process.

Postgresql started nicely and the recovery started...

[root@opentunnel-db data]# cat pg_log/postgresql-Fri.log

...

< 2014-08-15 10:05:26.731 CEST >LOG: starting archive recovery

rsync: link_stat "/opt/restored-backup/00000005.history" failed: No such file or directory (2)