Re: kern/57965: urtwn(4) command queue can overflow and deadlock

[Ramiro Aceves <ea1abz%gmail.com@localhost>]

El 2/29/24 a las 16:15, Taylor R Campbell escribió:
> The following reply was made to PR kern/57965; it has been noted by GNATS.
>
> From: Taylor R Campbell <riastradh%NetBSD.org@localhost>
> To: Ramiro Aceves <ea1abz%gmail.com@localhost>
> Cc: gnats-bugs%NetBSD.org@localhost, kern-bug-people%NetBSD.org@localhost,
> 	gnats-admin%NetBSD.org@localhost, netbsd-bugs%NetBSD.org@localhost
> Subject: Re: kern/57965: urtwn(4) command queue can overflow and deadlock
> Date: Thu, 29 Feb 2024 15:13:28 +0000
>
>   > Date: Thu, 29 Feb 2024 13:05:09 +0100
>   > From: Ramiro Aceves <ea1abz%gmail.com@localhost>
>   >
>   > My RaspberryPi Zero W is using now the urtwn driver with a USB WIFI
>   > adaptor because of bwfm driver does not function well. I made a
>   > service that checks www.google.com and reboots the system if there is
>   > no ping,  checking 3 times during  5 min intervals.
>   >
>   > With urtwn, network worked fine but router automatic changing channels
>   > leaded to complete network loss, needing reboot.
>   
>   Can you share the output of these commands when it fails, before you
>   reboot?
>   
>   ifconfig urtwn0
>   wpa_cli status
>   dhcpcd -U urtwn0
>   
>   The symptom in this PR is that the commands will actually just hang in
>   tstile or mutex, and examination with `ps' (either ps(1), or in
>   crash(8) or ddb(4)) will show that some process is waiting for
>   urtwntsk; the stack trace in crash/ddb will show it is waiting in
>   urtwn_stop.
>   
>   If your symptom does match, there's a good chance this will resolve
>   it.
>   
>   If your symptom doesn't match, can you file a new PR for it?
>   

Thanks Taylor for the instructions.

I have reproduced the problem forcing a channel change from the router. 
I made a simple diagnose.sh script that is called from the automatic 
reboot script just before issuing "shutdown -r" now command.

I do not use dhcpcd daemon, I use static IP address.

a diagnose.log file is recorded:

netbsd-raspa$ cat /root/diagnose.log
Thu Feb 29 22:32:36 CET 2024
# ifconfig urtwn0
urtwn0: flags=0x8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> mtu 1500
	ssid MiFibra-3422 nwkey 65536:"",0x433cc28429aedde0f4f22d14c5032697,"",""
	powersave off
	bssid 60:8d:26:32:34:24 chan 1
	address: e4:fa:c4:52:ac:4c
	media: IEEE802.11 autoselect (OFDM54 mode 11g)
	status: active
	inet6 fe80::e6fa:c4ff:fe52:ac4c%urtwn0/64 flags 0 scopeid 0x1
	inet 192.168.1.230/24 broadcast 192.168.1.255 flags 0
# wpa_cli status
Selected interface 'urtwn0'
22:32:36.067: bssid=60:8d:26:32:34:24
freq=0
ssid=MiFibra-3422
id=0
mode=station
pairwise_cipher=CCMP
group_cipher=CCMP
key_mgmt=WPA2-PSK
wpa_state=COMPLETED
ip_address=192.168.1.230
address=e4:fa:c4:52:ac:4c

# dhcpcd -U urtwn0
dhcpcd is not running
# ps axu
USER     PID %CPU %MEM   VSZ   RSS TTY    STAT STARTED    TIME COMMAND
root       0  0.0  1.7     0  8008 ?      DKl  10:01PM 0:03.66 [system]
root       1  0.0  0.3  5836  1464 ?      Is   10:01PM 0:00.06 init
root     214  0.0  0.3  5840  1512 ?      S    10:32PM 0:00.02 /bin/sh 
/root/diagnose.sh
root     293  0.0  0.7 12184  3252 ?      Ss   10:02PM 0:00.07 
/usr/sbin/wpa_supplicant -B -B -s -i urtwn0 -D bsd -c /etc/wpa_suppl
root     346  0.0  0.2  5640   768 ?      Is   10:02PM 0:00.00 
/sbin/devpubd
root     456  0.0  0.5 11124  2164 ?      Ss   10:02PM 0:00.12 
/usr/sbin/syslogd -s
root     563  0.0  2.2 11256 10312 ?      Ss   10:02PM 0:00.58 
/usr/sbin/ntpd -p /var/run/ntpd.pid -g
root     793  0.0  0.6 15128  2768 ?      Is   10:02PM 0:00.03 sshd: 
/usr/sbin/sshd [listener] 0 of 10-100 startups (sshd)
root     809  0.0  1.1 74620  5088 ?      Ss   10:02PM 0:00.06 
/usr/pkg/sbin/minidlnad -f /usr/pkg/etc/minidlna.conf
postfix  810  0.0  0.8 14948  3836 ?      S    10:02PM 0:00.11 pickup -l 
-t unix -u
postfix  811  0.0  0.8 15000  3852 ?      S    10:02PM 0:00.11 qmgr -l 
-t unix -u
root     823  0.0  0.3  5908  1324 ?      O    10:32PM 0:00.01 ps -axuw
root     844  0.0  0.5 15360  2488 ?      Ss   10:02PM 0:00.09 
/usr/libexec/postfix/master -w
root     860  0.0  0.3  5952  1452 ?      Is   10:02PM 0:00.03 
/usr/sbin/cron
ramiro   919  0.0  1.1 16120  5100 ?      I    10:08PM 0:02.82 sshd: 
ramiro@pts/0 (sshd)
root     950  0.0  0.5 11392  2232 ?      S    10:21PM 0:00.05 ntpd: 
asynchronous dns resolver
root     961  0.0  1.5 15980  6692 ?      Is   10:07PM 0:00.37 sshd: 
ramiro [priv]
root    1048  0.0  0.3  6160  1284 ?      Is   10:02PM 0:00.01 
/usr/sbin/inetd -l
ramiro   847  0.0  0.4  6192  1868 pts/0  Is   10:08PM 0:00.09 -sh
root    1141  0.0  0.4  6192  1880 pts/0  I+   10:13PM 0:00.26 sh
root     560  0.0  0.3  5888  1556 ttyE0- S    10:02PM 0:00.03 /bin/sh 
/root/nettest
root     963  0.0  0.3  5616  1396 ttyE0  Is+  10:02PM 0:00.02 
/usr/libexec/getty default constty
root    1041  0.0  0.3  5612  1392 ttyE1  Is+  10:02PM 0:00.02 
/usr/libexec/getty Pc ttyE1
root     967  0.0  0.3  5616  1396 ttyE2  Is+  10:02PM 0:00.02 
/usr/libexec/getty Pc ttyE2
root    1112  0.0  0.3  5616  1400 ttyE3  Is+  10:02PM 0:00.02 
/usr/libexec/getty Pc ttyE3
netbsd-raspa$

Commands do not hang, I think...

Regards.
Ramiro