Re: Postgres 16 unexpected shutdown - Mailing list pgsql-general

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
  <postgres@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
> 
>