Opened 8 months ago

Last modified 7 months ago

#68348 new defect

psql: error: connection to server on socket "/tmp/.s.PGSQL.5432" failed

Reported by: conradwt (Conrad Taylor) Owned by:
Priority: Normal Milestone:
Component: ports Version:
Keywords: Cc: jyrkiwahlstedt
Port: postgresql15-server

Description

First, I have performed the following steps on both macOS 11.7.10 (Big Sur) and macOS 14 (Sonoma):

sudo port install postgresql15-server postgresql15
sudo port select postgresql postgresql15
sudo mkdir -p /opt/local/var/db/postgresql15/defaultdb
sudo chown postgres:postgres /opt/local/var/db/postgresql15/defaultdb
sudo su postgres -c 'cd /opt/local/var/db/postgresql15 && /opt/local/lib/postgresql15/bin/initdb -D /opt/local/var/db/postgresql15/defaultdb'
sudo port load postgresql15-server

When I attempt to access psql, I'm getting the following error:

➜ psql -U postgres           
psql: error: connection to server on socket "/tmp/.s.PGSQL.5432" failed: No such file or directory
	Is the server running locally and accepting connections on that socket?

Finally, I also tried using the following command without success:

/opt/local/lib/postgresql15/bin/pg_ctl -D /opt/local/var/db/postgresql15/defaultdb -l logfile start
pg_ctl: could not open PID file "/opt/local/var/db/postgresql15/defaultdb/postmaster.pid": Permission denied

Change History (5)

comment:1 Changed 8 months ago by ryandesign (Ryan Carsten Schmidt)

Then I guess the server is not running. Did the server create a logfile? If so, what's in it?

comment:2 Changed 8 months ago by conradwt (Conrad Taylor)

PostgreSQL 15 hasn't updated the existing logfile, /opt/local/var/log/postgresql15/postgres.log, since 2 AM yesterday. Here's the contents of that file:

