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

From: Zaphod Beeblebrox <zbeeble_at_gmail.com>
Date: Mon, 9 Aug 2021 08:40:04 -0400
IIRC, isn't the postgresql-server's default install on FreeBSD, from ports,
have TCP turned off?  IE: try editing the config (in the database
directory) to uncomment the listen directive?

On Sun, Aug 8, 2021 at 5:21 AM FreeBSD User <freebsd_at_walstatt-de.de> wrote:

> 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 Mon Aug 09 2021 - 12:40:04 UTC

Original text of this message