From: Mark Dilger <mark.dilger@enterprisedb.com>
Message-Id: <AACAF464-092B-4497-ADA2-AE1B122FAC6A@enterprisedb.com>
Content-Type: multipart/mixed;
	boundary="Apple-Mail=_44E5CCDA-D653-4015-B165-A414CD09393C"
Mime-Version: 1.0 (Mac OS X Mail 13.4 \(3608.120.23.2.7\))
Subject: Re: New Object Access Type hooks
Date: Mon, 4 Apr 2022 10:56:11 -0700
In-Reply-To: <1923706.1649094673@sss.pgh.pa.us>
Cc: Thomas Munro <thomas.munro@gmail.com>,
 PostgreSQL-development <pgsql-hackers@postgresql.org>,
 Joshua Brindle <joshua.brindle@crunchydata.com>,
 Robert Haas <robertmhaas@gmail.com>,
 Andrew Dunstan <andrew@dunslane.net>,
 Jeff Davis <pgsql@j-davis.com>,
 Joe Conway <joe@crunchydata.com>
To: Tom Lane <tgl@sss.pgh.pa.us>
References: <47F87A0E-C0E5-43A6-89F6-D403F2B45175@enterprisedb.com>
 <CA+hUKG+LOza8iSLiv6ymn=0R8S0x-R7KaqZmYfY+_b_cubcDOg@mail.gmail.com>
 <17BD82D7-49AC-40C9-8204-E7ADD30321A0@enterprisedb.com>
 <1918971.1649091790@sss.pgh.pa.us> <1922986.1649094077@sss.pgh.pa.us>
 <1923706.1649094673@sss.pgh.pa.us>
Archived-At: <https://www.postgresql.org/message-id/AACAF464-092B-4497-ADA2-AE1B122FAC6A%40enterprisedb.com>
Precedence: bulk


--Apple-Mail=_44E5CCDA-D653-4015-B165-A414CD09393C
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain;
	charset=us-ascii


> On Apr 4, 2022, at 10:51 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>=20
> Oh, I'm barking up the wrong tree.  This test must have been run
> against HEAD between 6da65a3f9 (23 Feb) and 2beb4acff (31 Mar), when
> pump_until indeed didn't print this essential information :-(
>=20
> If you just got this failure, could you look in the log to
> see if there's a pump_until report?

I was running `make -j12 check-world` against my local patched version =
of master:

commit 80399fa5f208c4acd4ec194c47e534ba8dd3ae7c (HEAD -> 0001)
Author: Mark Dilger <mark.dilger@enterprisedb.com>
Date:   Mon Mar 28 13:35:11 2022 -0700

    Allow grant and revoke of privileges on parameters
   =20
    Add new SET and ALTER SYSTEM privileges for configuration parameters
    (GUCs), and a new catalog, pg_parameter_acl, for tracking grants of
    these privileges.
   =20
    The privilege to SET a parameter marked USERSET is inherent in that
    parameter's marking and cannot be revoked.  This saves cycles when
    performing SET operations, as looking up privileges in the catalog
    can be skipped.  If we find that administrators need to revoke SET
    privilege on a particular variable from public, that variable can be
    redefined in future releases as SUSET with a default grant of SET to
    PUBLIC issued.

commit 4eb9798879680dcc0e3ebb301cf6f925dfa69422 (origin/master, =
origin/HEAD, master)
Author: Andrew Dunstan <andrew@dunslane.net>
Date:   Mon Apr 4 10:12:30 2022 -0400

    Avoid freeing objects during json aggregate finalization
   =20
    Commit f4fb45d15c tried to free memory during aggregate =
finalization.
    This cause issues, particularly when used as a window function, so =
stop
    doing that.
   =20
    Per complaint by Jaime Casanova and diagnosis by Andres Freund
   =20
    Discussion: https://postgr.es/m/YkfeMNYRCGhySKyg@ahch-to


The test logs are attached.


--Apple-Mail=_44E5CCDA-D653-4015-B165-A414CD09393C
Content-Disposition: attachment;
	filename=013_crash_restart_primary.log
Content-Type: application/octet-stream;
	x-unix-mode=0600;
	name="013_crash_restart_primary.log"
Content-Transfer-Encoding: 7bit

