Subject: Re: cleanup temporary files after crash
To: Euler Taveira <euler@eulerto.com>, Tom Lane <tgl@sss.pgh.pa.us>
Cc: Thomas Munro <thomas.munro@gmail.com>,
 Michael Paquier <michael@paquier.xyz>,
 Euler Taveira <euler.taveira@2ndquadrant.com>,
 Anastasia Lubennikova <a.lubennikova@postgrespro.ru>,
 Tomas Vondra <tomas.vondra@2ndquadrant.com>,
 PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
References: 
 <CAH503wDKdYzyq7U-QJqGn=Gm6XmoK+6_6xTJ-Yn5WSvoHLY1Ww@mail.gmail.com>
 <4245d284-97b2-4056-96c2-455792d9b564@www.fastmail.com>
 <8740f056-a7c0-ff12-0a50-de5324a928ee@enterprisedb.com>
 <822e3a60-56a1-219d-c473-365751c3e108@enterprisedb.com>
 <a32a7f28-570c-24a2-aa2a-9f7c96abd88b@enterprisedb.com>
 <54663718-1d87-46f2-a27b-e7edacbfae0d@www.fastmail.com>
 <1ec33f3d-ea4c-28c8-502c-3eb0a008a6ac@enterprisedb.com>
 <34226249-c5ba-4780-a1bb-f3433d19716e@www.fastmail.com>
 <05d307fc-8391-4091-b279-1b3214658f10@www.fastmail.com>
 <049a2752-fc99-194d-31b2-b15ffa914cd4@enterprisedb.com>
 <a26a35c6-8816-4c2b-91b9-7a428e430a57@www.fastmail.com>
 <482a6498-7713-e937-c554-7d235c415fba@enterprisedb.com>
 <112f0847-a71!a-eec2-e561-2d39dc26127a@enterprisedb.com>
 <4028905.1616122655@sss.pgh.pa.us>
 <19bc3276-6280-43bd-d868-ab3cb146266a@enter!prisedb.com>
 <4030089.1616124234@sss.pgh.pa.us>
 <6eff9861-b059-4eaa-ae70-e5ff877b6448@www.fastmail.com>
From: Tomas Vondra <tomas.vondra@enterprisedb.com>
Message-ID: <70bbfaac-74dd-de9a-b086-8bf43224e1c0@enterprisedb.com>
Date: Fri, 19 Mar 2021 17:23:13 +0100
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:78.0) Gecko/20100101
 Thunderbird/78.8.0
MIME-Version: 1.0
In-Reply-To: <6eff9861-b059-4eaa-ae70-e5ff877b6448@www.fastmail.com>
Content-Type: multipart/mixed;
 boundary="------------700A927E2CAA82830FB56622"
Content-Language: en-US
Archived-At: 
 <https://www.postgresql.org/message-id/70bbfaac-74dd-de9a-b086-8bf43224e1c0%40enterprisedb.com>
Precedence: bulk

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


On 3/19/21 3:17 PM, Euler Taveira wrote:
> On Fri, Mar 19, 2021, at 12:23 AM, Tom Lane wrote:
>> [ reads code... ]
>> ... no, I think the problem is the test is still full of race conditions.
>>
>> In the first place, waiting till you see the output of a SELECT that's
>> before the useful query is not enough to guarantee that the useful query
>> is done, or even started.  That's broken on both sessions.
> That's an ugly and fragile mechanism to workaround the fact that pump_until
> reacts after you have the query return.
> 
>> In the second place, even if the second INSERT has started, you don't know
>> that it's reached the point of blocking on the tuple conflict yet.
>> Which in turn means that it might not've filled its tuplestore yet.
>>
>> In short, this script is designed to ensure that the test query can't
>> finish too soon, but that proves nothing about whether the test query
>> has even started.  And since you also haven't really guaranteed that the
>> intended-to-be-blocking query is done, I don't think that the first
>> condition really holds either.
> In order to avoid the race condition between filling the tuplestore and
> killing
> the backend, we could use a pool_query_until() before SIGKILL to wait the
> temporary file being created. Do you think this modification will make this
> test more stable?
> 

