Subject: FailedAssertion("prev_first_lsn < cur_txn->first_lsn", File: "reorderbuffer.c", Line: 1173, ...

From: Thomas Munro <[email-masked]>
Date: Sun, 13 Feb 2022 12:57:28 +1300

Hi,

I don't know what happened here, but I my little script that scrapes
for build farm assertion failures hasn't seen this one before now.
It's on a 15 year old macOS release and compiled with 15 year old GCC
version, for some added mystery.

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=locust&dt=2022-02-12%2022%3A07%3A21

2022-02-13 00:09:52.859 CET [92423:92] pg_regress/replorigin
STATEMENT:  SELECT data FROM
pg_logical_slot_get_changes('regression_slot', NULL, NULL,
'include-xids', '0', 'skip-empty-xacts', '1', 'include-sequences',
'0');
TRAP: FailedAssertion("prev_first_lsn < cur_txn->first_lsn", File:
"reorderbuffer.c", Line: 1173, PID: 92423)
0   postgres                            0x00592dd0 ExceptionalCondition + 160\\0
1   postgres                            0x00391c40
ReorderBufferGetRelids + 304\\0
2   postgres                            0x00394794
ReorderBufferAllocate + 1044\\0
3   postgres                            0x003834dc heap_decode + 76\\0
4   postgres                            0x003829c8
LogicalDecodingProcessRecord + 168\\0
5   postgres                            0x0038a1d4
pg_logical_emit_message_text + 1876\\0
6   postgres                            0x00241810
ExecMakeTableFunctionResult + 576\\0
7   postgres                            0x002576c4
ExecInitFunctionScan + 1444\\0
8   postgres                            0x00242140 ExecScan + 896\\0
9   postgres                            0x002397cc standard_ExecutorRun + 540\\0
10  postgres                            0x00427940
EnsurePortalSnapshotExists + 832\\0
11  postgres                            0x00428e84 PortalRun + 644\\0
12  postgres                            0x004252e0 pg_plan_queries + 3232\\0
13  postgres                            0x00426270 PostgresMain + 3424\\0
14  postgres                            0x0036b9ec PostmasterMain + 8060\\0
15  postgres                            0x0029f24c main + 1356\\0
16  postgres                            0x00002524 start + 68\\0

---

From: Andres Freund <[email-masked]>
Date: Sat, 12 Feb 2022 16:28:42 -0800

Hi, 

>16  postgres                            0x00002524 start + 68\\0

I think that may be the bug that Tomas fixed a short while ago. He said the skip empty xacts stuff didn't yet work for sequences. That's only likely to be hit in slower machines...

Andres
-- 
Sent from my Android device with K-9 Mail. Please excuse my brevity.

---

From: Tomas Vondra <[email-masked]>
Date: Sun, 13 Feb 2022 13:27:08 +0100

On 2/13/22 01:28, Andres Freund wrote:
> I think that may be the bug that Tomas fixed a short while ago. He
> said the skip empty xacts stuff didn't yet work for sequences. That's
> only likely to be hit in slower machines...
> 

I'm not sure how could this be related to the issue fixed by b779d7d8fd.
That's merely about handling of empty xacts in the output plugin, it has
little (nothing) to do with reorderbuffer - the failures was simply
about (not) printing BEGIN/COMMIT for empty xacts.

So why would it be triggering an Assert in reorderbuffer? Also, there
was a successful run with the test_decoding changes 80901b3291 (and also
with sequence decoding infrastructure committed a couple days ago) ...

Do we have access to the machine? If yes, it'd be interesting to run the
tests before the fix, and see how often it fails. Also, printing the LSN
would be interesting, so that we can correlate it to WAL.

BTW it's probably just a coincidence, but the cfbot does show a strange
failure on the macOS machine [1], as if we did not wait for all changes
to be applied by replica. I thought it's because of the issue with
tracking LSN for sequences [2], but this is with a reworked test that
does not do just nextval(). So I'm wondering if these two things may be
related ... both things happened on macOS only.

[1] https://cirrus-ci.com/task/6299472241098752

[2]
https://www.postgresql.org/message-id/712cad46-a9c8-1389-aef8-faf0203c9be9%40enterprisedb.com

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

---

From: Tomas Vondra <[email-masked]>
Date: Sun, 13 Feb 2022 14:11:36 +0100

On 2/13/22 13:27, Tomas Vondra wrote:
> ...

I take this back - this failure was just a thinko in the ROLLBACK test,
I've posted an updated patch fixing this.

regards