Mike Bennett
Mike Bennett

Reputation: 386

DBD::Pg slow to connect to Postgresql on Mac OS

After some updates (system and brew - I don't know which was the cause), Perl's DBD:Pg is slow to establish a connection to a local Postgresql instance. It is not slow to execute queries once the connection has been established. No other utility or driver (psql, jdbc, .NET) is slow to connect.

This code creates a connection to a local postgres instance:

#!/usr/bin/env perl

use strict;
use DBI;
use DBD::Pg;
use Carp;
  
my $appname = "test-connect";
my $host = "127.0.0.1";
my $port = "5432";
my $dbname = "postgres";
my $dbuser = "postgres";
my $password = "";
my $sslmode = "disable";

carp( "************* - DBI trace settings (before)= " . (DBI->trace() // '(none)'));
DBI->trace(DBD::Pg->parse_trace_flag('pglibpq'));
carp( "************* - DBI trace settings (after)= " . (DBI->trace() // '(none)'));

# Create the connection
carp("************* - creating connection at " . localtime());
my $dbh = DBI->connect("dbi:Pg:"
  . "application_name=$appname;"
  # . "hostaddr=$host;"
  . "host=$host;"
  . "port=$port;"
  . "database=$dbname;"
  . "user=$dbuser;" 
  . "password=$password;" 
  . "sslmode=$sslmode;"
  , '', '', {AutoCommit => 0});

carp("************* - connected at " . localtime());

The output of this is:

************* - DBI trace settings (before)= 0 at ./test-db.pl line 16.
************* - DBI trace settings (after)= 16777216 at ./test-db.pl line 19.
************* - creating connection at Tue Jun 13 10:10:11 2023 at ./test-db.pl line 22.
PQconnectdb
PQstatus
PQsetNoticeProcessor
PQprotocolVersion
PQserverVersion
************* - connected at Tue Jun 13 10:11:11 2023 at ./test-db.pl line 34.

Note that it takes one minute to connect. This time occurs between these two lines:

PQconnectdb
PQstatus

On other machines, this takes no time at all.

I don't believe this is related to name resolution. If the postgresql service is down, it takes no time to recognize that and give an error.

************* - creating connection at Tue Jun 13 10:15:08 2023 at ./test-db.pl line 22.
PQconnectdb
PQstatus
PQerrorMessage
PQfinish
         DESTROY for DBI::db=HASH(0x1592fd8e0) ignored - handle not initialised
DBI connect('application_name=test-connect;host=127.0.0.1;port=5432;database=postgres;user=postgres;password=;sslmode=disable;','',...) failed: connection to server at "127.0.0.1", port 5432 failed: Connection refused
        Is the server running on that host and accepting TCP/IP connections? at ./test-db.pl line 23.
************* - connected at Tue Jun 13 10:15:08 2023 at ./test-db.pl line 34.

Switching from host to hostaddr makes no difference.

SSL is disabled. I've disabled it both in the parameters and by setting $ENV{'PGSSLMODE'} = 'disable'; with no change.

It's a vanilla local postgresql instance, installed with brew, with a vanilla local postgresql's pg_hba.conf file.

The fact that it takes exactly 60 seconds is suspicious. It's as if it's trying something and failing, but I don't know what.

EDIT: This is postgresql output with log_min_messages=debug5

2023-06-13 13:23:40.164 MDT [6961] DEBUG:  forked new backend, pid=7010 socket=11
2023-06-13 13:23:40.166 MDT [7010] LOG:  connection received: host=127.0.0.1 port=51546
2023-06-13 13:23:59.172 MDT [6966] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:23:59.172 MDT [6966] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:23:59.173 MDT [6967] DEBUG:  received inquiry for database 0
2023-06-13 13:23:59.173 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2023-06-13 13:23:59.173 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2023-06-13 13:23:59.188 MDT [7020] DEBUG:  InitPostgres
2023-06-13 13:23:59.188 MDT [7020] DEBUG:  my backend ID is 3
2023-06-13 13:23:59.188 MDT [7020] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:23:59.191 MDT [7020] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:23:59.191 MDT [7020] DEBUG:  autovacuum: processing database "postgres"
2023-06-13 13:23:59.191 MDT [6967] DEBUG:  received inquiry for database 14034
2023-06-13 13:23:59.191 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2023-06-13 13:23:59.191 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/db_14034.stat"
2023-06-13 13:23:59.192 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2023-06-13 13:23:59.202 MDT [7020] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_statistic: vac: 82 (threshold 139), ins: 0 (threshold 1089), anl: 1423 (threshold 95)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_type: vac: 134 (threshold 318), ins: 134 (threshold 1268), anl: 0 (threshold 184)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_foreign_table: vac: 10 (threshold 50), ins: 10 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_authid: vac: 0 (threshold 52), ins: 0 (threshold 1002), anl: 0 (threshold 51)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_attribute: vac: 1687 (threshold 2932), ins: 1560 (threshold 3882), anl: 0 (threshold 1491)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_proc: vac: 10 (threshold 868), ins: 10 (threshold 1818), anl: 20 (threshold 459)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_class: vac: 302 (threshold 503), ins: 239 (threshold 1453), anl: 0 (threshold 277)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_attrdef: vac: 146 (threshold 307), ins: 146 (threshold 1257), anl: 0 (threshold 178)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_constraint: vac: 198 (threshold 245), ins: 198 (threshold 1195), anl: 0 (threshold 147)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_inherits: vac: 40 (threshold 50), ins: 40 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_index: vac: 216 (threshold 299), ins: 216 (threshold 1249), anl: 0 (threshold 175)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_operator: vac: 21 (threshold 211), ins: 30 (threshold 1161), anl: 40 (threshold 130)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_opclass: vac: 0 (threshold 85), ins: 0 (threshold 1035), anl: 0 (threshold 68)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_am: vac: 0 (threshold 51), ins: 0 (threshold 1001), anl: 0 (threshold 51)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_amop: vac: 0 (threshold 239), ins: 0 (threshold 1189), anl: 0 (threshold 144)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_amproc: vac: 0 (threshold 189), ins: 0 (threshold 1139), anl: 0 (threshold 120)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_language: vac: 0 (threshold 51), ins: 0 (threshold 1001), anl: 0 (threshold 50)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_largeobject_metadata: vac: 40 (threshold 55), ins: 52 (threshold 1005), anl: 36 (threshold 52)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_aggregate: vac: 0 (threshold 79), ins: 0 (threshold 1029), anl: 0 (threshold 64)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_rewrite: vac: 20 (threshold 95), ins: 20 (threshold 1045), anl: 0 (threshold 72)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_trigger: vac: 384 (threshold 615), ins: 320 (threshold 1565), anl: 224 (threshold 332)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_description: vac: 202 (threshold 1068), ins: 202 (threshold 2018), anl: 404 (threshold 559)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_cast: vac: 0 (threshold 96), ins: 0 (threshold 1046), anl: 0 (threshold 73)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_enum: vac: 20 (threshold 53), ins: 20 (threshold 1003), anl: 40 (threshold 52)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_namespace: vac: 48 (threshold 52), ins: 48 (threshold 1002), anl: 48 (threshold 51)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_depend: vac: 3580 (threshold 4729), ins: 3580 (threshold 5679), anl: 2336 (threshold 2389)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_database: vac: 0 (threshold 52), ins: 0 (threshold 1002), anl: 0 (threshold 51)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_tablespace: vac: 0 (threshold 50), ins: 0 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_shdepend: vac: 560 (threshold 935), ins: 572 (threshold 1885), anl: 482 (threshold 492)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_foreign_data_wrapper: vac: 10 (threshold 50), ins: 10 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_foreign_server: vac: 10 (threshold 50), ins: 10 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_collation: vac: 0 (threshold 263), ins: 0 (threshold 1213), anl: 0 (threshold 157)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_sequence: vac: 88 (threshold 93), ins: 68 (threshold 1043), anl: 66 (threshold 72)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_publication: vac: 0 (threshold 50), ins: 0 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_subscription_rel: vac: 0 (threshold 50), ins: 0 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:23:59.203 MDT [7020] DEBUG:  pg_largeobject: vac: 68 (threshold 72), ins: 138 (threshold 1022), anl: 54 (threshold 61)
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  sys_users: vac: 0 (threshold 50), ins: 0 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  pg_toast_2619: vac: 38 (threshold 52), ins: 38 (threshold 1002), anl: 76 (threshold 51)
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  pg_toast_2618: vac: 0 (threshold 107), ins: 0 (threshold 1057), anl: 0 (threshold 78)
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  shmem_exit(0): 8 on_shmem_exit callbacks to make
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  proc_exit(0): 2 callbacks to make
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  exit(0)
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2023-06-13 13:23:59.204 MDT [7020] DEBUG:  proc_exit(-1): 0 callbacks to make
2023-06-13 13:23:59.205 MDT [6961] DEBUG:  reaping dead processes
2023-06-13 13:23:59.205 MDT [6961] DEBUG:  server process (PID 7020) exited with exit code 0
2023-06-13 13:24:29.274 MDT [6966] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:24:29.275 MDT [6966] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:24:29.275 MDT [6967] DEBUG:  received inquiry for database 0
2023-06-13 13:24:29.275 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2023-06-13 13:24:29.276 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2023-06-13 13:24:29.291 MDT [7021] DEBUG:  InitPostgres
2023-06-13 13:24:29.291 MDT [7021] DEBUG:  my backend ID is 3
2023-06-13 13:24:29.292 MDT [7021] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:24:29.294 MDT [7021] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:24:29.294 MDT [7021] DEBUG:  autovacuum: processing database "landview_dev"
2023-06-13 13:24:29.294 MDT [6967] DEBUG:  received inquiry for database 90753
2023-06-13 13:24:29.294 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/global.stat"
2023-06-13 13:24:29.294 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/db_90753.stat"
2023-06-13 13:24:29.295 MDT [6967] DEBUG:  writing stats file "pg_stat_tmp/db_0.stat"
2023-06-13 13:24:29.306 MDT [7021] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_statistic: vac: 4 (threshold 582), ins: 0 (threshold 1532), anl: 14 (threshold 316)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_type: vac: 0 (threshold 318), ins: 0 (threshold 1268), anl: 0 (threshold 184)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_authid: vac: 0 (threshold 52), ins: 0 (threshold 1002), anl: 0 (threshold 51)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_attribute: vac: 0 (threshold 2932), ins: 0 (threshold 3882), anl: 0 (threshold 1491)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_proc: vac: 0 (threshold 873), ins: 0 (threshold 1823), anl: 0 (threshold 462)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_class: vac: 0 (threshold 503), ins: 0 (threshold 1453), anl: 0 (threshold 277)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_attrdef: vac: 0 (threshold 307), ins: 0 (threshold 1257), anl: 0 (threshold 178)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_index: vac: 0 (threshold 299), ins: 0 (threshold 1249), anl: 0 (threshold 175)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_operator: vac: 0 (threshold 221), ins: 0 (threshold 1171), anl: 0 (threshold 136)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_opclass: vac: 0 (threshold 85), ins: 0 (threshold 1035), anl: 0 (threshold 68)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_am: vac: 0 (threshold 51), ins: 0 (threshold 1001), anl: 0 (threshold 51)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_amop: vac: 0 (threshold 239), ins: 0 (threshold 1189), anl: 0 (threshold 144)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_amproc: vac: 0 (threshold 189), ins: 0 (threshold 1139), anl: 0 (threshold 120)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_trigger: vac: 0 (threshold 615), ins: 0 (threshold 1565), anl: 0 (threshold 332)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_cast: vac: 0 (threshold 96), ins: 0 (threshold 1046), anl: 0 (threshold 73)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_namespace: vac: 0 (threshold 51), ins: 0 (threshold 1001), anl: 0 (threshold 50)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_database: vac: 0 (threshold 52), ins: 0 (threshold 1002), anl: 0 (threshold 51)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_tablespace: vac: 0 (threshold 50), ins: 0 (threshold 1000), anl: 0 (threshold 50)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  pg_shdepend: vac: 560 (threshold 936), ins: 572 (threshold 1886), anl: 482 (threshold 493)
2023-06-13 13:24:29.307 MDT [7021] DEBUG:  sys_users: vac: 0 (threshold 69), ins: 0 (threshold 1019), anl: 0 (threshold 59)
2023-06-13 13:24:29.308 MDT [7021] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 13:24:29.308 MDT [7021] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2023-06-13 13:24:29.308 MDT [7021] DEBUG:  shmem_exit(0): 8 on_shmem_exit callbacks to make
2023-06-13 13:24:29.308 MDT [7021] DEBUG:  proc_exit(0): 2 callbacks to make
2023-06-13 13:24:29.308 MDT [7021] DEBUG:  exit(0)
2023-06-13 13:24:29.308 MDT [7021] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2023-06-13 13:24:29.308 MDT [7021] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2023-06-13 13:24:29.308 MDT [7021] DEBUG:  proc_exit(-1): 0 callbacks to make
2023-06-13 13:24:29.309 MDT [6961] DEBUG:  reaping dead processes
2023-06-13 13:24:29.309 MDT [6961] DEBUG:  server process (PID 7021) exited with exit code 0
2023-06-13 13:24:40.169 MDT [6961] DEBUG:  reaping dead processes
2023-06-13 13:24:40.169 MDT [6961] DEBUG:  server process (PID 7010) exited with exit code 1
2023-06-13 13:24:41.602 MDT [6961] DEBUG:  forked new backend, pid=7022 socket=11
2023-06-13 13:24:41.604 MDT [7022] LOG:  connection received: host=127.0.0.1 port=51555
2023-06-13 13:24:41.604 MDT [7022] DEBUG:  InitPostgres
2023-06-13 13:24:41.604 MDT [7022] DEBUG:  my backend ID is 3
2023-06-13 13:24:41.605 MDT [7022] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0

We see the initial connection:

2023-06-13 13:23:40.166 MDT [7010] LOG:  connection received: host=127.0.0.1 port=51546

This connection eventually fails. The client retries and succeeds:

2023-06-13 13:24:41.604 MDT [7022] LOG:  connection received: host=127.0.0.1 port=51555

EDIT: If we remove the background stuff, it is just:

2023-06-13 13:23:40.164 MDT [6961] DEBUG:  forked new backend, pid=7010 socket=11
2023-06-13 13:23:40.166 MDT [7010] LOG:  connection received: host=127.0.0.1 port=51546
2023-06-13 13:24:41.604 MDT [7022] LOG:  connection received: host=127.0.0.1 port=51555
2023-06-13 13:24:41.604 MDT [7022] DEBUG:  InitPostgres
2023-06-13 13:24:41.604 MDT [7022] DEBUG:  my backend ID is 3
2023-06-13 13:24:41.605 MDT [7022] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0

I don't know enough about Postgresql to glean why or how that first connection is failing.

For comparison, here's a successful connection on a colleague's machine:

2023-06-13 14:33:09.962 MDT [1719] DEBUG:  forked new backend, pid=2203 socket=11
2023-06-13 14:33:09.962 MDT [2203] LOG:  connection received: host=127.0.0.1 port=53268
2023-06-13 14:33:10.028 MDT [2203] DEBUG:  InitPostgres
2023-06-13 14:33:10.028 MDT [2203] DEBUG:  my backend ID is 3
2023-06-13 14:33:10.028 MDT [2203] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 14:33:10.028 MDT [2203] LOG:  connection authorized: user=postgres database=postgres
2023-06-13 14:33:10.042 MDT [2203] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-06-13 14:33:10.043 MDT [2203] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2023-06-13 14:33:10.043 MDT [2203] DEBUG:  shmem_exit(0): 7 on_shmem_exit callbacks to make
2023-06-13 14:33:10.043 MDT [2203] DEBUG:  proc_exit(0): 3 callbacks to make
2023-06-13 14:33:10.043 MDT [2203] DEBUG:  exit(0)
2023-06-13 14:33:10.043 MDT [2203] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2023-06-13 14:33:10.043 MDT [2203] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2023-06-13 14:33:10.043 MDT [2203] DEBUG:  proc_exit(-1): 0 callbacks to make
2023-06-13 14:33:10.044 MDT [1719] DEBUG:  reaping dead processes
2023-06-13 14:33:10.044 MDT [1719] DEBUG:  server process (PID 2203) exited with exit code 0

Upvotes: 3

Views: 1065

Answers (1)

Mike Bennett
Mike Bennett

Reputation: 386

The problem turned out to be Postgresql's GSS encryption, which broke on my Mac. The problem was not particular to Perl but was with libpq itself. I don't yet know why GSS is failing. According to the docs, it is not normally used in Unix socket communication.

gssencmode

    This option determines whether or with what priority a secure GSS TCP/IP connection will be negotiated with the server. There are three modes:

    disable
        only try a non-GSSAPI-encrypted connection

    prefer (default)
        if there are GSSAPI credentials present (i.e., in a credentials cache), first try a GSSAPI-encrypted connection; if that fails or there are no credentials, try a non-GSSAPI-encrypted connection. This is the default when PostgreSQL has been compiled with GSSAPI support.

    require
        only try a GSSAPI-encrypted connection

    gssencmode is ignored for Unix domain socket communication. If PostgreSQL is compiled without GSSAPI support, using the require option will cause an error, while prefer will be accepted but libpq will not actually attempt a GSSAPI-encrypted connection.

The setting can be controlled with an environment variable, and so setting PGGSSENCMODE="disable" fixes the problem.

Upvotes: 10

Related Questions