databases/postgresl13-server issue: micsompilation on IvyBridge arch?
Date: Sun, 08 Aug 2021 09:20:05 UTC
Hello,
on all(!) of my home systems based on Intel's IvyBridge CPU architecture
a) CPU microcode: updated from 0x1f to 0x21
CPU: Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz (3200.09-MHz K8-class CPU)
b) CPU microcode: updated from 0x1f to 0x21
CPU: Intel(R) Xeon(R) CPU E3-1245 V2 @ 3.40GHz (3400.09-MHz K8-class CPU)
I face a severe and nasty problem:
database/postgresql12-server, database/postgresql13-server, database/postgresql14-server, when
installed, do not allow any kind of tcp/ip connections, even on ::1 or 127.0.0.1 (localhost).
All systems in question are dual stack and fully configured using IPv6. Firewall is FreeBSD
standard IPFW running from /etc/rc.conf (port 5432/tcp is open and listening as one can check
via sockstat -4 or sockstat -6).
The hosts in question do run 14-CURRENT (with customized kernels).
Phenomenon:
Login locally via "psql -U postgres -d postgres" via socket works for ALL DB users on all
configured to access databases as expected. Login via "psql -U postgres -d postgres -h
localhost" (or any form of an IP if access tried from another remote host, even locally via
127.0.0.1 or ::1) does result in:
: psql -U postgres -d postgres -h localhost
psql: error: server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
On the server's postgresql log I always see connection attempts like:
[...]
2021-08-08 08:56:57.601 GMT [42987] LOG: connection received: host=localhost port=12340
but nothing more, no error message or any kind of timeout message.
I tried to raise the log level to debug, but it is always nothing shown execept the initial
connection attempt.
What I tried so far:
I used either self compiled ports or packages taken via pkg fetch from the official FreeBSD
pkg repos. I had LLVM suspected to miscompile something on IvyBridge. No different result so
far. Postgres 12, 13 14 fail the same way.
I installed with the above strategy vanilla databases. That includes a pg_hba.conf with the
follwoing lines (as anybody can proof):
[...]
# TYPE DATABASE USER ADDRESS METHOD
# "local" is for Unix domain socket connections only
local all all trust
# IPv4 local connections:
host all all 127.0.0.1/32 trust
# IPv6 local connections:
host all all ::1/128 trust
host all all 0.0.0.0/32 trust
host all all ::/128 trust
That should grant access via "localhost" and, for test purposes, access from any other machine
in our LAN for any user to any database.
Also, I configured postgresql13-server's postgresql.conf with following additions:
log_destination = 'syslog,stderr'
log_min_messages = debug5
log_min_error_statement = debug5
debug_print_parse = on
debug_print_rewritten = on
debug_print_plan = on
debug_pretty_print = on
log_checkpoints = on
log_connections = on
log_disconnections = on
log_duration = on
log_error_verbosity = verbose # terse, default, or verbose messages
log_hostname = on
Trying again a login from localhost via the psql command show above, gives this :
[...]
2021-08-08 09:12:12.999 GMT [55664] DEBUG: 00000: forked new backend, pid=55673 socket=12
2021-08-08 09:12:12.999 GMT [55664] LOCATION: BackendStartup, postmaster.c:4232
2021-08-08 09:12:13.000 GMT [55673] LOG: 00000: connection received: host=localhost
port=42708
2021-08-08 09:12:13.000 GMT [55673] LOCATION: BackendInitialize, postmaster.c:4385
2021-08-08 09:12:19.994 GMT [55667] DEBUG: 00000: snapshot of 0+0 running transaction ids
(lsn 0/15FF178 oldest xid 487 latest complete 486 next xid 487)
2021-08-08 09:12:19.994 GMT [55667] LOCATION: LogCurrentRunningXacts, standby.c:1124
2021-08-08 09:13:04.988 GMT [55669] DEBUG: 00000: StartTransaction(1) name: unnamed;
blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2021-08-08 09:13:04.988 GMT [55669] LOCATION: ShowTransactionStateRec, xact.c:5358
2021-08-08 09:13:04.988 GMT [55669] DEBUG: 00000: CommitTransaction(1) name: unnamed;
blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2021-08-08 09:13:04.988 GMT [55669] LOCATION: ShowTransactionStateRec, xact.c:5358
2021-08-08 09:13:04.988 GMT [55670] DEBUG: 00000: received inquiry for database 0
2021-08-08 09:13:04.988 GMT [55670] LOCATION: pgstat_recv_inquiry, pgstat.c:5872
2021-08-08 09:13:04.988 GMT [55670] DEBUG: 00000: writing stats file "pg_stat_tmp/global.stat"
2021-08-08 09:13:04.988 GMT [55670] LOCATION: pgstat_write_statsfiles, pgstat.c:4879
2021-08-08 09:13:04.988 GMT [55670] DEBUG: 00000: writing stats file "pg_stat_tmp/db_0.stat"
2021-08-08 09:13:04.988 GMT [55670] LOCATION: pgstat_write_db_statsfile, pgstat.c:5042
2021-08-08 09:13:05.000 GMT [55674] DEBUG: 00000: InitPostgres
2021-08-08 09:13:05.000 GMT [55674] LOCATION: InitPostgres, postinit.c:587
2021-08-08 09:13:05.000 GMT [55674] DEBUG: 00000: my backend ID is 3
2021-08-08 09:13:05.000 GMT [55674] LOCATION: SharedInvalBackendInit, sinvaladt.c:323
2021-08-08 09:13:05.000 GMT [55674] DEBUG: 00000: StartTransaction(1) name: unnamed;
blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2021-08-08 09:13:05.000 GMT [55674] LOCATION: ShowTransactionStateRec, xact.c:5358
2021-08-08 09:13:05.005 GMT [55674] DEBUG: 00000: CommitTransaction(1) name: unnamed;
blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2021-08-08 09:13:05.005 GMT [55674] LOCATION: ShowTransactionStateRec, xact.c:5358
2021-08-08 09:13:05.005 GMT [55674] DEBUG: 00000: autovacuum: processing database "postgres"
2021-08-08 09:13:05.005 GMT [55674] LOCATION: AutoVacWorkerMain, autovacuum.c:1686
2021-08-08 09:13:05.005 GMT [55670] DEBUG: 00000: received inquiry for database 13805
2021-08-08 09:13:05.005 GMT [55670] LOCATION: pgstat_recv_inquiry, pgstat.c:5872
2021-08-08 09:13:05.005 GMT [55670] DEBUG: 00000: writing stats file "pg_stat_tmp/global.stat"
2021-08-08 09:13:05.005 GMT [55670] LOCATION: pgstat_write_statsfiles, pgstat.c:4879
2021-08-08 09:13:05.005 GMT [55670] DEBUG: 00000: writing stats file
"pg_stat_tmp/db_13805.stat"
2021-08-08 09:13:05.005 GMT [55670] LOCATION: pgstat_write_db_statsfile, pgstat.c:5042
2021-08-08 09:13:05.005 GMT [55670] DEBUG: 00000: writing stats file "pg_stat_tmp/db_0.stat"
2021-08-08 09:13:05.005 GMT [55670] LOCATION: pgstat_write_db_statsfile, pgstat.c:5042
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: StartTransaction(1) name: unnamed;
blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2021-08-08 09:13:05.016 GMT [55674] LOCATION: ShowTransactionStateRec, xact.c:5358
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_type: vac: 0 (threshold 132), ins: 0
(threshold 1082), anl: 0 (threshold 91)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_authid: vac: 1 (threshold 52), ins: 0
(threshold 1002), anl: 1 (threshold 51)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_attribute: vac: 0 (threshold 622), ins:
0 (threshold 1572), anl: 0 (threshold 336)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_class: vac: 0 (threshold 127), ins: 0
(threshold 1077), anl: 0 (threshold 89)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_index: vac: 0 (threshold 81), ins: 0
(threshold 1031), anl: 0 (threshold 65)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_opclass: vac: 0 (threshold 76), ins: 0
(threshold 1026), anl: 0 (threshold 63)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_am: vac: 0 (threshold 51), ins: 0
(threshold 1001), anl: 0 (threshold 51)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_amproc: vac: 0 (threshold 147), ins: 0
(threshold 1097), anl: 0 (threshold 98)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: pg_database: vac: 0 (threshold 50), ins: 0
(threshold 1000), anl: 0 (threshold 50)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: relation_needs_vacanalyze, autovacuum.c:3091
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: CommitTransaction(1) name: unnamed;
blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2021-08-08 09:13:05.016 GMT [55674] LOCATION: ShowTransactionStateRec, xact.c:5358
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: shmem_exit(0): 1 before_shmem_exit
callbacks to make
2021-08-08 09:13:05.016 GMT [55674] LOCATION: shmem_exit, ipc.c:237
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: shmem_exit(0): 7 on_shmem_exit callbacks to
make
2021-08-08 09:13:05.016 GMT [55674] LOCATION: shmem_exit, ipc.c:270
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: proc_exit(0): 2 callbacks to make
2021-08-08 09:13:05.016 GMT [55674] LOCATION: proc_exit_prepare, ipc.c:197
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: exit(0)
2021-08-08 09:13:05.016 GMT [55674] LOCATION: proc_exit, ipc.c:150
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2021-08-08 09:13:05.016 GMT [55674] LOCATION: shmem_exit, ipc.c:237
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: shmem_exit(-1): 0 on_shmem_exit callbacks
to make
2021-08-08 09:13:05.016 GMT [55674] LOCATION: shmem_exit, ipc.c:270
2021-08-08 09:13:05.016 GMT [55674] DEBUG: 00000: proc_exit(-1): 0 callbacks to make
2021-08-08 09:13:05.016 GMT [55674] LOCATION: proc_exit_prepare, ipc.c:197
2021-08-08 09:13:05.018 GMT [55664] DEBUG: 00000: reaping dead processes
2021-08-08 09:13:05.018 GMT [55664] LOCATION: reaper, postmaster.c:2921
2021-08-08 09:13:05.018 GMT [55664] DEBUG: 00000: server process (PID 55674) exited with exit
code 0
2021-08-08 09:13:05.018 GMT [55664] LOCATION: LogChildExit, postmaster.c:3714
2021-08-08 09:13:13.000 GMT [55673] DEBUG: 00000: shmem_exit(1): 0 before_shmem_exit
callbacks to make
2021-08-08 09:13:13.000 GMT [55673] LOCATION: shmem_exit, ipc.c:237
2021-08-08 09:13:13.000 GMT [55673] DEBUG: 00000: shmem_exit(1): 0 on_shmem_exit callbacks to
make
2021-08-08 09:13:13.000 GMT [55673] LOCATION: shmem_exit, ipc.c:270
2021-08-08 09:13:13.000 GMT [55673] DEBUG: 00000: proc_exit(1): 1 callbacks to make
2021-08-08 09:13:13.000 GMT [55673] LOCATION: proc_exit_prepare, ipc.c:197
2021-08-08 09:13:13.000 GMT [55673] DEBUG: 00000: exit(1)
2021-08-08 09:13:13.000 GMT [55673] LOCATION: proc_exit, ipc.c:150
2021-08-08 09:13:13.000 GMT [55673] DEBUG: 00000: shmem_exit(-1): 0 before_shmem_exit
callbacks to make
2021-08-08 09:13:13.000 GMT [55673] LOCATION: shmem_exit, ipc.c:237
2021-08-08 09:13:13.000 GMT [55673] DEBUG: 00000: shmem_exit(-1): 0 on_shmem_exit callbacks
to make
2021-08-08 09:13:13.000 GMT [55673] LOCATION: shmem_exit, ipc.c:270
2021-08-08 09:13:13.000 GMT [55673] DEBUG: 00000: proc_exit(-1): 0 callbacks to make
2021-08-08 09:13:13.000 GMT [55673] LOCATION: proc_exit_prepare, ipc.c:197
2021-08-08 09:13:13.001 GMT [55664] DEBUG: 00000: reaping dead processes
2021-08-08 09:13:13.001 GMT [55664] LOCATION: reaper, postmaster.c:2921
2021-08-08 09:13:13.002 GMT [55664] DEBUG: 00000: server process (PID 55673) exited with exit
code 1
2021-08-08 09:13:13.002 GMT [55664] LOCATION: LogChildExit, postmaster.c:3714
[...]
I moved the complete DB configuration onto another Host running a more modern XEON CPU (I do
not have the arch specs at hand, but it is one of Intel's later models of the Core -i
generation 8000 I guess, purchased two years ago). We use a very similar customized kernel
there, except for the SCSI/SAS controller and some mellanox NICs (the box in question is a
Fujitsu, dual socket system).
The mysterious thing here is: nothing unusual on that box! I can run the DB in a regular
manner, login from external sites/services, use the DB for the cloud service and login via
localhost.
And now I'm out of ideas and it slowly drives my crazy. Is there something I miss?
Appreciate help, thanks in advance and
kind regards
Oliver
--
O. Hartmann