Wow, I thought I understand the perl code, but clearly I was wrong.

I think the solution is not particularly difficult.

For the initial insert, it's fine to switch the order of the SQL
commands, so that the insert happens first, and only then emit the string.

For the second insert, we can't do that, because it's expected to block
on the lock. So we have to verify that by looking at the lock directly.

I however don't understand what the pump_until function does. AFAICS it
should run the query in a loop, and bail out once it matches the
expected output. But that does not seem to happen, so when the query
gets executed before the lock is there, it results in infinite loop.

In the attached patch I've simulated this by random() < 0.5.

If I replace this with a wait loop in a plpgsql block, that works
perfectly fine (no infinite loops). Tested both on x86_64 and rpi.


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

--------------700A927E2CAA82830FB56622
Content-Type: text/x-patch; charset=UTF-8;
 name="cleanup-tap.patch"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="cleanup-tap.patch"

diff --git a/src/test/recovery/t/022_crash_temp_files.pl b/src/test/recovery/t/022_crash_temp_files.pl
index 8044849b73..88478d44c1 100644
--- a/src/test/recovery/t/022_crash_temp_files.pl
+++ b/src/test/recovery/t/022_crash_temp_files.pl
@@ -79,8 +79,8 @@ my $killme2 = IPC::Run::start(
 # Insert one tuple and leave the transaction open
 $killme_stdin2 .= q[
 BEGIN;
-SELECT $$insert-tuple-to-lock-next-insert$$;
 INSERT INTO tab_crash (a) VALUES(1);
+SELECT $$insert-tuple-to-lock-next-insert$$;
 ];
 pump_until($killme2, \$killme_stdout2, qr/insert-tuple-to-lock-next-insert/m);
 $killme_stdout2 = '';
@@ -100,6 +100,15 @@ ok(pump_until($killme, \$killme_stdout, qr/in-progress-before-sigkill/m),
 $killme_stdout = '';
 $killme_stderr = '';
 
+# Wait until the batch insert gets stuck on the lock.
+$killme_stdin2 .= q[
+SELECT $$insert-tuple-lock-waiting$$ FROM pg_locks WHERE pid = ] . $pid . q[ AND NOT granted AND random() < 0.5;
+];
+
+pump_until($killme2, \$killme_stdout2, qr/insert-tuple-lock-waiting/m);
+$killme_stdout2 = '';
+$killme_stderr2 = '';
+
 # Kill with SIGKILL
 my $ret = TestLib::system_log('pg_ctl', 'kill', 'KILL', $pid);
 is($ret, 0, 'killed process with KILL');
@@ -147,8 +156,8 @@ $killme2->run();
 # Insert one tuple and leave the transaction open
 $killme_stdin2 .= q[
 BEGIN;
-SELECT $$insert-tuple-to-lock-next-insert$$;
 INSERT INTO tab_crash (a) VALUES(1);
+SELECT $$insert-tuple-to-lock-next-insert$$;
 ];
 pump_until($killme2, \$killme_stdout2, qr/insert-tuple-to-lock-next-insert/m);
 $killme_stdout2 = '';
@@ -168,6 +177,15 @@ ok(pump_until($killme, \$killme_stdout, qr/in-progress-before-sigkill/m),
 $killme_stdout = '';
 $killme_stderr = '';
 
+# Wait until the batch insert gets stuck on the lock.
+$killme_stdin2 .= q[
+SELECT $$insert-tuple-lock-waiting$$ FROM pg_locks WHERE pid = ] . $pid . q[ AND NOT granted AND random() < 0.5;
+];
+
+pump_until($killme2, \$killme_stdout2, qr/insert-tuple-lock-waiting/m);
+$killme_stdout2 = '';
+$killme_stderr2 = '';
+
 # Kill with SIGKILL
 $ret = TestLib::system_log('pg_ctl', 'kill', 'KILL', $pid);
 is($ret, 0, 'killed process with KILL');

--------------700A927E2CAA82830FB56622--