Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1puhTq-0000uI-Ji for pgsql-admin@arkaria.postgresql.org; Thu, 04 May 2023 22:31:18 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1puhTp-0001oR-EG for pgsql-admin@arkaria.postgresql.org; Thu, 04 May 2023 22:31:17 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1puhTp-0001oH-1X for pgsql-admin@lists.postgresql.org; Thu, 04 May 2023 22:31:17 +0000 Received: from mout-u-107.mailbox.org ([2001:67c:2050:101:465::107]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1puhTl-000c6D-9k for pgsql-admin@lists.postgresql.org; Thu, 04 May 2023 22:31:16 +0000 Received: from smtp102.mailbox.org (smtp102.mailbox.org [IPv6:2001:67c:2050:b231:465::102]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange ECDHE (P-384) server-signature RSA-PSS (4096 bits) server-digest SHA256) (No client certificate requested) by mout-u-107.mailbox.org (Postfix) with ESMTPS id 4QC7nl4wSJz9sTq; Fri, 5 May 2023 00:31:07 +0200 (CEST) Date: Fri, 5 May 2023 00:31:06 +0200 (CEST) From: Erik Wienhold To: Rui DeSousa Cc: "pgsql-admin@lists.postgresql.org" Message-ID: <1151082415.1702693.1683239466943@office.mailbox.org> In-Reply-To: <10E1C934-CAAF-4863-A774-714B92DFC251@crazybean.net> References: <1123557200.1646445.1683195543242@office.mailbox.org> <10E1C934-CAAF-4863-A774-714B92DFC251@crazybean.net> Subject: Re: pg_stat_activity.client_addr sometimes null for host connections MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable X-Priority: 3 Importance: Normal X-Rspamd-Queue-Id: 4QC7nl4wSJz9sTq List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk > On 04/05/2023 18:31 CEST Rui DeSousa wrote: > > > On May 4, 2023, at 6:19 AM, Erik Wienhold wrote: > > > > I have a process that regularly queries pg_stat_activity for user conne= ctions. > > Today I noticed an error because sometimes client_addr is null for some= user > > connections. pg_hba.conf only allows host connections. So client_addr= should > > not be null according to [0]. pg_stat_activity is queried as superuser= who > > should see client_addr for all connections, not just his own. > > > > This is on v12.14 on Windows Server (regular EnterpriseDB install). Is= this a > > known issue or just an undocumented corner case? > > > > [0] https://www.postgresql.org/docs/12/monitoring-stats.html#PG-STAT-AC= TIVITY-VIEW > > > > =E2=80=94 > > Erik > > > > > > Are those local connections, as those will not have a client_addr? What = does > your pg_hba look like? Connection type is host for all entries (as I already mentioned). The user= s don't even have access to the server to open a local connection. pg_hba_file_rules: line_number | type | database | user_name | address | = netmask | auth_method | options | error -------------+------+---------------+--------------------+--------------+--= ---------------------------------------+-------------+---------+------- 80 | host | {all} | {all} | 127.0.0.1 | 2= 55.255.255.255 | md5 | | 82 | host | {all} | {all} | ::1 | f= fff:ffff:ffff:ffff:ffff:ffff:ffff:ffff | md5 | | 87 | host | {replication} | {all} | 127.0.0.1 | 2= 55.255.255.255 | md5 | | 88 | host | {replication} | {all} | ::1 | f= fff:ffff:ffff:ffff:ffff:ffff:ffff:ffff | md5 | | 90 | host | {postgres} | {barman} | 10.69.133.98 | 2= 55.255.255.255 | md5 | | 91 | host | {postgres} | {streaming_barman} | 10.69.133.98 | 2= 55.255.255.255 | md5 | | 92 | host | {replication} | {streaming_barman} | 10.69.133.98 | 2= 55.255.255.255 | md5 | | 96 | host | {all} | {all} | 10.49.24.0 | 2= 55.255.255.0 | md5 | | 97 | host | {all} | {all} | 10.49.40.0 | 2= 55.255.255.0 | md5 | | 98 | host | {all} | {all} | 10.49.41.0 | 2= 55.255.255.0 | md5 | | 99 | host | {all} | {all} | 10.49.42.0 | 2= 55.255.255.0 | md5 | | 100 | host | {all} | {all} | 10.49.43.0 | 2= 55.255.255.0 | md5 | | 101 | host | {all} | {all} | 10.49.44.0 | 2= 55.255.255.0 | md5 | | 102 | host | {all} | {all} | 10.49.45.0 | 2= 55.255.255.0 | md5 | | 103 | host | {all} | {all} | 10.49.46.0 | 2= 55.255.255.0 | md5 | | 104 | host | {all} | {all} | 10.49.47.0 | 2= 55.255.255.0 | md5 | | 107 | host | {all} | {all} | 10.63.133.0 | 2= 55.255.252.0 | md5 | | 110 | host | {all} | {all} | 10.70.64.0 | 2= 55.255.254.0 | md5 | | 111 | host | {all} | {all} | 10.70.66.0 | 2= 55.255.255.0 | md5 | | 112 | host | {all} | {all} | 10.70.67.0 | 2= 55.255.255.0 | md5 | | 113 | host | {all} | {all} | 10.70.68.0 | 2= 55.255.255.0 | md5 | | 114 | host | {all} | {all} | 10.70.69.0 | 2= 55.255.255.0 | md5 | | 115 | host | {all} | {all} | 10.70.70.0 | 2= 55.255.255.0 | md5 | | 116 | host | {all} | {all} | 10.70.71.0 | 2= 55.255.255.0 | md5 | | 117 | host | {all} | {all} | 10.70.73.0 | 2= 55.255.255.0 | md5 | | 118 | host | {all} | {all} | 10.70.74.0 | 2= 55.255.255.0 | md5 | | 119 | host | {all} | {all} | 10.70.75.0 | 2= 55.255.255.0 | md5 | | 120 | host | {all} | {all} | 10.70.90.0 | 2= 55.255.255.0 | md5 | | 121 | host | {all} | {all} | 10.70.99.0 | 2= 55.255.255.0 | md5 | | 122 | host | {all} | {all} | 10.70.100.0 | 2= 55.255.255.0 | md5 | | 123 | host | {all} | {all} | 10.120.16.0 | 2= 55.255.255.0 | md5 | | 124 | host | {all} | {all} | 10.125.136.0 | 2= 55.255.255.0 | md5 | | 127 | host | {all} | {***REDACTED***} | 10.181.161.0 | 2= 55.255.255.0 | md5 | | (33 rows) The last change and reload of pg_hba.conf was on 2023-04-24. The file has = not been modified since. I got a log for the error and it occurs as early as 2022-03-01. The server= was running v12.10 at that time. The first 4 columns are from pg_stat_activity extracted from the log's deta= il message. Notice the short interval between state_change and log_time. The clients a= ll happen to just change state when querying pg_stat_activity. Could there be a race condition between executing pg_stat_get_activity(null) and the serve= r cleaning up closed connections? Closed connections still appear but the so= cket address is no longer available? pid | usesysid | datid | state_change | log= _time | log_time - state_change -------+----------+----------+-------------------------------+-------------= ---------------+------------------------- 11436 | 9034571 | 13643185 | 2022-03-01 14:40:18.193012+01 | 2022-03-01 1= 4:40:18.198+01 | 00:00:00.004988 5028 | 2142762 | 16394 | 2022-05-24 11:38:18.410533+02 | 2022-05-24 1= 1:38:18.415+02 | 00:00:00.004467 3192 | 16393 | 14884324 | 2022-07-22 09:34:18.434034+02 | 2022-07-22 0= 9:34:18.438+02 | 00:00:00.003966 9628 | 34349 | 13805996 | 2022-08-02 07:23:29.302691+02 | 2022-08-02 0= 7:23:29.313+02 | 00:00:00.010309 9596 | 16393 | 13805996 | 2022-08-05 16:08:29.507613+02 | 2022-08-05 1= 6:08:29.512+02 | 00:00:00.004387 6344 | 16393 | 13805996 | 2022-10-20 13:47:28.843096+02 | 2022-10-20 1= 3:47:28.848+02 | 00:00:00.004904 3752 | 16393 | 13805996 | 2022-10-20 14:32:29.311198+02 | 2022-10-20 1= 4:32:29.321+02 | 00:00:00.009802 9784 | 2142762 | 13805996 | 2022-10-20 14:37:29.766515+02 | 2022-10-20 1= 4:37:29.773+02 | 00:00:00.006485 5456 | 16130084 | 16136740 | 2022-11-21 21:45:29.319827+01 | 2022-11-21 2= 1:45:29.324+01 | 00:00:00.004173 5456 | 16130084 | 16136740 | 2022-11-21 21:46:29.278565+01 | 2022-11-21 2= 1:46:29.299+01 | 00:00:00.020435 5456 | 16130084 | 16136740 | 2022-11-21 21:47:29.385187+01 | 2022-11-21 2= 1:47:29.393+01 | 00:00:00.007813 5456 | 16130084 | 16136740 | 2022-11-21 21:48:29.295469+01 | 2022-11-21 2= 1:48:29.3+01 | 00:00:00.004531 9764 | 16130084 | 16136740 | 2022-11-21 22:09:29.858269+01 | 2022-11-21 2= 2:09:29.863+01 | 00:00:00.004731 9764 | 16130084 | 16136740 | 2022-11-21 22:10:29.506984+01 | 2022-11-21 2= 2:10:29.511+01 | 00:00:00.004016 9764 | 16130084 | 16136740 | 2022-11-21 22:11:29.538942+01 | 2022-11-21 2= 2:11:29.544+01 | 00:00:00.005058 9764 | 16130084 | 16136740 | 2022-11-21 22:12:29.43297+01 | 2022-11-21 2= 2:12:29.438+01 | 00:00:00.00503 9764 | 16130084 | 16136740 | 2022-11-21 22:13:29.606039+01 | 2022-11-21 2= 2:13:29.611+01 | 00:00:00.004961 8360 | 16393 | 16978159 | 2023-02-03 16:07:29.660733+01 | 2023-02-03 1= 6:07:29.665+01 | 00:00:00.004267 8360 | 16393 | 16978159 | 2023-02-03 16:08:29.660019+01 | 2023-02-03 1= 6:08:29.665+01 | 00:00:00.004981 8360 | 16393 | 16978159 | 2023-02-03 16:09:29.542798+01 | 2023-02-03 1= 6:09:29.547+01 | 00:00:00.004202 8360 | 16393 | 16978159 | 2023-02-03 16:10:29.511686+01 | 2023-02-03 1= 6:10:29.517+01 | 00:00:00.005314 8360 | 16393 | 16978159 | 2023-02-03 16:11:29.727772+01 | 2023-02-03 1= 6:11:29.737+01 | 00:00:00.009228 8872 | 19920816 | 15526205 | 2023-03-15 18:11:29.567727+01 | 2023-03-15 1= 8:11:29.587+01 | 00:00:00.019273 5844 | 19920816 | 15526205 | 2023-03-15 18:14:29.576651+01 | 2023-03-15 1= 8:14:29.597+01 | 00:00:00.020349 1360 | 2142762 | 16978159 | 2023-03-16 13:30:31.409793+01 | 2023-03-16 1= 3:30:31.418+01 | 00:00:00.008207 4844 | 4324803 | 16978159 | 2023-03-21 09:26:33.968217+01 | 2023-03-21 0= 9:26:33.978+01 | 00:00:00.009783 2008 | 16393 | 16978159 | 2023-03-22 14:33:32.389439+01 | 2023-03-22 1= 4:33:32.398+01 | 00:00:00.008561 5136 | 19920816 | 17673077 | 2023-03-24 22:52:32.635385+01 | 2023-03-24 2= 2:52:32.644+01 | 00:00:00.008615 5148 | 19920816 | 17673077 | 2023-03-24 22:59:33.305081+01 | 2023-03-24 2= 2:59:33.315+01 | 00:00:00.009919 3512 | 19920816 | 17673077 | 2023-03-24 23:00:34.104535+01 | 2023-03-24 2= 3:00:34.111+01 | 00:00:00.006465 2728 | 16393 | 16978159 | 2023-04-11 13:05:32.674562+02 | 2023-04-11 1= 3:05:32.681+02 | 00:00:00.006438 4164 | 16393 | 16978159 | 2023-04-11 13:27:32.761902+02 | 2023-04-11 1= 3:27:32.767+02 | 00:00:00.005098 6248 | 19920816 | 16978159 | 2023-04-12 22:01:31.753148+02 | 2023-04-12 2= 2:01:31.761+02 | 00:00:00.007852 6248 | 19920816 | 16978159 | 2023-04-12 22:02:31.830579+02 | 2023-04-12 2= 2:02:31.838+02 | 00:00:00.007421 6248 | 19920816 | 16978159 | 2023-04-12 22:03:32.545472+02 | 2023-04-12 2= 2:03:32.553+02 | 00:00:00.007528 6248 | 19920816 | 16978159 | 2023-04-12 22:04:31.835557+02 | 2023-04-12 2= 2:04:31.842+02 | 00:00:00.006443 7652 | 19920816 | 16978159 | 2023-04-12 22:44:33.142687+02 | 2023-04-12 2= 2:44:33.158+02 | 00:00:00.015313 7652 | 19920816 | 16978159 | 2023-04-12 22:45:32.22895+02 | 2023-04-12 2= 2:45:32.241+02 | 00:00:00.01205 7652 | 19920816 | 16978159 | 2023-04-12 22:46:32.155199+02 | 2023-04-12 2= 2:46:32.162+02 | 00:00:00.006801 7652 | 19920816 | 16978159 | 2023-04-12 22:47:32.226809+02 | 2023-04-12 2= 2:47:32.234+02 | 00:00:00.007191 7652 | 19920816 | 16978159 | 2023-04-12 22:48:32.249175+02 | 2023-04-12 2= 2:48:32.257+02 | 00:00:00.007825 7652 | 19920816 | 16978159 | 2023-04-12 22:49:32.363036+02 | 2023-04-12 2= 2:49:32.37+02 | 00:00:00.006964 7652 | 19920816 | 16978159 | 2023-04-12 22:50:32.167531+02 | 2023-04-12 2= 2:50:32.175+02 | 00:00:00.007469 7652 | 19920816 | 16978159 | 2023-04-12 22:51:32.169011+02 | 2023-04-12 2= 2:51:32.175+02 | 00:00:00.005989 7652 | 19920816 | 16978159 | 2023-04-12 22:52:32.136483+02 | 2023-04-12 2= 2:52:32.145+02 | 00:00:00.008517 7652 | 19920816 | 16978159 | 2023-04-12 22:53:32.247358+02 | 2023-04-12 2= 2:53:32.255+02 | 00:00:00.007642 7652 | 19920816 | 16978159 | 2023-04-12 22:54:32.225536+02 | 2023-04-12 2= 2:54:32.233+02 | 00:00:00.007464 7652 | 19920816 | 16978159 | 2023-04-12 22:55:32.205943+02 | 2023-04-12 2= 2:55:32.214+02 | 00:00:00.008057 7652 | 19920816 | 16978159 | 2023-04-12 22:56:32.313652+02 | 2023-04-12 2= 2:56:32.327+02 | 00:00:00.013348 7652 | 19920816 | 16978159 | 2023-04-12 22:57:32.310341+02 | 2023-04-12 2= 2:57:32.324+02 | 00:00:00.013659 7652 | 19920816 | 16978159 | 2023-04-12 22:58:32.178025+02 | 2023-04-12 2= 2:58:32.188+02 | 00:00:00.009975 5464 | 29593 | 16978159 | 2023-04-13 09:40:32.163192+02 | 2023-04-13 0= 9:40:32.171+02 | 00:00:00.007808 5008 | 29593 | 16978159 | 2023-04-13 12:52:32.133676+02 | 2023-04-13 1= 2:52:32.147+02 | 00:00:00.013324 10072 | 292899 | 16978159 | 2023-04-25 16:02:32.28129+02 | 2023-04-25 1= 6:02:32.289+02 | 00:00:00.00771 2864 | 55697 | 16978159 | 2023-04-27 09:23:32.54067+02 | 2023-04-27 0= 9:23:32.552+02 | 00:00:00.01133 2864 | 55697 | 16978159 | 2023-04-27 09:24:32.503118+02 | 2023-04-27 0= 9:24:32.51+02 | 00:00:00.006882 9956 | 19920816 | 15526205 | 2023-04-27 17:51:33.165037+02 | 2023-04-27 1= 7:51:33.174+02 | 00:00:00.008963 5448 | 19920816 | 15526205 | 2023-04-27 17:58:33.387277+02 | 2023-04-27 1= 7:58:33.396+02 | 00:00:00.008723 2268 | 16393 | 16978159 | 2023-05-03 09:09:33.176452+02 | 2023-05-03 0= 9:09:33.187+02 | 00:00:00.010548 2268 | 16393 | 16978159 | 2023-05-03 09:10:33.171076+02 | 2023-05-03 0= 9:10:33.181+02 | 00:00:00.009924 3160 | 2142762 | 16978159 | 2023-05-03 13:30:31.911463+02 | 2023-05-03 1= 3:30:31.923+02 | 00:00:00.011537 9696 | 292899 | 13643185 | 2023-05-04 08:30:32.816732+02 | 2023-05-04 0= 8:30:32.834+02 | 00:00:00.017268 8004 | 19920817 | 16978159 | 2023-05-04 08:56:32.430163+02 | 2023-05-04 0= 8:56:32.44+02 | 00:00:00.009837 7152 | 19920817 | 16978159 | 2023-05-04 08:57:32.068336+02 | 2023-05-04 0= 8:57:32.076+02 | 00:00:00.007664 7152 | 19920817 | 16978159 | 2023-05-04 08:58:32.346978+02 | 2023-05-04 0= 8:58:32.356+02 | 00:00:00.009022 7152 | 19920817 | 16978159 | 2023-05-04 08:59:32.149638+02 | 2023-05-04 0= 8:59:32.159+02 | 00:00:00.009362 7476 | 19920817 | 16978159 | 2023-05-04 09:05:36.285914+02 | 2023-05-04 0= 9:05:36.295+02 | 00:00:00.009086 5020 | 19920817 | 16978159 | 2023-05-04 09:09:34.760794+02 | 2023-05-04 0= 9:09:34.775+02 | 00:00:00.014206 1208 | 19920817 | 16978159 | 2023-05-04 09:23:32.33564+02 | 2023-05-04 0= 9:23:32.344+02 | 00:00:00.00836 8824 | 19920817 | 16978159 | 2023-05-04 09:30:32.798865+02 | 2023-05-04 0= 9:30:32.81+02 | 00:00:00.011135 9348 | 19920816 | 13318 | 2023-05-04 09:33:33.213291+02 | 2023-05-04 0= 9:33:33.221+02 | 00:00:00.007709 4512 | 19920817 | 16978159 | 2023-05-04 09:56:32.723868+02 | 2023-05-04 0= 9:56:32.732+02 | 00:00:00.008132 3092 | 19920817 | 16978159 | 2023-05-04 09:59:32.762951+02 | 2023-05-04 0= 9:59:32.772+02 | 00:00:00.009049 8684 | 292899 | 16978159 | 2023-05-04 10:15:32.704223+02 | 2023-05-04 1= 0:15:32.712+02 | 00:00:00.007777 8684 | 292899 | 16978159 | 2023-05-04 10:16:32.671539+02 | 2023-05-04 1= 0:16:32.681+02 | 00:00:00.009461 8684 | 292899 | 16978159 | 2023-05-04 10:17:32.779535+02 | 2023-05-04 1= 0:17:32.789+02 | 00:00:00.009465 8956 | 19920817 | 16978159 | 2023-05-04 10:59:32.241457+02 | 2023-05-04 1= 0:59:32.251+02 | 00:00:00.009543 8956 | 19920817 | 16978159 | 2023-05-04 11:00:32.09836+02 | 2023-05-04 1= 1:00:32.109+02 | 00:00:00.01064 10020 | 19920817 | 16978159 | 2023-05-04 11:02:32.120748+02 | 2023-05-04 1= 1:02:32.129+02 | 00:00:00.008252 10020 | 19920817 | 16978159 | 2023-05-04 11:03:33.004381+02 | 2023-05-04 1= 1:03:33.049+02 | 00:00:00.044619 10020 | 19920817 | 16978159 | 2023-05-04 11:04:32.140172+02 | 2023-05-04 1= 1:04:32.15+02 | 00:00:00.009828 10020 | 19920817 | 16978159 | 2023-05-04 11:05:34.367158+02 | 2023-05-04 1= 1:05:34.378+02 | 00:00:00.010842 10020 | 19920817 | 16978159 | 2023-05-04 11:07:54.337009+02 | 2023-05-04 1= 1:07:54.348+02 | 00:00:00.010991 10020 | 19920817 | 16978159 | 2023-05-04 11:08:32.652642+02 | 2023-05-04 1= 1:08:32.663+02 | 00:00:00.010358 10020 | 19920817 | 16978159 | 2023-05-04 11:09:33.219233+02 | 2023-05-04 1= 1:09:33.229+02 | 00:00:00.009767 10020 | 19920817 | 16978159 | 2023-05-04 11:10:32.707746+02 | 2023-05-04 1= 1:10:32.721+02 | 00:00:00.013254 10020 | 19920817 | 16978159 | 2023-05-04 11:11:34.92758+02 | 2023-05-04 1= 1:11:34.954+02 | 00:00:00.02642 10020 | 19920817 | 16978159 | 2023-05-04 11:12:36.175842+02 | 2023-05-04 1= 1:12:36.187+02 | 00:00:00.011158 10020 | 19920817 | 16978159 | 2023-05-04 11:13:35.14939+02 | 2023-05-04 1= 1:13:35.162+02 | 00:00:00.01261 (89 rows) -- Erik