2023-09-27 04:35:05.604 PDT [55565] LOG:  starting PostgreSQL 15.4 on aarch64-apple-darwin23.0.0, compiled by Apple clang version 15.0.0 (clang-1500.0.40.1), 64-bit
2023-09-27 04:35:05.605 PDT [55565] LOG:  listening on IPv6 address "::1", port 5432
2023-09-27 04:35:05.606 PDT [55565] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2023-09-27 04:35:05.606 PDT [55565] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-09-27 04:35:05.624 PDT [55568] LOG:  database system was shut down at 2023-09-27 04:35:04 PDT
2023-09-27 04:35:05.628 PDT [55565] LOG:  database system is ready to accept connections
2023-09-27 04:40:05.630 PDT [55566] LOG:  checkpoint starting: time
2023-09-27 04:40:05.636 PDT [55566] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.003 s, sync=0.001 s, total=0.007 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB
2023-09-29 02:34:31.060 PDT [55565] LOG:  received smart shutdown request
2023-09-29 02:34:31.290 PDT [55565] LOG:  background worker "logical replication launcher" (PID 55571) exited with exit code 1
2023-09-29 02:34:31.700 PDT [55566] LOG:  shutting down
2023-09-29 02:34:31.703 PDT [55566] LOG:  checkpoint starting: shutdown immediate
2023-09-29 02:34:31.710 PDT [55566] LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.010 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB
2023-09-29 02:34:31.720 PDT [55565] LOG:  database system is shut down
2023-09-29 20:21:27.907 PDT [453] LOG:  starting PostgreSQL 15.4 on aarch64-apple-darwin23.0.0, compiled by Apple clang version 15.0.0 (clang-1500.0.40.1), 64-bit
2023-09-29 20:21:27.909 PDT [453] LOG:  listening on IPv6 address "::1", port 5432
2023-09-29 20:21:27.909 PDT [453] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2023-09-29 20:21:27.909 PDT [453] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-09-29 20:21:27.933 PDT [456] LOG:  database system was shut down at 2023-09-29 02:34:31 PDT
2023-09-29 20:21:27.938 PDT [453] LOG:  database system is ready to accept connections
2023-09-29 20:26:27.848 PDT [454] LOG:  checkpoint starting: time
2023-09-29 20:26:27.852 PDT [454] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.005 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB
2023-09-30 18:34:02.847 PDT [454] LOG:  checkpoint starting: time
2023-09-30 18:35:37.573 PDT [454] LOG:  checkpoint complete: wrote 937 buffers (5.7%); 0 WAL file(s) added, 0 removed, 0 recycled; write=94.705 s, sync=0.013 s, total=94.726 s; sync files=300, longest=0.001 s, average=0.001 s; distance=4296 kB, estimate=4296 kB
2023-09-30 18:49:02.572 PDT [454] LOG:  checkpoint starting: time
2023-09-30 18:49:05.915 PDT [454] LOG:  checkpoint complete: wrote 34 buffers (0.2%); 0 WAL file(s) added, 0 removed, 0 recycled; write=3.338 s, sync=0.004 s, total=3.344 s; sync files=32, longest=0.001 s, average=0.001 s; distance=126 kB, estimate=3879 kB
2023-10-01 05:11:23.123 PDT [453] LOG:  received smart shutdown request
2023-10-01 05:11:23.224 PDT [453] LOG:  background worker "logical replication launcher" (PID 459) exited with exit code 1
2023-10-01 05:11:23.606 PDT [454] LOG:  shutting down
2023-10-01 05:11:23.609 PDT [454] LOG:  checkpoint starting: shutdown immediate
2023-10-01 05:11:23.619 PDT [454] LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.003 s, sync=0.001 s, total=0.013 s; sync files=1, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=3491 kB
2023-10-01 05:11:23.628 PDT [453] LOG:  database system is shut down
2023-10-01 11:22:07.089 PDT [390] LOG:  starting PostgreSQL 15.4 on aarch64-apple-darwin23.0.0, compiled by Apple clang version 15.0.0 (clang-1500.0.40.1), 64-bit
2023-10-01 11:22:07.091 PDT [390] LOG:  listening on IPv6 address "::1", port 5432
2023-10-01 11:22:07.091 PDT [390] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2023-10-01 11:22:07.092 PDT [390] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-10-01 11:22:07.113 PDT [393] LOG:  database system was shut down at 2023-10-01 05:11:23 PDT
2023-10-01 11:22:07.117 PDT [390] LOG:  database system is ready to accept connections
2023-10-01 11:27:07.134 PDT [391] LOG:  checkpoint starting: time
2023-10-01 11:27:07.249 PDT [391] LOG:  checkpoint complete: wrote 4 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.105 s, sync=0.004 s, total=0.115 s; sync files=3, longest=0.003 s, average=0.002 s; distance=0 kB, estimate=0 kB
2023-10-01 18:07:04.821 PDT [390] LOG:  received smart shutdown request
2023-10-01 18:07:04.824 PDT [390] LOG:  background worker "logical replication launcher" (PID 396) exited with exit code 1
2023-10-01 18:07:04.824 PDT [391] LOG:  shutting down
2023-10-01 18:07:04.825 PDT [391] LOG:  checkpoint starting: shutdown immediate
2023-10-01 18:07:04.830 PDT [391] LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.006 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB
2023-10-01 18:07:04.837 PDT [390] LOG:  database system is shut down
2023-10-01 18:07:35.477 PDT [382] LOG:  starting PostgreSQL 15.4 on aarch64-apple-darwin23.0.0, compiled by Apple clang version 15.0.0 (clang-1500.0.40.1), 64-bit
2023-10-01 18:07:35.479 PDT [382] LOG:  listening on IPv6 address "::1", port 5432
2023-10-01 18:07:35.479 PDT [382] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2023-10-01 18:07:35.480 PDT [382] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-10-01 18:07:35.500 PDT [385] LOG:  database system was shut down at 2023-10-01 18:07:04 PDT
2023-10-01 18:07:35.504 PDT [382] LOG:  database system is ready to accept connections
2023-10-01 18:12:35.505 PDT [383] LOG:  checkpoint starting: time
2023-10-01 18:12:35.517 PDT [383] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.003 s, sync=0.001 s, total=0.013 s; sync files=2, longest=0.001 s, average=0.001 s; distance=0 kB, estimate=0 kB
2023-10-02 02:08:17.204 PDT [382] LOG:  received smart shutdown request
2023-10-02 02:08:17.206 PDT [382] LOG:  background worker "logical replication launcher" (PID 388) exited with exit code 1
2023-10-02 02:08:17.206 PDT [383] LOG:  shutting down
2023-10-02 02:08:17.207 PDT [383] LOG:  checkpoint starting: shutdown immediate
2023-10-02 02:08:17.212 PDT [383] LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.006 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB
2023-10-02 02:08:17.219 PDT [382] LOG:  database system is shut down

comment:3 Changed 8 months ago by conradwt (Conrad Taylor)

After a bit more research, the following appears to work without error:

sudo -u postgres pg_ctl -D /opt/local/var/db/postgresql15/defaultdb -l /opt/local/var/log/postgresql15/postgres.log start

Note: The above was derived from the following file:

/opt/local/etc/LaunchDaemons/org.macports.postgresql15-server/postgresql15-server.wrapper

However, the following no longer works as expected:

sudo port load postgresql15-server

comment:4 Changed 8 months ago by conradwt (Conrad Taylor)

During testing, I have noticed that sudo port load postgresql15-server will create the following processes:

