Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WQMgF-00084S-DG for pgsql-performance@arkaria.postgresql.org; Wed, 19 Mar 2014 20:01:39 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.80) (envelope-from ) id 1WQMgE-0001ug-Uo for pgsql-performance@arkaria.postgresql.org; Wed, 19 Mar 2014 20:01:38 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WQMgE-0001uY-1U for pgsql-performance@postgresql.org; Wed, 19 Mar 2014 20:01:38 +0000 Received: from mail-ee0-x22f.google.com ([2a00:1450:4013:c00::22f]) by magus.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1WQMgA-0002fO-67 for pgsql-performance@postgresql.org; Wed, 19 Mar 2014 20:01:37 +0000 Received: by mail-ee0-f47.google.com with SMTP id b15so6983317eek.20 for ; Wed, 19 Mar 2014 13:01:33 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=content-type:mime-version:subject:from:in-reply-to:date:cc :message-id:references:to; bh=5/DrU5Gv3p9iabGUzm0UU9l4OvH3YJoC3XEWn5h1QjA=; b=A1lhLP1+QmFUtcLD7NgYgbu9Vn+hkvezvjgfKKQP5SPW7oRg+aR0NQNUGxl9OWQDFc etuWfcShxJt1dKzDBkTXcsDi1FwN+An0O3HTF2p5Y5ElgvDYWSyn7C4hy7YOeB+8hNXd 6ZX7tGcZQZhShX10FNTkZ7vj/1FFioPaVzIltkKTu7jSUNIrNwqTgl0EVjjnZvP/HPxh e/BEFJMXgnfiK0juy8cl9mSq25xrzj3poi5un/gC1g4B2pg+s/kzvbaryioYHOrjpmHg GnRO8PekhDudI0iarTvVz8OuRwLTEfeSwN+bO/Wizz2i1GabCY1/+MwiSZiB1Fg9G1UL 7fMg== X-Received: by 10.15.81.135 with SMTP id x7mr35177299eey.61.1395259293104; Wed, 19 Mar 2014 13:01:33 -0700 (PDT) Received: from [192.168.1.7] ([93.84.47.168]) by mx.google.com with ESMTPSA id l42sm56838794eew.19.2014.03.19.13.01.31 for (version=TLSv1 cipher=ECDHE-RSA-RC4-SHA bits=128/128); Wed, 19 Mar 2014 13:01:32 -0700 (PDT) Content-Type: multipart/alternative; boundary="Apple-Mail=_CEC72A53-6ED2-464A-8C40-27D02B53DAC8" Mime-Version: 1.0 (Mac OS X Mail 7.2 \(1874\)) Subject: Re: slave wal is ahead of master From: Evgeny Shishkin In-Reply-To: Date: Wed, 19 Mar 2014 23:01:34 +0300 Cc: "pgsql-performance@postgresql.org list" Message-Id: References: <561E3FF0-C1B4-448A-AB33-176540E72D16@gmail.com> To: Sethu Prasad X-Mailer: Apple Mail (2.1874) X-Pg-Spam-Score: -1.2 (-) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-performance Precedence: bulk Sender: pgsql-performance-owner@postgresql.org --Apple-Mail=_CEC72A53-6ED2-464A-8C40-27D02B53DAC8 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=windows-1252 On 19 Mar 2014, at 21:11, Sethu Prasad wrote: > fsync > ... taking more knowledge around this will shed some light to = understand this problem "slave ahead of master" >=20 > "there was silence, because master hang." > ... replication halted here, master holds the latest copy which is = missing at both the slaves >=20 Master hang in very strange way. I could ssh to it, and see dmesg, but = not any other command. Also tcp connection was alive to slaves. So we can=92t say that slaves did not receive data. > "I decided to promote one of the slaves" > ... only 2 slaves are left, and one among them is going to be the = master now, in master/slave nomenclature the data from master is = considered as the valid one from this point onward There was no any failover procedure. Slaves was slaves.=20 >=20 > "master is behind his slave" > ... you mentioned that the original master comes up in the mean time = one of the slave was already a master >=20 No, after we rebooted master slaves did not reconnected to it. Later i stopped replication on one of the slaves to preserve data its = state. So the main question is, under which circumstances slaves can not = reconnect to master with error that master is behind. With fsync on, and synchronous* on. >=20 > On Wed, Mar 19, 2014 at 10:40 PM, Evgeniy Shishkin = wrote: > 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. >=20 > Suddenly master hang up with hardware failure, it is a strange bug in = iLo which we investigate with HP. >=20 > Before master was rebooted, i ran ps aux on slave > postgres: wal receiver process streaming 12/F1031DF8 >=20 > Last messages in slaves logs was > 2014-03-19 02:41:29.005 GMT,,,7389,,53108c69.1cdd,16029,,2014-02-28 = 13:17:29 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",,,,,,,,"" >=20 > and then there was silence, because master hang. >=20 > 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 GMT,,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 GMT,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 GMT,,0,FATAL,XX000,"could not connect to the primary server: = could not connect to server: No route to host > Is the server running on host ""10.162.2.50"" and accepting > TCP/IP connections on port 5432? > ",,,,,,,,,"" >=20 > 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 GMT,,0,FATAL,XX000,"could not connect to the primary server: = FATAL: the database system is starting up > ",,,,,,,,,"" > 2014-03-19 15:40:16.468 GMT,,,13136,,5329ba5e.3350,1,,2014-03-19 = 15:40:14 GMT,,0,LOG,00000,"started streaming WAL from primary at = 12/F1000000 on timeline 1",,,,,,,,,"" > 2014-03-19 15:40:16.468 GMT,,,13136,,5329ba5e.3350,2,,2014-03-19 = 15:40:14 GMT,,0,FATAL,XX000,"could not receive data from WAL stream: = ERROR: requested starting point 12/F1000000 is ahead of the WAL flush = position of this server 12/F0FFFCE8 > ",,,,,,,,,"" >=20 > last message was repeated several times > and then this happened >=20 > 2014-03-19 15:42:04.623 GMT,,,13722,,5329bacc.359a,1,,2014-03-19 = 15:42:04 GMT,,0,LOG,00000,"started streaming WAL from primary at = 12/F1000000 on timeline 1",,,,,,,,,"" > 2014-03-19 15:42:04.628 GMT,,,7388,,53108c69.1cdc,7,,2014-02-28 = 13:17:29 GMT,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 GMT,,0,FATAL,57P01,"terminating walreceiver process due to = administrator command",,,,,,,,,"" > 2014-03-19 15:42:09.628 GMT,,,7388,,53108c69.1cdc,8,,2014-02-28 = 13:17:29 GMT,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 GMT,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 GMT,1/0,0,LOG,00000,"invalid record length at = 12/F1031DF8",,,,,,,,,=94" > and it just repeats forever. >=20 >=20 > Meanwhile on master > 2014-03-19 15:39:30.957 GMT,,,7115,,5329ba32.1bcb,2,,2014-03-19 = 15:39:30 GMT,,0,LOG,00000,"database system was not properly shut down; = automatic recovery in progress",,,,,,,,,"" > 2014-03-19 15:39:30.989 GMT,,,7115,,5329ba32.1bcb,3,,2014-03-19 = 15:39:30 GMT,,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 GMT,,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 GMT,,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 GMT,,0,LOG,00000,"checkpoint starting: end-of-recovery = immediate",,,,,,,,,"" > 2014-03-19 15:40:16.466 = GMT,"replicator","",7986,"10.162.2.52:44336",5329ba5e.1f32,1,"idle",2014-0= 3-19 15:40:14 GMT,2/0,0,ERROR,XX000,"requested starting point = 12/F1000000 is ahead of the WAL flush position of this server = 12/F0FFFCE8",,,,,,,,,"walreceiver" >=20 > So, all two slaves are disconnected from master, which somehow is past = his slaves. >=20 > I decided to promote one of the slaves, so we can have some snapshot = of the data. > relevant logs from this are > 2014-03-19 16:50:43.118 GMT,,,4444,,5329cae3.115c,3,,2014-03-19 = 16:50:43 GMT,,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 starting = up",,,,,,,,,"" > 2014-03-19 16:50:51.128 GMT,,,4444,,5329cae3.115c,4,,2014-03-19 = 16:50:43 GMT,,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 GMT,,0,LOG,00000,"redo done at 12/F0FFFC38",,,,,,,,,=94=94 >=20 > It is interesting that redo done at 12/F0FFFC38 both on master and = promoted slave. >=20 > The main question is there is actual latest data, and how is it = possible that master is behind his slave in synchronous replication. >=20 > 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 >=20 --Apple-Mail=_CEC72A53-6ED2-464A-8C40-27D02B53DAC8 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=windows-1252
On 19 Mar 2014, at 21:11, Sethu Prasad = <sethuprasad.in@gmail.com> = wrote:

