subject:"backup manifests"

On Sat, Apr 4, 2020 at 10:57 AM Tom Lane  wrote:
> It's not so surprising that we could get a different result that way
> from a CLOBBER_CACHE_ALWAYS animal like hyrax, since CCA-forced
> cache reloads would cause extra stack expenditure at a lot of places.
> And it could vary depending on totally random details, like the number
> of local variables in seemingly unrelated code.

Oh, yeah. That's unfortunate.

> What is odd is that
> (AFAIR) we've never seen this before.  Maybe somebody recently added
> an error cursor callback in a place that didn't have it before, and
> is involved in SQL-function processing?  None of the commits leading
> up to the earlier failure look promising for that, though.

The relevant range of commits (e8b1774fc2 to a7b9d24e4e) includes an
ereport change (bda6dedbea) and a couple of "simple expression"
changes (8f59f6b9c0, fbc7a71608) but I don't know exactly why they
would have caused this. It seems at least possible, though, that
changing the return type of functions involved in error reporting
would slightly change the amount of stack space used; and the others
are related to SQL-function processing. Other than experimenting on
that machine, I'm not sure how we could really determine the relevant
factors here.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests and contemporaneous buildfarm failures

2020-04-04 Thread Tom Lane

Robert Haas  writes:
> hyrax's last run was before any of this happened, so it seems to have
> an unrelated problem. The last two runs, three and six days ago, both
> failed like this:

> -ERROR:  stack depth limit exceeded
> +ERROR:  stack depth limit exceeded at character 8

> Not sure what that's about.

What it looks like is that hyrax is managing to detect stack overflow
at a point where an errcontext callback is active that adds an error
cursor to the failure.

It's not so surprising that we could get a different result that way
from a CLOBBER_CACHE_ALWAYS animal like hyrax, since CCA-forced
cache reloads would cause extra stack expenditure at a lot of places.
And it could vary depending on totally random details, like the number
of local variables in seemingly unrelated code.  What is odd is that
(AFAIR) we've never seen this before.  Maybe somebody recently added
an error cursor callback in a place that didn't have it before, and
is involved in SQL-function processing?  None of the commits leading
up to the earlier failure look promising for that, though.

regards, tom lane

Re: backup manifests

2020-04-04 Thread Tom Lane

Robert Haas  writes:
> On Fri, Apr 3, 2020 at 8:18 PM Tom Lane  wrote:
>> I suppose that judicious s/time_t/pg_time_t/ would fix this.

> I think you sent this email just after I pushed
> db1531cae00941bfe4f6321fdef1e1ef355b6bed, or maybe after I'd committed
> it locally and just before I pushed it. If you prefer a different fix
> than what I did there, I can certainly whack it around some more.

Yeah, that commit showed up moments after I sent this.  Your fix
seems fine -- at least prairiedog and gaur are OK with it.
(I did verify that gaur was reproducibly crashing at that new
pg_strftime call, so we know it was that and not some on-again-
off-again issue.)

regards, tom lane

Re: backup manifests and contemporaneous buildfarm failures

On Fri, Apr 3, 2020 at 10:43 PM Robert Haas  wrote:
> I think I've done about as much as I can do for tonight, though. Most
> things are green now, and the ones that aren't are failing because of
> stuff that is at least plausibly fixed. By morning it should be
> clearer how much broken stuff is left, although that will be somewhat
> complicated by at least sidewinder and seawasp needing manual
> intervention to get back on track.

Taking stock of the situation this morning, most of the buildfarm is
now green. There are three failures, on eelpout (6 hours ago),
fairywren (17 hours ago), and hyrax (3 days, 7 hours ago).

eelpout is unhappy because:

+WARNING:  could not remove shared memory segment
"/PostgreSQL.248989127": No such file or directory
+WARNING:  could not remove shared memory segment
"/PostgreSQL.1450751626": No such file or directory
  multibatch

  f
@@ -861,22 +863,15 @@

 select length(max(s.t))
 from wide left join (select id, coalesce(t, '') || '' as t from wide)
s using (id);
- length
-
- 32
-(1 row)
-
+ERROR:  could not open shared memory segment "/PostgreSQL.605707657":
No such file or directory
+CONTEXT:  parallel worker

I'm not sure what caused that exactly, but it sorta looks like
operator intervention. Thomas, any ideas?

fairywren's last run was on 21dc488, and commit
460314db08e8688e1a54a0a26657941e058e45c5 was an attempt to fix what
broken there. I guess we'll find out whether that worked the next time
it runs.

hyrax's last run was before any of this happened, so it seems to have
an unrelated problem. The last two runs, three and six days ago, both
failed like this:

-ERROR:  stack depth limit exceeded
+ERROR:  stack depth limit exceeded at character 8

Not sure what that's about.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests

On Fri, Apr 3, 2020 at 8:18 PM Tom Lane  wrote:
> BTW, some of the buildfarm is showing a simpler portability problem:
> they think you were too cavalier about the difference between time_t
> and pg_time_t.  (On a platform with 32-bit time_t, that's an actual
> bug, probably.)  lapwing is actually failing:
>
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=lapwing=2020-04-03%2021%3A41%3A49
>
> ccache gcc -std=gnu99 -Wall -Wmissing-prototypes -Wpointer-arith 
> -Wdeclaration-after-statement -Werror=vla -Wendif-labels 
> -Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv 
> -fexcess-precision=standard -g -O2 -Werror -I. -I. -I../../../src/include  
> -DENFORCE_REGRESSION_TEST_NAME_RESTRICTIONS -D_GNU_SOURCE 
> -I/usr/include/libxml2  -I/usr/include/et  -c -o basebackup.o basebackup.c
> basebackup.c: In function 'AddFileToManifest':
> basebackup.c:1199:10: error: passing argument 1 of 'pg_gmtime' from 
> incompatible pointer type [-Werror]
> In file included from ../../../src/include/access/xlog_internal.h:26:0,
>  from basebackup.c:20:
> ../../../src/include/pgtime.h:49:22: note: expected 'const pg_time_t *' but 
> argument is of type 'time_t *'
> cc1: all warnings being treated as errors
> make[3]: *** [basebackup.o] Error 1
>
> but some others are showing it as a warning.
>
> I suppose that judicious s/time_t/pg_time_t/ would fix this.

I think you sent this email just after I pushed
db1531cae00941bfe4f6321fdef1e1ef355b6bed, or maybe after I'd committed
it locally and just before I pushed it. If you prefer a different fix
than what I did there, I can certainly whack it around some more.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests and contemporaneous buildfarm failures

On Fri, Apr 3, 2020 at 11:06 PM Andres Freund  wrote:
> On 2020-04-03 20:48:09 -0400, Robert Haas wrote:
> > 'serinus' is also failing. This is less obviously related:
>
> Hm. Tests passed once since then.

Yeah, but conchuela also failed once in what I think was a similar
way. I suspect the fix I pushed last night
(3e0d80fd8d3dd4f999e0d3aa3e591f480d8ad1fd) may have been enough to
clear this up.

> That already seems suspicious. I checked the following (successful) run
> and I did not see that in the stage's logs.

Yeah, the behavior of the test case doesn't seem to be entirely deterministic.

> I, again, have to say that the amount of stuff that was done as part of
>
> commit 7c4f52409a8c7d85ed169bbbc1f6092274d03920
> Author: Peter Eisentraut 
> Date:   2017-03-23 08:36:36 -0400
>
> Logical replication support for initial data copy
>
> is insane. Adding support for running sql over replication connections
> and extending CREATE_REPLICATION_SLOT with new options (without even
> mentioning that in the commit message!) as part of a commit described as
> "Logical replication support for initial data copy" shouldn't happen.

I agreed then and still do.

