Subject: Re: Unstable tests for recovery conflict handling

From: Mark Dilger <[email-masked]>
Date: Wed, 27 Apr 2022 10:11:53 -0700

> On Apr 27, 2022, at 9:45 AM, Tom Lane <[email-masked]> wrote:
> 
> [ starting a new thread cuz the shared-stats one is way too long ]
> 
> Andres Freund <[email-masked]> writes:
>> Add minimal tests for recovery conflict handling.
> 
> It's been kind of hidden by other buildfarm noise, but
> 031_recovery_conflict.pl is not as stable as it should be [1][2][3][4].
> 
> Three of those failures look like

Interesting,

I have been getting failures on REL_14_STABLE:

t/012_subtransactions.pl ............. 11/12                                                            
#   Failed test 'Rollback of PGPROC_MAX_CACHED_SUBXIDS+ prepared transaction on promoted standby'
#   at t/012_subtransactions.pl line 211.
#          got: '3'
#     expected: '0'
t/012_subtransactions.pl ............. 12/12 # Looks like you failed 1 test of 12.
t/012_subtransactions.pl ............. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/12 subtests 

And the logs, tmp_check/log/regress_log_012_subtransactions, showing:

### Enabling streaming replication for node "primary"
### Starting node "primary"
# Running: pg_ctl -D /Users/mark.dilger/recovery_test/postgresql/src/test/recovery/tmp_check/t_012_subtransactions_primary_data/pgdata -l /Users/mark.dilger/recovery_test/postgresql/src/test/recovery/tmp_check/log/012_subtransactions_primary.log -o --cluster-name=primary start
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 46270
psql:<stdin>:1: ERROR:  prepared transaction with identifier "xact_012_1" does not exist
not ok 11 - Rollback of PGPROC_MAX_CACHED_SUBXIDS+ prepared transaction on promoted standby

#   Failed test 'Rollback of PGPROC_MAX_CACHED_SUBXIDS+ prepared transaction on promoted standby'
#   at t/012_subtransactions.pl line 211.
#          got: '3'
#     expected: '0'

This is quite consistent for me, but only when I configure with --enable-coverage and --enable-dtrace.  (I haven't yet tried one of those without the other.)

I wasn't going to report this yet, having not yet completely narrowed this down, but I wonder if anybody else is seeing this?

I'll try again on master....

—
Mark Dilger
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

---

From: Mark Dilger <[email-masked]>
Date: Wed, 27 Apr 2022 10:50:06 -0700

> On Apr 27, 2022, at 10:11 AM, Mark Dilger <[email-masked]> wrote:
> 

Still with coverage and dtrace enabled, I get the same thing, except that master formats the logs a bit differently:

# Postmaster PID for node "primary" is 19797
psql:<stdin>:1: ERROR:  prepared transaction with identifier "xact_012_1" does not exist
[10:26:16.314](1.215s) not ok 11 - Rollback of PGPROC_MAX_CACHED_SUBXIDS+ prepared transaction on promoted standby
[10:26:16.314](0.000s)
[10:26:16.314](0.000s) #   Failed test 'Rollback of PGPROC_MAX_CACHED_SUBXIDS+ prepared transaction on promoted standby'
[10:26:16.314](0.000s) #   at t/012_subtransactions.pl line 208.
[10:26:16.314](0.000s) #          got: '3'
#     expected: '0'

With coverage but not dtrace enabled, I still get the error, though the log leading up to the error now has a bunch of coverage noise lines like:

profiling: /Users/mark.dilger/recovery_test/postgresql/src/backend/utils/sort/tuplesort.gcda: cannot merge previous GCDA file: corrupt arc tag

The error itself looks the same except the timing numbers differ a little.

With neither enabled, all tests pass.

I'm inclined to think that either the recovery code or the test have a race condition, and that enabling coverage causes the race to come out differently.  I'll keep poking....

—
Mark Dilger

---

From: Thomas Munro <[email-masked]>
Date: Wed, 11 May 2022 17:28:15 +1200

> [10:26:16.314](0.000s) #          got: '3'

FWIW I see that on my FBSD/clang system when I build with
-fsanitize=undefined -fno-sanitize-recover=all.  It's something to do
with our stack depth detection and tricks being used by -fsanitize,
because there's a stack depth exceeded message in the log.