From d16faf3f011456f47044c243c83fb268cac8ee27 Mon Sep 17 00:00:00 2001 From: "Andrey M. Borodin" Date: Wed, 21 Feb 2024 19:34:26 +0300 Subject: [PATCH v3] Add timeouts TAP tests These tests verify that transaction_timeout, idle_session_timeout and idle_in_transaction_session_timeout work as expected. To do so we add injection points in before throwing a FATAL and test that these injection points are reached. Discussion: https://postgr.es/m/CAAhFRxiQsRs2Eq5kCo9nXE3HTugsAAJdSQSmxncivebAxdmBjQ%40mail.gmail.com --- src/backend/tcop/postgres.c | 10 ++ src/test/modules/test_misc/Makefile | 4 + src/test/modules/test_misc/meson.build | 4 + src/test/modules/test_misc/t/005_timeouts.pl | 149 +++++++++++++++++++ 4 files changed, 167 insertions(+) create mode 100644 src/test/modules/test_misc/t/005_timeouts.pl diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index aec1b194424..be5cb2cf2c2 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -72,6 +72,7 @@ #include "tcop/tcopprot.h" #include "tcop/utility.h" #include "utils/guc_hooks.h" +#include "utils/injection_point.h" #include "utils/lsyscache.h" #include "utils/memutils.h" #include "utils/ps_status.h" @@ -3411,9 +3412,12 @@ ProcessInterrupts(void) * interrupt. */ if (IdleInTransactionSessionTimeout > 0) + { + INJECTION_POINT("idle-in-transaction-session-timeout"); ereport(FATAL, (errcode(ERRCODE_IDLE_IN_TRANSACTION_SESSION_TIMEOUT), errmsg("terminating connection due to idle-in-transaction timeout"))); + } else IdleInTransactionSessionTimeoutPending = false; } @@ -3422,9 +3426,12 @@ ProcessInterrupts(void) { /* As above, ignore the signal if the GUC has been reset to zero. */ if (TransactionTimeout > 0) + { + INJECTION_POINT("transaction-timeout"); ereport(FATAL, (errcode(ERRCODE_TRANSACTION_TIMEOUT), errmsg("terminating connection due to transaction timeout"))); + } else TransactionTimeoutPending = false; } @@ -3433,9 +3440,12 @@ ProcessInterrupts(void) { /* As above, ignore the signal if the GUC has been reset to zero. */ if (IdleSessionTimeout > 0) + { + INJECTION_POINT("idle-session-timeout"); ereport(FATAL, (errcode(ERRCODE_IDLE_SESSION_TIMEOUT), errmsg("terminating connection due to idle-session timeout"))); + } else IdleSessionTimeoutPending = false; } diff --git a/src/test/modules/test_misc/Makefile b/src/test/modules/test_misc/Makefile index 39c6c2014a0..a958d156f47 100644 --- a/src/test/modules/test_misc/Makefile +++ b/src/test/modules/test_misc/Makefile @@ -2,6 +2,10 @@ TAP_TESTS = 1 +EXTRA_INSTALL=src/test/modules/injection_points + +export enable_injection_points enable_injection_points + ifdef USE_PGXS PG_CONFIG = pg_config PGXS := $(shell $(PG_CONFIG) --pgxs) diff --git a/src/test/modules/test_misc/meson.build b/src/test/modules/test_misc/meson.build index 964d95db263..df2913e8938 100644 --- a/src/test/modules/test_misc/meson.build +++ b/src/test/modules/test_misc/meson.build @@ -5,11 +5,15 @@ tests += { 'sd': meson.current_source_dir(), 'bd': meson.current_build_dir(), 'tap': { + 'env': { + 'enable_injection_points': get_option('injection_points') ? 'yes' : 'no', + }, 'tests': [ 't/001_constraint_validation.pl', 't/002_tablespace.pl', 't/003_check_guc.pl', 't/004_io_direct.pl', + 't/005_timeouts.pl' ], }, } diff --git a/src/test/modules/test_misc/t/005_timeouts.pl b/src/test/modules/test_misc/t/005_timeouts.pl new file mode 100644 index 00000000000..fb8e7a07df3 --- /dev/null +++ b/src/test/modules/test_misc/t/005_timeouts.pl @@ -0,0 +1,149 @@ + +# Copyright (c) 2024, PostgreSQL Global Development Group + +use strict; +use warnings; +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Time::HiRes qw(usleep); +use Test::More; + +# Test timeouts that will FATAL-out. +# This test relies on an injection points to await timeout ocurance. +# Relying on sleep prooved to be unstable on buildfarm. +# It's difficult to rely on NOTICE injection point, because FATALed +# backend can look differently under different circumstances. + +if ($ENV{enable_injection_points} ne 'yes') +{ + plan skip_all => 'Injection points not supported by this build'; +} + +# Node initialization +my $node = PostgreSQL::Test::Cluster->new('master'); +$node->init(); +$node->start; + +$node->safe_psql('postgres', 'CREATE EXTENSION injection_points;'); +$node->safe_psql('postgres', + "SELECT injection_points_attach('transaction-timeout', 'wait');"); + +# Update the start position to check logs later +my $logstart = -s $node->logfile; + + +# +# 1. Test of transaction timeout +# + +my $psql_session = + $node->background_psql('postgres'); + +# Following query will generate a stream of SELECT 1 queries. This is done to +# excersice transaction timeout in presence of short queries. +$psql_session->query_until( + qr/starting_bg_psql/, q( + \echo starting_bg_psql + SET transaction_timeout to '10ms'; + BEGIN; + SELECT 1 \watch 0.001 + \q +)); + +# Wait until the backend is in the timeout. +# In case if anything get broken this waiting will error-out +$node->wait_for_event('client backend','transaction-timeout'); + +# Remove injection point. +$node->safe_psql('postgres', + "SELECT injection_points_wakeup('transaction-timeout');"); + +# If we send \q with $psql_session->quit it can get to pump already closed. +# So \q is in initial script, here we only finish IPC::Run. +$psql_session->{run}->finish; + + +# +# 2. Test of idle in transaction timeout +# + +$node->safe_psql('postgres', + "SELECT injection_points_attach('idle-in-transaction-session-timeout', 'wait');"); + +# We begin a transaction and the hand on the line +$psql_session = + $node->background_psql('postgres'); +$psql_session->query_until( + qr/starting_bg_psql/, q( + \echo starting_bg_psql + SET idle_in_transaction_session_timeout to '10ms'; + BEGIN; +)); + +# Wait until the backend is in the timeout. +$node->wait_for_event('client backend','idle-in-transaction-session-timeout'); + +# Remove injection point. +$node->safe_psql('postgres', + "SELECT injection_points_wakeup('idle-in-transaction-session-timeout');"); +ok($psql_session->quit); + + +# +# 3. Test of idle session timeout +# +$node->safe_psql('postgres', + "SELECT injection_points_attach('idle-session-timeout', 'wait');"); + +# We just initialize GUC and wait. No transaction required. +$psql_session = + $node->background_psql('postgres'); +$psql_session->query_until( + qr/starting_bg_psql/, q( + \echo starting_bg_psql + SET idle_session_timeout to '10ms'; +)); + +# Wait until the backend is in the timeout. +$node->wait_for_event('client backend','idle-session-timeout'); + +# Remove injection point. +$node->safe_psql('postgres', + "SELECT injection_points_wakeup('idle-session-timeout');"); +ok($psql_session->quit); + +# Check that every timeout was logged +my $transaction_timeout_logged = 0; +my $idle_in_transaction_session_timeout_logged = 0; +my $idle_session_timeout_logged = 0; +foreach my $i (0 .. 10 * $PostgreSQL::Test::Utils::timeout_default) +{ + if ((!$transaction_timeout_logged) && + $node->log_contains('terminating connection due to transaction timeout', $logstart)) + { + $transaction_timeout_logged = 1; + } + if ((!$idle_in_transaction_session_timeout_logged) && + $node->log_contains('terminating connection due to idle-in-transaction timeout', $logstart)) + { + $idle_in_transaction_session_timeout_logged = 1; + } + if ((!$idle_session_timeout_logged) && + $node->log_contains('terminating connection due to idle-session timeout', $logstart)) + { + $idle_session_timeout_logged = 1; + } + + if ($transaction_timeout_logged && $idle_in_transaction_session_timeout_logged && + $idle_session_timeout_logged) + { + last; + } + + usleep(100_000); +} +ok($transaction_timeout_logged, 'transaction timeout was logged'); +ok($idle_in_transaction_session_timeout_logged, 'transaction timeout was logged'); +ok($idle_session_timeout_logged, 'transaction timeout was logged'); + +done_testing(); -- 2.42.0