From: Evgeniy Shishkin <itparanoia@gmail.com>
Content-Type: text/plain; charset=windows-1252
Content-Transfer-Encoding: quoted-printable
Subject: slave wal is ahead of master
Message-Id: <561E3FF0-C1B4-448A-AB33-176540E72D16@gmail.com>
Date: Wed, 19 Mar 2014 20:10:22 +0300
To: "pgsql-performance@postgresql.org list" <pgsql-performance@postgresql.org>
Mime-Version: 1.0 (Mac OS X Mail 7.2 \(1874\))
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Hello,=20

we have 3 servers with postgresql 9.3.3. One is master and two slaves.
We run synchronous_replication and fsync, synchronous_commit and full_page_=
writes are on.

Suddenly master hang up with hardware failure, it is a strange bug in iLo w=
hich we investigate with HP.

Before master was rebooted, i ran ps aux on slave
postgres: wal receiver process   streaming 12/F1031DF8

Last messages in slaves logs was
2014-03-19 02:41:29.005 GMT,,,7389,,53108c69.1cdd,16029,,2014-02-28 13:17:2=
9 GMT,,0,LOG,00000,"recovery restart point at 12/DFFBB3E8","last completed =
transaction was at log time 2014-03-19 02:41:28.886869+00",,,,,,,,""

and then there was silence, because master hang.

Then master was rebooted and slave wrote in log
2014-03-19 15:36:39.176 GMT,,,7392,,53108c69.1ce0,2,,2014-02-28 13:17:29 GM=
T,,0,FATAL,XX000,"terminating walreceiver due to timeout",,,,,,,,,""
2014-03-19 15:36:39.177 GMT,,,7388,,53108c69.1cdc,6,,2014-02-28 13:17:29 GM=
T,1/0,0,LOG,00000,"record with zero length at 12/F1031DF8",,,,,,,,,""
2014-03-19 15:36:57.181 GMT,,,12100,,5329b996.2f44,1,,2014-03-19 15:36:54 G=
MT,,0,FATAL,XX000,"could not connect to the primary server: could not conne=
ct to server: No route to host
        Is the server running on host ""10.162.2.50"" and accepting
        TCP/IP connections on port 5432?
",,,,,,,,,""

Then master finally came back, slave wrote
2014-03-19 15:40:09.389 GMT,,,13121,,5329ba59.3341,1,,2014-03-19 15:40:09 G=
MT,,0,FATAL,XX000,"could not connect to the primary server: FATAL:  the dat=
abase system is starting up
",,,,,,,,,""
2014-03-19 15:40:16.468 GMT,,,13136,,5329ba5e.3350,1,,2014-03-19 15:40:14 G=
MT,,0,LOG,00000,"started streaming WAL from primary at 12/F1000000 on timel=
ine 1",,,,,,,,,""
2014-03-19 15:40:16.468 GMT,,,13136,,5329ba5e.3350,2,,2014-03-19 15:40:14 G=
MT,,0,FATAL,XX000,"could not receive data from WAL stream: ERROR:  requeste=
d starting point 12/F1000000 is ahead of the WAL flush position of this ser=
ver 12/F0FFFCE8
",,,,,,,,,""

last message was repeated several times
and then this happened

