Thread

1. Got FATAL in lock_twophase_recover() during recovery

   suyu.cmj <mengjuan.cmj@alibaba-inc.com> — 2023-07-11T02:35:15Z

   Hi, all.
   I want to report a bug about the recovery of two-phase transaction, in current implementation of crash recovery, there are two ways to recover 2pc data:
   1、before redo, func restoreTwoPhaseData() will restore 2pc data those xid < ShmemVariableCache->nextXid, which is initialized from checkPoint.nextXid;
   2、during redo, func xact_redo() will add 2pc from wal;
   The following scenario may cause the same 2pc transaction to be added repeatedly, I have attached a patch for pg11 that reproduces the error:
   1、start creating checkpoint_1, checkpoint_1.redo is set as curInsert;
   2、before set checkPoint_1.nextXid, a new 2pc is prepared, suppose the xid of this 2pc is 100, and then ShmemVariableCache->nextXid will be advanced as 101;
   3、checkPoint_1.nextXid is set as 101;
   4、in CheckPointTwoPhase() of checkpoint_1, 2pc_100 won't be copied to disk because its prepare_end_lsn > checkpoint_1.redo;
   5、checkPoint_1 is finished, after checkpoint_timeout, start creating checkpoint_2;
   6、during checkpoint_2, data of 2pc_100 will be copied to disk;
   7、before UpdateControlFile() of checkpoint_2, crash happened;
   8、during crash recovery, redo will start from checkpoint_1, and 2pc_100 will be restored first by restoreTwoPhaseData() because xid_100 < checkPoint_1.nextXid, which is 101; 
   9、because prepare_start_lsn of 2pc_100 > checkpoint_1.redo, 2pc_100 will be added again by xact_redo() during wal replay, resulting in the same 2pc data being added twice;
   10、In RecoverPreparedTransactions() -> lock_twophase_recover(), lock the same 2pc will cause FATAL.
   After running the patch that reproduced the error, you will get the following error during crash recovery:
   2023-07-10 13:04:30.670 UTC [11169] LOG: recovering prepared transaction 569 from shared memory
   2023-07-10 13:04:30.670 UTC [11169] LOG: recovering prepared transaction 569 from shared memory
   2023-07-10 13:04:30.670 UTC [11169] FATAL: lock ExclusiveLock on object 569/0/0 is already held
   2023-07-10 13:04:30.670 UTC [11168] LOG: startup process (PID 11169) exited with exit code 1
   2023-07-10 13:04:30.670 UTC [11168] LOG: aborting startup due to startup process failure
   I also added a patch for pg11 to fix this problem, hope you can check it when you have time.
   Thanks & Best Regard
   

2. Re: Got FATAL in lock_twophase_recover() during recovery

   Michael Paquier <michael@paquier.xyz> — 2023-07-11T23:41:45Z

   On Tue, Jul 11, 2023 at 10:35:15AM +0800, suyu.cmj wrote:
   > I want to report a bug about the recovery of two-phase transaction,
   > in current implementation of crash recovery, there are two ways to
   > recover 2pc data: 
   > 1、before redo, func restoreTwoPhaseData() will restore 2pc data
   > those xid < ShmemVariableCache->nextXid, which is initialized from
   > checkPoint.nextXid; 
   > 2、during redo, func xact_redo() will add 2pc from wal;
   > The following scenario may cause the same 2pc transaction to be
   > added repeatedly, I have attached a patch for pg11 that reproduces
   > the error: 
   > 1、start creating checkpoint_1, checkpoint_1.redo is set as
   > curInsert; 
   > 2、before set checkPoint_1.nextXid, a new 2pc is prepared, suppose
   > the xid of this 2pc is 100, and then ShmemVariableCache->nextXid
   > will be advanced as 101; 
   > 3、checkPoint_1.nextXid is set as 101;
   > 4、in CheckPointTwoPhase() of checkpoint_1, 2pc_100 won't be copied
   > to disk because its prepare_end_lsn > checkpoint_1.redo; 
   > 5、checkPoint_1 is finished, after checkpoint_timeout, start
   > creating checkpoint_2; 
   > 6、during checkpoint_2, data of 2pc_100 will be copied to disk;
   > 7、before UpdateControlFile() of checkpoint_2, crash happened;
   > 8、during crash recovery, redo will start from checkpoint_1, and
   > 2pc_100 will be restored first by restoreTwoPhaseData() because
   > xid_100 < checkPoint_1.nextXid, which is 101;  
   > 9、because prepare_start_lsn of 2pc_100 > checkpoint_1.redo, 2pc_100
   > will be added again by xact_redo() during wal replay, resulting in
   > the same 2pc data being added twice; 
   
   It looks like you have something here.  I'll try to look at it.  This
   is a bug, so I have removed pgsql-hackers from the CC list keeping
   only pgsql-bugs as cross-list posts are not encouraged.
   --
   Michael