Problem after replication switchover

Hi, I hope I'm mailing this to the correct mailing list.
We get errors inserting into a table:
2016-04-04 07:27:51 CEST [43342-2] <someuser>@<db1> ERROR: could not read block 28991 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:27:51 CEST [43342-3] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:28:27 CEST [43342-4] <someuser>@<db1> ERROR: could not read block 28992 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:28:27 CEST [43342-5] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:28:50 CEST [43342-6] <someuser>@<db1> ERROR: could not read block 28993 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:28:50 CEST [43342-7] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:29:06 CEST [44085-1] <someuser>@<db1> ERROR: could not read block 28994 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:29:06 CEST [44085-2] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:29:07 CEST [44085-3] <someuser>@<db1> ERROR: could not read block 28995 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:29:07 CEST [44085-4] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:29:33 CEST [44085-5] <someuser>@<db1> ERROR: could not read block 28996 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:29:33 CEST [44085-6] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:29:47 CEST [44085-7] <someuser>@<db1> ERROR: could not read block 28997 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:29:47 CEST [44085-8] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:30:04 CEST [43267-2] <someuser>@<db1> ERROR: could not read block 28998 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:30:04 CEST [43267-3] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:30:12 CEST [43267-4] <someuser>@<db1> ERROR: could not read block 28999 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:30:12 CEST [43267-5] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:31:08 CEST [44063-1] <someuser>@<db1> ERROR: could not read block 29000 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:31:08 CEST [44063-2] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"
2016-04-04 07:31:11 CEST [44063-3] <someuser>@<db1> ERROR: could not read block 29001 in file "base/16390/572026": read only 0 of 8192 bytes
2016-04-04 07:31:11 CEST [44063-4] <someuser>@<db1> STATEMENT: INSERT INTO <table_12> (...) VALUES (...) RETURNING "id"

We use steaming (asynchronous) replication and do a controlled automated switchover (the master is demoted to slave and the previous slave promoted to master) each week. Most times this works like a charm but a few times after the switchover inserts into one table fail (se log extract above). Aside from that error the application runs as normal and replication is working. The last two times this has happened I have trigged a switch back to the original master and everything runs fine.

The switchover is done in the following steps assuming cluster1 is current master and cluster2 is the slave we want to promote:
1. Make sure cluster1 is not in recovery mode.
2. Make sure cluster2 is in recovery mode.
3. Pause all new database activity in the web application and wait a few seconds to give current work a chance to finish.
4. Create a recovery.conf file on cluster1 "pointing" to cluster2 (current slave).
5. Run "pg_ctlcluster -m fast ${CLUSTER_VERSION} ${CLUSTER_NAME} restart" on cluster1 and wait for it to restart.
6. Make sure cluster1 is in recovery mode (the clusters are now replicating from each other).
7. Wait for SELECT pg_xlog_location_diff(pg_last_xlog_replay_location(), replay_location) from pg_stat_replication where application_name='s2s-replication' to return "0" on both servers. This should make sure cluster2 is up to date and synchronized with cluster1.
8. Run "pg_ctlcluster ${CLUSTER_VERSION} ${CLUSTER_NAME} promote" on cluster2.
9. Wait for "SELECT pg_is_in_recovery()" to return "f" on cluster2.
10. Tell the application to detect what cluster is master and resume database activity.

Log from cluster1:
2016-04-04 06:32:09 CEST [48286-3] LOG:  received fast shutdown request
2016-04-04 06:32:09 CEST [48286-4] LOG:  aborting any active transactions
2016-04-04 06:32:09 CEST [15011-1] <someuser>@<db1> FATAL:  terminating connection due to administrator command
--- lots more terminating connections ---
2016-04-04 06:32:10 CEST [48301-51] LOG:  shutting down
2016-04-04 06:32:10 CEST [48301-52] LOG:  database system is shut down
2016-04-04 06:32:17 CEST [15203-1] [unknown]@[unknown] LOG:  incomplete startup packet
2016-04-04 06:32:17 CEST [15201-1] LOG:  database system was shut down at 2016-04-04 06:32:10 CEST
2016-04-04 06:32:17 CEST [15202-1] <someuser>@[unknown] FATAL:  the database system is starting up
2016-04-04 06:32:17 CEST [15206-1] <someuser>@[unknown] FATAL:  the database system is starting up
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo2-dbshard2-ufoprod/0000001E.history': No such file or directory
2016-04-04 06:32:17 CEST [15201-2] LOG:  entering standby mode
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo2-dbshard2-ufoprod/0000001D.history': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo2-dbshard2-ufoprod/0000001D00000B860000009C': No such file or directory
2016-04-04 06:32:17 CEST [15213-1] <someuser>@<db0> FATAL:  the database system is starting up
2016-04-04 06:32:17 CEST [15201-3] LOG:  consistent recovery state reached at B86/9C000090
2016-04-04 06:32:17 CEST [15201-4] LOG:  record with zero length at B86/9C000090
2016-04-04 06:32:17 CEST [15200-1] LOG:  database system is ready to accept read only connections
2016-04-04 06:32:17 CEST [15217-1] LOG:  started streaming WAL from primary at B86/9C000000 on timeline 29
2016-04-04 06:32:28 CEST [15217-2] LOG:  replication terminated by primary server
2016-04-04 06:32:28 CEST [15217-3] DETAIL:  End of WAL reached on timeline 29 at B86/9C000090.
2016-04-04 06:32:28 CEST [15217-4] LOG:  fetching timeline history file for timeline 30 from primary server
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo2-dbshard2-ufoprod/0000001E.history': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo2-dbshard2-ufoprod/0000001F.history': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo2-dbshard2-ufoprod/0000001E.history': No such file or directory
2016-04-04 06:32:28 CEST [15201-5] LOG:  new target timeline is 30
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo2-dbshard2-ufoprod/0000001E00000B860000009C': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo2-dbshard2-ufoprod/0000001D00000B860000009C': No such file or directory
2016-04-04 06:32:28 CEST [15217-5] LOG:  restarted WAL streaming at B86/9C000000 on timeline 30
2016-04-04 06:32:28 CEST [15201-6] LOG:  redo starts at B86/9C000090

