Backup command and functions can cause assertion failure and segmentation fault

At Thu, 30 Jun 2022 12:28:43 +0900, Fujii Masao <masao.fujii@oss.nttdata.com> wrote in

The root cause of these failures seems that sessionBackupState flag
is not reset to SESSION_BACKUP_NONE even when BASE_BACKUP is aborted.
So attached patch changes do_pg_abort_backup callback so that
it resets sessionBackupState. I confirmed that, with the patch,
those assertion failure and segmentation fault didn't happen.

But this change has one issue that; if BASE_BACKUP is run while
a backup is already in progress in the session by pg_backup_start()
and that session is terminated, the change causes
XLogCtl->Insert.runningBackups
to be decremented incorrectly. That is, XLogCtl->Insert.runningBackups
is incremented by two by pg_backup_start() and BASE_BACKUP,
but it's decremented only by one by the termination of the session.

To address this issue, I think that we should disallow BASE_BACKUP
to run while a backup is already in progress in the *same* session
as we already do this for pg_backup_start(). Thought? I included
the code to disallow that in the attached patch.

It seems like to me that the root cause is the callback is registered
twice. The callback does not expect to be called more than once (at
least per one increment of runningBackups).

register_persistent_abort_backup_hanedler() prevents duplicate
regsitration of the callback so I think perform_base_backup should use
this function instead of protecting by the PG_*_ERROR_CLEANUP()
section.

Please find the attached.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

At Fri, 01 Jul 2022 11:46:53 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in

Please find the attached.

Mmm. It forgot the duplicate-call prevention and query-cancel
handling... The first one is the same as you posted but the second one
is still a problem..

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

At Fri, 01 Jul 2022 11:56:14 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in

At Fri, 01 Jul 2022 11:46:53 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in

Please find the attached.

Mmm. It forgot the duplicate-call prevention and query-cancel
handling... The first one is the same as you posted but the second one
is still a problem..

So this is the first cut of that.

regards.

--
Kyotaro Horiguchi
NTT Open Source Software Center

On 2022/07/01 12:05, Kyotaro Horiguchi wrote:

At Fri, 01 Jul 2022 11:56:14 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in

At Fri, 01 Jul 2022 11:46:53 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in

Please find the attached.

Mmm. It forgot the duplicate-call prevention and query-cancel
handling... The first one is the same as you posted but the second one
is still a problem..

So this is the first cut of that.

Thanks for reviewing the patch!

+	PG_FINALLY();
+	{
  		endptr = do_pg_backup_stop(labelfile->data, !opt->nowait, &endtli);
  	}
-	PG_END_ENSURE_ERROR_CLEANUP(do_pg_abort_backup, BoolGetDatum(false));
-
+	PG_END_TRY();

This change makes perform_base_backup() call do_pg_backup_stop() even when an error is reported while taking a backup, i.e., between PG_TRY() and PG_FINALLY(). Why do_pg_backup_stop() needs to be called in such an error case? It not only cleans up the backup state but also writes the backup-end WAL record, waits for WAL archiving. In an error case, I think that only the cleanup of the backup state is necessary. So it seems ok to use do_pg_abort_backup() in that case, as it is for now.

So I'm still thinking that the patch I posted is simpler and enough.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

Hi,

On Thu, Jun 30, 2022 at 12:29 PM Fujii Masao
<masao.fujii@oss.nttdata.com> wrote:

Hi,

I found that the assertion failure and the segmentation fault could
happen by running pg_backup_start(), pg_backup_stop() and BASE_BACKUP
replication command, in v15 or before.

Here is the procedure to reproduce the assertion failure.

1. Connect to the server as the REPLICATION user who is granted
EXECUTE to run pg_backup_start() and pg_backup_stop().

$ psql
=# CREATE ROLE foo REPLICATION LOGIN;
=# GRANT EXECUTE ON FUNCTION pg_backup_start TO foo;
=# GRANT EXECUTE ON FUNCTION pg_backup_stop TO foo;
=# \q

$ psql "replication=database user=foo dbname=postgres"

2. Run pg_backup_start() and pg_backup_stop().

=> SELECT pg_backup_start('test', true);
=> SELECT pg_backup_stop();

3. Run BASE_BACKUP replication command with smaller MAX_RATE so that
it can take a long time to finish.

=> BASE_BACKUP (CHECKPOINT 'fast', MAX_RATE 32);

4. Terminate the replication connection while it's running BASE_BACKUP.

$ psql
=# SELECT pg_terminate_backend(pid) FROM pg_stat_activity WHERE backend_type = 'walsender';

