NetBSD Problem Report #59636

From www@netbsd.org  Sun Sep  7 01:35:47 2025
Return-Path: <www@netbsd.org>
Received: from mail.netbsd.org (mail.netbsd.org [199.233.217.200])
	(using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
	 key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
	 client-signature RSA-PSS (2048 bits) client-digest SHA256)
	(Client CN "mail.NetBSD.org", Issuer "mail.NetBSD.org CA" (not verified))
	by mollari.NetBSD.org (Postfix) with ESMTPS id 8199E1A923D
	for <gnats-bugs@gnats.NetBSD.org>; Sun,  7 Sep 2025 01:35:47 +0000 (UTC)
Message-Id: <20250907013546.191FB1A923E@mollari.NetBSD.org>
Date: Sun,  7 Sep 2025 01:35:46 +0000 (UTC)
From: htodd@twofifty.com
Reply-To: htodd@twofifty.com
To: gnats-bugs@NetBSD.org
Subject: Lots of getsockname log spam from blocklistd
X-Send-Pr-Version: www-1.0

>Number:         59636
>Category:       bin
>Synopsis:       Lots of getsockname log spam from blocklistd
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    bin-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Sun Sep 07 01:40:00 +0000 2025
>Last-Modified:  Sun Sep 07 12:55:01 +0000 2025
>Originator:     Hisashi T Fujinaka
>Release:        NetBSD 11.0_BETA
>Organization:
>Environment:
NetBSD mail.i8u.org 11.0_BETA NetBSD 11.0_BETA (MARA) #3486: Fri Aug 29 15:06:25 PDT 2025  htodd@mail.i8u.org:/usr/obj/amd64/sys/arch/amd64/compile/MARA amd64
>Description:
Twice a minute, sshd caused blocklistd to generate log messages like:
Sep  5 19:30:58 mail blocklistd[1071]: unconnected socket with no peer in message
Sep  5 19:31:28 mail blocklistd[1071]: processing type=1 fd=6 remote=192.168.11.1:50552 msg=ssh uid=0 gid=0
Sep  5 19:31:28 mail blocklistd[1071]: getsockname failed (Invalid argument)

Using ktrace, Riastradh@ had a look and said the following in irc:
(18:20) < Riastradh>   9213   9213 sshd-session 1757034027.975948004 CALL  sendmsg(8,0x7f7fff842190,0) (18:21) < Riastradh>         
9213   9213 sshd-session 1757034027.975949112 MISC  msghdr: [name=0x0, namelen=0, iov=0x7f7fff842160,                               
                     iovlen=1, control=0x7f7fff842170, controllen=24, flags=4000000]                                                
(18:21) < Riastradh>   9213   9213 sshd-session 1757034027.975950657 MISC  mbcontrol: [len=20, level=65535, type=1]                 
(18:21) < Riastradh> is the pfilter_notify -> blocklist_r call that sends the fd to blocklistd                                      
(18:21) < Riastradh>   1071   1071 blocklistd 1757034027.975979446 CALL  recvmsg(3,0x7f7fff9cf550,0)                                
(18:21) < Riastradh>   1071   1071 blocklistd 1757034027.975980897 MISC  msghdr: [name=0x0, namelen=0, iov=0x7f7fff9cf540,          
                     iovlen=1, control=0x7f7fff9cf580, controllen=128, flags=4000000]                                               
(18:21) < Riastradh>   1071   1071 blocklistd 1757034027.975988685 MISC  mbcontrol: [len=20, level=65535, type=1]                   
(18:21) < Riastradh> is where blocklistd receives the fd                                                                            
(18:22) < Riastradh> then                                                                                                           
(18:22) < Riastradh>   1071   1071 blocklistd 1757034027.976076234 CALL  getsockname(6,0x7f7fff9cf790,0x7f7fff9cf814)               
(18:22) < Riastradh>   1071   1071 blocklistd 1757034027.976077623 RET   getsockname -1 errno 22 Invalid argument                   
(18:22) < Riastradh> and shortly after                                                                                              
(18:22) < Riastradh>   9213   9213 sshd-session 1757034027.976481806 CALL  exit(0xff)                                               
(18:23) < Riastradh> So that's actually pretty puzzling -- getsockname fails while sshd-session is still running and hasn't         
closed                                                                                                                              
                     or shutdown the fd!                                                                                            
