NetBSD-Bugs archive

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]

bin/59636: Lots of getsockname log spam from blocklistd



>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
>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@localhost:/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:



Home | Main Index | Thread Index | Old Index