> So I'm a bit confused here. The best approach is probably to try to
> reproduce this by adding an artifical delay into backend shutdown.

I was able to reproduce an assertion failure by starting a
transaction, running a replication command that failed, and then
exiting the backend. 3e0d80fd8d3dd4f999e0d3aa3e591f480d8ad1fd made
that go away. I had wrongly assumed that there was no other way for a
walsender to have a ResourceOwner, and in the face of SQL commands
also being executed by walsenders, that's clearly not true. I'm not
sure *precisely* how that lead to the BF failures, but it was really
clear that it was wrong.

> > (I still really dislike the fact that we have this evil hack allowing
> > one connection to mix and match those sets of commands...)
>
> FWIW, I think the opposite. We should get rid of the difference as much
> as possible.

Well, that's another approach. It's OK to have one system and it's OK
to have two systems, but one and a half is not ideal.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests and contemporaneous buildfarm failures

2020-04-03 Thread Petr Jelinek


On 04/04/2020 05:06, Andres Freund wrote:

Hi,

Peter, Petr, CCed you because it's probably a bug somewhere around the
initial copy code for logical replication.


On 2020-04-03 20:48:09 -0400, Robert Haas wrote:

'serinus' is also failing. This is less obviously related:


Hm. Tests passed once since then.



2020-04-04 02:08:57.299 CEST [5e87d019.506c1:4] LOG:  received
replication command: CREATE_REPLICATION_SLOT
"tap_sub_16390_sync_16384" TEMPORARY LOGICAL pgoutput USE_SNAPSHOT
2020-04-04 02:08:57.299 CEST [5e87d019.506c1:5] ERROR:  replication
slot "tap_sub_16390_sync_16384" already exists


That already seems suspicious. I checked the following (successful) run
and I did not see that in the stage's logs.

Looking at the failing log, it fails because for some reason there's
rounds (once due to a refresh, once due to an intention replication
failure) of copying the relation. Each creates its own temporary slot.

first time:
2020-04-04 02:08:57.276 CEST [5e87d019.506bd:1] LOG:  connection received: 
host=[local]
2020-04-04 02:08:57.278 CEST [5e87d019.506bd:4] LOG:  received replication command: 
CREATE_REPLICATION_SLOT "tap_sub_16390_sync_16384" TEMPORARY LOGICAL pgoutput 
USE_SNAPSHOT
2020-04-04 02:08:57.282 CEST [5e87d019.506bd:9] LOG:  statement: COPY 
public.tab_rep TO STDOUT
2020-04-04 02:08:57.284 CEST [5e87d019.506bd:10] LOG:  disconnection: session 
time: 0:00:00.007 user=bf database=postgres host=[local]

second time:
2020-04-04 02:08:57.288 CEST [5e87d019.506bf:1] LOG:  connection received: 
host=[local]
2020-04-04 02:08:57.289 CEST [5e87d019.506bf:4] LOG:  received replication command: 
CREATE_REPLICATION_SLOT "tap_sub_16390_sync_16384" TEMPORARY LOGICAL pgoutput 
USE_SNAPSHOT
2020-04-04 02:08:57.293 CEST [5e87d019.506bf:9] LOG:  statement: COPY 
public.tab_rep TO STDOUT

third time:
2020-04-04 02:08:57.297 CEST [5e87d019.506c1:1] LOG:  connection received: 
host=[local]
2020-04-04 02:08:57.299 CEST [5e87d019.506c1:4] LOG:  received replication command: 
CREATE_REPLICATION_SLOT "tap_sub_16390_sync_16384" TEMPORARY LOGICAL pgoutput 
USE_SNAPSHOT
2020-04-04 02:08:57.299 CEST [5e87d019.506c1:5] ERROR:  replication slot 
"tap_sub_16390_sync_16384" already exists

Note that the connection from the second attempt has not yet
disconnected. Hence the error about the replication slot already
existing - it's a temporary replication slot that'd otherwise already
have been dropped.


Seems the logical rep code needs to do something about this race?



The downstream:


2020-04-04 02:08:57.275 CEST [5e87d019.506bc:1] LOG:  logical replication table synchronization 
worker for subscription "tap_sub", table "tab_rep" has started
2020-04-04 02:08:57.282 CEST [5e87d019.506bc:2] ERROR:  duplicate key value violates 
unique constraint "tab_rep_pkey"
2020-04-04 02:08:57.282 CEST [5e87d019.506bc:3] DETAIL:  Key (a)=(1) already 
exists.
2020-04-04 02:08:57.282 CEST [5e87d019.506bc:4] CONTEXT:  COPY tab_rep, line 1
2020-04-04 02:08:57.283 CEST [5e87d018.50689:5] LOG:  background worker "logical 
replication worker" (PID 329404) exited with exit code 1
2020-04-04 02:08:57.287 CEST [5e87d019.506be:1] LOG:  logical replication table synchronization 
worker for subscription "tap_sub", table "tab_rep" has started
2020-04-04 02:08:57.293 CEST [5e87d019.506be:2] ERROR:  duplicate key value violates 
unique constraint "tab_rep_pkey"
2020-04-04 02:08:57.293 CEST [5e87d019.506be:3] DETAIL:  Key (a)=(1) already 
exists.
2020-04-04 02:08:57.293 CEST [5e87d019.506be:4] CONTEXT:  COPY tab_rep, line 1
2020-04-04 02:08:57.295 CEST [5e87d018.50689:6] LOG:  background worker "logical 
replication worker" (PID 329406) exited with exit code 1
2020-04-04 02:08:57.297 CEST [5e87d019.506c0:1] LOG:  logical replication table synchronization 
worker for subscription "tap_sub", table "tab_rep" has started
2020-04-04 02:08:57.299 CEST [5e87d019.506c0:2] ERROR:  could not create replication slot 
"tap_sub_16390_sync_16384": ERROR:  replication slot "tap_sub_16390_sync_16384" 
already exists
2020-04-04 02:08:57.300 CEST [5e87d018.50689:7] LOG:  background worker "logical replication worker" (PID 329408) exited with exit code 


Looks like we are simply retrying so fast that upstream will not have 
finished cleanup after second try by the time we already run the third one.


The last_start_times is supposed to protect against that so I guess 
there is some issue with how that works.


--
Petr Jelinek
2ndQuadrant - PostgreSQL Solutions for the Enterprise
https://www.2ndQuadrant.com/

Re: backup manifests and contemporaneous buildfarm failures

2020-04-03 Thread Andres Freund

Hi,

Peter, Petr, CCed you because it's probably a bug somewhere around the
initial copy code for logical replication.


On 2020-04-03 20:48:09 -0400, Robert Haas wrote:
> 'serinus' is also failing. This is less obviously related:

Hm. Tests passed once since then.


> 2020-04-04 02:08:57.299 CEST [5e87d019.506c1:4] LOG:  received
> replication command: CREATE_REPLICATION_SLOT
> "tap_sub_16390_sync_16384" TEMPORARY LOGICAL pgoutput USE_SNAPSHOT
> 2020-04-04 02:08:57.299 CEST [5e87d019.506c1:5] ERROR:  replication
> slot "tap_sub_16390_sync_16384" already exists

That already seems suspicious. I checked the following (successful) run
and I did not see that in the stage's logs.

Looking at the failing log, it fails because for some reason there's
rounds (once due to a refresh, once due to an intention replication
failure) of copying the relation. Each creates its own temporary slot.

