Re: Windows vs recovery tests

Hi,

On 2022-01-12 20:03:14 -0800, Andres Freund wrote:
> So it looks like psql is hanging somewhere after that. I assume with an error
> popup that nobody can click on :/.

Not quite. Psql is actually just logging output in an endless loop. I
connected with cdb.exe.

kP:

00000000`007fd3c8 00007ffc`0d00f13a ntdll!NtWriteFile+0x14
00000000`007fd3d0 00007ffc`03978ec3 KERNELBASE!WriteFile+0x7a
00000000`007fd440 00007ffc`03979d21 ucrtbased!write_text_ansi_nolock(
int fh = 0n2,
char * buffer = 0x00000000`007febb0 " ???",
unsigned int buffer_size = 1)+0x183
00000000`007fe8f0 00007ffc`039798a7 ucrtbased!_write_nolock(
int fh = 0n2,
void * buffer = 0x00000000`007febb0,
unsigned int buffer_size = 1,
class __crt_cached_ptd_host * ptd = 0x00000000`007fef40)+0x451
00000000`007fea80 00007ffc`03920e1d ucrtbased!_write_internal(
int fh = 0n2,
void * buffer = 0x00000000`007febb0,
unsigned int size = 1,
class __crt_cached_ptd_host * ptd = 0x00000000`007fef40)+0x377
00000000`007feb20 00007ffc`0392090e ucrtbased!write_buffer_nolock<char>(
char c = 0n32 ' ',
class __crt_stdio_stream stream = class __crt_stdio_stream,
class __crt_cached_ptd_host * ptd = 0x00000000`007fef40)+0x27d
00000000`007febb0 00007ffc`03921242 ucrtbased!common_flush_and_write_nolock<char>(
int c = 0n32,
class __crt_stdio_stream stream = class __crt_stdio_stream,
class __crt_cached_ptd_host * ptd = 0x00000000`007fef40)+0x22e
00000000`007fec20 00007ffc`038ddf5a ucrtbased!__acrt_stdio_flush_and_write_narrow_nolock(
int c = 0n32,
struct _iobuf * stream = 0x00007ffc`03a27ce0,
class __crt_cached_ptd_host * ptd = 0x00000000`007fef40)+0x32
00000000`007fec60 00007ffc`038dd5a3 ucrtbased!_fwrite_nolock_internal(
void * buffer = 0x00000000`007ff020,
unsigned int64 element_size = 1,
unsigned int64 element_count = 7,
struct _iobuf * public_stream = 0x00007ffc`03a27ce0,
class __crt_cached_ptd_host * ptd = 0x00000000`007fef40)+0x79a
00000000`007fed60 00007ffc`038dd426 ucrtbased!<lambda_26974eb511f701c600fccfa2a97a8e1b>::operator()(void)+0x73
00000000`007fedd0 00007ffc`038dd4a8 ucrtbased!__crt_seh_guarded_call<unsigned __int64>::operator()<<lambda_a2589f19c
515cac03caf6db9c38355e9>,<lambda_26974eb511f701c600fccfa2a97a8e1b> &,<lambda_ad9ce2f38261e34e8a422b9cc35dfe8d> >(
class __acrt_lock_stream_and_call::__l2::<lambda_a2589f19c515cac03caf6db9c38355e9> * setup = 0x0
0000000`007fee58,
class _fwrite_internal::__l2::<lambda_26974eb511f701c600fccfa2a97a8e1b> * action = 0x00000000`00
7feec0,
class __acrt_lock_stream_and_call::__l2::<lambda_ad9ce2f38261e34e8a422b9cc35dfe8d> * cleanup = 0
x00000000`007fee50)+0x36
00000000`007fee10 00007ffc`038dd72d ucrtbased!__acrt_lock_stream_and_call<<lambda_26974eb511f701c600fccfa2a97a8e1b>
>(
struct _iobuf * stream = 0x00007ffc`03a27ce0,
class _fwrite_internal::__l2::<lambda_26974eb511f701c600fccfa2a97a8e1b> * action = 0x00000000`00
7feec0)+0x58
00000000`007fee70 00007ffc`038de046 ucrtbased!_fwrite_internal(
void * buffer = 0x00000000`007ff020,
unsigned int64 size = 1,
unsigned int64 count = 7,
struct _iobuf * stream = 0x00007ffc`03a27ce0,
class __crt_cached_ptd_host * ptd = 0x00000000`007fef40)+0x15d
00000000`007fef00 00000001`4004a639 ucrtbased!fwrite(
void * buffer = 0x00000000`007ff020,
unsigned int64 size = 1,
unsigned int64 count = 7,
struct _iobuf * stream = 0x00007ffc`03a27ce0)+0x56
00000000`007fef90 00000001`4004a165 psql!flushbuffer(
struct PrintfTarget * target = 0x00000000`007feff8)+0x59
00000000`007fefd0 00000001`4004a1e6 psql!pg_vfprintf(
struct _iobuf * stream = 0x00007ffc`03a27ce0,
char * fmt = 0x00000001`40094268 "error: ",
char * args = 0x00000000`007ff4a0 "@???")+0xa5
00000000`007ff450 00000001`40045962 psql!pg_fprintf(
struct _iobuf * stream = 0x00007ffc`03a27ce0,
char * fmt = 0x00000001`40094268 "error: ")+0x36
00000000`007ff490 00000001`40045644 psql!pg_log_generic_v(
pg_log_level level = PG_LOG_ERROR (0n4),
char * fmt = 0x00000001`40062e90 "unexpected PQresultStatus: %d",
char * ap = 0x00000000`007ff540 "???")+0x302
00000000`007ff4f0 00000001`4000ef1f psql!pg_log_generic(
pg_log_level level = PG_LOG_ERROR (0n4),
char * fmt = 0x00000001`40062e90 "unexpected PQresultStatus: %d")+0x34
00000000`007ff530 00000001`4000e794 psql!AcceptResult(
struct pg_result * result = 0x00000000`0015af90,
bool show_error = false)+0x9f
00000000`007ff580 00000001`4000c8fe psql!SendQueryAndProcessResults(
char * query = 0x00000000`00107570 "START_REPLICATION 0/0",
double * pelapsed_msec = 0x00000000`007ff718,
bool is_watch = false,
struct printQueryOpt * opt = 0x00000000`00000000,
struct _iobuf * printQueryFout = 0x00000000`00000000,
bool * tx_ended = 0x00000000`007ff6b3)+0x1a4
00000000`007ff680 00000001`40024104 psql!SendQuery(
char * query = 0x00000000`00107570 "START_REPLICATION 0/0")+0x42e
00000000`007ff750 00000001`40001524 psql!MainLoop(
struct _iobuf * source = 0x00007ffc`03a27c30)+0xf84
00000000`007ff890 00000001`40032903 psql!process_file(
char * filename = 0x00000001`400618e0 "<stdin>",
bool use_relative_path = false)+0x274
00000000`007ffcf0 00000001`400503f9 psql!main(
int argc = 0n8,
char ** argv = 0x00000000`0012a750)+0xc43
00000000`007ffe10 00000001`4005034e psql!invoke_main(void)+0x39
00000000`007ffe60 00000001`4005020e psql!__scrt_common_main_seh(void)+0x12e
00000000`007ffed0 00000001`4005046e psql!__scrt_common_main(void)+0xe
00000000`007fff00 00007ffc`0d2a7974 psql!mainCRTStartup(
void * __formal = 0x00000000`002e6000)+0xe
00000000`007fff30 00007ffc`0fe1a2f1 KERNEL32!BaseThreadInitThunk+0x14
00000000`007fff60 00000000`00000000 ntdll!RtlUserThreadStart+0x21

