Broken Postgres

anatoli · March 17, 2025, 9:28am

For some reason Postgres decided it doesn’t wanna live and is constantly killed every 2 minutes. Any ideas on how to fix this?

[root@web1 ~]# tail -f /var/lib/pgsql/12/data/log/postgresql-Mon.log 
2025-03-17 10:20:43.805 CET [1359187] FATAL:  terminating connection due to administrator command
2025-03-17 10:20:43.805 CET [1359189] LOG:  terminating TimescaleDB job scheduler due to administrator command
2025-03-17 10:20:43.807 CET [1359179] LOG:  background worker "logical replication launcher" (PID 1359188) exited with exit code 1
2025-03-17 10:20:43.807 CET [1359179] LOG:  background worker "TimescaleDB Background Worker Launcher" (PID 1359187) exited with exit code 1
2025-03-17 10:20:43.807 CET [1359179] LOG:  background worker "TimescaleDB Background Worker Scheduler" (PID 1359189) exited with exit code 1
2025-03-17 10:20:43.808 CET [1359182] LOG:  shutting down
2025-03-17 10:20:43.822 CET [1359179] LOG:  database system is shut down
2025-03-17 10:20:48.778 CET [1509943] LOG:  database system was shut down at 2025-03-17 10:20:43 CET
2025-03-17 10:20:48.785 CET [1509941] LOG:  database system is ready to accept connections
2025-03-17 10:20:48.787 CET [1509950] LOG:  TimescaleDB background worker launcher connected to shared catalogs
2025-03-17 10:22:17.050 CET [1538457] FATAL:  terminating connection due to administrator command
2025-03-17 10:22:17.050 CET [1538457] STATEMENT:  SELECT pg_terminate_backend(pg_backend_pid())
2025-03-17 10:23:13.438 CET [1509941] LOG:  received fast shutdown request
2025-03-17 10:23:13.439 CET [1509941] LOG:  aborting any active transactions
2025-03-17 10:23:13.440 CET [1538373] FATAL:  terminating connection due to administrator command
2025-03-17 10:23:13.440 CET [1509952] LOG:  terminating TimescaleDB job scheduler due to administrator command
2025-03-17 10:23:13.440 CET [1509952] FATAL:  terminating connection due to administrator command
2025-03-17 10:23:13.441 CET [1509941] LOG:  background worker "logical replication launcher" (PID 1509951) exited with exit code 1
2025-03-17 10:23:13.441 CET [1509950] FATAL:  terminating connection due to administrator command
2025-03-17 10:23:13.441 CET [1557950] FATAL:  terminating connection due to administrator command
2025-03-17 10:23:13.442 CET [1509941] LOG:  background worker "TimescaleDB Background Worker Scheduler" (PID 1509952) exited with exit code 1
2025-03-17 10:23:13.443 CET [1509941] LOG:  background worker "TimescaleDB Background Worker Launcher" (PID 1509950) exited with exit code 1
2025-03-17 10:23:13.443 CET [1558177] FATAL:  terminating connection due to administrator command
2025-03-17 10:23:13.445 CET [1558006] FATAL:  terminating connection due to administrator command
2025-03-17 10:23:13.446 CET [1557911] FATAL:  terminating connection due to administrator command
2025-03-17 10:23:13.452 CET [1509945] LOG:  shutting down
2025-03-17 10:23:13.471 CET [1509941] LOG:  database system is shut down
2025-03-17 10:23:17.553 CET [1562995] LOG:  database system was shut down at 2025-03-17 10:23:13 CET
2025-03-17 10:23:17.559 CET [1562966] LOG:  database system is ready to accept connections
2025-03-17 10:23:17.561 CET [1563004] LOG:  TimescaleDB background worker launcher connected to shared catalogs
2025-03-17 10:23:18.539 CET [1563738] FATAL:  terminating connection due to administrator command
2025-03-17 10:23:18.539 CET [1563738] STATEMENT:  SELECT pg_terminate_backend(pg_backend_pid())
2025-03-17 10:24:20.075 CET [1644824] FATAL:  terminating connection due to administrator command
2025-03-17 10:24:20.075 CET [1644824] STATEMENT:  SELECT pg_terminate_backend(pg_backend_pid())

