Message-ID: <1508243364.2210.2.camel@europecamions-interactive.com>
Subject: Hot-standby 9.6 server stopped after losing master, won't start nor
 be promoted
From: David Guyot <david.guyot@europecamions-interactive.com>
To: pgsql-admin@postgresql.org
Date: Tue, 17 Oct 2017 14:29:24 +0200
Content-Type: multipart/signed; micalg="pgp-sha256";
	protocol="application/pgp-signature"; boundary="=-64hQ9LwsdgRjZzFkU242"
Mime-Version: 1.0
Precedence: bulk
Sender: pgsql-admin-owner@postgresql.org


--=-64hQ9LwsdgRjZzFkU242
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

Hello, there.

I just encountered a problem with a 9.6 hot standby architecture: by
mistake, we stopped the master and destroyed its data, so, some tens of
minutes later, when we noticed the problem, we tried to promote the
standby server. It stopped after the master failed, and we weren't able
to start it, so we also failed to promote it. I don't understand why,
but I assume I'm missing something in the replication process which
would explain that. The logs at master failure are the following:=20
2017-10-17 10:51:39.182 CEST,,,32236,,59dcdafa.7dec,2,,2017-10-10
16:36:42 CEST,,0,FATAL,XX000,"could not receive data from WAL stream:
SSL SYSCALL error: EOF detected",,,,,,,,,""
2017-10-17 10:51:39.540 CEST,,,32142,,59dcdaf4.7d8e,13,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"invalid resource manager ID 32 at
28/B0163E8",,,,,,,,,""
2017-10-17 10:51:39.642 CEST,,,8532,,59e5c49b.2154,1,,2017-10-17
10:51:39 CEST,,0,LOG,00000,"started streaming WAL from primary at
28/B000000 on timeline 1",,,,,,,,,""
2017-10-17 10:51:53.760 CEST,,,8532,,59e5c49b.2154,2,,2017-10-17
10:51:39 CEST,,0,LOG,00000,"replication terminated by primary
server","End of WAL reached on timeline 1 at 28/C000098",,,,,,,,""
2017-10-17 10:51:53.760 CEST,,,8532,,59e5c49b.2154,3,,2017-10-17
10:51:39 CEST,,0,FATAL,XX000,"could not send end-of-streaming message
to primary: no COPY in progress",,,,,,,,,""
2017-10-17 10:51:54.088 CEST,,,32142,,59dcdaf4.7d8e,14,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"record with incorrect prev-link 3F136/36 at
28/C000098",,,,,,,,,""
2017-10-17 10:51:54.113 CEST,,,8607,,59e5c4aa.219f,1,,2017-10-17
10:51:54 CEST,,0,FATAL,XX000,"could not connect to the primary server:
could not connect to server: Connection refused
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0Is the server running on ho=
st =C2=AB xxxxxx =C2=BB
(2001:41d0:xxxx:xxxx::1) and accepting
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TCP/IP connections on port =
5433?
could not connect to server: Connection refused
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0Is the server running on ho=
st =C2=AB xxxxxx =C2=BB (137.xx.xx.xx) and
accepting
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TCP/IP connections on port =
5433?",,,,,,,,,""
2017-10-17 10:51:59.133 CEST,,,8610,,59e5c4af.21a2,1,,2017-10-17
10:51:59 CEST,,0,FATAL,XX000,"could not connect to the primary server:
could not connect to server: Connection refused
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0Is the server running on ho=
st =C2=AB xxxxxx =C2=BB
(2001:41d0:xxxx:xxxx::1) and accepting
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TCP/IP connections on port =
5433 ?
could not connect to server: Connection refused
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0Is the server running on ho=
st =C2=AB xxxxxx =C2=BB (137.xx.xx.xx) and
accepting
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TCP/IP connections on port =
5433?",,,,,,,,,""
2017-10-17 10:52:03.969 CEST,,,32142,,59dcdaf4.7d8e,15,,2017-10-10
16:36:36 CEST,,0,FATAL,XX000,"could not restore file =C2=AB
00000001000000280000000C =C2=BB from archive: child process exited with exi=
t
code 255",,,,,,,,,""
2017-10-17 10:52:03.977 CEST,,,32139,,59dcdaf4.7d8b,2,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"startup process (PID 32142) exited with
exit code 1",,,,,,,,,""
2017-10-17 10:52:03.977 CEST,,,32139,,59dcdaf4.7d8b,3,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"terminating any other active server
processes",,,,,,,,,""
2017-10-17 10:52:03.990 CEST,,,32139,,59dcdaf4.7d8b,4,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"database system is shut down",,,,,,,,,""

As I understand these lines, the standby server lost the WAL stream to
the master and tried to reconnect; on failure, it tried to retrieve the
last archive and, failing again stopped. First problem: in such a case,
I thought the standby would stay online, waiting for instructions,
instead of shutting itself down. Am I wrong on that? If not, what did I
missed, which prompted the standby to shut itself down?

