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