(18:23) < Riastradh> (I believe I put all those records in chronological order.)                                                    
(18:25) <     htodd> huh                                                                                                            
(18:26) < Riastradh> fd_getsock never fails with EINVAL                                                                             
(18:26) < Riastradh> (EBADF or ENOTSOCK, but not EINVAL)                                                                            
(18:26) < Riastradh> and I don't think copyin or copyout fail with EINVAL                                                           
(18:27) < Riastradh> so that narrows it down to                                                                                     
(18:27) < Riastradh>         error = (*so->so_proto->pr_usrreqs->pr_sockaddr)(so, nam);                                             
(18:27) < Riastradh> for which the thing is presumably                                                                              
(18:27) < Riastradh> netinet/tcp_usrreq.c:   .pr_sockaddr    = tcp_sockaddr,                                                        
(18:27) < Riastradh> oh                                                                                                             
(18:27) < Riastradh> duh                                                                                                            
(18:27) < Riastradh> the _other_ side shut down the socket                                                                          
(18:28) < Riastradh>         inp = sotoinpcb(so);                                                                                   
(18:28) < Riastradh>         if (inp == NULL)
(18:28) < Riastradh>                 return EINVAL;                                                                                 
(18:28) < Riastradh> The interaction with sshd-session was this:                                                                    
(18:28) < Riastradh>   9213   9213 sshd-session 1757034027.975891847 CALL  write(7,0x705ec590cc00,0x40)                             
(18:28) < Riastradh>   9213   9213 sshd-session 1757034027.975907115 GIO   fd 7 wrote 64 bytes                                      
(18:28) < Riastradh>        "SSH-2.0-OpenSSH_10.0 NetBSD_Secure_Shell-20250409-hpn13v14-lpk\r\n"                                    
(18:28) < Riastradh>   9213   9213 sshd-session 1757034027.975908316 RET   write 64/0x40                                            
(18:28) < Riastradh>   9213   9213 sshd-session 1757034027.975920735 CALL  read(7,0x7f7fff8423d7,1)                                 
(18:28) < Riastradh> That is, sshd-session wrote the banner, and then the remote side hung up, so read returned 0 (eof).            
(18:28) < Riastradh>   9213   9213 sshd-session 1757034027.975921939 GIO   fd 7 read 0 bytes                                        
(18:28) < Riastradh>        ""                                                                                                      
(18:29) < Riastradh> fvc70r: so blocklistd fundamentally doesn't work for this use-case                                             
(18:29) < Riastradh> fvc70r: not if you insist on verifying getsockname in blocklistd itself                                        
(18:29) < Riastradh> mystery solved                                         
>How-To-Repeat:
It repeats twice a minute for me.
>Fix:

>Audit-Trail:
From: Christos Zoulas <christos@zoulas.com>
To: gnats-bugs@netbsd.org
Cc: gnats-admin@netbsd.org,
 netbsd-bugs@netbsd.org
Subject: Re: bin/59636: Lots of getsockname log spam from blocklistd
Date: Sun, 7 Sep 2025 08:53:49 -0400

 --Apple-Mail=_655CE126-B97A-4724-9CFF-F686EFDBEB18
 Content-Transfer-Encoding: quoted-printable
 Content-Type: text/plain;
 	charset=us-ascii

 This means we got 2 messages from ssh at the same time:

 > Sep  5 19:30:58 mail blocklistd[1071]: unconnected socket with no peer =
 in message

 The above is the first message that got aborted because of no peer

 > Sep  5 19:31:28 mail blocklistd[1071]: processing type=3D1 fd=3D6 =
 remote=3D192.168.11.1:50552 msg=3Dssh uid=3D0 gid=3D0
 > Sep  5 19:31:28 mail blocklistd[1071]: getsockname failed (Invalid =
 argument)

 This is the second that has a peer, but died later in getsockname. To =
 debug this we can add more annotations on the ssh side to see where in =
 the code this is generated from.

 christos=

 --Apple-Mail=_655CE126-B97A-4724-9CFF-F686EFDBEB18
 Content-Transfer-Encoding: 7bit
 Content-Disposition: attachment;
 	filename=signature.asc
 Content-Type: application/pgp-signature;
 	name=signature.asc
 Content-Description: Message signed with OpenPGP

 -----BEGIN PGP SIGNATURE-----
 Comment: GPGTools - http://gpgtools.org

 iF0EARECAB0WIQS+BJlbqPkO0MDBdsRxESqxbLM7OgUCaL2AXQAKCRBxESqxbLM7
 Ol89AJ9W5TSbltkQPrcyqQt4UegmIohx9wCeMLeOBxLQHYwTbvzyNI/MZ0DLN8U=
 =YyIr
 -----END PGP SIGNATURE-----

 --Apple-Mail=_655CE126-B97A-4724-9CFF-F686EFDBEB18--

Home	PR Database Search