first time:
2020-04-04 02:08:57.276 CEST [5e87d019.506bd:1] LOG:  connection received: 
host=[local]
2020-04-04 02:08:57.278 CEST [5e87d019.506bd:4] LOG:  received replication 
command: CREATE_REPLICATION_SLOT "tap_sub_16390_sync_16384" TEMPORARY LOGICAL 
pgoutput USE_SNAPSHOT
2020-04-04 02:08:57.282 CEST [5e87d019.506bd:9] LOG:  statement: COPY 
public.tab_rep TO STDOUT
2020-04-04 02:08:57.284 CEST [5e87d019.506bd:10] LOG:  disconnection: session 
time: 0:00:00.007 user=bf database=postgres host=[local]

second time:
2020-04-04 02:08:57.288 CEST [5e87d019.506bf:1] LOG:  connection received: 
host=[local]
2020-04-04 02:08:57.289 CEST [5e87d019.506bf:4] LOG:  received replication 
command: CREATE_REPLICATION_SLOT "tap_sub_16390_sync_16384" TEMPORARY LOGICAL 
pgoutput USE_SNAPSHOT
2020-04-04 02:08:57.293 CEST [5e87d019.506bf:9] LOG:  statement: COPY 
public.tab_rep TO STDOUT

third time:
2020-04-04 02:08:57.297 CEST [5e87d019.506c1:1] LOG:  connection received: 
host=[local]
2020-04-04 02:08:57.299 CEST [5e87d019.506c1:4] LOG:  received replication 
command: CREATE_REPLICATION_SLOT "tap_sub_16390_sync_16384" TEMPORARY LOGICAL 
pgoutput USE_SNAPSHOT
2020-04-04 02:08:57.299 CEST [5e87d019.506c1:5] ERROR:  replication slot 
"tap_sub_16390_sync_16384" already exists

Note that the connection from the second attempt has not yet
disconnected. Hence the error about the replication slot already
existing - it's a temporary replication slot that'd otherwise already
have been dropped.


Seems the logical rep code needs to do something about this race?


About the assertion failure:

TRAP: FailedAssertion("owner->bufferarr.nitems == 0", File: 
"/home/bf/build/buildfarm-serinus/HEAD/pgsql.build/../pgsql/src/backend/utils/resowner/resowner.c",
 Line: 718)
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(ExceptionalCondition+0x5c)[0x9a13ac]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(ResourceOwnerDelete+0x295)[0x9db8e5]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)[0x54c61f]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(AbortOutOfAnyTransaction+0x122)[0x550e32]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)[0x9b3bc9]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(shmem_exit+0x35)[0x80db45]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)[0x80dc77]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(proc_exit+0x8)[0x80dd08]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(PostgresMain+0x59f)[0x83bd0f]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)[0x7a0264]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(PostmasterMain+0xbfc)[0x7a2b8c]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(main+0x6fb)[0x49749b]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb)[0x7fc52d83]
postgres: publisher: walsender bf [local] idle in transaction 
(aborted)(_start+0x2a)[0x49753a]
2020-04-04 02:08:57.302 CEST [5e87d018.5066b:4] LOG:  server process (PID 
329409) was terminated by signal 6: Aborted

Due to the log_line_prefix used, I was at first not entirely sure the
backend that crashed was the one with the ERROR. But it appears we print
the pid as hex for '%c' (why?), so it indeed is the one.


I, again, have to say that the amount of stuff that was done as part of

commit 7c4f52409a8c7d85ed169bbbc1f6092274d03920
Author: Peter Eisentraut 
Date:   2017-03-23 08:36:36 -0400

Logical replication support for initial data copy

is insane. Adding support for running sql over replication connections
and extending CREATE_REPLICATION_SLOT with new options (without even
mentioning that in the commit message!) as part of a commit described as
"Logical replication support for initial data copy" shouldn't happen.


It's not obvious to me what buffer pins could be held at this point. I
wonder if this could be somehow related to

commit

Re: backup manifests and contemporaneous buildfarm failures

On Fri, Apr 3, 2020 at 9:52 PM Tom Lane  wrote:
> Robert Haas  writes:
> > 'prairiedog' is also unhappy, and it looks related:
>
> Yeah, gaur also failed in the same place.  Both of those are
> alignment-picky 32-bit hardware, so I'm thinking the problem is
> pg_gmtime() trying to fetch a 64-bit pg_time_t from an insufficiently
> aligned address.  I'm trying to confirm that on gaur's host right now,
> but it's a slow machine ...

You might just want to wait until tomorrow and see whether it clears
up in newer runs. I just pushed yet another fix that might be
relevant.

I think I've done about as much as I can do for tonight, though. Most
things are green now, and the ones that aren't are failing because of
stuff that is at least plausibly fixed. By morning it should be
clearer how much broken stuff is left, although that will be somewhat
complicated by at least sidewinder and seawasp needing manual
intervention to get back on track.

I apologize to everyone who has been or will be inconvenienced by all
of this. So far I've pushed 4 test case fixes, 2 bug fixes, and 1
makefile fix, which I'm pretty sure is over quota for one patch. :-(

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests and contemporaneous buildfarm failures

Robert Haas  writes:
> Interestingly, on my machine, rmtree coped with a mode 0 directory
> just fine, but mode 0400 was more than its tiny brain could handle, so
> the originally committed fix had code to revert 0400 back to 0700, but
> I didn't add similar code to revert from 0 back to 0700 because that
> was working fine.

It seems really odd that an implementation could cope with mode-0
but not mode-400.  Not sure I care enough to dig into the Perl
library code, though.

regards, tom lane

Re: backup manifests and contemporaneous buildfarm failures

Robert Haas  writes:
> 'prairiedog' is also unhappy, and it looks related:

Yeah, gaur also failed in the same place.  Both of those are
alignment-picky 32-bit hardware, so I'm thinking the problem is
pg_gmtime() trying to fetch a 64-bit pg_time_t from an insufficiently
aligned address.  I'm trying to confirm that on gaur's host right now,
but it's a slow machine ...

> 'serinus' is also failing. This is less obviously related:

Dunno about this one.

regards, tom lane

Re: backup manifests and contemporaneous buildfarm failures

On Fri, Apr 3, 2020 at 8:12 PM Tom Lane  wrote:
> Yeah, so it would seem.  The buildfarm script uses rmtree to clean out
> the old build tree.  The man page for File::Path suggests (but can't
> quite bring itself to say in so many words) that by default, rmtree
> will adjust the permissions on target directories to allow the deletion
> to succeed.  But that's very clearly not happening on some platforms.
> (Maybe that represents a local patch on the part of some packagers
> who thought it was too unsafe?)

Interestingly, on my machine, rmtree coped with a mode 0 directory
just fine, but mode 0400 was more than its tiny brain could handle, so
the originally committed fix had code to revert 0400 back to 0700, but
I didn't add similar code to revert from 0 back to 0700 because that
was working fine.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests and contemporaneous buildfarm failures

On Fri, Apr 3, 2020 at 6:13 PM Tom Lane  wrote:
> Locally, I observe that "make clean" in src/bin/pg_validatebackup fails
> to clean up the tmp_check directory left behind by "make check".

Fixed.

I also tried to fix 'lapwing', which was complaining about about a
call to pg_gmtime, saying that it "expected 'const pg_time_t *' but
argument is of type 'time_t *'". I was thinking that the problem had
something to do with const, but Thomas pointed out to me that
pg_time_t != time_t, so I pushed a fix which assumes that was the
issue. (It was certainly *an* issue.)

'prairiedog' is also unhappy, and it looks related:

/bin/sh ../../../../config/install-sh -c -d
'/Users/buildfarm/bf-data/HEAD/pgsql.build/src/test/modules/commit_ts'/tmp_check
cd . && 
TESTDIR='/Users/buildfarm/bf-data/HEAD/pgsql.build/src/test/modules/commit_ts'
PATH="/Users/buildfarm/bf-data/HEAD/pgsql.build/tmp_install/Users/buildfarm/bf-data/HEAD/inst/bin:$PATH"
DYLD_LIBRARY_PATH="/Users/buildfarm/bf-data/HEAD/pgsql.build/tmp_install/Users/buildfarm/bf-data/HEAD/inst/lib:$DYLD_LIBRARY_PATH"
 PGPORT='65678'
