4

I'm attempting to use my Raspberry Pi 4 Model B with one of these ModMyPi Ralink RT3070-based-chipset usb wireless adapters as an AP via hostapd.

The issue I'm facing is as follows:

  • Start hostapd
  • AP works fine (DHCP/DNS/routing/etc) for an undetermined period of time
  • hostapd eventually crashes with little useful information in logs (that I can see) to help indicate why this is the case.

Restarting hostapd after this seems to bring it back online.

The USB WiFi dongle is showing as utilising the rt2800 family of drivers:

pi@raspberrypi:/tmp $ lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 004: ID 046d:c52b Logitech, Inc. Unifying Receiver
Bus 001 Device 005: ID 148f:3070 Ralink Technology, Corp. RT2870/RT3070 Wireless Adapter
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

dmesg output is as follows:

...
[13591.906444] usb 1-1.1: new high-speed USB device number 6 using xhci_hcd
[13592.069548] usb 1-1.1: New USB device found, idVendor=148f, idProduct=3070, bcdDevice= 1.01
[13592.069569] usb 1-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[13592.069586] usb 1-1.1: Product: 802.11 n WLAN
[13592.069601] usb 1-1.1: Manufacturer: Ralink
[13592.069616] usb 1-1.1: SerialNumber: 1.0
[13592.177043] usb 1-1.1: reset high-speed USB device number 6 using xhci_hcd
[13592.318245] ieee80211 phy3: rt2x00_set_rt: Info - RT chipset 3070, rev 0201 detected
[13592.344614] ieee80211 phy3: rt2x00_set_rf: Info - RF chipset 0005 detected
[13592.344939] ieee80211 phy3: Selected rate control algorithm 'minstrel_ht'
[13592.351931] ieee80211 phy3: rt2x00lib_request_firmware: Info - Loading firmware file 'rt2870.bin'
[13592.352027] ieee80211 phy3: rt2x00lib_request_firmware: Info - Firmware detected - version: 0.36
...

Loaded modules as follows:

pi@raspberrypi:/tmp $ lsmod | grep rt2
rt2800usb              28672  0
rt2800lib             114688  1 rt2800usb
rt2x00usb              24576  1 rt2800usb
rt2x00lib              57344  3 rt2800lib,rt2800usb,rt2x00usb
mac80211              729088  3 rt2800lib,rt2x00lib,rt2x00usb
crc_ccitt              16384  1 rt2800lib
cfg80211              679936  3 rt2x00lib,mac80211,brcmfmac

My hostapd configuration looks like:

auth_algs=1
wpa_key_mgmt=WPA-PSK
ssid=<REDACTED>
channel=7
hw_mode=g
wpa_passphrase=<REDACTED>
interface=wlan1
wpa=2
wpa_pairwise=CCMP
country_code=AU
ignore_broadcast_ssid=0
disassoc_low_ack=0
ctrl_interface=/var/run/hostapd

iwconfig is showing this device as not being powered managed:

pi@raspberrypi:/tmp $ iwconfig wlan1
wlan1     IEEE 802.11  ESSID:off/any
          Mode:Managed  Access Point: Not-Associated   Tx-Power=36 dBm
          Retry short  long limit:2   RTS thr:off   Fragment thr:off
          Power Management:off

I had a cron job setup to run every 5 minutes with iwconfig wlan1 power off to see if that made any difference but it did not appear to.

Below are some log entries that might be of interest:

