Opened 14 months ago

Last modified 13 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 14 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 14 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 14 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 14 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 14 months ago by conradwt (Conrad Taylor) (previous) (diff)

comment:5 Changed 13 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 13 months ago by conradwt (Conrad Taylor) (previous) (diff)
Note: See TracTickets for help on using tickets.