This procedure can cause the following assertion failure.

TRAP: FailedAssertion("XLogCtl->Insert.runningBackups > 0", File: "xlog.c", Line: 8779, PID: 69434)
0 postgres 0x000000010ab2ff7f ExceptionalCondition + 223
1 postgres 0x000000010a455126 do_pg_abort_backup + 102
2 postgres 0x000000010a8e13aa shmem_exit + 218
3 postgres 0x000000010a8e11ed proc_exit_prepare + 125
4 postgres 0x000000010a8e10f3 proc_exit + 19
5 postgres 0x000000010ab3171c errfinish + 1100
6 postgres 0x000000010a91fa80 ProcessInterrupts + 1376
7 postgres 0x000000010a886907 throttle + 359
8 postgres 0x000000010a88675d bbsink_throttle_archive_contents + 29
9 postgres 0x000000010a885aca bbsink_archive_contents + 154
10 postgres 0x000000010a885a2a bbsink_forward_archive_contents + 218
11 postgres 0x000000010a884a99 bbsink_progress_archive_contents + 89
12 postgres 0x000000010a881aba bbsink_archive_contents + 154
13 postgres 0x000000010a881598 sendFile + 1816
14 postgres 0x000000010a8806c5 sendDir + 3573
15 postgres 0x000000010a8805d9 sendDir + 3337
16 postgres 0x000000010a87e262 perform_base_backup + 1250
17 postgres 0x000000010a87c734 SendBaseBackup + 500
18 postgres 0x000000010a89a7f8 exec_replication_command + 1144
19 postgres 0x000000010a92319a PostgresMain + 2154
20 postgres 0x000000010a82b702 BackendRun + 50
21 postgres 0x000000010a82acfc BackendStartup + 524
22 postgres 0x000000010a829b2c ServerLoop + 716
23 postgres 0x000000010a827416 PostmasterMain + 6470
24 postgres 0x000000010a703e19 main + 809
25 libdyld.dylib 0x00007fff2072ff3d start + 1

Here is the procedure to reproduce the segmentation fault.

1. Connect to the server as the REPLICATION user who is granted
EXECUTE to run pg_backup_stop().

$ psql
=# CREATE ROLE foo REPLICATION LOGIN;
=# GRANT EXECUTE ON FUNCTION pg_backup_stop TO foo;
=# \q

$ psql "replication=database user=foo dbname=postgres"

2. Run BASE_BACKUP replication command with smaller MAX_RATE so that
it can take a long time to finish.

=> BASE_BACKUP (CHECKPOINT 'fast', MAX_RATE 32);

3. Press Ctrl-C to cancel BASE_BACKUP while it's running.

4. Run pg_backup_stop().

=> SELECT pg_backup_stop();

This procedure can cause the following segmentation fault.

LOG: server process (PID 69449) was terminated by signal 11: Segmentation fault: 11
DETAIL: Failed process was running: SELECT pg_backup_stop();

The root cause of these failures seems that sessionBackupState flag
is not reset to SESSION_BACKUP_NONE even when BASE_BACKUP is aborted.
So attached patch changes do_pg_abort_backup callback so that
it resets sessionBackupState. I confirmed that, with the patch,
those assertion failure and segmentation fault didn't happen.

The change looks good to me. I've also confirmed the change fixed the issues.

But this change has one issue that; if BASE_BACKUP is run while
a backup is already in progress in the session by pg_backup_start()
and that session is terminated, the change causes XLogCtl->Insert.runningBackups
to be decremented incorrectly. That is, XLogCtl->Insert.runningBackups
is incremented by two by pg_backup_start() and BASE_BACKUP,
but it's decremented only by one by the termination of the session.

To address this issue, I think that we should disallow BASE_BACKUP
to run while a backup is already in progress in the *same* session
as we already do this for pg_backup_start(). Thought? I included
the code to disallow that in the attached patch.

+1

@@ -233,6 +233,12 @@ perform_base_backup(basebackup_options *opt, bbsink *sink)
    StringInfo  labelfile;
    StringInfo  tblspc_map_file;
    backup_manifest_info manifest;
+   SessionBackupState status = get_backup_status();
+
+   if (status == SESSION_BACKUP_RUNNING)
+       ereport(ERROR,
+               (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
+                errmsg("a backup is already in progress in this session")));

I think we can move it to the beginning of SendBaseBackup() so we can
avoid bbsink initialization and cleanup in the error case.

Regards,

--
Masahiko Sawada
EDB: https://www.enterprisedb.com/