What version of apnscp are you running?

[root@web1 ~]# cpcmd misc_cp_version
WARNING: PingablePDO::__construct(): Connection failed: could not connect to server: Connection refused
	Is the server running on host "localhost" (::1) and accepting
	TCP/IP connections on port 5432?
could not connect to server: Connection refused
	Is the server running on host "localhost" (127.0.0.1) and accepting
	TCP/IP connections on port 5432?
(Exception) INTERNAL REPORT: NULL Constructor failed 
         0. Error_Reporter::report("NULL Constructor failed")
            [/usr/local/apnscp/lib/PingablePDO.php:26]

Which version of RHEL or CentOS are you using?

[root@web1 ~]# cat /etc/redhat-release
Red Hat Enterprise Linux release 8.10 (Ootpa)

Can you reproduce this bug reliably? Yes, every 2 minutes. Just leave it sit there.

anatoli · March 17, 2025, 10:43am

Temp solution not to get flooded with bug emails:

systemctl stop monit
systemctl stop apiscp
systemctl restart postgresql

gizu_72498 · March 17, 2025, 10:58am

I can confirm this bug as well… Have couple of hundred error-emails now and many non-stop notifications as well. What a morning…

anatoli · March 17, 2025, 11:43am

Oh yeah, couple hundred here too…

anatoli · March 17, 2025, 11:44am

Tried running upcp -sbf pgsql/install which should reset appldb credentials but had no luck…

Troy · March 17, 2025, 12:36pm

psql appldb works on my machine, the service shows running but the Dashboard reports it can’t connect and Monit is pissed.

Seems I’m having the same issue on all servers.

Monit Alert:

p114: [p114] postgres 
 restart - failed protocol test [PGSQL] at /tmp/.s.PGSQL.5432 -- PGSQL: response message is too large: 134217724 bytes received (maximum 1024)

Leob3n · March 17, 2025, 1:19pm

Same issue on AlmaLinux 8.10

Troy · March 17, 2025, 4:24pm

Yum downgrade monit, worked for me while Matt figures things out!

msaladna · March 17, 2025, 4:30pm

Latest Monit 5.34.5 prerelease - that provides improvements in recovering if firewalld enters panic mode - also slipped in a buffer read problem with Postgres.

Postgres isn’t the problem but rather Monit reading more data than in the buffer and issuing a restart. Looking through tildeslash’s commit log to see if I can spot the relevant change.

3615933 connect(6, {sa_family=AF_UNIX, sun_path="/tmp/.s.PGSQL.5432"}, 110) = 0
3615933 write(6, "\0\0\0&\0\3\0\0user\0root\0database\0template1\0\0", 38) = 38
3615933 poll([{fd=6, events=POLLIN}], 1, 5000) = 1 ([{fd=6, revents=POLLIN}])
3615933 read(6, "R\0\0\0\10\0\0\0\0S\0\0\0\26application_name\0\0S\0\0\0\31client_encoding\0UTF8\0S\0\0\0\27DateStyle\0ISO, MDY\0S\0\0\0\31integer_datetimes\0on\0S\0\0\0\33IntervalStyle\0postgres\0S\0\0\0\24is_superuser\0on\0S\0\0\0\31server_encoding\0UTF8\0S\0\0\0\31server_version\00010.23\0S\0\0\0\37session_authorization\0root\0S\0\0\0#standard_conforming_strings\0on\0S\0\0\0\30TimeZone\0US/Eastern\0K\0\0\0\f\0007,\277#\333\312TZ\0\0\0\5I", 1460) = 321
3615933 getsockopt(6, SOL_SOCKET, SO_TYPE, [1], [4]) = 0
3615933 shutdown(6, SHUT_RDWR)          = 0
3615933 close(6)                        = 0
3615933 write(2, "'postgres' failed protocol test [PGSQL] at /tmp/.s.PGSQL.5432 -- PGSQL: response message is too large: 134217724 bytes received (maximum 1024)\n", 143) = 143
3615933 getpid()                        = 3615933
3615933 sendto(3, "<11>Mar 17 12:25:34 monit[3615933]: 'postgres' failed protocol test [PGSQL] at /tmp/.s.PGSQL.5432 -- PGSQL: response message is too large: 134217724 bytes received (maximum 1024)\n", 179, MSG_NOSIGNAL, NULL, 0) = 179
3615933 stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=91, ...}) = 0