fsync
... taking more = knowledge around this will shed some light to understand this problem = "slave ahead of master"

= "there was silence, because master hang."
... replication = halted here, master holds the latest copy which is missing at both the = slaves


Master hang in very strange way. = I could ssh to it, and see dmesg, but not any other command. Also tcp = connection was alive to slaves.
So we can=92t say that slaves = did not receive data.


"I decided to = promote one of the slaves"
... only 2 slaves = are left, and one among them is going to be the master now, in = master/slave nomenclature the data from master is considered as the = valid one from this point = onward

There was no any = failover procedure. Slaves was = slaves. 



"mast= er is behind his slave"
... you mentioned that the original master comes up in the = mean time one of the slave was already a master


No, = after we rebooted master slaves did not reconnected to = it.
Later i stopped replication on one of the slaves to = preserve data its state.


So the = main question is, under which circumstances slaves can not reconnect to = master with error that master is behind.
With fsync on, and = synchronous* on.


On Wed, Mar 19, = 2014 at 10:40 PM, Evgeniy Shishkin <itparanoia@gmail.com> wrote:
Hello,

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 which 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:29 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 = GMT,,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 = GMT,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 GMT,,0,FATAL,XX000,"could not connect to the primary server: = could not connect 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 GMT,,0,FATAL,XX000,"could not connect to the primary server: = FATAL:  the database system is starting up
",,,,,,,,,""
2014-03-19 15:40:16.468 GMT,,,13136,,5329ba5e.3350,1,,2014-03-19 = 15:40:14 GMT,,0,LOG,00000,"started streaming WAL from primary at = 12/F1000000 on timeline 1",,,,,,,,,""
2014-03-19 15:40:16.468 GMT,,,13136,,5329ba5e.3350,2,,2014-03-19 = 15:40:14 GMT,,0,FATAL,XX000,"could not receive data from WAL stream: = ERROR:  requested starting point 12/F1000000 is ahead of the WAL = flush position of this server 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 GMT,,0,LOG,00000,"started streaming WAL from primary at = 12/F1000000 on timeline 1",,,,,,,,,""
2014-03-19 15:42:04.628 GMT,,,7388,,53108c69.1cdc,7,,2014-02-28 13:17:29 = GMT,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 GMT,,0,FATAL,57P01,"terminating walreceiver process due to = administrator command",,,,,,,,,""
2014-03-19 15:42:09.628 GMT,,,7388,,53108c69.1cdc,8,,2014-02-28 13:17:29 = GMT,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 = GMT,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 GMT,1/0,0,LOG,00000,"invalid record length at = 12/F1031DF8",,,,,,,,,=94"
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 = GMT,,0,LOG,00000,"database system was not properly shut down; automatic = recovery in progress",,,,,,,,,""
2014-03-19 15:39:30.989 GMT,,,7115,,5329ba32.1bcb,3,,2014-03-19 15:39:30 = GMT,,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 = GMT,,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 = GMT,,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 = GMT,,0,LOG,00000,"checkpoint starting: end-of-recovery = immediate",,,,,,,,,""
2014-03-19 15:40:16.466 GMT,"replicator","",7986,"10.162.2.52:44336",5329ba5e.1f32,1,"idle",2014-03-19= 15:40:14 GMT,2/0,0,ERROR,XX000,"requested starting 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
2014-03-19 16:50:43.118 GMT,,,4444,,5329cae3.115c,3,,2014-03-19 16:50:43 = GMT,,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 starting = up",,,,,,,,,""
2014-03-19 16:50:51.128 GMT,,,4444,,5329cae3.115c,4,,2014-03-19 16:50:43 = GMT,,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 = GMT,,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 = that master is behind his slave in synchronous replication.

Thanks for the help.

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


= --Apple-Mail=_CEC72A53-6ED2-464A-8C40-27D02B53DAC8--