From nobody Sun Aug 8 09:20:05 2021 X-Original-To: freebsd-current@mlmmj.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mlmmj.nyi.freebsd.org (Postfix) with ESMTP id 1E49B1379357; Sun, 8 Aug 2021 09:20:43 +0000 (UTC) (envelope-from freebsd@walstatt-de.de) Received: from smtp1.goneo.de (smtp1.goneo.de [IPv6:2001:1640:5::8:30]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 4GjDGL1NC8z3s3M; Sun, 8 Aug 2021 09:20:41 +0000 (UTC) (envelope-from freebsd@walstatt-de.de) Received: from thor.intern.walstatt.dynvpn.de (x4dbf64fd.dyn.telefonica.de [77.191.100.253]) by smtp1.goneo.de (Postfix) with ESMTPSA id 3B6402040671; Sun, 8 Aug 2021 11:20:33 +0200 (CEST) Date: Sun, 8 Aug 2021 11:20:05 +0200 From: FreeBSD User To: FreeBSD CURRENT , FreeBSD Ports Subject: databases/postgresl13-server issue: micsompilation on IvyBridge arch? Message-ID: <20210808112032.56889213@thor.intern.walstatt.dynvpn.de> Organization: walstatt-de.de List-Id: Discussions about the use of FreeBSD-current List-Archive: https://lists.freebsd.org/archives/freebsd-current List-Help: List-Post: List-Subscribe: List-Unsubscribe: Sender: owner-freebsd-current@freebsd.org MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit X-Rspamd-Queue-Id: 4GjDGL1NC8z3s3M X-Spamd-Bar: / Authentication-Results: mx1.freebsd.org; dkim=none; dmarc=none; spf=none (mx1.freebsd.org: domain of freebsd@walstatt-de.de has no SPF policy when checking 2001:1640:5::8:30) smtp.mailfrom=freebsd@walstatt-de.de X-Spamd-Result: default: False [-0.44 / 15.00]; RCVD_VIA_SMTP_AUTH(0.00)[]; ARC_NA(0.00)[]; RCVD_IN_DNSWL_LOW(-0.10)[2001:1640:5::8:30:from]; FROM_HAS_DN(0.00)[]; TO_MATCH_ENVRCPT_ALL(0.00)[]; NEURAL_HAM_LONG(-1.00)[-1.000]; MIME_GOOD(-0.10)[text/plain]; DMARC_NA(0.00)[walstatt-de.de]; AUTH_NA(1.00)[]; HAS_ORG_HEADER(0.00)[]; RBL_AMI_RCVD_FAIL(0.00)[77.191.100.253:server fail]; NEURAL_HAM_MEDIUM(-1.00)[-1.000]; TO_DN_ALL(0.00)[]; NEURAL_HAM_SHORT(-0.24)[-0.236]; RCPT_COUNT_TWO(0.00)[2]; R_SPF_NA(0.00)[no SPF record]; FROM_EQ_ENVFROM(0.00)[]; R_DKIM_NA(0.00)[]; MIME_TRACE(0.00)[0:+]; ASN(0.00)[asn:25394, ipnet:2001:1640::/32, country:DE]; SUBJECT_ENDS_QUESTION(1.00)[]; RCVD_TLS_ALL(0.00)[]; RCVD_COUNT_TWO(0.00)[2] X-ThisMailContainsUnwantedMimeParts: N 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