Then, when we tried to restart it to promote it, we got these lines:
2017-10-17 10:51:39.182 CEST,,,32236,,59dcdafa.7dec,2,,2017-10-10
16:36:42 CEST,,0,FATAL,XX000,"could not receive data from WAL stream:
SSL SYSCALL error: EOF detected",,,,,,,,,""
2017-10-17 10:51:39.540 CEST,,,32142,,59dcdaf4.7d8e,13,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"invalid resource manager ID 32 at
28/B0163E8",,,,,,,,,""
2017-10-17 10:51:39.642 CEST,,,8532,,59e5c49b.2154,1,,2017-10-17
10:51:39 CEST,,0,LOG,00000,"started streaming WAL from primary at
28/B000000 on timeline 1",,,,,,,,,""
2017-10-17 10:51:53.760 CEST,,,8532,,59e5c49b.2154,2,,2017-10-17
10:51:39 CEST,,0,LOG,00000,"replication terminated by primary
server","End of WAL reached on timeline 1 at 28/C000098",,,,,,,,""
2017-10-17 10:51:53.760 CEST,,,8532,,59e5c49b.2154,3,,2017-10-17
10:51:39 CEST,,0,FATAL,XX000,"could not send end-of-streaming message
to primary: no COPY in progress",,,,,,,,,""
2017-10-17 10:51:54.088 CEST,,,32142,,59dcdaf4.7d8e,14,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"record with incorrect prev-link 3F136/36 at
28/C000098",,,,,,,,,""
2017-10-17 10:51:54.113 CEST,,,8607,,59e5c4aa.219f,1,,2017-10-17
10:51:54 CEST,,0,FATAL,XX000,"could not connect to the primary server:
could not connect to server: Connection refused
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0Is the server running on ho=
st =C2=AB xxxxxx =C2=BB
(2001:41d0:xxxx:xxxx::1) and accepting
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TCP/IP connections on port =
5433?
could not connect to server: Connection refused
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0Is the server running on ho=
st =C2=AB xxxxxx =C2=BB (137.xx.xx.xx) and
accepting
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TCP/IP connections on port =
5433?",,,,,,,,,""
2017-10-17 10:51:59.133 CEST,,,8610,,59e5c4af.21a2,1,,2017-10-17
10:51:59 CEST,,0,FATAL,XX000,"could not connect to the primary server:
could not connect to server: Connection refused
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0Is the server running on ho=
st =C2=AB xxxxxx =C2=BB
(2001:41d0:xxxx:xxxx::1) and accepting
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TCP/IP connections on port =
5433 ?
could not connect to server: Connection refused
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0Is the server running on ho=
st =C2=AB xxxxxx =C2=BB (137.xx.xx.xx) and
accepting
=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0=C2=A0TCP/IP connections on port =
5433?",,,,,,,,,""
2017-10-17 10:52:03.969 CEST,,,32142,,59dcdaf4.7d8e,15,,2017-10-10
16:36:36 CEST,,0,FATAL,XX000,"could not restore file =C2=AB
00000001000000280000000C =C2=BB from archive: child process exited with exi=
t
code 255",,,,,,,,,""
2017-10-17 10:52:03.977 CEST,,,32139,,59dcdaf4.7d8b,2,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"startup process (PID 32142) exited with
exit code 1",,,,,,,,,""
2017-10-17 10:52:03.977 CEST,,,32139,,59dcdaf4.7d8b,3,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"terminating any other active server
processes",,,,,,,,,""
2017-10-17 10:52:03.990 CEST,,,32139,,59dcdaf4.7d8b,4,,2017-10-10
16:36:36 CEST,,0,LOG,00000,"database system is shut down",,,,,,,,,""

It seems that the server complains that the WAL stream was abruptly
stopped and that, as it fails to reconnect to the master, it can't
check if its (the standby) data are fresh, so it refuses to start. If
so, is it consistant? I don't think something as important as
replication would fail to start on master failure, as its goal is to
mitigate the master failure, so I assume I did something wrong, but
what? Otherwise, what should I do to allow the standby to restart and
be promoted?

Awaiting your answers,

Regards.
--=20
David Guyot
Administrateur syst=C3=A8me=C2=A0/ Sysadmin
Europe Camions Interactive=C2=A0/ Stockway
Moulin Collot F-88500 Ambacourt
T=C3=A9l=C2=A0: +33 (0)3 29 30 47 85
--=-64hQ9LwsdgRjZzFkU242
Content-Type: application/pgp-signature; name="signature.asc"
Content-Description: This is a digitally signed message part
Content-Transfer-Encoding: 7bit

-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEE3x4z121mNEB/JJ/PgVDjr4mKouAFAlnl96QACgkQgVDjr4mK
ouCCqQ/+PNaN3PHEkPtuDN6MH11bNZA2Rxa/oiP/Xm8GRlOGFi8LC1ITCGi2uBxn
2Dsqw4HRwbmdVPf/iDyJKjwk4Ja/qmjzpT1bBgqrYmZUQVlA/Dz+8oCrqwirZtwS
DXm3EqHAXKv49cPWl7+jekRxJ3YSzuiG6KukpS6/I+XTPJhzdXJEyMKJSSALhE7y
hOT1Mtan9IpPw6bXf5faUTAakENt7niiNgdx9QuzBtK1ibqiF/ce+Y2CXdSBHgUf
4BiNr5Wq+WRCTkhExs8HSs3qR5lj0WlWLyJ8QXo91ASoT+7KhqqpAZQiPpxZb850
hV1RSibjp95Guih9WKs1rkZYrRLvUBKNFMePm+DHjMQP5EKVqUaSWTbfNaNjjn/+
v6ZxCLgXCra/1GLL54HxC8PSNNZ+5Uc1Nkdk/oCqZgr0sjnsQOE1wC3D+XFZDRDt
KFeVzpFVOTnmgDzDuuU4tJxrmEmIO+H/Pe7L52/qeU4LCz8feCfb81B70S5XFzXD
8E0wjrNK9Rzpd6Au2dtIwP+/1c41WCZRUWgvFjJMpoISzU7+T64OeHUFHYZ5hTfz
sXnS0kIuD0AmLAmMBEmfMetXjHXLx0ptgEvxzY54dPUy8XZIDAoyYdNS1dW1WSVV
wRSNxZCK5hhmutcZnY79TE6c2CBXmhQa1OpIqkZ5+/D5xBe0yW8=
=YXom
-----END PGP SIGNATURE-----

--=-64hQ9LwsdgRjZzFkU242--