databases/postgresl13-server issue: micsompilation on IvyBridge arch?

From: FreeBSD User <freebsd_at_walstatt-de.de>
Date: Sun, 8 Aug 2021 11:20:05 +0200
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 _at_ 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 _at_ 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
Received on Sun Aug 08 2021 - 09:20:05 UTC

Original text of this message