Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rjxUu-009Es8-7E for pgsql-hackers@arkaria.postgresql.org; Tue, 12 Mar 2024 08:28:33 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1rjxUr-008M4u-SB for pgsql-hackers@arkaria.postgresql.org; Tue, 12 Mar 2024 08:28:30 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rjxUr-008M1c-B8 for pgsql-hackers@lists.postgresql.org; Tue, 12 Mar 2024 08:28:30 +0000 Received: from forwardcorp1a.mail.yandex.net ([2a02:6b8:c0e:500:1:45:d181:df01]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rjxUo-00450T-9u for pgsql-hackers@lists.postgresql.org; Tue, 12 Mar 2024 08:28:29 +0000 Received: from mail-nwsmtp-smtp-corp-main-83.vla.yp-c.yandex.net (mail-nwsmtp-smtp-corp-main-83.vla.yp-c.yandex.net [IPv6:2a02:6b8:c18:486:0:640:cf34:0]) by forwardcorp1a.mail.yandex.net (Yandex) with ESMTPS id DB00660F70; Tue, 12 Mar 2024 11:28:23 +0300 (MSK) Received: from smtpclient.apple (unknown [2a02:6b8:b081:b70b::1:32]) by mail-nwsmtp-smtp-corp-main-83.vla.yp-c.yandex.net (smtpcorp/Yandex) with ESMTPSA id KShnLX5OlOs0-PP4aKNvI; Tue, 12 Mar 2024 11:28:23 +0300 X-Yandex-Fwd: 1 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yandex-team.ru; s=default; t=1710232103; bh=NaBf57Pcs3lzrb0RH7Ml6vWKLfbez06trmdbmp9XCM0=; h=References:To:Cc:In-Reply-To:Date:From:Message-Id:Subject; b=Hdm8mh8FBmEv4sKMDq+9aGm+Cht8cwmXL+LgkwGDBuE78x1ipmbruEzOusjsUpLH3 4ZNtRkDSPP2TXV9iF5fK4p8wnKDnFnQD39CuGq9NnH4hzZkqyCpVMkuHP8RnYwim// SMLYdomsuNa+VO8pb/lZMUOg2lY65X8Uy3eL4yeI= Authentication-Results: mail-nwsmtp-smtp-corp-main-83.vla.yp-c.yandex.net; dkim=pass header.i=@yandex-team.ru From: "Andrey M. Borodin" Message-Id: Content-Type: multipart/mixed; boundary="Apple-Mail=_AA3D01A1-E46E-4F73-94CA-2E87CF8F65A8" Mime-Version: 1.0 (Mac OS X Mail 16.0 \(3696.120.41.1.4\)) Subject: Re: Transaction timeout Date: Tue, 12 Mar 2024 13:28:19 +0500 In-Reply-To: Cc: Japin Li , Peter Smith , Junwang Zhao , =?utf-8?B?6YKx5a6H6Iiq?= , Fujii Masao , Andrew Borodin , Michael Paquier , Nikolay Samokhvalov , pgsql-hackers mailing list , pgsql-hackers mailing list , Andres Freund To: Alexander Korotkov References: <4C30F833-C0F2-4664-B0FF-192FD8AB2E2E@yandex-team.ru> <20240215230856.pc6k57tqxt7fhldm@awork3.anarazel.de> <29FFC4CE-EFB3-4A72-B53A-ADAB2B5F66A9@yandex-team.ru> <7ED6E126-5A6F-4279-8ECF-2D45CCCEB74D@yandex-team.ru> <51D27E3F-B6E7-464B-B36D-6FC1D8E0B118@yandex-team.ru> X-Mailer: Apple Mail (2.3696.120.41.1.4) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --Apple-Mail=_AA3D01A1-E46E-4F73-94CA-2E87CF8F65A8 Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=us-ascii > On 11 Mar 2024, at 16:18, Alexander Korotkov wrote: > > I think if checking psql stderr is problematic, checking just logs is > fine. Could we wait for the relevant log messages one by one with > $node->wait_for_log() just like 040_standby_failover_slots_sync.pl do? PFA version with $node->wait_for_log() Best regards, Andrey Borodin. --Apple-Mail=_AA3D01A1-E46E-4F73-94CA-2E87CF8F65A8 Content-Disposition: attachment; filename=v4-0001-Add-timeouts-TAP-tests.patch Content-Type: application/octet-stream; x-unix-mode=0644; name="v4-0001-Add-timeouts-TAP-tests.patch" Content-Transfer-Encoding: quoted-printable =46rom=2006d0a39115da7ce2290a3cb64645b70a77b40686=20Mon=20Sep=2017=20= 00:00:00=202001=0AFrom:=20"Andrey=20M.=20Borodin"=20=0A= Date:=20Wed,=2021=20Feb=202024=2019:34:26=20+0300=0ASubject:=20[PATCH=20= v4]=20Add=20timeouts=20TAP=20tests=0A=0AThese=20tests=20verify=20that=20= transaction_timeout,=20idle_session_timeout=0Aand=20= idle_in_transaction_session_timeout=20work=20as=20expected.=0ATo=20do=20= so=20we=20add=20injection=20points=20in=20before=20throwing=20a=20FATAL=0A= and=20test=20that=20these=20injection=20points=20are=20reached.=0A=0A= Discussion:=20= https://postgr.es/m/CAAhFRxiQsRs2Eq5kCo9nXE3HTugsAAJdSQSmxncivebAxdmBjQ%40= mail.gmail.com=0A---=0A=20src/backend/tcop/postgres.c=20=20=20=20=20=20=20= =20=20=20=20=20=20=20=20=20=20=20|=20=2010=20++=0A=20= src/test/modules/test_misc/Makefile=20=20=20=20=20=20=20=20=20=20|=20=20=20= 4=20+=0A=20src/test/modules/test_misc/meson.build=20=20=20=20=20=20=20|=20= =20=204=20+=0A=20src/test/modules/test_misc/t/005_timeouts.pl=20|=20118=20= +++++++++++++++++++=0A=204=20files=20changed,=20136=20insertions(+)=0A=20= create=20mode=20100644=20src/test/modules/test_misc/t/005_timeouts.pl=0A=0A= diff=20--git=20a/src/backend/tcop/postgres.c=20= b/src/backend/tcop/postgres.c=0Aindex=20aec1b19442..be5cb2cf2c=20100644=0A= ---=20a/src/backend/tcop/postgres.c=0A+++=20= b/src/backend/tcop/postgres.c=0A@@=20-72,6=20+72,7=20@@=0A=20#include=20= "tcop/tcopprot.h"=0A=20#include=20"tcop/utility.h"=0A=20#include=20= "utils/guc_hooks.h"=0A+#include=20"utils/injection_point.h"=0A=20= #include=20"utils/lsyscache.h"=0A=20#include=20"utils/memutils.h"=0A=20= #include=20"utils/ps_status.h"=0A@@=20-3411,9=20+3412,12=20@@=20= ProcessInterrupts(void)=0A=20=09=09=20*=20interrupt.=0A=20=09=09=20*/=0A=20= =09=09if=20(IdleInTransactionSessionTimeout=20>=200)=0A+=09=09{=0A+=09=09= =09INJECTION_POINT("idle-in-transaction-session-timeout");=0A=20=09=09=09= ereport(FATAL,=0A=20=09=09=09=09=09= (errcode(ERRCODE_IDLE_IN_TRANSACTION_SESSION_TIMEOUT),=0A=20=09=09=09=09=09= =20errmsg("terminating=20connection=20due=20to=20idle-in-transaction=20= timeout")));=0A+=09=09}=0A=20=09=09else=0A=20=09=09=09= IdleInTransactionSessionTimeoutPending=20=3D=20false;=0A=20=09}=0A@@=20= -3422,9=20+3426,12=20@@=20ProcessInterrupts(void)=0A=20=09{=0A=20=09=09= /*=20As=20above,=20ignore=20the=20signal=20if=20the=20GUC=20has=20been=20= reset=20to=20zero.=20*/=0A=20=09=09if=20(TransactionTimeout=20>=200)=0A+=09= =09{=0A+=09=09=09INJECTION_POINT("transaction-timeout");=0A=20=09=09=09= ereport(FATAL,=0A=20=09=09=09=09=09= (errcode(ERRCODE_TRANSACTION_TIMEOUT),=0A=20=09=09=09=09=09=20= errmsg("terminating=20connection=20due=20to=20transaction=20timeout")));=0A= +=09=09}=0A=20=09=09else=0A=20=09=09=09TransactionTimeoutPending=20=3D=20= false;=0A=20=09}=0A@@=20-3433,9=20+3440,12=20@@=20= ProcessInterrupts(void)=0A=20=09{=0A=20=09=09/*=20As=20above,=20ignore=20= the=20signal=20if=20the=20GUC=20has=20been=20reset=20to=20zero.=20*/=0A=20= =09=09if=20(IdleSessionTimeout=20>=200)=0A+=09=09{=0A+=09=09=09= INJECTION_POINT("idle-session-timeout");=0A=20=09=09=09ereport(FATAL,=0A=20= =09=09=09=09=09(errcode(ERRCODE_IDLE_SESSION_TIMEOUT),=0A=20=09=09=09=09=09= =20errmsg("terminating=20connection=20due=20to=20idle-session=20= timeout")));=0A+=09=09}=0A=20=09=09else=0A=20=09=09=09= IdleSessionTimeoutPending=20=3D=20false;=0A=20=09}=0Adiff=20--git=20= a/src/test/modules/test_misc/Makefile=20= b/src/test/modules/test_misc/Makefile=0Aindex=2039c6c2014a..a958d156f4=20= 100644=0A---=20a/src/test/modules/test_misc/Makefile=0A+++=20= b/src/test/modules/test_misc/Makefile=0A@@=20-2,6=20+2,10=20@@=0A=20=0A=20= TAP_TESTS=20=3D=201=0A=20=0A= +EXTRA_INSTALL=3Dsrc/test/modules/injection_points=0A+=0A+export=20= enable_injection_points=20enable_injection_points=0A+=0A=20ifdef=20= USE_PGXS=0A=20PG_CONFIG=20=3D=20pg_config=0A=20PGXS=20:=3D=20$(shell=20= $(PG_CONFIG)=20--pgxs)=0Adiff=20--git=20= a/src/test/modules/test_misc/meson.build=20= b/src/test/modules/test_misc/meson.build=0Aindex=20= 964d95db26..df2913e893=20100644=0A---=20= a/src/test/modules/test_misc/meson.build=0A+++=20= b/src/test/modules/test_misc/meson.build=0A@@=20-5,11=20+5,15=20@@=20= tests=20+=3D=20{=0A=20=20=20'sd':=20meson.current_source_dir(),=0A=20=20=20= 'bd':=20meson.current_build_dir(),=0A=20=20=20'tap':=20{=0A+=20=20=20=20= 'env':=20{=0A+=20=20=20=20=20=20=20'enable_injection_points':=20= get_option('injection_points')=20?=20'yes'=20:=20'no',=0A+=20=20=20=20},=0A= =20=20=20=20=20'tests':=20[=0A=20=20=20=20=20=20=20= 't/001_constraint_validation.pl',=0A=20=20=20=20=20=20=20= 't/002_tablespace.pl',=0A=20=20=20=20=20=20=20't/003_check_guc.pl',=0A=20= =20=20=20=20=20=20't/004_io_direct.pl',=0A+=20=20=20=20=20=20= 't/005_timeouts.pl'=0A=20=20=20=20=20],=0A=20=20=20},=0A=20}=0Adiff=20= --git=20a/src/test/modules/test_misc/t/005_timeouts.pl=20= b/src/test/modules/test_misc/t/005_timeouts.pl=0Anew=20file=20mode=20= 100644=0Aindex=200000000000..3046eca641=0A---=20/dev/null=0A+++=20= b/src/test/modules/test_misc/t/005_timeouts.pl=0A@@=20-0,0=20+1,118=20@@=0A= +=0A+#=20Copyright=20(c)=202024,=20PostgreSQL=20Global=20Development=20= Group=0A+=0A+use=20strict;=0A+use=20warnings;=0A+use=20= PostgreSQL::Test::Cluster;=0A+use=20PostgreSQL::Test::Utils;=0A+use=20= Time::HiRes=20qw(usleep);=0A+use=20Test::More;=0A+=0A+#=20Test=20= timeouts=20that=20will=20FATAL-out.=0A+#=20This=20test=20relies=20on=20= an=20injection=20points=20to=20await=20timeout=20ocurance.=0A+#=20= Relying=20on=20sleep=20prooved=20to=20be=20unstable=20on=20buildfarm.=0A= +#=20It's=20difficult=20to=20rely=20on=20NOTICE=20injection=20point,=20= because=20FATALed=0A+#=20backend=20can=20look=20differently=20under=20= different=20circumstances.=0A+=0A+if=20($ENV{enable_injection_points}=20= ne=20'yes')=0A+{=0A+=09plan=20skip_all=20=3D>=20'Injection=20points=20= not=20supported=20by=20this=20build';=0A+}=0A+=0A+#=20Node=20= initialization=0A+my=20$node=20=3D=20= PostgreSQL::Test::Cluster->new('master');=0A+$node->init();=0A= +$node->start;=0A+=0A+$node->safe_psql('postgres',=20'CREATE=20EXTENSION=20= injection_points;');=0A+$node->safe_psql('postgres',=0A+=09"SELECT=20= injection_points_attach('transaction-timeout',=20'wait');");=0A+=0A+=0A= +#=0A+#=201.=20Test=20of=20transaction=20timeout=0A+#=0A+=0A+my=20= $psql_session=20=3D=0A+=20=20$node->background_psql('postgres');=0A+=0A= +#=20Following=20query=20will=20generate=20a=20stream=20of=20SELECT=201=20= queries.=20This=20is=20done=20to=0A+#=20excersice=20transaction=20= timeout=20in=20presence=20of=20short=20queries.=0A= +$psql_session->query_until(=0A+=09qr/starting_bg_psql/,=20q(=0A+=20=20=20= \echo=20starting_bg_psql=0A+=20=20=20SET=20transaction_timeout=20to=20= '10ms';=0A+=20=20=20BEGIN;=0A+=20=20=20SELECT=201=20\watch=200.001=0A+=20= =20=20\q=0A+));=0A+=0A+#=20Wait=20until=20the=20backend=20is=20in=20the=20= timeout.=0A+#=20In=20case=20if=20anything=20get=20broken=20this=20= waiting=20will=20error-out=0A+$node->wait_for_event('client=20= backend','transaction-timeout');=0A+=0A+#=20Remove=20injection=20point.=0A= +$node->safe_psql('postgres',=0A+=09"SELECT=20= injection_points_wakeup('transaction-timeout');");=0A+=0A+#=20If=20we=20= send=20\q=20with=20$psql_session->quit=20it=20can=20get=20to=20pump=20= already=20closed.=0A+#=20So=20\q=20is=20in=20initial=20script,=20here=20= we=20only=20finish=20IPC::Run.=0A+$psql_session->{run}->finish;=0A+=0A+=0A= +#=0A+#=202.=20Test=20of=20idle=20in=20transaction=20timeout=0A+#=0A+=0A= +$node->safe_psql('postgres',=0A+=09"SELECT=20= injection_points_attach('idle-in-transaction-session-timeout',=20= 'wait');");=0A+=0A+#=20We=20begin=20a=20transaction=20and=20the=20hand=20= on=20the=20line=0A+$psql_session=20=3D=0A+=20=20= $node->background_psql('postgres');=0A+$psql_session->query_until(=0A+=09= qr/starting_bg_psql/,=20q(=0A+=20=20=20\echo=20starting_bg_psql=0A+=20=20= =20SET=20idle_in_transaction_session_timeout=20to=20'10ms';=0A+=20=20=20= BEGIN;=0A+));=0A+=0A+#=20Wait=20until=20the=20backend=20is=20in=20the=20= timeout.=0A+$node->wait_for_event('client=20= backend','idle-in-transaction-session-timeout');=0A+=0A+#=20Remove=20= injection=20point.=0A+$node->safe_psql('postgres',=0A+=09"SELECT=20= injection_points_wakeup('idle-in-transaction-session-timeout');");=0A= +ok($psql_session->quit);=0A+=0A+=0A+#=0A+#=203.=20Test=20of=20idle=20= session=20timeout=0A+#=0A+$node->safe_psql('postgres',=0A+=09"SELECT=20= injection_points_attach('idle-session-timeout',=20'wait');");=0A+=0A+#=20= We=20just=20initialize=20GUC=20and=20wait.=20No=20transaction=20= required.=0A+$psql_session=20=3D=0A+=20=20= $node->background_psql('postgres');=0A+$psql_session->query_until(=0A+=09= qr/starting_bg_psql/,=20q(=0A+=20=20=20\echo=20starting_bg_psql=0A+=20=20= =20SET=20idle_session_timeout=20to=20'10ms';=0A+));=0A+=0A+#=20Wait=20= until=20the=20backend=20is=20in=20the=20timeout.=0A= +$node->wait_for_event('client=20backend','idle-session-timeout');=0A+=0A= +#=20Remove=20injection=20point.=0A+$node->safe_psql('postgres',=0A+=09= "SELECT=20injection_points_wakeup('idle-session-timeout');");=0A= +ok($psql_session->quit);=0A+=0A+=0A+#=20Check=20that=20every=20timeout=20= was=20logged=0A+$node->wait_for_log('terminating=20connection=20due=20to=20= transaction=20timeout');=0A+$node->wait_for_log('terminating=20= connection=20due=20to=20idle-in-transaction=20timeout');=0A= +$node->wait_for_log('terminating=20connection=20due=20to=20idle-session=20= timeout');=0A+=0A+done_testing();=0A--=20=0A2.37.1=20(Apple=20Git-137.1)=0A= =0A= --Apple-Mail=_AA3D01A1-E46E-4F73-94CA-2E87CF8F65A8--