On 2022/07/01 15:09, Masahiko Sawada wrote:

The change looks good to me. I've also confirmed the change fixed the issues.

Thanks for the review and test!

@@ -233,6 +233,12 @@ perform_base_backup(basebackup_options *opt, bbsink *sink)
StringInfo  labelfile;
StringInfo  tblspc_map_file;
backup_manifest_info manifest;
+   SessionBackupState status = get_backup_status();
+
+   if (status == SESSION_BACKUP_RUNNING)
+       ereport(ERROR,
+               (errcode(ERRCODE_OBJECT_NOT_IN_PREREQUISITE_STATE),
+                errmsg("a backup is already in progress in this session")));

I think we can move it to the beginning of SendBaseBackup() so we can
avoid bbsink initialization and cleanup in the error case.

Sounds good idea to me. I updated the patch in that way. Attached.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On Fri, Jul 01, 2022 at 03:32:50PM +0900, Fujii Masao wrote:

Sounds good idea to me. I updated the patch in that way. Attached.

Skimming quickly through the thread, this failure requires a
termination of a backend running BASE_BACKUP. This is basically
something done by the TAP test added in 0475a97f with a WAL sender
killed, and MAX_RATE being used to make sure that we have enough time
to kill the WAL sender even on fast machines. So you could add a
regression test, no?
--
Michael

On 2022/07/01 15:41, Michael Paquier wrote:

On Fri, Jul 01, 2022 at 03:32:50PM +0900, Fujii Masao wrote:

Sounds good idea to me. I updated the patch in that way. Attached.

Skimming quickly through the thread, this failure requires a
termination of a backend running BASE_BACKUP. This is basically
something done by the TAP test added in 0475a97f with a WAL sender
killed, and MAX_RATE being used to make sure that we have enough time
to kill the WAL sender even on fast machines. So you could add a
regression test, no?

For the test, BASE_BACKUP needs to be canceled after it finishes do_pg_backup_start(), i.e., checkpointing, and before it calls do_pg_backup_stop(). So the timing to cancel that seems more severe than the test added in 0475a97f. I'm afraid that some tests can easily cancel the BASE_BACKUP while it's performing a checkpoint in do_pg_backup_start(). So for now I'm thinking to avoid such an unstable test.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On Wed, Jul 06, 2022 at 11:27:58PM +0900, Fujii Masao wrote:

For the test, BASE_BACKUP needs to be canceled after it finishes
do_pg_backup_start(), i.e., checkpointing, and before it calls
do_pg_backup_stop(). So the timing to cancel that seems more severe
than the test added in 0475a97f. I'm afraid that some tests can
easily cancel the BASE_BACKUP while it's performing a checkpoint in
do_pg_backup_start(). So for now I'm thinking to avoid such an
unstable test.

Hmm. In order to make sure that the checkpoint of the base backup is
completed, and assuming that the checkpoint is fast while the base
backup has a max rate, you could rely on a query that does a
poll_query_until() on pg_control_checkpoint(), no? As long as you use
IPC::Run::start, pg_basebackup would be async so the polling query and
the cancellation can be done in parallel of it. 0475a97 did almost
that, except that it waits for the WAL sender to be started.
--
Michael

On 2022/07/07 9:09, Michael Paquier wrote:

On Wed, Jul 06, 2022 at 11:27:58PM +0900, Fujii Masao wrote:

For the test, BASE_BACKUP needs to be canceled after it finishes
do_pg_backup_start(), i.e., checkpointing, and before it calls
do_pg_backup_stop(). So the timing to cancel that seems more severe
than the test added in 0475a97f. I'm afraid that some tests can
easily cancel the BASE_BACKUP while it's performing a checkpoint in
do_pg_backup_start(). So for now I'm thinking to avoid such an
unstable test.

Hmm. In order to make sure that the checkpoint of the base backup is
completed, and assuming that the checkpoint is fast while the base
backup has a max rate, you could rely on a query that does a
poll_query_until() on pg_control_checkpoint(), no? As long as you use
IPC::Run::start, pg_basebackup would be async so the polling query and
the cancellation can be done in parallel of it. 0475a97 did almost
that, except that it waits for the WAL sender to be started.

There seems to be some corner cases where we cannot rely on that.

If "spread" checkpoint is already running when BASE_BACKUP is executed, poll_query_until() may report the end of that "spread" checkpoint before BASE_BACKUP internally starts its checkpoint. Which may cause the test to fail.