bp psql!pg_log_generic

0:000> k3
Child-SP RetAddr Call Site
00000000`007ff528 00000001`4000ef1f psql!pg_log_generic [C:\cirrus\src\common\logging.c @ 198]
00000000`007ff530 00000001`4000e794 psql!AcceptResult+0x9f [C:\cirrus\src\bin\psql\common.c @ 385]
00000000`007ff580 00000001`4000c8fe psql!SendQueryAndProcessResults+0x1a4 [C:\cirrus\src\bin\psql\common.c @ 1163]
0:000> g
Breakpoint 0 hit
psql!pg_log_generic:
00000001`40045610 4889542410 mov qword ptr [rsp+10h],rdx ss:00000000`007ff538=0000000100000006
0:000> k3
Child-SP RetAddr Call Site
00000000`007ff528 00000001`4000ef1f psql!pg_log_generic [C:\cirrus\src\common\logging.c @ 198]
00000000`007ff530 00000001`4000e794 psql!AcceptResult+0x9f [C:\cirrus\src\bin\psql\common.c @ 385]
00000000`007ff580 00000001`4000c8fe psql!SendQueryAndProcessResults+0x1a4 [C:\cirrus\src\bin\psql\common.c @ 1163]

Ah, I see the bug. It's a use-after-free introduced in the patch:

SendQueryAndProcessResults(const char *query, double *pelapsed_msec,
bool is_watch, const printQueryOpt *opt, FILE *printQueryFout, bool *tx_ended)

...
/* first result */
result = PQgetResult(pset.db);

while (result != NULL)

...
if (!AcceptResult(result, false))
{
...
ClearOrSaveResult(result);
success = false;

/* and switch to next result */
result_status = PQresultStatus(result);
if (result_status == PGRES_COPY_BOTH ||
result_status == PGRES_COPY_OUT ||
result_status == PGRES_COPY_IN)

So we called ClearOrSaveResult() with did a PQclear(), and then we go and call
PQresultStatus().

So this really is unrelated to CI. I'll mention this message in the other
thread.

Greetings,

Andres Freund