2022-04-04 09:11:50.951 PDT [2070] LOG:  starting PostgreSQL 15devel on x86_64-apple-darwin19.6.0, compiled by Apple clang version 11.0.0 (clang-1100.0.33.17), 64-bit
2022-04-04 09:11:50.951 PDT [2070] LOG:  listening on Unix socket "/var/folders/6n/3f4vwbnn7fz5qk0xqhgbjrkw0000gp/T/hDGeeFsYRd/.s.PGSQL.49823"
2022-04-04 09:11:50.957 PDT [2073] LOG:  database system was shut down at 2022-04-04 09:11:50 PDT
2022-04-04 09:11:50.959 PDT [2070] LOG:  database system is ready to accept connections
2022-04-04 09:11:51.056 PDT [2080] 013_crash_restart.pl LOG:  statement: ALTER SYSTEM SET restart_after_crash = 1;
2022-04-04 09:11:51.057 PDT [2080] 013_crash_restart.pl LOG:  statement: ALTER SYSTEM SET log_connections = 1;
2022-04-04 09:11:51.058 PDT [2080] 013_crash_restart.pl LOG:  statement: SELECT pg_reload_conf();
2022-04-04 09:11:51.059 PDT [2070] LOG:  received SIGHUP, reloading configuration files
2022-04-04 09:11:51.060 PDT [2070] LOG:  parameter "restart_after_crash" changed to "1"
2022-04-04 09:11:51.060 PDT [2070] LOG:  parameter "log_connections" changed to "1"
2022-04-04 09:11:51.075 PDT [2083] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.076 PDT [2083] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.077 PDT [2084] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.078 PDT [2083] 013_crash_restart.pl LOG:  statement: CREATE TABLE alive(status text);
2022-04-04 09:11:51.078 PDT [2084] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.083 PDT [2083] 013_crash_restart.pl LOG:  statement: INSERT INTO alive VALUES($$committed-before-sigquit$$);
2022-04-04 09:11:51.084 PDT [2083] 013_crash_restart.pl LOG:  statement: SELECT pg_backend_pid();
2022-04-04 09:11:51.085 PDT [2083] 013_crash_restart.pl LOG:  statement: BEGIN;
2022-04-04 09:11:51.086 PDT [2083] 013_crash_restart.pl LOG:  statement: INSERT INTO alive VALUES($$in-progress-before-sigquit$$) RETURNING status;
2022-04-04 09:11:51.086 PDT [2084] 013_crash_restart.pl LOG:  statement: SELECT $$psql-connected$$;
2022-04-04 09:11:51.087 PDT [2084] 013_crash_restart.pl LOG:  statement: SELECT pg_sleep(3600);
2022-04-04 09:11:51.094 PDT [2083] 013_crash_restart.pl WARNING:  terminating connection because of unexpected SIGQUIT signal
2022-04-04 09:11:51.095 PDT [2070] LOG:  server process (PID 2083) exited with exit code 2
2022-04-04 09:11:51.095 PDT [2070] DETAIL:  Failed process was running: INSERT INTO alive VALUES($$in-progress-before-sigquit$$) RETURNING status;
2022-04-04 09:11:51.095 PDT [2070] LOG:  terminating any other active server processes
2022-04-04 09:11:51.096 PDT [2070] LOG:  all server processes terminated; reinitializing
2022-04-04 09:11:51.100 PDT [2087] LOG:  database system was interrupted; last known up at 2022-04-04 09:11:50 PDT
2022-04-04 09:11:51.100 PDT [2087] LOG:  database system was not properly shut down; automatic recovery in progress
2022-04-04 09:11:51.102 PDT [2087] LOG:  redo starts at 0/15213F8
2022-04-04 09:11:51.104 PDT [2087] LOG:  invalid record length at 0/1544A58: wanted 24, got 0
2022-04-04 09:11:51.104 PDT [2087] LOG:  redo done at 0/1544A30 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2022-04-04 09:11:51.106 PDT [2088] LOG:  checkpoint starting: end-of-recovery immediate wait
2022-04-04 09:11:51.109 PDT [2088] LOG:  checkpoint complete: wrote 33 buffers (25.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.003 s; sync files=0, longest=0.000 s, average=0.000 s; distance=141 kB, estimate=141 kB
2022-04-04 09:11:51.110 PDT [2090] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.110 PDT [2090] [unknown] FATAL:  the database system is not yet accepting connections
2022-04-04 09:11:51.110 PDT [2090] [unknown] DETAIL:  Consistent recovery state has not been yet reached.
2022-04-04 09:11:51.112 PDT [2070] LOG:  database system is ready to accept connections
2022-04-04 09:11:51.226 PDT [2097] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.227 PDT [2097] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.248 PDT [2099] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.249 PDT [2099] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.263 PDT [2101] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.264 PDT [2101] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.277 PDT [2103] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.278 PDT [2103] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.279 PDT [2103] 013_crash_restart.pl LOG:  statement: SELECT pg_backend_pid();
2022-04-04 09:11:51.281 PDT [2103] 013_crash_restart.pl LOG:  statement: INSERT INTO alive VALUES($$committed-before-sigkill$$) RETURNING status;
2022-04-04 09:11:51.282 PDT [2103] 013_crash_restart.pl LOG:  statement: BEGIN;
2022-04-04 09:11:51.282 PDT [2103] 013_crash_restart.pl LOG:  statement: INSERT INTO alive VALUES($$in-progress-before-sigkill$$) RETURNING status;
2022-04-04 09:11:51.293 PDT [2105] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.294 PDT [2105] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.296 PDT [2105] 013_crash_restart.pl LOG:  statement: SELECT $$psql-connected$$;
2022-04-04 09:11:51.297 PDT [2105] 013_crash_restart.pl LOG:  statement: SELECT pg_sleep(3600);
2022-04-04 09:11:51.304 PDT [2070] LOG:  server process (PID 2103) was terminated by signal 9: Killed: 9
2022-04-04 09:11:51.304 PDT [2070] DETAIL:  Failed process was running: INSERT INTO alive VALUES($$in-progress-before-sigkill$$) RETURNING status;
2022-04-04 09:11:51.304 PDT [2070] LOG:  terminating any other active server processes
2022-04-04 09:11:51.306 PDT [2070] LOG:  all server processes terminated; reinitializing
2022-04-04 09:11:51.308 PDT [2108] LOG:  database system was interrupted; last known up at 2022-04-04 09:11:51 PDT
2022-04-04 09:11:51.309 PDT [2108] LOG:  database system was not properly shut down; automatic recovery in progress
2022-04-04 09:11:51.310 PDT [2108] LOG:  redo starts at 0/1544AD0
2022-04-04 09:11:51.311 PDT [2108] LOG:  invalid record length at 0/15490D0: wanted 24, got 0
2022-04-04 09:11:51.311 PDT [2108] LOG:  redo done at 0/15490A8 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
2022-04-04 09:11:51.313 PDT [2109] LOG:  checkpoint starting: end-of-recovery immediate wait
2022-04-04 09:11:51.315 PDT [2109] LOG:  checkpoint complete: wrote 7 buffers (5.5%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s; distance=17 kB, estimate=17 kB
2022-04-04 09:11:51.316 PDT [2070] LOG:  database system is ready to accept connections
2022-04-04 09:11:51.320 PDT [2115] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.321 PDT [2115] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.342 PDT [2117] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.343 PDT [2117] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.344 PDT [2117] 013_crash_restart.pl LOG:  statement: SELECT * FROM alive
2022-04-04 09:11:51.359 PDT [2119] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.359 PDT [2119] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.361 PDT [2119] 013_crash_restart.pl LOG:  statement: INSERT INTO alive VALUES($$before-orderly-restart$$) RETURNING status
2022-04-04 09:11:51.369 PDT [2070] LOG:  received fast shutdown request
2022-04-04 09:11:51.370 PDT [2070] LOG:  aborting any active transactions
2022-04-04 09:11:51.370 PDT [2070] LOG:  background worker "logical replication launcher" (PID 2114) exited with exit code 1
2022-04-04 09:11:51.370 PDT [2109] LOG:  shutting down
2022-04-04 09:11:51.370 PDT [2109] LOG:  checkpoint starting: shutdown immediate
2022-04-04 09:11:51.371 PDT [2109] LOG:  checkpoint complete: wrote 4 buffers (3.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=9 kB, estimate=16 kB
2022-04-04 09:11:51.373 PDT [2070] LOG:  database system is shut down
2022-04-04 09:11:51.498 PDT [2127] LOG:  starting PostgreSQL 15devel on x86_64-apple-darwin19.6.0, compiled by Apple clang version 11.0.0 (clang-1100.0.33.17), 64-bit
2022-04-04 09:11:51.498 PDT [2127] LOG:  listening on Unix socket "/var/folders/6n/3f4vwbnn7fz5qk0xqhgbjrkw0000gp/T/hDGeeFsYRd/.s.PGSQL.49823"
2022-04-04 09:11:51.504 PDT [2130] LOG:  database system was shut down at 2022-04-04 09:11:51 PDT
2022-04-04 09:11:51.507 PDT [2127] LOG:  database system is ready to accept connections
2022-04-04 09:11:51.588 PDT [2136] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.588 PDT [2136] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.597 PDT [2136] 013_crash_restart.pl LOG:  statement: SELECT * FROM alive
2022-04-04 09:11:51.611 PDT [2138] [unknown] LOG:  connection received: host=[local]
2022-04-04 09:11:51.612 PDT [2138] [unknown] LOG:  connection authorized: user=mark.dilger database=postgres application_name=013_crash_restart.pl
2022-04-04 09:11:51.613 PDT [2138] 013_crash_restart.pl LOG:  statement: INSERT INTO alive VALUES($$after-orderly-restart$$) RETURNING status
2022-04-04 09:11:51.621 PDT [2127] LOG:  received fast shutdown request
2022-04-04 09:11:51.622 PDT [2127] LOG:  aborting any active transactions
2022-04-04 09:11:51.622 PDT [2127] LOG:  background worker "logical replication launcher" (PID 2134) exited with exit code 1
2022-04-04 09:11:51.622 PDT [2128] LOG:  shutting down
2022-04-04 09:11:51.622 PDT [2128] LOG:  checkpoint starting: shutdown immediate
2022-04-04 09:11:51.624 PDT [2128] LOG:  checkpoint complete: wrote 4 buffers (3.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB
2022-04-04 09:11:51.626 PDT [2127] LOG:  database system is shut down

--Apple-Mail=_44E5CCDA-D653-4015-B165-A414CD09393C
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain;
	charset=utf-8


=E2=80=94
Mark Dilger
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company


--Apple-Mail=_44E5CCDA-D653-4015-B165-A414CD09393C--