pi@raspberrypi:/var/log $ grep wlan1 * | grep -v CRON | grep -v dhcp | grep -v avahi | grep -v dns | grep -v "24:62:ab:fd:24:34" | grep -v "light" | grep -v "iwconfig wlan1 power off"
daemon.log:Sep 20 18:42:25 raspberrypi vnstatd[504]: Info: Interface "wlan1" disabled.
daemon.log:Sep 20 18:42:30 raspberrypi vnstatd[504]: Info: Interface "wlan1" enabled.
daemon.log.1:Sep 13 13:16:42 raspberrypi vnstatd[504]: Info: Interface "wlan1" enabled.
daemon.log.1:Sep 14 21:51:28 raspberrypi vnstatd[504]: Info: Interface "wlan1" disabled.
daemon.log.1:Sep 14 21:51:33 raspberrypi vnstatd[504]: Info: Interface "wlan1" enabled.
daemon.log.1:Sep 15 19:09:21 raspberrypi vnstatd[504]: Info: Interface "wlan1" disabled.
daemon.log.1:Sep 15 19:09:26 raspberrypi vnstatd[504]: Info: Interface "wlan1" enabled.
daemon.log.1:Sep 17 11:09:18 raspberrypi vnstatd[504]: Info: Interface "wlan1" disabled.
daemon.log.1:Sep 17 11:09:23 raspberrypi vnstatd[504]: Info: Interface "wlan1" enabled.
daemon.log.1:Sep 17 11:38:23 raspberrypi vnstatd[504]: Info: Interface "wlan1" disabled.
daemon.log.1:Sep 17 11:38:28 raspberrypi vnstatd[504]: Info: Interface "wlan1" enabled.
kern.log:Sep 20 14:08:07 raspberrypi kernel: [927055.823706] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log:Sep 20 14:29:07 raspberrypi kernel: [928315.433328] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log:Sep 20 14:38:19 raspberrypi kernel: [928867.033359] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log:Sep 20 14:55:46 raspberrypi kernel: [    8.827781] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log:Sep 20 14:56:01 raspberrypi kernel: [   23.574682] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log.1:Sep 13 13:40:12 raspberrypi kernel: [320571.239666] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log.1:Sep 13 13:57:22 raspberrypi kernel: [321601.827227] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log.1:Sep 13 20:33:56 raspberrypi kernel: [345395.775302] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log.1:Sep 13 20:47:40 raspberrypi kernel: [346220.238577] device wlan1 entered promiscuous mode
kern.log.1:Sep 13 20:47:43 raspberrypi kernel: [346222.405713] device wlan1 left promiscuous mode
kern.log.1:Sep 13 20:49:55 raspberrypi kernel: [346355.010522] device wlan1 entered promiscuous mode
kern.log.1:Sep 13 20:51:01 raspberrypi kernel: [346420.542532] device wlan1 left promiscuous mode
kern.log.1:Sep 14 18:16:09 raspberrypi kernel: [423530.404296] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
kern.log.1:Sep 17 11:38:42 raspberrypi kernel: [658886.773095] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages:Sep 20 14:08:07 raspberrypi kernel: [927055.823706] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages:Sep 20 14:29:07 raspberrypi kernel: [928315.433328] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages:Sep 20 14:38:19 raspberrypi kernel: [928867.033359] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages:Sep 20 14:55:46 raspberrypi kernel: [    8.827781] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages:Sep 20 14:56:01 raspberrypi kernel: [   23.574682] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages.1:Sep 13 13:40:12 raspberrypi kernel: [320571.239666] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages.1:Sep 13 13:57:22 raspberrypi kernel: [321601.827227] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages.1:Sep 13 20:33:56 raspberrypi kernel: [345395.775302] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages.1:Sep 13 20:47:40 raspberrypi kernel: [346220.238577] device wlan1 entered promiscuous mode
messages.1:Sep 13 20:47:43 raspberrypi kernel: [346222.405713] device wlan1 left promiscuous mode
messages.1:Sep 13 20:49:55 raspberrypi kernel: [346355.010522] device wlan1 entered promiscuous mode
messages.1:Sep 13 20:51:01 raspberrypi kernel: [346420.542532] device wlan1 left promiscuous mode
messages.1:Sep 14 18:16:09 raspberrypi kernel: [423530.404296] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
messages.1:Sep 17 11:38:42 raspberrypi kernel: [658886.773095] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
syslog:Sep 20 14:08:07 raspberrypi kernel: [927055.823706] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
syslog:Sep 20 14:29:07 raspberrypi kernel: [928315.433328] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
syslog:Sep 20 14:38:19 raspberrypi kernel: [928867.033359] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
syslog:Sep 20 14:55:46 raspberrypi kernel: [    8.827781] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
syslog:Sep 20 14:56:01 raspberrypi kernel: [   23.574682] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
syslog:Sep 20 18:42:25 raspberrypi vnstatd[504]: Info: Interface "wlan1" disabled.
syslog:Sep 20 18:42:30 raspberrypi vnstatd[504]: Info: Interface "wlan1" enabled.