Unmonitoring both postgres and authlib services will be appropriate until I can track this down:

monit unmonitor postgres
monit unmonitor authlib

Troy · March 17, 2025, 5:20pm

For me, the downgrade worked where the unmonitor did not.
I didn’t dig in to find out why, since the 5.34.5 version works without issues.
5.35.0 is what fails with the posgresql monitoring.

[root@p100 ~]# monit status postgres
Monit 5.34.5 uptime: 0m

Process 'postgres'
  status                       OK
  monitoring status            Monitored

[root@p100 ~]# monit status postgres
Monit 5.35.0 uptime: 0m

Process 'postgres'
  status                       Connection failed
  monitoring status            Monitored

asheroto · March 17, 2025, 7:15pm

Same for me with PostgreSQL version 16 as of this morning.

[root@apiscp ~]# tail -f /var/lib/pgsql/16/data/log/postgresql-Mon.log
2025-03-17 19:11:59.175 UTC [2005889] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2025-03-17 19:11:59.177 UTC [2005889] LOG:  listening on Unix socket "/.socket/pgsql/.s.PGSQL.5432"
2025-03-17 19:11:59.177 UTC [2005889] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2025-03-17 19:11:59.183 UTC [2005893] LOG:  database system was shut down at 2025-03-17 19:11:58 UTC
2025-03-17 19:11:59.190 UTC [2005889] LOG:  database system is ready to accept connections
2025-03-17 19:11:59.192 UTC [2005896] LOG:  TimescaleDB background worker launcher connected to shared catalogs
2025-03-17 19:12:01.010 UTC [2005937] FATAL:  terminating connection due to administrator command
2025-03-17 19:12:01.010 UTC [2005937] STATEMENT:  SELECT pg_terminate_backend(pg_backend_pid())
2025-03-17 19:13:01.611 UTC [2006489] FATAL:  terminating connection due to administrator command
2025-03-17 19:13:01.611 UTC [2006489] STATEMENT:  SELECT pg_terminate_backend(pg_backend_pid())
2025-03-17 19:13:59.206 UTC [2005889] LOG:  received fast shutdown request
2025-03-17 19:13:59.229 UTC [2005889] LOG:  aborting any active transactions
2025-03-17 19:13:59.229 UTC [2007032] FATAL:  terminating connection due to administrator command
2025-03-17 19:13:59.229 UTC [2007066] FATAL:  terminating connection due to administrator command
2025-03-17 19:13:59.229 UTC [2007066] STATEMENT:  SELECT username, cryptpw, clearpw, uid, gid, home, maildir, quota, fullname, options FROM (SELECT uids.user||'@'||siteinfo.domain as username, NULL as cryptpw, NULL as clearpw, uid as uid, gid as gid, '/home/'||uids.user||'/' as home, 'Mail/'||COALESCE('.'||fs_destination,'') as maildir, NULL as quota, NULL as fullname, NULL as options, enabled, CASE WHEN (email_lookup.user = '') THEN 2 ELSE 1 END as pri FROM email_lookup JOIN uids USING(uid) JOIN gids USING(site_id) JOIN domain_lookup USING(domain) JOIN siteinfo ON(siteinfo.site_id = domain_lookup.site_id) WHERE ( email_lookup."user" = 'root' AND email_lookup.domain = '' OR email_lookup."user" = '' AND email_lookup.domain = '' ) AND email_lookup.type = 'v' ORDER BY PRI LIMIT 1) AS master WHERE enabled = 1::bit;
2025-03-17 19:13:59.232 UTC [2005898] FATAL:  terminating background worker "TimescaleDB Background Worker Scheduler" due to administrator command
2025-03-17 19:13:59.232 UTC [2007030] FATAL:  terminating connection due to administrator command
2025-03-17 19:13:59.234 UTC [2005896] FATAL:  terminating background worker "TimescaleDB Background Worker Launcher" due to administrator command
2025-03-17 19:13:59.234 UTC [2006153] FATAL:  terminating connection due to administrator command
2025-03-17 19:13:59.236 UTC [2005916] FATAL:  terminating connection due to administrator command
2025-03-17 19:13:59.241 UTC [2007028] FATAL:  terminating connection due to administrator command
2025-03-17 19:13:59.243 UTC [2005889] LOG:  background worker "TimescaleDB Background Worker Launcher" (PID 2005896) exited with exit code 1
2025-03-17 19:13:59.243 UTC [2005889] LOG:  background worker "logical replication launcher" (PID 2005897) exited with exit code 1
2025-03-17 19:13:59.243 UTC [2005889] LOG:  background worker "TimescaleDB Background Worker Scheduler" (PID 2005898) exited with exit code 1
2025-03-17 19:13:59.244 UTC [2005891] LOG:  shutting down
2025-03-17 19:13:59.262 UTC [2005891] LOG:  checkpoint starting: shutdown immediate
2025-03-17 19:13:59.392 UTC [2005891] LOG:  checkpoint complete: wrote 89 buffers (4.3%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.051 s, sync=0.040 s, total=0.148 s; sync files=23, longest=0.007 s, average=0.002 s; distance=655 kB, estimate=655 kB; lsn=2/616BF850, redo lsn=2/616BF850
2025-03-17 19:13:59.397 UTC [2005889] LOG:  database system is shut down
2025-03-17 19:13:59.598 UTC [2007073] LOG:  starting PostgreSQL 16.8 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-23), 64-bit
2025-03-17 19:13:59.598 UTC [2007073] LOG:  listening on IPv4 address "127.0.0.1", port 5432
2025-03-17 19:13:59.637 UTC [2007073] LOG:  listening on IPv6 address "::1", port 5432
2025-03-17 19:13:59.637 UTC [2007073] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2025-03-17 19:13:59.684 UTC [2007073] LOG:  listening on Unix socket "/.socket/pgsql/.s.PGSQL.5432"
2025-03-17 19:13:59.684 UTC [2007073] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2025-03-17 19:13:59.706 UTC [2007077] LOG:  database system was shut down at 2025-03-17 19:13:59 UTC
2025-03-17 19:13:59.717 UTC [2007078] FATAL:  the database system is starting up
2025-03-17 19:13:59.759 UTC [2007073] LOG:  database system is ready to accept connections
2025-03-17 19:13:59.760 UTC [2007081] LOG:  TimescaleDB background worker launcher connected to shared catalogs
2025-03-17 19:14:02.413 UTC [2007646] FATAL:  terminating connection due to administrator command
2025-03-17 19:14:02.413 UTC [2007646] STATEMENT:  SELECT pg_terminate_backend(pg_backend_pid())

msaladna · March 17, 2025, 7:18pm

Opened an issue with tildeslash, it won’t be visible until authorized on their part. In the meanwhile, problem linked back to commit #decd56e, removal of packed struts.

dnf clean all
dnf update -y monit

Fixed in a custom release, 5.34.4-1.20250316, that rejects this commit.

anatoli · March 18, 2025, 9:11pm

Still going for this even after the downgrade, as it keeps breaking every now and then.

Screenshot 2025-03-18 at 22.11.22

Troy · March 18, 2025, 9:26pm

Same here, still occasionally get failure notices.

msaladna · March 18, 2025, 10:28pm

I’m not seeing it on either server running 5.34.4-1.20250316 but these are checking the unix socket rather than TCP. Edit /etc/monit.d/postgres.conf, replace the if failed directive with this then systemctl restart monit

 if failed unixsocket /tmp/.s.PGSQL.5432 protocol pgsql database template1

Does this make an improvement?

asheroto · March 20, 2025, 2:49pm

I updated monit and began monitoring postgres and authlib again. So far so good, no alerts in a day or so.

Should we hold of on changing the directive unless we see more issues?

msaladna · March 20, 2025, 6:29pm

Yes, hold off for now.