From nobody Tue Aug 10 05:48:11 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 7BC551757C4A; Tue, 10 Aug 2021 05:48:26 +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 4GkMSV2F48z3Hx8; Tue, 10 Aug 2021 05:48:26 +0000 (UTC) (envelope-from freebsd@walstatt-de.de) Received: from freyja (p5de883f5.dip0.t-ipconnect.de [93.232.131.245]) by smtp1.goneo.de (Postfix) with ESMTPSA id B5158203C4E2; Tue, 10 Aug 2021 07:48:17 +0200 (CEST) Date: Tue, 10 Aug 2021 07:48:11 +0200 From: FreeBSD User To: Zaphod Beeblebrox Cc: FreeBSD CURRENT , FreeBSD Ports Subject: Re: databases/postgresl13-server issue: micsompilation on IvyBridge arch? Message-ID: <20210810074800.552d08bd@freyja> In-Reply-To: References: <20210808112032.56889213@thor.intern.walstatt.dynvpn.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: 4GkMSV2F48z3Hx8 X-Spamd-Bar: ---- Authentication-Results: mx1.freebsd.org; none X-Spamd-Result: default: False [-4.00 / 15.00]; REPLY(-4.00)[] X-ThisMailContainsUnwantedMimeParts: N On Mon, 9 Aug 2021 08:40:04 -0400 Zaphod Beeblebrox wrote: > 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? Hello and thank you very much for responding. I do not understand what you mean by "editing the config (in the database directory). Do you mean by that the postgresql.conf file? Well, this file is proper set and has been, the installation has worked well once until May the 26th. I try out to figure out what happened to CURRENT that time. In the meanwhile, I tried to rebuild CURRENT from scratch with WITHOUT_OPENSSL_KTLS set, avoiding any CPU optimization during compilation of world and postgresql - but without any effect. The pain is, that two boxes ofthe same CPU arch affected the same way, no matter what I do. > > On Sun, Aug 8, 2021 at 5:21 AM FreeBSD User 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 @ 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 > > > >