Log from cluster2:
2016-04-04 06:32:12 CEST [1801-2] LOG: replication terminated by primary server
2016-04-04 06:32:12 CEST [1801-3] DETAIL: End of WAL reached on timeline 29 at B86/9C000090.
2016-04-04 06:32:12 CEST [1801-4] FATAL: could not send end-of-streaming message to primary: no COPY in progress

cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001E.history': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001D00000B860000009C': No such file or directory
2016-04-04 06:32:12 CEST [1472-6] LOG: invalid record length at B86/9C000090
2016-04-04 06:32:16 CEST [27378-1] FATAL: could not connect to the primary server: server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.

cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001E.history': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001D00000B860000009C': No such file or directory
2016-04-04 06:32:17 CEST [27383-1] FATAL: could not connect to the primary server: FATAL: the database system is starting up
FATAL: the database system is starting up

cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001E.history': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001D00000B860000009C': No such file or directory
2016-04-04 06:32:23 CEST [27389-1] LOG: started streaming WAL from primary at B86/9C000000 on timeline 29
2016-04-04 06:32:23 CEST [1472-7] LOG: received promote request
2016-04-04 06:32:23 CEST [27389-2] FATAL: terminating walreceiver process due to administrator command
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001E.history': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001D00000B860000009C': No such file or directory
2016-04-04 06:32:27 CEST [1472-8] LOG: redo done at B86/9C000028
2016-04-04 06:32:27 CEST [1472-9] LOG: last completed transaction was at log time 2016-04-04 06:32:03.399836+02
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001D00000B860000009C': No such file or directory
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001E.history': No such file or directory
2016-04-04 06:32:27 CEST [1472-10] LOG: selected new timeline ID: 30
cp: cannot stat '/net/glusterfs/pgwal/postgresql/wal/ufcolo1-dbshard2-ufoprod/0000001D.history': No such file or directory
2016-04-04 06:32:28 CEST [1472-11] LOG: archive recovery complete
2016-04-04 06:32:28 CEST [1472-12] LOG: MultiXact member wraparound protections are now enabled
2016-04-04 06:32:28 CEST [27513-1] LOG: autovacuum launcher started
2016-04-04 06:32:28 CEST [1465-2] LOG: database system is ready to accept connections

We have had tree similar incidents:
2016-01-26 Postgresql version: 9.4.1 on Ubuntu 14.04
2016-03-07 Postgresql version: 9.4.5
2016-04-04 Postgresql version: 9.4.5/9.4.6 (The newly promoted cluster where the error occurred was running 9.4.6, the demoted cluster was running 9.4.5)
I'm not entirely sure the incident 2016-01-26 was the same problem as I was on vacation and there are not much logs saved. I only have one log row and that looks similar to the other once and it was triggered by an insert "ERROR: could not read block 2023 in file "base/16390/22841": read only 0 of 8192 bytes". The offending file was an index. This problem was fixed with a VACCUM FULL on the table the index belonged to.
The incident 2016-03-07 was very similar to the latest incident 2016-04-04. The offending file was a pg_toast table.
From what I can see in the logs the two clusters should be completely synchronized? Yet the base/16390/572026 file is not the same on both servers as it fails to read (the last?) blocks from it.
Next time this happens I will try to check the size of the offending file.

Is there something I missed in the switchover or could this be a bug?

Regards
Lars Arvidson

--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general