Date: Sat, 3 Nov 2018 13:14:19 +0100
From: Karsten Hilbert <Karsten.Hilbert@gmx.net>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Alvaro Herrera <alvherre@2ndquadrant.com>,
	pgsql-general@lists.postgresql.org
Subject: Re: backend crash on DELETE, reproducible locally
Message-ID: <20181103121419.GA3885@hermes.hilbert.loc>
References: <20181101152723.zq2dtcgntmcmr4br@alvherre.pgsql>
 <18072.1541087036@sss.pgh.pa.us>
 <20181101160007.GJ2954@hermes.hilbert.loc>
 <32192.1541217418@sss.pgh.pa.us>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <32192.1541217418@sss.pgh.pa.us>
Ma_X_il-Followup-to: d
Re_X_turn-receipt-to: Karsten.Hilbert@gmx.net
Di_X_sposition-Notification-To: Karsten.Hilbert@gmx.net
X-Confi_X_rm-Reading-To: Karsten.Hilbert@gmx.net
X-Pri_X_ority: 2 (High)
User-Agent: Mutt/1.10.1 (2018-07-13)
Sender: <karsten.hilbert@gmx.net>
X-Provags-ID: V03:K1:Jh4uUVrvQqejyfPEQO/v4P2xlwEHqfKyBQtDe9ub8+MqQifK7qR
 D56HPWtUGxetJJ8qp1itbT01ebILGuk4ZFrJ3lpayq6MF726DlBMmM49cHYcttgWh/y6SPo
 MaC4qVOoN3s5ijGHWm09VBtMljyw8l8V+lSjEASyC71ab/YNtbwWe5SHM3x745JugNMkgAw
 Wf5PztTdItTSGAlo0Ryag==
X-Spam-Flag: NO
X-UI-Out-Filterresults: notjunk:1;V01:K0:/JVwMYJaLY8=:9XwFsEsJo/N/Gqc9xgdK34
 seYshzFUtCWrGNOSQQ3FCWasFx9ay56c8iQwPYznS5tm+FNQAzM1CY81JqsOBOXa3lWKmMj+O
 9C5zKBUdq8Y4xjx4b2HRhq2uiIw+u9LxaDUVTiYUfkPLFzgIb5weHnkqn1P52KvC3aU6Qu5+B
 bDihyfluXPDVzQOQnH70UPh+GuaYJgYwHiGGTeiMR8IEY9hQrPpc8N35ZhBfmjMEqOe46Xc8+
 8ZFaZyJl78yyAjnUhi+2zKnKM0EzyAtaPOS5RSJlvJ92NA6FVb3gugE9AA5/RNUYJyGln6S24
 PepURsgnCeHt9WyOuzPG7qHbbw/un6gkEHJlR2j/I9lj0B+6VVi3jo/vib46rxE04/QxJkbmj
 4KZaQWywTZYmGi+NVuKWfOxqZjf9vaZ0/h6EWG2yltXXg8/OVY+/t06XqHHBuI+EGJYbZ5Ok8
 LAWJTNYVm9//r0AABfo+mXYr1qfsF4ZbZKhgMuR/ywXY6F4BA1wC+wpgXb6dDw02cagyOay2C
 fR2M7o9XRx4pcHbBhOdrvhk1fXzgUfeA1YADAN0xy5Qo1COHspUhpO4AuMgtgtBzAGP0VnfSg
 cXeD9zwMJiKS4PW2Vxwvq1bqg9w0EeKZE0Mllu6nY6iBrHFP8Y+AZC668XENIZWomLQF2teJi
 0wM4yecuvm6/XoQ83SPR2DEFclv+X4U16VGRx9Ho4J/xZQ1D25pf5uHmbD9+QbXZYNSs1UUxU
 ntaaOAhSgvV1zRa89FfyKt+QqBvmZCwGnYNlBsH78sGUOLWO58oBxI3lHzTW9kw/F0F7pjqud
 oudIoUN2v/q8KnYIhYY4AdQcVjoLw==
List-Id: <pgsql-general.lists.postgresql.org>
List-Help: <https://lists.postgresql.org/manage/>
List-Subscribe: <https://lists.postgresql.org/manage/>
List-Post: <mailto:pgsql-general@lists.postgresql.org>
List-Owner: <mailto:pgsql-general-owner@lists.postgresql.org>
List-Archive: <https://www.postgresql.org/list/pgsql-general>
Precedence: bulk

On Fri, Nov 02, 2018 at 11:56:58PM -0400, Tom Lane wrote:

> > On Thu, Nov 01, 2018 at 11:43:56AM -0400, Tom Lane wrote:
> >> Yeah, apparently we've passed a null OLD tuple to an RI_FKey_cascade_del
> >> trigger, which surely shouldn't happen.  It'd be interesting to look at
> >> the set of triggers on this table.  I don't entirely trust psql's \d
> >> to show us reality if there's something screwed up about the triggers,
> >> so in addition to \d output, could we see
> >> select * from pg_trigger where tgrelid  = 'ref.auto_hint'::regclass;
> 
> > [ pretty normal-looking trigger entries ]
> 
> I was feeling baffled about this, but it suddenly occurs to me that maybe
> the bug fixed in 040a1df61/372102b81 explains this.  If the particular
> tuple you're trying to delete predates the last ALTER TABLE ADD COLUMN
> operation on the table, then this bug would result in t_self getting
> set to "invalid", which'd cause AfterTriggerSaveEvent to save "ate_ctid1"
> as "invalid", which'd lead to a null tuple getting passed when the trigger
> eventually gets invoked.

Now, that is a theory I can follow up on -- all the
bootstrapping SQL scripts are under version control so I can
pin down the exact sequence of events.

... goes off to do some checks ...

And sure enough there's an ALTER TABLE ADD COLUMN related to
that table:

	alter table ref.auto_hint
		add column recommendation_query text;

	-- (audit log table needs to get the new column, too)
	alter table audit.log_auto_hint
		add column recommendation_query text;

before the DELETE of the pre-existing tuple.

When running a rigged upgrade that stops right before those
ALTER TABLEs and then doing the following:

	begin;
	-- instrument:
	insert into ref.auto_hint (title, query, hint, source, lang) values (
		'DELETE test',
		'select 1;',
		'insertion before ADD COLUMN',
		'testing',
		'en'
	);
	-- works:
	DELETE from ref.auto_hint where title = 'DELETE test';
	-- instrument, again:
	insert into ref.auto_hint (title, query, hint, source, lang) values (
		'DELETE test',
		'select 1;',
		'insertion before ADD COLUMN',
		'testing',
		'en'
	);
	alter table ref.auto_hint
		add column recommendation_query text;
	-- audit log table needs to get the message
	alter table audit.log_auto_hint
		add column recommendation_query text;
	-- fails:
	DELETE from ref.auto_hint where title = 'DELETE test';
	rollback;

the expected segfault does indeed occur.

Conversely, moving the offending

	DELETE FROM ref.auto_hint WHERE title = 'Kontraindikation: ACE/Sartan <-> Schwangerschaft';

to right before the ALTER TABLEs makes the full upgrade run
through without further problems.

Looking at 040a1df61/372102b81 feels like it fits the bill.

So, I guess I can work around the issue by the above
manoeuvre and report back once 040a1df61/372102b81 is
released.

Anything else you'd want me to look into ?

Many thanks,
Karsten
-- 
GPG  40BE 5B0E C98E 1713 AFA6  5BC0 3BEA AC80 7D4F C89B