Here are some interesting log entries from hostapd:

Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
Could not set interface wlan1 flags (UP): Input/output error
nl80211: Could not set interface 'wlan1' UP
Could not set interface wlan1 flags (UP): No such device
nl80211: Could not set interface 'wlan1' UP
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: INTERFACE-DISABLED 
Could not set interface wlan1 flags (UP): Input/output error
nl80211: Could not set interface 'wlan1' UP
Could not set interface wlan1 flags (UP): Device or resource busy
nl80211: Could not set interface 'wlan1' UP
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
Could not set interface wlan1 flags (UP): No such device
nl80211: Could not set interface 'wlan1' UP
Could not set interface wlan1 flags (UP): No such device
nl80211: Could not set interface 'wlan1' UP
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
Could not set interface wlan1 flags (UP): Input/output error
nl80211: Could not set interface 'wlan1' UP
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
Could not set interface wlan1 flags (UP): Input/output error
nl80211: Could not set interface 'wlan1' UP
Could not set interface wlan1 flags (UP): Input/output error
nl80211: Could not set interface 'wlan1' UP
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
Could not set interface wlan1 flags (UP): No such device
nl80211: Could not set interface 'wlan1' UP
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: INTERFACE-DISABLED 
wlan1: INTERFACE-ENABLED 
Failed to set beacon parameters
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED 
wlan1: interface state ENABLED->DISABLED
wlan1: AP-DISABLED 
wlan1: CTRL-EVENT-TERMINATING 
nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Configuration file: /etc/hostapd/hostapd.conf
wlan1: AP-ENABLED

OS details:

pi@raspberrypi:/tmp $ cat /etc/*release*
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
pi@raspberrypi:/tmp $ uname -a
Linux raspberrypi 5.4.51-v7l+ #1333 SMP Mon Aug 10 16:51:40 BST 2020 armv7l GNU/Linux

At this point I'm wondering whether it could be a bad adapter but wanted to know what else I can do to troubleshoot this/resolve it?

Update 21/09/20 - Hostapd debug logs

I've pulled out lines that I believe to be of interest for the issue:

1600641182.604187: nl80211: Drv Event 16 (NL80211_CMD_STOP_AP) received for wlan1
1600641182.604214: wlan1: Event INTERFACE_UNAVAILABLE (28) received
1600641182.604228: Interface wlan1 is unavailable -- stopped
1600641182.605808: RTM_NEWLINK: ifi_index=466 ifname=wlan1 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x1002 ()
1600641182.605920: nl80211: Interface down (wlan1/wlan1)
1600641182.605943: wlan1: Event INTERFACE_DISABLED (26) received
1600641182.605961: wlan1: INTERFACE-DISABLED 
1600641182.606036: VLAN: RTM_NEWLINK: ifi_index=466 ifname=wlan1 ifi_family=0 ifi_flags=0x1002 ()
1600641182.606054: VLAN: vlan_newlink(wlan1)
1600641182.724045: RTM_DELLINK: ifi_index=466 ifname=wlan1 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x1002 ()
1600641182.724069: RTM_DELLINK: Interface 'wlan1' removed - mark if_removed=1
1600641182.724083: wlan1: Event INTERFACE_STATUS (5) received
1600641182.724092: Unknown event 5
1600641182.741668: VLAN: RTM_DELLINK: ifi_index=466 ifname=wlan1 ifi_family=0 ifi_flags=0x1002 ()
1600641182.741703: VLAN: vlan_dellink(wlan1)
1600641182.759151: nl80211: Ignored event (cmd=36) for foreign interface (ifindex -1 wdev 0x0)
1600641182.759221: nl80211: Drv Event 36 (NL80211_CMD_REG_CHANGE) received for wlan1
1600641182.759230: nl80211: Regulatory domain change
1600641182.759235:  * initiator=1
1600641182.759241:  * type=0
1600641182.759247:  * alpha2=AU
1600641182.759258: wlan1: Event CHANNEL_LIST_CHANGED (27) received
1600641183.536944: RTM_NEWLINK: ifi_index=2081 ifname=wlan1 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x1002 ()
1600641183.538906: nl80211: Update ifindex for a removed interface
1600641183.539417: nl80211: Supported cipher 00-0f-ac:1
1600641183.539444: nl80211: Supported cipher 00-0f-ac:5
1600641183.539461: nl80211: Supported cipher 00-0f-ac:2
1600641183.539476: nl80211: Supported cipher 00-0f-ac:4
1600641183.539491: nl80211: Supported cipher 00-0f-ac:10
1600641183.539506: nl80211: Supported cipher 00-0f-ac:8
1600641183.539520: nl80211: Supported cipher 00-0f-ac:9
1600641183.539534: nl80211: Supported cipher 00-0f-ac:6
1600641183.539548: nl80211: Supported cipher 00-0f-ac:13
1600641183.539562: nl80211: Supported cipher 00-0f-ac:11
1600641183.539577: nl80211: Supported cipher 00-0f-ac:12
1600641183.539647: nl80211: Using driver-based off-channel TX
1600641183.539717: nl80211: interface wlan1 in phy phy4
1600641183.539737: nl80211: Set mode ifindex 2081 iftype 3 (AP)
1600641183.539849: nl80211: Unsubscribe mgmt frames handle 0x89823791 (start AP)
1600641183.540033: nl80211: Setup AP(wlan1) - device_ap_sme=0 use_monitor=0
1600641183.540125: nl80211: Subscribe to mgmt frames with AP handle 0x10abf18
1600641186.653836: Could not set interface wlan1 flags (UP): Input/output error
1600641186.653876: nl80211: Could not set interface 'wlan1' UP
1600641186.653899: nl80211: Found matching own interface, but failed to complete reinitialization
1600641186.654069: VLAN: RTM_NEWLINK: ifi_index=2081 ifname=wlan1 ifi_family=0 ifi_flags=0x1002 ()
1600641186.654087: VLAN: vlan_newlink(wlan1)
1600641186.713941: RTM_DELLINK: ifi_index=2081 ifname=wlan1 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x1002 ()
1600641186.713965: nl80211: if_removed already set - ignore RTM_DELLINK event for wlan1
1600641186.725633: VLAN: RTM_DELLINK: ifi_index=2081 ifname=wlan1 ifi_family=0 ifi_flags=0x1002 ()
1600641186.725659: VLAN: vlan_dellink(wlan1)
1600641187.584495: RTM_NEWLINK: ifi_index=2082 ifname=wlan1 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x1002 ()
1600641187.585759: nl80211: Update ifindex for a removed interface
1600641187.586447: nl80211: Supported cipher 00-0f-ac:1
1600641187.586483: nl80211: Supported cipher 00-0f-ac:5
1600641187.586500: nl80211: Supported cipher 00-0f-ac:2
1600641187.586525: nl80211: Supported cipher 00-0f-ac:4
1600641187.586540: nl80211: Supported cipher 00-0f-ac:10
1600641187.586554: nl80211: Supported cipher 00-0f-ac:8
1600641187.586569: nl80211: Supported cipher 00-0f-ac:9
1600641187.586583: nl80211: Supported cipher 00-0f-ac:6
1600641187.586597: nl80211: Supported cipher 00-0f-ac:13
1600641187.586831: nl80211: Supported cipher 00-0f-ac:11
1600641187.586855: nl80211: Supported cipher 00-0f-ac:12
1600641187.586932: nl80211: Using driver-based off-channel TX
1600641187.587157: nl80211: interface wlan1 in phy phy5
1600641187.587184: nl80211: Set mode ifindex 2082 iftype 3 (AP)
1600641187.587421: nl80211: Unsubscribe mgmt frames handle 0x89823791 (start AP)
1600641187.587643: nl80211: Setup AP(wlan1) - device_ap_sme=0 use_monitor=0
1600641187.587741: nl80211: Subscribe to mgmt frames with AP handle 0x10abf18
1600641188.364296: nl80211: Connect handle already created (nl_connect=0x10ac970)
1600641188.364502: nl80211: Mark if_removed=0 for wlan1 based on RTM_NEWLINK event
1600641188.364583: wlan1: Event INTERFACE_STATUS (5) received
1600641188.364658: Unknown event 5
1600641188.364744: RTM_NEWLINK: ifi_index=2082 ifname=wlan1 operstate=0 linkmode=0 ifi_family=0 ifi_flags=0x1043 ([UP][RUNNING])
1600641188.364868: nl80211: Interface up (wlan1/wlan1)
1600641188.364980: wlan1: Event INTERFACE_ENABLED (25) received
1600641188.365049: wlan1: INTERFACE-ENABLED 
1600641188.365174: wpa_driver_nl80211_set_key: ifindex=2082 (wlan1) alg=3 addr=0x119324 key_idx=1 set_tx=1 seq_len=0 key_len=16
1600641188.365257: nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
1600641188.365339:    broadcast key
1600641188.365571: nl80211: Set beacon (beacon_set=0)
1600641188.365975: nl80211: ifindex=2082
1600641188.366043: nl80211: beacon_int=100
1600641188.366112: nl80211: beacon_rate=0
1600641188.366186: nl80211: rate_type=0
1600641188.366261: nl80211: dtim_period=2
1600641188.366333: nl80211: ssid - hexdump_ascii(len=7):
     47 2d 57 41 47 4f 4e                              <REDACTED>         
1600641188.366503:   * beacon_int=100
1600641188.366581:   * dtim_period=2
1600641188.366657: nl80211: hidden SSID not in use
1600641188.366735: nl80211: privacy=1
1600641188.366810: nl80211: auth_algs=0x1
1600641188.366882: nl80211: wpa_version=0x2
1600641188.366961: nl80211: key_mgmt_suites=0x2
1600641188.367043: nl80211: pairwise_ciphers=0x10
1600641188.367126: nl80211: group_cipher=0x10
1600641188.367200: nl80211: beacon_ies - hexdump(len=10): 7f 08 00 00 00 02 00 00 00 40
1600641188.367281: nl80211: proberesp_ies - hexdump(len=10): 7f 08 00 00 00 02 00 00 00 40
1600641188.367368: nl80211: assocresp_ies - hexdump(len=10): 7f 08 00 00 00 02 00 00 00 40
1600641188.367517: nl80211: Beacon set failed: -22 (Invalid argument)
1600641188.367590: Failed to set beacon parameters
1600641188.367733: RTM_NEWLINK: ifi_index=2082 ifname=wlan1 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x1003 ([UP])
1600641188.367894: VLAN: RTM_NEWLINK: ifi_index=2082 ifname=wlan1 ifi_family=0 ifi_flags=0x1002 ()
1600641188.367971: VLAN: vlan_newlink(wlan1)
1600641188.368087: VLAN: RTM_NEWLINK: ifi_index=2082 ifname=wlan1 ifi_family=0 ifi_flags=0x1043 ([UP][RUNNING])
1600641188.368156: VLAN: vlan_newlink(wlan1)
1600641188.368274: VLAN: RTM_NEWLINK: ifi_index=2082 ifname=wlan1 ifi_family=0 ifi_flags=0x1003 ([UP])
1600641188.368340: VLAN: vlan_newlink(wlan1)
1600641188.398935: RTM_NEWLINK: ifi_index=2082 ifname=wlan1 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x1003 ([UP])
1600641188.399082: VLAN: RTM_NEWLINK: ifi_index=2082 ifname=wlan1 ifi_family=0 ifi_flags=0x1003 ([UP])
1600641188.399135: VLAN: vlan_newlink(wlan1)
1600641195.734325: Unknown Microsoft information element ignored (type=8 len=8)
1600641195.734536: Ignore Probe Request due to DS Params mismatch: chan=7 != ds.chan=1
1600642515.763249: nl80211: send_mlme - da= 64:1c:b0:ef:99:22 noack=1 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
1600642515.763274: nl80211: send_mlme -> send_frame
1600642515.763287: nl80211: send_frame - Use bss->freq=2442
1600642515.763300: nl80211: send_frame -> send_frame_cmd
1600642515.763314: nl80211: CMD_FRAME freq=2442 wait=0 no_cck=0 no_ack=1 offchanok=0
1600642515.763568: nl80211: Frame command failed: ret=-16 (Device or resource busy) (freq=2442 wait=0)
1600642515.763591: handle_probe_req: send failed
1600642515.765742: nl80211: send_mlme - da= 64:1c:b0:ef:99:22 noack=1 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
1600642515.765860: nl80211: send_mlme -> send_frame
1600642515.765957: nl80211: send_frame - Use bss->freq=2442
1600642515.766056: nl80211: send_frame -> send_frame_cmd
1600642515.766079: nl80211: CMD_FRAME freq=2442 wait=0 no_cck=0 no_ack=1 offchanok=0
1600642515.766282: nl80211: Frame command failed: ret=-16 (Device or resource busy) (freq=2442 wait=0)
1600642515.766304: handle_probe_req: send failed
1600643055.956614: Ignore Probe Request due to DS Params mismatch: chan=7 != ds.chan=4
1600643955.647033: nl80211: send_mlme - da= 64:1c:b0:ef:99:22 noack=1 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
1600643955.647057: nl80211: send_mlme -> send_frame
1600643955.647070: nl80211: send_frame - Use bss->freq=2442
1600643955.647084: nl80211: send_frame -> send_frame_cmd
1600643955.647097: nl80211: CMD_FRAME freq=2442 wait=0 no_cck=0 no_ack=1 offchanok=0
1600643955.647326: nl80211: Frame command failed: ret=-16 (Device or resource busy) (freq=2442 wait=0)
1600643955.647353: handle_probe_req: send failed
1600643955.649431: nl80211: send_mlme - da= 64:1c:b0:ef:99:22 noack=1 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
1600643955.649454: nl80211: send_mlme -> send_frame
1600643955.649467: nl80211: send_frame - Use bss->freq=2442
1600643955.649480: nl80211: send_frame -> send_frame_cmd
1600643955.649493: nl80211: CMD_FRAME freq=2442 wait=0 no_cck=0 no_ack=1 offchanok=0
1600643955.649688: nl80211: Frame command failed: ret=-16 (Device or resource busy) (freq=2442 wait=0)
1600643955.649717: handle_probe_req: send failed
1600643955.652399: nl80211: send_mlme - da= 64:1c:b0:ef:99:22 noack=1 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
1600643955.652422: nl80211: send_mlme -> send_frame
1600643955.652434: nl80211: send_frame - Use bss->freq=2442
1600643955.652447: nl80211: send_frame -> send_frame_cmd
1600643955.652460: nl80211: CMD_FRAME freq=2442 wait=0 no_cck=0 no_ack=1 offchanok=0
1600643955.652650: nl80211: Frame command failed: ret=-16 (Device or resource busy) (freq=2442 wait=0)
1600643955.652674: handle_probe_req: send failed
1600645124.882081: Add randomness: count=10240 entropy=1010
1600645124.882096: random pool - hexdump(len=128): [REMOVED]
1600645124.882111: random_mix_pool - hexdump(len=8): [REMOVED]
1600645124.882126: random_mix_pool - hexdump(len=16): [REMOVED]
1600645124.882140: random pool - hexdump(len=128): [REMOVED]
1600647135.984635: nl80211: send_mlme - da= 64:1c:b0:ef:99:22 noack=1 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
1600647135.984658: nl80211: send_mlme -> send_frame
1600647135.984672: nl80211: send_frame - Use bss->freq=2442
1600647135.984687: nl80211: send_frame -> send_frame_cmd
1600647135.984700: nl80211: CMD_FRAME freq=2442 wait=0 no_cck=0 no_ack=1 offchanok=0
1600647135.984925: nl80211: Frame command failed: ret=-16 (Device or resource busy) (freq=2442 wait=0)
1600647135.984952: handle_probe_req: send failed
1600647135.989488: nl80211: send_mlme - da= 64:1c:b0:ef:99:22 noack=1 freq=0 no_cck=0 offchanok=0 wait_time=0 fc=0x50 (WLAN_FC_STYPE_PROBE_RESP) nlmode=3
1600647135.989510: nl80211: send_mlme -> send_frame
1600647135.989523: nl80211: send_frame - Use bss->freq=2442
1600647135.989536: nl80211: send_frame -> send_frame_cmd
1600647135.989549: nl80211: CMD_FRAME freq=2442 wait=0 no_cck=0 no_ack=1 offchanok=0
1600647135.989752: nl80211: Frame command failed: ret=-16 (Device or resource busy) (freq=2442 wait=0)
1600647135.989775: handle_probe_req: send failed

Full debug log here.

Update 27/09/20 - Additional output

Additional details:

iw-list output

iwconfig output

usb-devices output

Cheers.

Improve this question
12
  • looks like the device crashes. Probably resets so disappears and reappears
    – A.B
    Commented Sep 20, 2020 at 8:58
  • @A.B yea it does look that way but need to understand why that is the case so I can prevent it (if its a software issue).
    – Kane Charles
    Commented Sep 21, 2020 at 0:29
  • Can you post iw list output, as well as iwconfig and usb-devices (the last two when the machine /hostapd is capable of maintaining connection). The Rasberry Pi has a very important caveat related to its usb ports, namely the max current draw is 1.2A (way higher than for a typical PC usb port , usually maxed out at 500 mA) but that 1.2A gets shared (NOT divided ) across all ports, and connecting other usb devices can deplete the usb dongle of its min. power needed.
    – NetIceCat
    Commented Sep 26, 2020 at 19:51
  • Hi @BarBar1234 I've now uploaded the additional output as requested. I do note that it is listed as MxPwr=420mA and the total of everything combined is less than 1200mA, should be okay? Thanks for helping answer this, haven't had much traction even with a bounty.
    – Kane Charles
    Commented Sep 27, 2020 at 2:49
  • Ok, if I am reading your usb-devices list correctly, you have a USB hub connected to the Rasberry Pi, followed by Logitech receiver and your RT3070 dongle. The way I am reading it, the external hub is not the bus for the other two devices (which are connected directly to the Rasberry Pi) but it is still a big variable when it comes to power. However your print out of iw list is off the charts. I have the same device and take a look at my iw list and the corresponding power levels pastebin.com/hZ4cw2fe . I have no idea how that 36 dBm on the 2.4 GHz, as that is 4 Watts.
    – NetIceCat
    Commented Sep 27, 2020 at 23:30

1 Answer 1

Reset to default
1
+100

Ok, after running multiple tests on the RT3070 dongle, I can state with certainty that it is related to the tx-power setting.

There are several issues at play here:

1. The database for CRDA regulation appears to have changed very recently. Some of the allowed values seem to now represent EIRP while others still report ERP.

EIRP corresponds to Effective isotropic radiated power, which is calculated as follows:

EIRP(dBm) = [Output Power] - [Cable Loss] + [Antenna Gain]

If one uses iw reg set AU to use Australia country code, followed by iw reg get they will see the following output:

global
country AU: DFS-ETSI
    (2400 - 2483 @ 40), (N/A, 36), (N/A)
    (5150 - 5250 @ 80), (N/A, 23), (N/A), NO-OUTDOOR, AUTO-BW
    (5250 - 5350 @ 80), (N/A, 20), (0 ms), NO-OUTDOOR, DFS, AUTO-BW
    (5470 - 5600 @ 80), (N/A, 27), (0 ms), DFS
    (5650 - 5730 @ 80), (N/A, 27), (0 ms), DFS
    (5730 - 5850 @ 80), (N/A, 36), (N/A)
    (57000 - 66000 @ 2160), (N/A, 43), (N/A), NO-OUTDOOR

The 1st line shows the following: ( 2.4 GHz band @ 40 MHz) , (N/A , tx-power), in other words if your channel selection falls within the 1-14 channel range, then your maximum tx-power setting will be 36 dBm. Which you can easily confirm by running iwconfig wlan0 txpower 36

wlan0     IEEE 802.11  ESSID:"[SSID]"  
          Mode:Managed  Frequency:2.412 GHz  Access Point: [MAC]   
          Bit Rate=6.5 Mb/s   Tx-Power=36 dBm   
          Retry short  long limit:2   RTS thr:off   Fragment thr:off
          Encryption key:off
          Power Management:off
          Link Quality=61/70  Signal level=-49 dBm  
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:402  Invalid misc:3418   Missed beacon:0

However, the regulatory domain limits for Australia per ACMA (AU verion of FCC) specify the 36 dBm as being the maximum EIRP power, that is the total for both the transmitter and the antenna gain. In other words, using 36 dBm for the transmitter and connecting an antenna with significant gain, is against the law, and in many places operating radio equipment (36 dBm + 6dBi - 1dBm cable loss) with EIRP=40 dBm would cause substantial interference to get you noticed by authorities.

Checking another system still using old CRDA database (last updated approximately 1 month ago) , the iw reg get reports different values for AU country code. The max tx-power there is 20 dBm.

This is not just limited to AU country code either, the US tx-power also jumped from old 20 dBm to now showing 30 dBm.

2. Connection stability vs. tx-power

Seeing questionable tx-power values gives us a good point of reference, but it doesn't tell the whole story. Hence, the next step was to run connection tests using different country regulatory domains across various tx-power settings, with a hi-gain 6dBi panel antenna.

The tests actually recorded were simple 5-ping sequences on 8.8.8.8 per tx-power settings from 10dBm to 36dBm using AU(36dBm), BO(20 dBm), and US(30dBm) reg domains.

In the logs, TXPOWER corresponds iwconfig wlan0 txpower [TXPOWER] while the tx-power output on the next line is the print out from iwconfig wlan0 itself. Each time the tx-power was reconfigured, there was a sleep 5 issued to give the interface 5 seconds to do any and all calibration necessary.

US: https://dpaste.com//CRAVMGW8S

AU: https://dpaste.com//CETUDFVHA

BO: https://dpaste.com//674RUR9TT

As can be seen from the logs, the breakdown occurs at very different tx-power settings depending on the chosen regulatory domain. The AU domain could not maintain connection at less than 30 dBm while BO had its strongest connection at 19-20 dBm. Similarly, US started showing connection issues at less than <26 dBm.

4. Interface crash and causes

If you look at the log for the US domain, towards the bottom you will see the eponymous interface crash, preceeded by packet loss and (loss+errors). It was reproducible 100% of the time.

This error seems to be related to thread locking of some kind because restarting the interface with ifup and ifdown does not have any effect. Similarly, restarting any and all related networking and network-manager services does not bring the interface online if the tx-power has an incorrect value.

In spite of resets, the interface will appear to be up and iwconfig may even indeed report the maximum power(like in the OP iwconfig output), but there will not be any way to achieve connection on that interface, or even change its wireless settings.

However, if one does the following :

sudo ifconfig wlan0 down
sudo iw reg set BO
sudo iwconfig wlan0 txpower 20
sudo ifconfig wlan0 up

**The most important step being to have the txpower reset after the ifconfig wlan0 down and before bringing it back up. **

This solves the issue 100% of the time

5. Connection at 36 dBm with AU

I am yet to test this over a long period of time, but after an hour, the adapter does seem to get hotter and the ping average latency is worse than for iw reg set BO at tx-power of 20 dBm.

Improve this answer
3
  • I'm going to test this over the coming days and will report back but it seems like you've hit the nail on the head. Thank you so much!
    – Kane Charles
    Commented Oct 1, 2020 at 1:02
  • I've found that I'm unable to manually specify txpower settings to anything other than 36dBm when the reg is set to AU. For now I will try BO with a known reliable txpower setting and see how it goes. It seems you were able to manually set the txpower values for the AU country code, not sure why mine isn't working.
    – Kane Charles
    Commented Oct 1, 2020 at 11:06
  • Hi @BarBar1234, I just wanted to let you know I have also found the same results on my side with regards to stability. I have manually set mine to Bolivia with 20dBm as well. Interestingly I've not been able to manually configure any other txpower values for AU country code. Would you please mind sharing the script you used to test the different txpower settings with icmp? I'd like to check mine too.
    – Kane Charles
    Commented Oct 5, 2020 at 5:54

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .