Subject: Re: Failed assertion on standby while shutdown
To: Maxim Orlov <m.orlov@postgrespro.ru>,
 Pgsql Hackers <pgsql-hackers@postgresql.org>
References: <ad4ce692cc1d89a093b471ab1d969b0b@postgrespro.ru>
From: Fujii Masao <masao.fujii@oss.nttdata.com>
Message-ID: <9c7b69c2-fb17-1780-e475-7dd2c6bbe18b@oss.nttdata.com>
Date: Mon, 22 Mar 2021 22:40:54 +0900
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:78.0)
 Gecko/20100101 Thunderbird/78.8.1
MIME-Version: 1.0
In-Reply-To: <ad4ce692cc1d89a093b471ab1d969b0b@postgrespro.ru>
Content-Type: multipart/mixed;
 boundary="------------774718B88240D5725827601A"
Content-Language: en-US
Archived-At: 
 <https://www.postgresql.org/message-id/9c7b69c2-fb17-1780-e475-7dd2c6bbe18b%40oss.nttdata.com>
Precedence: bulk

This is a multi-part message in MIME format.
--------------774718B88240D5725827601A
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 8bit


On 2021/03/20 2:25, Maxim Orlov wrote:
> Hi, haсkers!
> 
> Recently, I was doing some experiments with primary/standby instances interaction. In certain conditions I’ve got and was able to reproduce crash on failed assertion.
> 
> The scenario is the following:
> 1. start primary server
> 2. start standby server by pg_basebackup -P -R -X stream -c fast -p5432 -D data
> 3. apply some load to the primary server by pgbench -p5432 -i -s 150 postgres
> 4. kill primary server (with kill -9) and keep it down
> 5. stop standby server by pg_ctl
> 6. run standby server
> 
> Then any standby server termination will result in a failed assertion.
> 
> The log with a backtrace is following:
> 
> 2021-03-19 18:54:25.352 MSK [3508443] LOG:  received fast shutdown request
> 2021-03-19 18:54:25.379 MSK [3508443] LOG:  aborting any active transactions
> TRAP: FailedAssertion("SHMQueueEmpty(&(MyProc->myProcLocks[i]))", File: "/home/ziva/projects/pgpro/build-secondary/../postgrespro/src/backend/storage/lmgr/proc.c", Line: 592, PID: 3508452)
> postgres: walreceiver (ExceptionalCondition+0xd0)[0x555555d0526f]
> postgres: walreceiver (InitAuxiliaryProcess+0x31c)[0x555555b43e31]
> postgres: walreceiver (AuxiliaryProcessMain+0x54f)[0x55555574ae32]
> postgres: walreceiver (+0x530bff)[0x555555a84bff]
> postgres: walreceiver (+0x531044)[0x555555a85044]
> postgres: walreceiver (+0x530959)[0x555555a84959]
> /lib/x86_64-linux-gnu/libpthread.so.0(+0x153c0)[0x7ffff7a303c0]
> /lib/x86_64-linux-gnu/libc.so.6(__select+0x1a)[0x7ffff72a40da]
> postgres: walreceiver (+0x52bea4)[0x555555a7fea4]
> postgres: walreceiver (PostmasterMain+0x129f)[0x555555a7f7c1]
> postgres: walreceiver (+0x41ff1f)[0x555555973f1f]
> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7ffff71b30b3]
> postgres: walreceiver (_start+0x2e)[0x55555561abfe]
> 
> After a brief investigation I found out that I can get this assert with 100% probability if I insert a sleep for about 5 sec into InitAuxiliaryProcess(void) in src/backend/storage/lmgr/proc.c:
> 
> diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
> index 897045ee272..b5f365f426d 100644
> --- a/src/backend/storage/lmgr/proc.c
> +++ b/src/backend/storage/lmgr/proc.c
> @@ -525,7 +525,7 @@ InitAuxiliaryProcess(void)
> 
>          if (MyProc != NULL)
>                  elog(ERROR, "you already exist");
> -
> +       pg_usleep(5000000L);
>          /*
>           * We use the ProcStructLock to protect assignment and releasing of
>           * AuxiliaryProcs entries.

Thanks for the report! I could reproduce this issue by adding that sleep
into InitAuxiliaryProcess().

> Maybe, this kinda behaviour would appear if a computer hosting instances is under significant side load, which cause delay to start db-instances under a heavy load.
> 
> Configuration for a primary server is default with "wal_level = logical"
> 
> Configuration for a standby server is default with "wal_level = logical" and "primary_conninfo = 'port=5432'"
> 
> I'm puzzled with this behavor. I'm pretty sure it is not what should be. Any ideas how this can be fixed?

ISTM that the cause of this issue is that the startup process exits
without releasing the locks that it was holding when shutdown is
requested. To address this issue, IMO the startup process should
call ShutdownRecoveryTransactionEnvironment() at its exit.
Attached is the POC patch that changes the startup process that way.

I've not tested the patch enough yet..

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

--------------774718B88240D5725827601A
Content-Type: text/plain; charset=UTF-8; x-mac-type="0"; x-mac-creator="0";
 name="fix_assertion_failure_walreceiver.patch"
Content-Transfer-Encoding: base64
Content-Disposition: attachment;
 filename="fix_assertion_failure_walreceiver.patch"

ZGlmZiAtLWdpdCBhL3NyYy9iYWNrZW5kL3Bvc3RtYXN0ZXIvc3RhcnR1cC5jIGIvc3JjL2Jh
Y2tlbmQvcG9zdG1hc3Rlci9zdGFydHVwLmMKaW5kZXggMjIxMzVkNWUwNy4uNjkwNzdiZDIw
NyAxMDA2NDQKLS0tIGEvc3JjL2JhY2tlbmQvcG9zdG1hc3Rlci9zdGFydHVwLmMKKysrIGIv
c3JjL2JhY2tlbmQvcG9zdG1hc3Rlci9zdGFydHVwLmMKQEAgLTYyLDYgKzYyLDkgQEAgc3Rh
dGljIHZvbGF0aWxlIHNpZ19hdG9taWNfdCBpbl9yZXN0b3JlX2NvbW1hbmQgPSBmYWxzZTsK
IHN0YXRpYyB2b2lkIFN0YXJ0dXBQcm9jVHJpZ2dlckhhbmRsZXIoU0lHTkFMX0FSR1MpOwog
c3RhdGljIHZvaWQgU3RhcnR1cFByb2NTaWdIdXBIYW5kbGVyKFNJR05BTF9BUkdTKTsKIAor
LyogQ2FsbGJhY2tzICovCitzdGF0aWMgdm9pZCBTdGFydHVwUHJvY0V4aXQoaW50IGNvZGUs
IERhdHVtIGFyZyk7CisKIAogLyogLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0K
ICAqCQlzaWduYWwgaGFuZGxlciByb3V0aW5lcwpAQCAtMTgzLDYgKzE4NiwxOSBAQCBIYW5k
bGVTdGFydHVwUHJvY0ludGVycnVwdHModm9pZCkKIH0KIAogCisvKiAtLS0tLS0tLS0tLS0t
LS0tLS0tLS0tLS0tLS0tLS0tLQorICoJCXNpZ25hbCBoYW5kbGVyIHJvdXRpbmVzCisgKiAt
LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLQorICovCitzdGF0aWMgdm9pZAorU3Rh
cnR1cFByb2NFeGl0KGludCBjb2RlLCBEYXR1bSBhcmcpCit7CisJLyogU2h1dGRvd24gdGhl
IHJlY292ZXJ5IGVudmlyb25tZW50ICovCisJaWYgKHN0YW5kYnlTdGF0ZSAhPSBTVEFOREJZ
X0RJU0FCTEVEKQorCQlTaHV0ZG93blJlY292ZXJ5VHJhbnNhY3Rpb25FbnZpcm9ubWVudCgp
OworfQorCisKIC8qIC0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0KICAqCVN0
YXJ0dXAgUHJvY2VzcyBtYWluIGVudHJ5IHBvaW50CiAgKiAtLS0tLS0tLS0tLS0tLS0tLS0t
LS0tLS0tLS0tLS0tLS0tCkBAIC0xOTAsNiArMjA2LDkgQEAgSGFuZGxlU3RhcnR1cFByb2NJ
bnRlcnJ1cHRzKHZvaWQpCiB2b2lkCiBTdGFydHVwUHJvY2Vzc01haW4odm9pZCkKIHsKKwkv
KiBBcnJhbmdlIHRvIGNsZWFuIHVwIGF0IHN0YXJ0dXAgcHJvY2VzcyBleGl0ICovCisJb25f
c2htZW1fZXhpdChTdGFydHVwUHJvY0V4aXQsIDApOworCiAJLyoKIAkgKiBQcm9wZXJseSBh
Y2NlcHQgb3IgaWdub3JlIHNpZ25hbHMgdGhlIHBvc3RtYXN0ZXIgbWlnaHQgc2VuZCB1cy4K
IAkgKi8KZGlmZiAtLWdpdCBhL3NyYy9iYWNrZW5kL3N0b3JhZ2UvaXBjL3N0YW5kYnkuYyBi
L3NyYy9iYWNrZW5kL3N0b3JhZ2UvaXBjL3N0YW5kYnkuYwppbmRleCAxN2RlNWE2ZDBlLi5h
YWU2ZDI4ZjkzIDEwMDY0NAotLS0gYS9zcmMvYmFja2VuZC9zdG9yYWdlL2lwYy9zdGFuZGJ5
LmMKKysrIGIvc3JjL2JhY2tlbmQvc3RvcmFnZS9pcGMvc3RhbmRieS5jCkBAIC0xMzEsNiAr
MTMxLDEyIEBAIEluaXRSZWNvdmVyeVRyYW5zYWN0aW9uRW52aXJvbm1lbnQodm9pZCkKIHZv
aWQKIFNodXRkb3duUmVjb3ZlcnlUcmFuc2FjdGlvbkVudmlyb25tZW50KHZvaWQpCiB7CisJ
c3RhdGljIGJvb2wJY2FsbGVkID0gZmFsc2U7CisKKwkvKiBQcmV2ZW50IHRyYW5zYWN0aW9u
IHRyYWNraW5nIGZyb20gYmVpbmcgc2h1dCBkb3duIG1vcmUgdGhhbiBvbmNlICovCisJaWYg
KGNhbGxlZCkKKwkJcmV0dXJuOworCiAJLyogTWFyayBhbGwgdHJhY2tlZCBpbi1wcm9ncmVz
cyB0cmFuc2FjdGlvbnMgYXMgZmluaXNoZWQuICovCiAJRXhwaXJlQWxsS25vd25Bc3NpZ25l
ZFRyYW5zYWN0aW9uSWRzKCk7CiAKQEAgLTE0Myw2ICsxNDksOCBAQCBTaHV0ZG93blJlY292
ZXJ5VHJhbnNhY3Rpb25FbnZpcm9ubWVudCh2b2lkKQogCiAJLyogQ2xlYW51cCBvdXIgVmly
dHVhbFRyYW5zYWN0aW9uICovCiAJVmlydHVhbFhhY3RMb2NrVGFibGVDbGVhbnVwKCk7CisK
KwljYWxsZWQgPSB0cnVlOwogfQogCiAK
--------------774718B88240D5725827601A--