PG_REGRESS='/Users/buildfarm/bf-data/HEAD/pgsql.build/src/test/modules/commit_ts/../../../../src/test/regress/pg_regress'
REGRESS_SHLIB='/Users/buildfarm/bf-data/HEAD/pgsql.build/src/test/regress/regress.so'
/usr/local/perl5.8.3/bin/prove -I ../../../../src/test/perl/ -I .
t/*.pl
t/001_base.ok
t/002_standby..FAILED--Further testing stopped: system pg_basebackup failed
make: *** [check] Error 25

Unfortunately, that error message is not very informative and for some
reason the TAP logs don't seem to be included in the buildfarm output
in this case, so it's hard to tell exactly what went wrong. This
appears to be another 32-bit critter, which may be related somehow,
but I don't know how exactly.

'serinus' is also failing. This is less obviously related:

[02:08:55] t/003_constraints.pl .. ok 2048 ms ( 0.01 usr  0.00 sys
+  1.28 cusr  0.38 csys =  1.67 CPU)
# poll_query_until timed out executing this query:
# SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN
('r', 's');
# expecting this output:
# t
# last actual query output:
# f
# with stderr:

But there's also this:

2020-04-04 02:08:57.297 CEST [5e87d019.506c1:1] LOG:  connection
received: host=[local]
2020-04-04 02:08:57.298 CEST [5e87d019.506c1:2] LOG:  replication
connection authorized: user=bf
application_name=tap_sub_16390_sync_16384
2020-04-04 02:08:57.299 CEST [5e87d019.506c1:3] LOG:  statement: BEGIN
READ ONLY ISOLATION LEVEL REPEATABLE READ
2020-04-04 02:08:57.299 CEST [5e87d019.506c1:4] LOG:  received
replication command: CREATE_REPLICATION_SLOT
"tap_sub_16390_sync_16384" TEMPORARY LOGICAL pgoutput USE_SNAPSHOT
2020-04-04 02:08:57.299 CEST [5e87d019.506c1:5] ERROR:  replication
slot "tap_sub_16390_sync_16384" already exists
TRAP: FailedAssertion("owner->bufferarr.nitems == 0", File:
"/home/bf/build/buildfarm-serinus/HEAD/pgsql.build/../pgsql/src/backend/utils/resowner/resowner.c",
Line: 718)
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(ExceptionalCondition+0x5c)[0x9a13ac]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(ResourceOwnerDelete+0x295)[0x9db8e5]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)[0x54c61f]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(AbortOutOfAnyTransaction+0x122)[0x550e32]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)[0x9b3bc9]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(shmem_exit+0x35)[0x80db45]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)[0x80dc77]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(proc_exit+0x8)[0x80dd08]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(PostgresMain+0x59f)[0x83bd0f]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)[0x7a0264]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(PostmasterMain+0xbfc)[0x7a2b8c]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(main+0x6fb)[0x49749b]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xeb)[0x7fc52d83]
postgres: publisher: walsender bf [local] idle in transaction
(aborted)(_start+0x2a)[0x49753a]
2020-04-04 02:08:57.302 CEST [5e87d018.5066b:4] LOG:  server process
(PID 329409) was terminated by signal 6: Aborted
2020-04-04 02:08:57.302 CEST [5e87d018.5066b:5] DETAIL:  Failed
process was running: BEGIN READ ONLY ISOLATION LEVEL REPEATABLE READ

That might well be related. I note in passing that the DETAIL emitted
by the postmaster shows the previous SQL command rather than the
more-recent replication command, which seems like something to fix. (I
still really dislike the fact that we have this evil hack allowing one
connection to mix and match those sets of commands...)

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL

Re: backup manifests

BTW, some of the buildfarm is showing a simpler portability problem:
they think you were too cavalier about the difference between time_t
and pg_time_t.  (On a platform with 32-bit time_t, that's an actual
bug, probably.)  lapwing is actually failing:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=lapwing=2020-04-03%2021%3A41%3A49

ccache gcc -std=gnu99 -Wall -Wmissing-prototypes -Wpointer-arith 
-Wdeclaration-after-statement -Werror=vla -Wendif-labels 
-Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv 
-fexcess-precision=standard -g -O2 -Werror -I. -I. -I../../../src/include  
-DENFORCE_REGRESSION_TEST_NAME_RESTRICTIONS -D_GNU_SOURCE 
-I/usr/include/libxml2  -I/usr/include/et  -c -o basebackup.o basebackup.c
basebackup.c: In function 'AddFileToManifest':
basebackup.c:1199:10: error: passing argument 1 of 'pg_gmtime' from 
incompatible pointer type [-Werror]
In file included from ../../../src/include/access/xlog_internal.h:26:0,
 from basebackup.c:20:
../../../src/include/pgtime.h:49:22: note: expected 'const pg_time_t *' but 
argument is of type 'time_t *'
cc1: all warnings being treated as errors
make[3]: *** [basebackup.o] Error 1

but some others are showing it as a warning.

I suppose that judicious s/time_t/pg_time_t/ would fix this.

regards, tom lane

Re: backup manifests and contemporaneous buildfarm failures

Robert Haas  writes:
> On Fri, Apr 3, 2020 at 6:48 PM Tom Lane  wrote:
>> I'm guessing that we're looking at a platform-specific difference in
>> whether "rm -rf" fails outright on an unreadable subdirectory, or
>> just tries to carry on by unlinking it anyway.

> My intention was that it would be cleaned by the TAP framework itself,
> since the temporary directories it creates are marked for cleanup. But
> it may be that there's a platform dependency in the behavior of Perl's
> File::Path::rmtree, too.

Yeah, so it would seem.  The buildfarm script uses rmtree to clean out
the old build tree.  The man page for File::Path suggests (but can't
quite bring itself to say in so many words) that by default, rmtree
will adjust the permissions on target directories to allow the deletion
to succeed.  But that's very clearly not happening on some platforms.
(Maybe that represents a local patch on the part of some packagers
who thought it was too unsafe?)

Anyway, the end state presumably is that the pgsql.build directory
is still there at the end of the buildfarm run, and the next run's
attempt to also rmtree it fares no better.  Then look what it does
to set up the new build:

system("cp -R -p $target $build_path 2>&1");

Of course, if $build_path already exists, then cp copies to a subdirectory
of the target not the target itself.  So that explains the symptom
"./configure does not exist" --- it exists all right, but in a
subdirectory below the one where the buildfarm expects it to be.

It looks to me like the same problem would occur with VPATH or no.
The lack of failures among the VPATH-using critters probably has
more to do with whether their rmtree is willing to deal with this
case than with VPATH.

Anyway, it's evident that the buildfarm critters that are busted
will need manual cleanup, because the script is not going to be
able to get out of this by itself.  I remain of the opinion that
the hazard of that happening again in the future (eg, if a buildfarm
animal loses power during the test) is sufficient reason to remove
this test case.

regards, tom lane

Re: backup manifests and contemporaneous buildfarm failures

On Fri, Apr 3, 2020 at 5:58 PM Fabien COELHO  wrote:
> seawasp just failed the same way. Good news, I can see "configure" under
> "HEAD/pgsql".

Ah, good.

> The only strange thing under buildroot I found is:
>
> HEAD/pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans/

Huh. I wonder how that got left behind ... it should've been cleaned
up by the TAP test framework. But I pushed a commit to change the
permissions back explicitly before exiting. As Tom says, I probably
need to remove that entire test, but I'm going to try this first.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests and contemporaneous buildfarm failures

On Fri, Apr 3, 2020 at 6:48 PM Tom Lane  wrote:
> I'm guessing that we're looking at a platform-specific difference in
> whether "rm -rf" fails outright on an unreadable subdirectory, or
> just tries to carry on by unlinking it anyway.

My intention was that it would be cleaned by the TAP framework itself,
since the temporary directories it creates are marked for cleanup. But
it may be that there's a platform dependency in the behavior of Perl's
File::Path::rmtree, too.

> A partial fix would be to have the test script put back normal
> permissions on that directory before it exits ... but any failure
> partway through the script would leave a time bomb requiring manual
> cleanup.

Yeah. I've pushed that fix for now, but as you say, it may not survive
contact with the enemy. That's kind of disappointing, because I put a
lot of work into trying to make the tests cover every line of code
that they possibly could, and there's no reason to suppose that
pg_validatebackup is the only tool that could benefit from having code
coverage of those kinds of scenarios. It's probably not even the tool
that is most in need of such testing; it must be far worse if, say,
pg_rewind can't cope with it.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests and contemporaneous buildfarm failures

I wrote:
> I'm guessing that we're looking at a platform-specific difference in
> whether "rm -rf" fails outright on an unreadable subdirectory, or
> just tries to carry on by unlinking it anyway.

Yeah... on my RHEL6 box, "make check" cleans up the working directories
under tmp_check, but on a FreeBSD 12.1 box, not so much: I'm left with

$ ls tmp_check/
log/t_003_corruption_master_data/
tgl@oldmini$ ls -R tmp_check/t_003_corruption_master_data/
backup/

tmp_check/t_003_corruption_master_data/backup:
open_directory_fails/

tmp_check/t_003_corruption_master_data/backup/open_directory_fails:
pg_subtrans/

tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans:
ls: 
tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans: 
Permission denied

I did not see any complaints printed to the terminal, but in
regress_log_003_corruption there's

...
ok 40 - corrupt backup fails validation: open_directory_fails: matches
cannot chdir to child for 
/usr/home/tgl/pgsql/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans:
 Permission denied at t/003_corruption.pl line 126.
cannot remove directory for 
/usr/home/tgl/pgsql/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails:
 Directory not empty at t/003_corruption.pl line 126.
# Running: pg_basebackup -D 
/usr/home/tgl/pgsql/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/search_directory_fails
 --no-sync -T /tmp/lxaL_sLcnr=/tmp/_fegwVjoDR
ok 41 - base backup ok
...

This may be more of a Perl version issue than a platform issue,
but either way it's a problem.

Also, on the FreeBSD box, "rm -rf" isn't happy either:

$ rm -rf tmp_check
rm: 
tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans: 
Permission denied
rm: tmp_check/t_003_corruption_master_data/backup/open_directory_fails: 
Directory not empty
rm: tmp_check/t_003_corruption_master_data/backup: Directory not empty
rm: tmp_check/t_003_corruption_master_data: Directory not empty
rm: tmp_check: Directory not empty


regards, tom lane

Re: backup manifests and contemporaneous buildfarm failures

Thomas Munro  writes:
> Same here, on elver.  I see pg_subtrans has been chmod(0)'d,
> presumably by the perl subroutine mutilate_open_directory_fails.  I
> see this in my inbox (the build farm wrote it to stderr or stdout
> rather than the log file):

> cannot chdir to child for
> pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans:
> Permission denied at ./run_build.pl line 1013.
> cannot remove directory for
> pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails:
> Directory not empty at ./run_build.pl line 1013.

I'm guessing that we're looking at a platform-specific difference in
whether "rm -rf" fails outright on an unreadable subdirectory, or
just tries to carry on by unlinking it anyway.

A partial fix would be to have the test script put back normal
permissions on that directory before it exits ... but any failure
partway through the script would leave a time bomb requiring manual
cleanup.

On the whole, I'd argue that testing that behavior is not valuable
enough to take risks of periodically breaking buildfarm members
in a way that will require manual recovery --- to say nothing of
annoying developers who trip over it.  So my vote is to remove
that part of the test and be satisfied with checking the behavior
for an unreadable file.

This doesn't directly explain the failure-at-next-configure behavior
that we're seeing in the buildfarm, but it wouldn't be too surprising
if it ends up being that the buildfarm client script doesn't manage
to fully recover from the situation.

regards, tom lane

Re: backup manifests and contemporaneous buildfarm failures

2020-04-03 Thread Stephen Frost

Greetings,

* Thomas Munro (thomas.mu...@gmail.com) wrote:
> On Sat, Apr 4, 2020 at 11:13 AM Tom Lane  wrote:
> > Fabien COELHO  writes:
> > > The only strange thing under buildroot I found is:
> >
> > > HEAD/pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans/
> >
> > > this last directory perms are d- which seems to break cleanup.
> 
> Same here, on elver.  I see pg_subtrans has been chmod(0)'d,
> presumably by the perl subroutine mutilate_open_directory_fails.  I
> see this in my inbox (the build farm wrote it to stderr or stdout
> rather than the log file):

Yup, saw the same here.

chmod'ing it to 755 seemed to result it the next run cleaning it up, at
least.  Not sure how things will go on the next actual build tho.

Thanks,

Stephen


signature.asc
Description: PGP signature

Re: backup manifests and contemporaneous buildfarm failures

2020-04-03 Thread Thomas Munro

On Sat, Apr 4, 2020 at 11:13 AM Tom Lane  wrote:
> Fabien COELHO  writes:
> > The only strange thing under buildroot I found is:
>
> > HEAD/pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans/
>
> > this last directory perms are d- which seems to break cleanup.

Same here, on elver.  I see pg_subtrans has been chmod(0)'d,
presumably by the perl subroutine mutilate_open_directory_fails.  I
see this in my inbox (the build farm wrote it to stderr or stdout
rather than the log file):

cannot chdir to child for
pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans:
Permission denied at ./run_build.pl line 1013.
cannot remove directory for
pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails:
Directory not empty at ./run_build.pl line 1013.
cannot remove directory for
pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup:
Directory not empty at ./run_build.pl line 1013.
cannot remove directory for
pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data:
Directory not empty at ./run_build.pl line 1013.
cannot remove directory for
pgsql.build/src/bin/pg_validatebackup/tmp_check: Directory not empty
at ./run_build.pl line 1013.
cannot remove directory for pgsql.build/src/bin/pg_validatebackup:
Directory not empty at ./run_build.pl line 1013.
cannot remove directory for pgsql.build/src/bin: Directory not empty
at ./run_build.pl line 1013.
cannot remove directory for pgsql.build/src: Directory not empty at
./run_build.pl line 1013.
cannot remove directory for pgsql.build: Directory not empty at
./run_build.pl line 1013.
cannot chdir to child for
pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans:
Permission denied at ./run_build.pl line 589.
cannot remove directory for
pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails:
Directory not empty at ./run_build.pl line 589.
cannot remove directory for
pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup:
Directory not empty at ./run_build.pl line 589.
cannot remove directory for
pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data:
Directory not empty at ./run_build.pl line 589.
cannot remove directory for
pgsql.build/src/bin/pg_validatebackup/tmp_check: Directory not empty
at ./run_build.pl line 589.
cannot remove directory for pgsql.build/src/bin/pg_validatebackup:
Directory not empty at ./run_build.pl line 589.
cannot remove directory for pgsql.build/src/bin: Directory not empty
at ./run_build.pl line 589.
cannot remove directory for pgsql.build/src: Directory not empty at
./run_build.pl line 589.
cannot remove directory for pgsql.build: Directory not empty at
./run_build.pl line 589.

Re: backup manifests and contemporaneous buildfarm failures

2020-04-03 Thread Alvaro Herrera

On 2020-Apr-03, Tom Lane wrote:

> I wonder if VPATH versus not-VPATH might be a relevant factor ...

Oh, absolutely.  The ones that failed show, in the last successful run,
the configure line invoked as "./configure", while the animals that are
still running are invoking configure from some other directory.

-- 
Álvaro Herrerahttps://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: backup manifests and contemporaneous buildfarm failures

Fabien COELHO  writes:
> The only strange thing under buildroot I found is:

> HEAD/pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans/

> this last directory perms are d- which seems to break cleanup.

Locally, I observe that "make clean" in src/bin/pg_validatebackup fails
to clean up the tmp_check directory left behind by "make check".
So the new makefile is not fully plugged into its standard
responsibilities.  I don't see any unreadable subdirectories though.

I wonder if VPATH versus not-VPATH might be a relevant factor ...

regards, tom lane

Re: backup manifests and contemporaneous buildfarm failures

2020-04-03 Thread Fabien COELHO

Hello Robert,

Done now. Meanwhile, two more machines have reported the mysterious message:

sh: ./configure: not found

...that first appeared on spurfowl a few hours ago. The other two
machines are eelpout and elver, both of which list Thomas Munro as a
maintainer. spurfowl lists Stephen Frost. Thomas, Stephen, can one of
you check and see what's going on? spurfowl has failed this way four
times now, and eelpout and elver have each failed the last two runs,
but since there's no helpful information in the logs, it's hard to
guess what went wrong.

I'm sort of afraid that something in the new TAP tests accidentally
removed way too many files during the cleanup phase - e.g. it decided
the temporary directory was / and removed every file it could access,
or something like that. It doesn't do that here, or I, uh, would've
noticed by now. But sometimes strange things happen on other people's
machines. Hopefully one of those strange things is not that my test
code is single-handedly destroying the entire buildfarm, but it's
possible.

seawasp just failed the same way. Good news, I can see "configure" under
"HEAD/pgsql".

The only strange thing under buildroot I found is:

HEAD/pgsql.build/src/bin/pg_validatebackup/tmp_check/t_003_corruption_master_data/backup/open_directory_fails/pg_subtrans/

this last directory perms are d- which seems to break cleanup.

It may be a left over from a previous run which failed (possibly 21dc488
?). I cannot see how this would be related to configure, though. Maybe
something else fails silently and the message is about a consequence of
the prior silent failure.

I commented out the cron job and will try to look into it on tomorrow if
the status has not changed by then.

--
Fabien.

backup manifests and contemporaneous buildfarm failures

[ splitting this off into a separate thread ]

On Fri, Apr 3, 2020 at 5:07 PM Robert Haas  wrote:
> I'lll go see about adding that.

Done now. Meanwhile, two more machines have reported the mysterious message:

sh: ./configure: not found

...that first appeared on spurfowl a few hours ago. The other two
machines are eelpout and elver, both of which list Thomas Munro as a
maintainer. spurfowl lists Stephen Frost. Thomas, Stephen, can one of
you check and see what's going on? spurfowl has failed this way four
times now, and eelpout and elver have each failed the last two runs,
but since there's no helpful information in the logs, it's hard to
guess what went wrong.

I'm sort of afraid that something in the new TAP tests accidentally
removed way too many files during the cleanup phase - e.g. it decided
the temporary directory was / and removed every file it could access,
or something like that. It doesn't do that here, or I, uh, would've
noticed by now. But sometimes strange things happen on other people's
machines. Hopefully one of those strange things is not that my test
code is single-handedly destroying the entire buildfarm, but it's
possible.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests

2020-04-03 Thread Justin Pryzby

oes 
not

-- 
Justin
>From 0bc8211dd325e8fec55eab4a3089ed1768563502 Mon Sep 17 00:00:00 2001
From: Justin Pryzby 
Date: Fri, 3 Apr 2020 16:17:28 -0500
Subject: [PATCH] docs: backup manifests

commit 0d8c9c1210c44b36ec2efcb223a1dfbe897a3661
Author: Robert Haas 
---
 doc/src/sgml/protocol.sgml  |  4 ++--
 doc/src/sgml/ref/pg_basebackup.sgml |  4 ++--
 doc/src/sgml/ref/pg_validatebackup.sgml | 12 ++--
 src/backend/replication/basebackup.c|  2 +-
 4 files changed, 11 insertions(+), 11 deletions(-)

diff --git a/doc/src/sgml/protocol.sgml b/doc/src/sgml/protocol.sgml
index 536de9a698..d84afb7b18 100644
--- a/doc/src/sgml/protocol.sgml
+++ b/doc/src/sgml/protocol.sgml
@@ -2586,7 +2586,7 @@ The commands accepted in replication mode are:
   and sent along with the backup.  The manifest is a list of every
   file present in the backup with the exception of any WAL files that
   may be included. It also stores the size, last modification time, and
-  an optional checksum for each file.
+  optionally a checksum for each file.
   A value of force-escape forces all filenames
   to be hex-encoded; otherwise, this type of encoding is performed only
   for files whose names are non-UTF8 octet sequences.
@@ -2602,7 +2602,7 @@ The commands accepted in replication mode are:
 MANIFEST_CHECKSUMS
 
  
-  Specifies the algorithm that should be applied to each file included
+  Specifies the checksum algorithm that should be applied to each file included
   in the backup manifest. Currently, the available
   algorithms are NONE, CRC32C,
   SHA224, SHA256,
diff --git a/doc/src/sgml/ref/pg_basebackup.sgml b/doc/src/sgml/ref/pg_basebackup.sgml
index c778e061f3..922688e227 100644
--- a/doc/src/sgml/ref/pg_basebackup.sgml
+++ b/doc/src/sgml/ref/pg_basebackup.sgml
@@ -604,7 +604,7 @@ PostgreSQL documentation
 not contain any checksums. Otherwise, it will contain a checksum
 of each file in the backup using the specified algorithm. In addition,
 the manifest will always contain a SHA256
-checksum of its own contents. The SHA algorithms
+checksum of its own content. The SHA algorithms
 are significantly more CPU-intensive than CRC32C,
 so selecting one of them may increase the time required to complete
 the backup.
@@ -614,7 +614,7 @@ PostgreSQL documentation
 of each file for users who wish to verify that the backup has not been
 tampered with, while the CRC32C algorithm provides a checksum which is
 much faster to calculate and good at catching errors due to accidental
-changes but is not resistant to targeted modifications.  Note that, to
+changes but is not resistant to malicious modifications.  Note that, to
 be useful against an adversary who has access to the backup, the backup
 manifest would need to be stored securely elsewhere or otherwise
 verified not to have been modified since the backup was taken.
diff --git a/doc/src/sgml/ref/pg_validatebackup.sgml b/doc/src/sgml/ref/pg_validatebackup.sgml
index 19888dc196..748ac439a6 100644
--- a/doc/src/sgml/ref/pg_validatebackup.sgml
+++ b/doc/src/sgml/ref/pg_validatebackup.sgml
@@ -41,12 +41,12 @@ PostgreSQL documentation
   
 
   
-   It is important to note that that the validation which is performed by
-   pg_validatebackup does not and can not include
+   It is important to note that the validation which is performed by
+   pg_validatebackup does not and cannot include
every check which will be performed by a running server when attempting
to make use of the backup. Even if you use this tool, you should still
perform test restores and verify that the resulting databases work as
-   expected and that they appear to contain the correct data. However,
+   expected and that they contain the correct data. However,
pg_validatebackup can detect many problems
that commonly occur due to storage problems or user error.
   
@@ -73,7 +73,7 @@ PostgreSQL documentation
a backup_manifest file in the target directory or
about anything inside pg_wal, even though these
files won't be listed in the backup manifest. Only files are checked;
-   the presence or absence or directories is not verified, except
+   the presence or absence of directories is not verified, except
indirectly: if a directory is missing, any files it should have contained
will necessarily also be missing. 
   
@@ -84,7 +84,7 @@ PostgreSQL documentation
for any files for which the computed checksum does not match the
checksum stored in the manifest. This step is not performed for any files
which produced errors in the previous step, since they are already known
-   to have problems. Also, files which were ignored in the previous step are
+   to have problems. Files which were ignored in the previous step are

Re: backup manifests

On Fri, Apr 3, 2020 at 4:54 PM Alvaro Herrera  wrote:
> Maybe it needs perl2host?

*jaw drops*

Wow, OK, yeah, that looks like the thing.  Thanks for the suggestion;
I didn't know that existed (and I kinda wish I still didn't).

I'lll go see about adding that.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests

2020-04-03 Thread Alvaro Herrera

On 2020-Apr-03, Robert Haas wrote:

> sub tempdir_short
> {
> 
> return File::Temp::tempdir(CLEANUP => 1);
> }
> 
> And File::Temp's documentation says that the temporary directory is
> picked using File::Spec's tmpdir(), which says that it knows about
> different operating systems and will DTRT on Unix, Mac, OS2, Win32,
> and VMS. Yet on fairywren it is apparently DTWT. I'm not sure why.

Maybe it needs perl2host?

-- 
Álvaro Herrerahttps://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Re: backup manifests

On Fri, Apr 3, 2020 at 3:53 PM Robert Haas  wrote:
> 2. Also, a bunch of machines were super-unhappy with
> 003_corruption.pl, failing with this sort of thing:
>
> pg_basebackup: error: could not get COPY data stream: ERROR:  symbolic
> link target too long for tar format: file name "pg_tblspc/16387",
> target 
> "/home/fabien/pg/build-farm-11/buildroot/HEAD/pgsql.build/src/bin/pg_validatebackup/tmp_check/tmp_test_7w0w"
>
> Apparently, this is a known problem and the solution is to use
> TestLib::tempdir_short instead of TestLib::tempdir, so I pushed a fix
> to make it do that.

By and large, the buildfarm is a lot happier now, but fairywren
(Windows / Msys Server 2019 / 2 gcc 7.3.0 x86_64) failed like this:

# Postmaster PID for node "master" is 198420
error running SQL: 'psql::3: ERROR:  directory
"/tmp/9peoZHrEia" does not exist'
while running 'psql -XAtq -d port=51493 host=127.0.0.1
dbname='postgres' -f - -v ON_ERROR_STOP=1' with sql 'CREATE TABLE x1
(a int);
INSERT INTO x1 VALUES (111);
CREATE TABLESPACE ts1 LOCATION '/tmp/9peoZHrEia';
CREATE TABLE x2 (a int) TABLESPACE ts1;
INSERT INTO x1 VALUES (222);
' at 
/home/pgrunner/bf/root/HEAD/pgsql.build/../pgsql/src/test/perl/PostgresNode.pm
line 1531.
### Stopping node "master" using mode immediate

I wondered why this should be failing on this machine when none of the
other places where tempdir_short is used are similarly failing. The
answer appears to be that most of the TAP tests that use tempdir_short
just do this:

my $tempdir_short = TestLib::tempdir_short;

...and then ignore that variable completely for the rest of the
script.  That's not ideal, and we should probably remove those calls
to avoid giving that it's actually used for something. The two TAP
tests that actually do something with it - apart from the one I just
added - are pg_basebackup's 010_pg_basebackup.pl and pg_ctl's
001_start_stop.pl. However, both of those are skipped on Windows.
Also, PostgresNode.pm itself uses it, but only when UNIX sockets are
used, so again not on Windows. So it sorta looks to me like we no
preexisting tests that meaningfully exercise TestLib::tempdir_short on
Windows.

Given that, I suppose I should consider myself lucky if this ends up
working on *any* of the Windows critters, but given the implementation
I'm kinda surprised we have a problem. That function is just:

sub tempdir_short
{

return File::Temp::tempdir(CLEANUP => 1);
}

And File::Temp's documentation says that the temporary directory is
picked using File::Spec's tmpdir(), which says that it knows about
different operating systems and will DTRT on Unix, Mac, OS2, Win32,
and VMS. Yet on fairywren it is apparently DTWT. I'm not sure why.

Any ideas?

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests

On Fri, Apr 3, 2020 at 3:22 PM Robert Haas  wrote:
> It looks like the buildfarm is unhappy though, so I guess I'd better
> go look at that.

I fixed two things so far, and there seems to be at least one more
possible issue that I don't understand.

1. Apparently, we have an automated perlcritic run built in to the
build farm, and apparently, it really hates Perl subroutines that
don't end with an explicit return statement. We have that overridden
to severity 5 in our Perl critic configuration. I guess I should've
known this, but didn't. I've pushed a fix adding return statements. I
believe I'm on record as thinking that perlcritic is a tool for
complaining about a lot of things that don't really matter and very
few that actually do -- but it's project style, so I'll suck it up!

2. Also, a bunch of machines were super-unhappy with
003_corruption.pl, failing with this sort of thing:

pg_basebackup: error: could not get COPY data stream: ERROR:  symbolic
link target too long for tar format: file name "pg_tblspc/16387",
target 
"/home/fabien/pg/build-farm-11/buildroot/HEAD/pgsql.build/src/bin/pg_validatebackup/tmp_check/tmp_test_7w0w"

Apparently, this is a known problem and the solution is to use
TestLib::tempdir_short instead of TestLib::tempdir, so I pushed a fix
to make it do that.

3. spurfowl has failed its last two runs like this:

sh: 1: ./configure: not found

I am not sure how this patch could've caused that to happen, but the
timing of the failures is certainly suspicious.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests

On Thu, Apr 2, 2020 at 4:34 PM David Steele  wrote:
> +1. These would be great tests to have and a win for pg_basebackup
> overall but I don't think they should be a prerequisite for this commit.

Not to mention the server. I can't say that I have a lot of confidence
that all of the server behavior in this area is well-understood and
sane.

I've pushed all the patches. Hopefully everyone is happy now, or at
least not so unhappy that they're going to break quarantine to beat me
up. I hope I acknowledged all of the relevant people in the commit
message, but it's possible that I missed somebody; if so, my
apologies. As is my usual custom, I added entries in roughly the order
that people chimed in on the thread, so the ordering should not be
taken as a reflection of magnitude of contribution or, well, anything
other than the approximate order in which they chimed in.

It looks like the buildfarm is unhappy though, so I guess I'd better
go look at that.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests

2020-04-02 Thread David Steele


On 4/2/20 3:47 PM, Andres Freund wrote:

On 2020-04-02 15:42:48 -0400, Robert Haas wrote:

I suspect I'm not doing quite what you had in mind here... thoughts?


I have some ideas, but I think it's complicated enough that I'd not put
it in the "pre commit path" for now.


+1. These would be great tests to have and a win for pg_basebackup 
overall but I don't think they should be a prerequisite for this commit.


Regards,
--
-David
da...@pgmasters.net

Re: backup manifests

On 2020-04-02 15:42:48 -0400, Robert Haas wrote:
> I suspect I'm not doing quite what you had in mind here... thoughts?

I have some ideas, but I think it's complicated enough that I'd not put
it in the "pre commit path" for now.

Re: backup manifests

2020-04-02 Thread Robert Haas

On Thu, Apr 2, 2020 at 2:55 PM Robert Haas  wrote:
> On Thu, Apr 2, 2020 at 2:23 PM Andres Freund  wrote:
> > > That might make the window fairly wide on normal systems, but I'm not
> > > sure about Raspberry Pi BF members or things running
> > > CLOBBER_CACHE_ALWAYS/RECURSIVELY. I guess I could try it.
> >
> > You can set checkpoint_timeout to be a day. If that's not enough, well,
> > then I think we have other problems.
>
> I'm not sure that's the only issue here, but I'll try it.

I ran into a few problems here. In trying to set this up manually, I
always began with the following steps:

# (1) create cluster
initdb

# (2) add to configuration file
log_checkpoints=on
checkpoint_timeout=1d
checkpoint_completion_target=0.99

# (3) fire it up
postgres
createdb

If at this point I do "pg_basebackup -D pgslave -R -c spread", it
completes within a few seconds anyway, because there's basically
nothing dirty, and no matter how slowly you write out no data, it's
still pretty quick. If I run "pgbench -i" first, and then
"pg_basebackup -D pgslave -R -c spread", it hangs, apparently
essentially forever, because now the checkpoint has something to do,
and it does it super-slowly, and "psql -c checkpoint" makes it finish
immediately. However, this experiment isn't testing quite the right
thing, because what I actually need is a slow backup off of a
cascading standby, so that I have time to promote the parent standby
before the backup completes. I tried continuing like this:

# (4) set up standby
pg_basebackup -D pgslave -R
postgres -D pgslave -c port=5433

# (5) set up cascading standby
pg_basebackup -D pgslave2 -d port=5433 -R
postgres -c port=5434 -D pgslave2

# (6) dirty some pages on the master
pgbench -i

# (7) start a backup of the cascading standby
pg_basebackup -D pgslave3 -d port=5434 -R -c spread

However, the pg_basebackup in the last step completes after only a few
seconds. If it were hanging, then I could continue with "pg_ctl
promote -D pgslave" and that might give me what I need, but that's not
what happens.

I suspect I'm not doing quite what you had in mind here... thoughts?

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests

2020-04-02 Thread Robert Haas

On Thu, Apr 2, 2020 at 3:26 PM David Steele  wrote:
> So, with the addition of the 0004 patch down-thread this looks
> committable to me.

Glad to hear it. Thank you.

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests

2020-04-02 Thread David Steele


On 4/2/20 1:04 PM, Robert Haas wrote:
>

There
are still some things that not everybody is happy about. In
particular, Stephen and David are unhappy about using CRC-32C as the
default algorithm, but Andres and Noah both think it's a reasonable
choice, even if not as robust as everybody will want. As I agree, I'm
going to stick with that choice.


Yeah, I seem to be on the losing side of this argument, at least for 
now, so I don't think it should block the commit of this patch. It's an 
easy enough tweak if we change our minds.



For my part, I think this is a general issue that is not really this
patch's problem to solve. We have had multiple discussions over the
years about reducing the number of binaries that we ship. We could
have a general binary called "pg" or similar and use subcommands: pg
createdb, pg basebackup, pg validatebackup, etc. I think such an
approach is worth considering, though it would certainly be an
adjustment for everyone. Or we might do something else. But I don't
want to deal with that in this patch.


I'm fine with the current name, especially now that WAL is validated.


A couple of other minor suggestions have been made: (1) rejigger
things to avoid message duplication related to launching external
binaries, 


That'd be nice to have, but I think we can live without it for now.


(2) maybe use appendShellString


Seems like this would be good to have but I'm not going to make a fuss 
about it.



and (3) change some details
of error-reporting related to manifest parsing. I don't believe anyone
views these as blockers


I'd view this as later refinement once we see how the tool is being used 
and/or get gripes from the field.


So, with the addition of the 0004 patch down-thread this looks 
committable to me.


Regards,
--
-David
da...@pgmasters.net

Re: backup manifests

On 2020-04-02 14:55:19 -0400, Robert Haas wrote:
> > Yes, I am asking for something to be changed: I'd like the code that
> > read()s the file when computing the checksum to add up how many bytes
> > were read, and compare that to the size in the manifest. And if there's
> > a difference report an error about that, instead of a checksum failure.
> >
> > I've repeatedly seen filesystem issues lead to to earlier EOFs when
> > read()ing than what stat() returns. It'll be pretty annoying to have to
> > debug a general "checksum failure", rather than just knowing that
> > reading stopped after 100MB of 1GB.
> 
> Is 0004 attached like what you have in mind?

Yes. Thanks!

- Andres

Re: backup manifests

Hi,

On 2020-04-02 14:16:27 -0400, Robert Haas wrote:
> On Thu, Apr 2, 2020 at 1:23 PM Andres Freund  wrote:
> > I suspect its possible to control the timing by preventing the
> > checkpoint at the end of recovery from completing within a relevant
> > timeframe. I think configuring a large checkpoint_timeout and using a
> > non-fast base backup ought to do the trick. The state can be advanced by
> > separately triggering an immediate checkpoint? Or by changing the
> > checkpoint_timeout?
> 
> That might make the window fairly wide on normal systems, but I'm not
> sure about Raspberry Pi BF members or things running
> CLOBBER_CACHE_ALWAYS/RECURSIVELY. I guess I could try it.

You can set checkpoint_timeout to be a day. If that's not enough, well,
then I think we have other problems.

> > FWIW, the only check I'd really like to see in this release is the
> > crosscheck with the files length and the actually read data (to be able
> > to disagnose FS issues).
> 
> Not sure I understand this comment. Isn't that a subset of what the
> patch already does? Are you asking for something to be changed?

Yes, I am asking for something to be changed: I'd like the code that
read()s the file when computing the checksum to add up how many bytes
were read, and compare that to the size in the manifest. And if there's
a difference report an error about that, instead of a checksum failure.

I've repeatedly seen filesystem issues lead to to earlier EOFs when
read()ing than what stat() returns. It'll be pretty annoying to have to
debug a general "checksum failure", rather than just knowing that
reading stopped after 100MB of 1GB.

Greetings,

Andres Freund

Re: backup manifests

2020-04-02 Thread Robert Haas

On Thu, Apr 2, 2020 at 1:23 PM Andres Freund  wrote:
> I suspect its possible to control the timing by preventing the
> checkpoint at the end of recovery from completing within a relevant
> timeframe. I think configuring a large checkpoint_timeout and using a
> non-fast base backup ought to do the trick. The state can be advanced by
> separately triggering an immediate checkpoint? Or by changing the
> checkpoint_timeout?

That might make the window fairly wide on normal systems, but I'm not
sure about Raspberry Pi BF members or things running
CLOBBER_CACHE_ALWAYS/RECURSIVELY. I guess I could try it.

> I think it might be worth looking, in a later release, at something like
> blake3 for a fast cryptographic checksum. By allowing for instruction
> parallelism (by independently checksuming different blocks in data, and
> only advancing the "shared" checksum separately) it achieves
> considerably higher throughput rates.
>
> I suspect we should also look at a better non-crypto hash. xxhash or
> whatever. Not just for these checksums, but also for in-memory.

I have no problem with that. I don't feel that I am well-placed to
recommend for or against specific algorithms. Speed is easy to
measure, but there's also code stability, the license under which
something is released, the quality of the hashes it produces, and the
extent to which it is cryptographically secure. I'm not an expert in
any of that stuff, but if we get consensus on something it should be
easy enough to plug it into this framework. Even changing the default
would be no big deal.

> FWIW, the only check I'd really like to see in this release is the
> crosscheck with the files length and the actually read data (to be able
> to disagnose FS issues).

Not sure I understand this comment. Isn't that a subset of what the
patch already does? Are you asking for something to be changed?

-- 
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

Re: backup manifests