After some investigation, I think we have narrowed down
the cause of this issue.
During the crash, we found the following in the System
Logs:
09:06:13.882143 com.apple.TCC AUTHREQ_SUBJECT:
msgID=152.1570, subject=com.apple.Terminal,
09:06:13.882190 com.apple.TCC Refusing TCCAccessRequest
for service kTCCServiceSystemPolicyRemovableVolumes from
client Sub:{com.apple.Terminal}Resp:{TCCDProcess:
identifier=com.apple.Terminal, pid=43183, auid=502,
euid=502,
responsible_path=/System/Applications/Utilities/Terminal.app/Contents/MacOS/Terminal,
binary_path=/Library/PostgreSQL/16/bin/postgres} in
background session
TCC uses a small db that takes care of permissions
concerning "full disk access", microphone, camera, ...
We were able to sometimes replicate the issue when:
- doing a "find / -name tcc.db" in Terminal , it shows a
popup several times to ask for permissions (network,
documents, ...), upon accepting the permissions there is a
big chance Postgres crashes.
- enabling/disabling “Full disk access” of Postgresql in
the system preferences.
This let us to believe that the issue was related to how
the Postgres service was started. We do this manually in
Terminal by logging in as user "postgres" and running the
pg_ctl start command. Doing this will have an effect
whether the Terminal app remains open or not. In Activity
Monitor, we noticed that the hierarchy of the Postgresql
processes changes:
- Terminal is open: Kernel_task -> launchd -> Terminal ->
postgres
- quitting Terminal: Kernel_task -> launchd -> postgres
(process ids are identical)
Since then, we have been using a launch daemon to
start/stop the Postgres service. This daemon also uses the
postgres command instead of the pg_ctl command, I don't
know if this is important.
The server has been running without problems for several
weeks now.
Nick Renders
On Tue, 25 Feb 2025 14:51:25 +0100
<postg...@arcict.com> wrote:
Hello,
We experienced something strange last weekend when all
of a sudden the Postgres service was unexpectedly stopped
(see logs below).
No maintenance or scripts were running at the time, just
our usual traffic over the network doing
SELECTS/INSERTS/UPDATES on the server.
The server is a Mac Mini M2 with Postgres 16.6 running
on macOS Sequoia 15.3.1. The data is stored on a Promise
Pegasus32 R8 RAID. The machine has only been active for a
little over week, when we replaced an older Intel Mini.
It had been running fine for about 8 days, when the issue
occurred.
In the past, we have noticed a similar issue with
external drives on macOS. That issue would briefly change
the permissions of certain (or all) files on the drive
and cause Postgres to log "Operation not permitted"
errors on the postmaster.pid. I believe that issue was
caused by the macOS Spotlight features, and we circumvent
it now by excluding the drive in the System Settings.
This issue seems a little different, since this time the
Postgres process was stopped altogether.
Does this sound familiar anyone? Any ideas what might
prompt Postgres to stop?
Below are the log entries from right before the issue
occurred.
We have started Postgres again since then, and it has
been running for 3 days now, without any issues.
Thank you,
Nick Renders
2025-02-22 07:55:02.449 CET [36988] LOG: checkpoint
starting: time
2025-02-22 07:55:58.761 CET [36988] LOG: checkpoint
complete: wrote 553 buffers (3.4%); 0 WAL file(s) added,
0 removed, 0 recycled; write=56.297 s, sync=0.004 s,
total=56.312 s; sync files=95, longest=0.001 s,
average=0.001 s; distance=6687 kB, estimate=6687 kB;
lsn=7DA/F373D898, redo lsn=7DA/F350CAE0
2025-02-22 08:00:02.764 CET [36988] LOG: checkpoint
starting: time
2025-02-22 08:01:30.018 CET [36988] LOG: checkpoint
complete: wrote 849 buffers (5.2%); 1 WAL file(s) added,
0 removed, 0 recycled; write=87.225 s, sync=0.008 s,
total=87.255 s; sync files=123, longest=0.001 s,
average=0.001 s; distance=6839 kB, estimate=6839 kB;
lsn=7DA/F4F604F0, redo lsn=7DA/F3BBA748
2025-02-22 08:05:02.019 CET [36988] LOG: checkpoint
starting: time
2025-02-22 08:05:49.427 CET [30566] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.427 CET [30566] STATEMENT: SET
application_name = 'JSN4101_190147128'
2025-02-22 08:05:49.427 CET [30566] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.427 CET [30566] STATEMENT: SET
application_name = 'JSN4101_190147128'
2025-02-22 08:05:49.433 CET [12639] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.433 CET [12639] STATEMENT: SET
application_name = 'SYN4304_41252765'
2025-02-22 08:05:49.433 CET [12639] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.433 CET [12639] STATEMENT: SET
application_name = 'SYN4304_41252765'
2025-02-22 08:05:49.438 CET [12639] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.438 CET [12639] STATEMENT: SET
application_name = 'SYN4304_41252765'
2025-02-22 08:05:49.438 CET [12639] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.438 CET [12639] STATEMENT: SET
application_name = 'SYN4304_41252765'
2025-02-22 08:05:49.474 CET [30600] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.474 CET [30600] STATEMENT: SET
application_name = 'JSN4106_190147133'
2025-02-22 08:05:49.474 CET [30600] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.474 CET [30600] STATEMENT: SET
application_name = 'JSN4106_190147133'
2025-02-22 08:05:49.512 CET [30531] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.512 CET [30531] STATEMENT: SET
application_name = 'JSN4116_190147135'
2025-02-22 08:05:49.512 CET [30531] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.512 CET [30531] STATEMENT: SET
application_name = 'JSN4116_190147135'
2025-02-22 08:05:49.545 CET [30580] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.545 CET [30580] STATEMENT: SET
application_name = 'JSN4103_190147137'
2025-02-22 08:05:49.545 CET [30580] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.545 CET [30580] STATEMENT: SET
application_name = 'JSN4103_190147137'
2025-02-22 08:05:49.639 CET [30524] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.639 CET [30524] STATEMENT: SET
application_name = 'JSN4115_190147143'
2025-02-22 08:05:49.639 CET [30524] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.639 CET [30524] STATEMENT: SET
application_name = 'JSN4115_190147143'
2025-02-22 08:05:49.644 CET [30559] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.644 CET [30559] STATEMENT: SET
application_name = 'JSN4110_190147143'
2025-02-22 08:05:49.644 CET [30559] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.644 CET [30559] STATEMENT: SET
application_name = 'JSN4110_190147143'
2025-02-22 08:05:49.708 CET [30574] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.708 CET [30574] STATEMENT: SET
application_name = 'JSN4108_190147147'
2025-02-22 08:05:49.708 CET [30574] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.708 CET [30574] STATEMENT: SET
application_name = 'JSN4108_190147147'
2025-02-22 08:05:49.757 CET [30514] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.757 CET [30514] STATEMENT: SET
application_name = 'JSN4105_190147150'
2025-02-22 08:05:49.757 CET [30514] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.757 CET [30514] STATEMENT: SET
application_name = 'JSN4105_190147150'
2025-02-22 08:05:49.792 CET [30542] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.792 CET [30542] STATEMENT: SET
application_name = 'JSN4102_190147152'
2025-02-22 08:05:49.792 CET [30542] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.792 CET [30542] STATEMENT: SET
application_name = 'JSN4102_190147152'
2025-02-22 08:05:49.839 CET [30544] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.839 CET [30544] STATEMENT: SET
application_name = 'JSN4111_190147155'
2025-02-22 08:05:49.839 CET [30544] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.839 CET [30544] STATEMENT: SET
application_name = 'JSN4111_190147155'
2025-02-22 08:05:49.958 CET [30566] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.958 CET [30566] STATEMENT: SET
application_name = 'JSN4101_190147162'
2025-02-22 08:05:49.958 CET [30566] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.958 CET [30566] STATEMENT: SET
application_name = 'JSN4101_190147162'
2025-02-22 08:05:49.999 CET [30600] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.999 CET [30600] STATEMENT: SET
application_name = 'JSN4106_190147164'
2025-02-22 08:05:49.999 CET [30600] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:49.999 CET [30600] STATEMENT: SET
application_name = 'JSN4106_190147164'
2025-02-22 08:05:50.035 CET [30531] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:50.035 CET [30531] STATEMENT: SET
application_name = 'JSN4116_190147167'
2025-02-22 08:05:50.035 CET [30531] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:50.035 CET [30531] STATEMENT: SET
application_name = 'JSN4116_190147167'
2025-02-22 08:05:50.039 CET [30580] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:50.039 CET [30580] STATEMENT: SET
application_name = 'JSN4103_190147167'
2025-02-22 08:05:50.039 CET [30580] LOG: could not
write file "pg_stat_tmp/pgss_query_texts.stat": Operation
not permitted
2025-02-22 08:05:50.039 CET [30580] STATEMENT: SET
application_name = 'JSN4103_190147167'
2025-02-22 08:05:50.096 CET [30518] LOG: could not
create archive status file
"pg_wal/archive_status/00000001000007DA000000F8.ready":
Operation not permitted
2025-02-22 08:05:50.096 CET [30518] PANIC: could not
create file "pg_wal/xlogtemp.30518": Operation not
permitted
2025-02-22 08:05:50.097 CET [36986] LOG: server process
(PID 30518) was terminated by signal 6: Abort trap: 6
2025-02-22 08:05:50.097 CET [36986] DETAIL: Failed
process was running: UPDATE f_gsxws_schedule SET
gwsc_date = $1 ,
gwsc_status = $2 ,
gwsc_result_bin = $3 ,
gwsc_result_json = $4 ::json,
gwsc_result_int = $5 ,
gwsc_initiated_flag = $6 ,
gwsc_initiated_platform = $7 ,
gwsc_initiated_date = $8 ,
gwsc_edit_date = now()
WHERE gwsc_number = 18286370
2025-02-22 08:05:50.097 CET [36986] LOG: terminating
any other active server processes
2025-02-22 08:05:50.191 CET [36986] LOG: all server
processes terminated; reinitializing
2025-02-22 08:05:50.191 CET [36986] LOG: could not open
directory "base/pgsql_tmp": Operation not permitted
2025-02-22 08:05:50.191 CET [36986] LOG: could not open
directory "base": Operation not permitted
2025-02-22 08:05:50.191 CET [36986] LOG: could not open
directory "pg_tblspc": Operation not permitted
2025-02-22 08:05:50.192 CET [36986] PANIC: could not
open file "global/pg_control": Operation not permitted