If BASE_BACKUP is accidentally canceled after poll_query_until() reports the end of checkpoint but before do_pg_backup_start() finishes (i.e., before entering the error cleanup block using do_pg_abort_backup callback), the test may fail.

Probably we may be able to decrease the risk of those test failures by using some techniques, e.g., adding the fixed wait time before requesting the cancel. But I'm not sure if it's worth adding the test for the corner case issue that I reported at the risk of adding the unstable test. The issue could happen only when both BASE_BACKUP and low level API for backup are eecuted via logical replication walsender mode, and BASE_BACKUP is canceled or terminated.

But if many think that it's worth adding the test, I will give a try. But even in that case, I think it's better to commit the proposed patch at first to fix the bug, and then to write the patch adding the test.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On Thu, Jul 7, 2022 at 10:58 AM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:

But if many think that it's worth adding the test, I will give a try. But even in that case, I think it's better to commit the proposed patch at first to fix the bug, and then to write the patch adding the test.

I don't think that we necessarily need to have a test for this patch.
It's true that we don't really have good test coverage of write-ahead
logging and recovery, but this doesn't seem like the most important
thing to be testing in that area, either, and developing stable tests
for stuff like this can be a lot of work.

I do kind of feel like the patch is fixing two separate bugs. The
change to SendBaseBackup() is fixing the problem that, because there's
SQL access on replication connections, we could try to start a backup
in the middle of another backup by mixing and matching the two
different methods of doing backups. The change to do_pg_abort_backup()
is fixing the fact that, after aborting a base backup, we don't reset
the session state properly so that another backup can be tried
afterwards.

I don't know if it's worth committing them separately - they are very
small fixes. But it would probably at least be good to highlight in
the commit message that there are two different issues.

--
Robert Haas
EDB: http://www.enterprisedb.com

On Fri, Jul 08, 2022 at 08:56:14AM -0400, Robert Haas wrote:

On Thu, Jul 7, 2022 at 10:58 AM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:

But if many think that it's worth adding the test, I will give a
try. But even in that case, I think it's better to commit the
proposed patch at first to fix the bug, and then to write the patch
adding the test.

I have looked at that in details, and it is possible to rely on
pg_stat_activity.wait_event to be BaseBackupThrottle, which would make
sure that the checkpoint triggered at the beginning of the backup
finishes and that we are in the middle of the base backup. The
command for the test should be a psql command with two -c switches
without ON_ERROR_STOP, so as the second pg_backup_stop() starts after
BASE_BACKUP is cancelled using the same connection, for something like
that:
psql -c "BASE_BACKUP (CHECKPOINT 'fast', MAX_RATE 32);" \
-c "select pg_backup_stop()" "replication=database"

The last part of the test should do a pump_until() and capture "backup
is not in progress" from the stderr output of the command run.

This is leading me to the attached, that crashes quickly without the
fix and passes with the fix.

It's true that we don't really have good test coverage of write-ahead
logging and recovery, but this doesn't seem like the most important
thing to be testing in that area, either, and developing stable tests
for stuff like this can be a lot of work.

Well, stability does not seem like a problem to me here.

I do kind of feel like the patch is fixing two separate bugs. The
change to SendBaseBackup() is fixing the problem that, because there's
SQL access on replication connections, we could try to start a backup
in the middle of another backup by mixing and matching the two
different methods of doing backups. The change to do_pg_abort_backup()
is fixing the fact that, after aborting a base backup, we don't reset
the session state properly so that another backup can be tried
afterwards.

I don't know if it's worth committing them separately - they are very
small fixes. But it would probably at least be good to highlight in
the commit message that there are two different issues.

Grouping both fixes in the same commit sounds fine by me. No
objections from here.
--
Michael

On 2022/07/14 17:00, Michael Paquier wrote:

On Fri, Jul 08, 2022 at 08:56:14AM -0400, Robert Haas wrote:

On Thu, Jul 7, 2022 at 10:58 AM Fujii Masao <masao.fujii@oss.nttdata.com> wrote:

But if many think that it's worth adding the test, I will give a
try. But even in that case, I think it's better to commit the
proposed patch at first to fix the bug, and then to write the patch
adding the test.

I have looked at that in details,

Thanks!

and it is possible to rely on

pg_stat_activity.wait_event to be BaseBackupThrottle, which would make

ISTM that you can also use pg_stat_progress_basebackup.phase.

sure that the checkpoint triggered at the beginning of the backup
finishes and that we are in the middle of the base backup. The
command for the test should be a psql command with two -c switches
without ON_ERROR_STOP, so as the second pg_backup_stop() starts after
BASE_BACKUP is cancelled using the same connection, for something like
that:
psql -c "BASE_BACKUP (CHECKPOINT 'fast', MAX_RATE 32);" \
-c "select pg_backup_stop()" "replication=database"

The last part of the test should do a pump_until() and capture "backup
is not in progress" from the stderr output of the command run.

This is leading me to the attached, that crashes quickly without the
fix and passes with the fix.

Thanks for the patch! But I'm still not sure if it's worth adding only this test for the corner case while we don't have basic tests for BASE_BACKUP, pg_backup_start and pg_backup_stop.

BTW, if we decide to add that test, are you planning to back-patch it?

It's true that we don't really have good test coverage of write-ahead
logging and recovery, but this doesn't seem like the most important
thing to be testing in that area, either, and developing stable tests
for stuff like this can be a lot of work.

Well, stability does not seem like a problem to me here.

I do kind of feel like the patch is fixing two separate bugs. The
change to SendBaseBackup() is fixing the problem that, because there's
SQL access on replication connections, we could try to start a backup
in the middle of another backup by mixing and matching the two
different methods of doing backups. The change to do_pg_abort_backup()
is fixing the fact that, after aborting a base backup, we don't reset
the session state properly so that another backup can be tried
afterwards.

I don't know if it's worth committing them separately - they are very
small fixes. But it would probably at least be good to highlight in
the commit message that there are two different issues.

Grouping both fixes in the same commit sounds fine by me. No
objections from here.

This sounds fine to me, too. On the other hand, it's also fine for me to push the changes separately so that we can easily identify each change later. So I separated the patch into two ones.

Since one of them failed to be applied to v14 or before cleanly, I also created the patch for those back branches. So I attached three patches.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On Fri, Jul 15, 2022 at 04:46:32PM +0900, Fujii Masao wrote:

On 2022/07/14 17:00, Michael Paquier wrote:

and it is possible to rely on
pg_stat_activity.wait_event to be BaseBackupThrottle, which would make

ISTM that you can also use pg_stat_progress_basebackup.phase.

Indeed, as of "streaming database files". That should work.

Thanks for the patch! But I'm still not sure if it's worth adding
only this test for the corner case while we don't have basic tests
for BASE_BACKUP, pg_backup_start and pg_backup_stop.

BTW, if we decide to add that test, are you planning to back-patch it?

I was thinking about doing that only on HEAD. One thing interesting
about this patch is that it can also be used as a point of reference
for other future things.

This sounds fine to me, too. On the other hand, it's also fine for
me to push the changes separately so that we can easily identify
each change later. So I separated the patch into two ones.

Since one of them failed to be applied to v14 or before cleanly, I
also created the patch for those back branches. So I attached three
patches.

Fine by me.
--
Michael

On 2022/07/16 11:36, Michael Paquier wrote:

I was thinking about doing that only on HEAD. One thing interesting
about this patch is that it can also be used as a point of reference
for other future things.

Ok, here are review comments:

+my $connstr =
+  $node->connstr('postgres') . " replication=database dbname=postgres";

Since the result of connstr() includes "dbname=postgres", you don't need to add "dbname=postgres" again.

+# The psql command should fail on pg_stop_backup().

Typo: s/pg_stop_backup/pg_stop_backup

I reported two trouble cases; they are the cases where BASE_BACKUP is canceled and terminated, respectively. But you added the test only for one of them. Is this intentional?

Since one of them failed to be applied to v14 or before cleanly, I
also created the patch for those back branches. So I attached three
patches.

Fine by me.

I pushed these bugfix patches at first. Thanks!

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On Wed, Jul 20, 2022 at 02:00:00PM +0900, Fujii Masao wrote:

I reported two trouble cases; they are the cases where BASE_BACKUP
is canceled and terminated, respectively. But you added the test
only for one of them. Is this intentional?

Nope. The one I have implemented was the fanciest case among the
two, so I just focused on it.

Adding an extra test to cover the second scenario is easier. So I
have added one as of the attached, addressing your other comments
while on it. I have also decided to add the tests at the bottom of
001_stream_rep.pl, as these are quicker than a node initialization.
--
Michael

On Wed, Jul 20, 2022 at 03:49:17PM +0900, Michael Paquier wrote:

Adding an extra test to cover the second scenario is easier. So I
have added one as of the attached, addressing your other comments
while on it. I have also decided to add the tests at the bottom of
001_stream_rep.pl, as these are quicker than a node initialization.

Hearing nothing, I have looked at that again and applied the two tests
on HEAD as of ad34146.
--
Michael