postgres          5625   0.0  0.0 408204320   6128   ??  S     1:50PM   0:00.03 /usr/sbin/cfprefsd agent
postgres          1140   0.0  0.0 408303616  11968   ??  S    10:47AM   0:03.65 /usr/libexec/trustd --agent
postgres          1123   0.0  0.0 408283664  10496   ??  S    10:46AM   0:00.33 /usr/libexec/containermanagerd --runmode=agent --user-container-mode=current --bundle-container-mode=proxy --system-container-mode=none
postgres          1122   0.0  0.0 408462496  21248   ??  S    10:46AM   0:00.26 /usr/libexec/secd
postgres          1121   0.0  0.0 408073248   3568   ??  S    10:46AM   0:00.01 /System/Library/Frameworks/CoreServices.framework/Versions/A/Frameworks/CarbonCore.framework/Versions/A/XPCServices/csnameddatad.xpc/Contents/MacOS/csnameddatad
postgres          1120   0.0  0.0 408303136  16816   ??  S    10:46AM   0:00.08 /usr/libexec/lsd
postgres          1119   0.0  0.0 408302048  14512   ??  S    10:46AM   0:00.06 /usr/libexec/pkd
postgres          1116   0.0  0.0 408249984  30720   ??  SN   10:46AM   0:22.38 /System/Library/Frameworks/CoreServices.framework/Frameworks/Metadata.framework/Versions/A/Support/mdbulkimport -s mdworker-bundle -c MDSImporterBundleFinder -m com.apple.metadata.mdbulkimport
postgres          1107   0.0  0.0 408185888   5616   ??  S    10:46AM   0:01.32 /usr/sbin/distnoted agent
root             48917   0.0  0.0 408638096   4752   ??  Ss    6:05PM   0:00.02 /opt/local/bin/daemondo --label=postgresql15-server --start-cmd /opt/local/etc/LaunchDaemons/org.macports.postgresql15-server/postgresql15-server.wrapper start ; --stop-cmd /opt/local/etc/LaunchDaemons/org.macports.postgresql15-server/postgresql15-server.wrapper stop ; --restart-cmd /opt/local/etc/LaunchDaemons/org.macports.postgresql15-server/postgresql15-server.wrapper restart ; --pid=none

Also, when I list the contents /opt/local/var/db/postgresql15, I'm seeing the following:

➜ ls -al /opt/local/var/db/postgresql15
total 0
drwxr-xr-x@  4 postgres  postgres  128 Jun  4 03:39 .
drwxr-xr-x@  6 postgres  postgres  192 Oct  5 16:48 ..
drwx------  11 postgres  postgres  352 Jun  4 03:41 Library
drwx------  25 postgres  postgres  800 Oct  3 23:11 defaultdb

➜ sudo ls -al /opt/local/var/db/postgresql15/Library
Password:
total 0
drwx------  11 postgres  postgres  352 Jun  4 03:41 .
drwxr-xr-x@  4 postgres  postgres  128 Jun  4 03:39 ..
drwx------   6 postgres  postgres  192 Sep 27 06:16 Application Scripts
drwx------   2 postgres  postgres   64 Jun  4 03:39 Audio
drwx------   3 postgres  postgres   96 Jun  4 03:39 Caches
drwx------   3 postgres  postgres   96 Oct  1 18:28 ContainerManager
drwx------   6 postgres  postgres  192 Sep 27 06:16 Containers
drwx------   3 postgres  postgres   96 Jun  4 03:39 Keychains
drwx------   2 postgres  postgres   64 Jun  4 03:39 Mail
drwxr-xr-x   4 postgres  postgres  128 Oct  1 18:28 Preferences
drwx------   2 postgres  postgres   64 Sep 27 06:16 Staging

➜ sudo ls -al /opt/local/var/db/postgresql15/Library/Preferences
total 40
drwxr-xr-x   4 postgres  postgres    128 Oct  1 18:28 .
drwx------  11 postgres  postgres    352 Jun  4 03:41 ..
drwxr-xr-x   3 postgres  postgres     96 Jun 22 11:49 com.apple.LaunchServices
-rw-r--r--   1 postgres  postgres  20480 Jun  4 03:41 com.apple.LaunchServices.QuarantineEventsV2

This looks like a macOS Sonoma issue but I'm not sure what's going on here. Thus, this weirdness should be resolved with the next patch. However, I do not see a similar issue on macOS Big Sur regarding the folder creation and postgres processes. Finally, sudo port load postgresql15-server isn't allowing me to start the server.

Last edited 8 months ago by conradwt (Conrad Taylor) (previous) (diff)

comment:5 Changed 7 months ago by conradwt (Conrad Taylor)

The following issue, #68412, appears to be the root cause that I'm seeing in both postgresql15-server and postgresql16-server. For example, when you run the following:

➜ dscl . -read /Users/postgres UserShell  
UserShell: /usr/bin/false

As one can see, the UserShell isn't being properly set. Next, this appears to be a new security measure introduced by Apple in macOS 14.0.0 (Sonoma), macOS 11.7.10 (Big Sur), and possibly other macOS versions.

Option #1

I recommend updating the notes for all effective postgresqlXY-server ports to include the following:

macOS Catalina and newer

sudo chsh -s /bin/zsh postgres

Otherwise

sudo chsh -s /bin/bash postgres

Option #2

Add a user account and group to User & Groups within System Preferences or System Settings. I believe that this may be the better option of the two because it's easier for an end user to manage any created user accounts.

Last edited 7 months ago by conradwt (Conrad Taylor) (previous) (diff)
Note: See TracTickets for help on using tickets.