2014-03-19 15:42:04.623 GMT,,,13722,,5329bacc.359a,1,,2014-03-19 15:42:04 G=
MT,,0,LOG,00000,"started streaming WAL from primary at 12/F1000000 on timel=
ine 1",,,,,,,,,""
2014-03-19 15:42:04.628 GMT,,,7388,,53108c69.1cdc,7,,2014-02-28 13:17:29 GM=
T,1/0,0,LOG,00000,"invalid record length at 12/F1031DF8",,,,,,,,,""
2014-03-19 15:42:04.628 GMT,,,13722,,5329bacc.359a,2,,2014-03-19 15:42:04 G=
MT,,0,FATAL,57P01,"terminating walreceiver process due to administrator com=
mand",,,,,,,,,""
2014-03-19 15:42:09.628 GMT,,,7388,,53108c69.1cdc,8,,2014-02-28 13:17:29 GM=
T,1/0,0,LOG,00000,"invalid record length at 12/F1031DF8",,,,,,,,,""
2014-03-19 15:42:14.628 GMT,,,7388,,53108c69.1cdc,9,,2014-02-28 13:17:29 GM=
T,1/0,0,LOG,00000,"invalid record length at 12/F1031DF8",,,,,,,,,""
2014-03-19 15:42:19.628 GMT,,,7388,,53108c69.1cdc,10,,2014-02-28 13:17:29 G=
MT,1/0,0,LOG,00000,"invalid record length at 12/F1031DF8",,,,,,,,,=94"=20
and it just repeats forever.


Meanwhile on master
2014-03-19 15:39:30.957 GMT,,,7115,,5329ba32.1bcb,2,,2014-03-19 15:39:30 GM=
T,,0,LOG,00000,"database system was not properly shut down; automatic recov=
ery in progress",,,,,,,,,""
2014-03-19 15:39:30.989 GMT,,,7115,,5329ba32.1bcb,3,,2014-03-19 15:39:30 GM=
T,,0,LOG,00000,"redo starts at 12/DFFBB3E8",,,,,,,,,""
2014-03-19 15:39:47.114 GMT,,,7115,,5329ba32.1bcb,4,,2014-03-19 15:39:30 GM=
T,,0,LOG,00000,"redo done at 12/F0FFFC38",,,,,,,,,""
2014-03-19 15:39:47.114 GMT,,,7115,,5329ba32.1bcb,5,,2014-03-19 15:39:30 GM=
T,,0,LOG,00000,"last completed transaction was at log time 2014-03-19 05:02=
:29.273138+00",,,,,,,,,""
2014-03-19 15:39:47.115 GMT,,,7115,,5329ba32.1bcb,6,,2014-03-19 15:39:30 GM=
T,,0,LOG,00000,"checkpoint starting: end-of-recovery immediate",,,,,,,,,""
2014-03-19 15:40:16.466 GMT,"replicator","",7986,"10.162.2.52:44336",5329ba=
5e.1f32,1,"idle",2014-03-19 15:40:14 GMT,2/0,0,ERROR,XX000,"requested start=
ing point 12/F1000000 is ahead of the WAL flush position of this server 12/=
F0FFFCE8",,,,,,,,,"walreceiver"

So, all two slaves are disconnected from master, which somehow is past his =
slaves.

I decided to promote one of the slaves, so we can have some snapshot of the=
 data.
relevant logs from this are=20
2014-03-19 16:50:43.118 GMT,,,4444,,5329cae3.115c,3,,2014-03-19 16:50:43 GM=
T,,0,LOG,00000,"redo starts at 12/DFFBB3E8",,,,,,,,,""
2014-03-19 16:50:50.028 GMT,"dboperator","postgres",4452,"[local]",5329caea=
.1164,1,"",2014-03-19 16:50:50 GMT,,0,FATAL,57P03,"the database system is s=
tarting up",,,,,,,,,""
2014-03-19 16:50:51.128 GMT,,,4444,,5329cae3.115c,4,,2014-03-19 16:50:43 GM=
T,,0,LOG,00000,"invalid contrecord length 5736 at 12/F0FFFC80",,,,,,,,,""
2014-03-19 16:50:51.128 GMT,,,4444,,5329cae3.115c,5,,2014-03-19 16:50:43 GM=
T,,0,LOG,00000,"redo done at 12/F0FFFC38",,,,,,,,,=94=94

It is interesting that redo done at 12/F0FFFC38 both on master and promoted=
 slave.

The main question is there is actual latest data, and how is it possible th=
at master is behind his slave in synchronous replication.

Thanks for the help.

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