[OpenWrt-Devel] Wifi is broken
diff mbox series

Message ID 5bc298cc-cd3d-0cdf-9772-36fc86cb1680@gmail.com
State Not Applicable
Headers show
Series
  • [OpenWrt-Devel] Wifi is broken
Related show

Commit Message

e9hack Nov. 16, 2019, 8:17 a.m. UTC
Hi,

this commit

commit	000b7687bc50be5b0f1161f4bf8ceb85c495c395
mac80211: restore mac80211_interface_cleanup()

breaks wifi on my tp-link archer C7 router. After update, only the 5G wifi will be activated. The 2.4G wifi doesn't start. I try to recover from this by shuting down and restart wifi by executing 'wifi down; sleep 30; wifi &'. Afterwards, wifi doesn't start anymore. I modify mac80211.sh to get some more log entries:

 
If I disable the ip and iw command in the loop, both wifi does start. 

This is stripped log file till the first client is connected to the 5G wifi and 2.4G didn't start:

Fri Nov 15 07:55:28 2019 kern.notice kernel: [    0.000000] Linux version 4.19.82 (I@my-vbox) (gcc version 9.2.0 (OpenWrt GCC 9.2.0 r11467-3ff3b044c0)) #0 Tue Nov 12 15:43:14 2019
Fri Nov 15 07:55:28 2019 kern.info kernel: [   24.994537] ath10k 4.19 driver, optimized for CT firmware, probing pci device: 0x3c.
Fri Nov 15 07:55:28 2019 kern.info kernel: [   25.003619] ath10k_pci 0000:00:00.0: enabling device (0000 -> 0002)
Fri Nov 15 07:55:28 2019 kern.info kernel: [   25.012275] ath10k_pci 0000:00:00.0: pci irq legacy oper_irq_mode 1 irq_mode 0 reset_mode 0
Fri Nov 15 07:55:28 2019 kern.err kernel: [   25.493698] firmware ath10k!fwcfg-pci-0000:00:00.0.txt: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.err kernel: [   25.816942] firmware ath10k!pre-cal-pci-0000:00:00.0.bin: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.err kernel: [   26.144589] firmware ath10k!QCA988X!hw2.0!ct-firmware-5.bin: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.err kernel: [   26.469953] firmware ath10k!QCA988X!hw2.0!ct-firmware-2.bin: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.err kernel: [   26.796028] firmware ath10k!QCA988X!hw2.0!firmware-6.bin: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.err kernel: [   27.120785] firmware ath10k!QCA988X!hw2.0!firmware-5.bin: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.err kernel: [   27.445941] firmware ath10k!QCA988X!hw2.0!firmware-4.bin: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.err kernel: [   27.773006] firmware ath10k!QCA988X!hw2.0!firmware-3.bin: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.info kernel: [   27.786068] ath10k_pci 0000:00:00.0: qca988x hw2.0 target 0x4100016c chip_id 0x043202ff sub 0000:0000
Fri Nov 15 07:55:28 2019 kern.info kernel: [   27.795472] ath10k_pci 0000:00:00.0: kconfig debug 0 debugfs 0 tracing 0 dfs 1 testmode 0
Fri Nov 15 07:55:28 2019 kern.info kernel: [   27.807607] ath10k_pci 0000:00:00.0: firmware ver 10.1-ct-8x-__fW-022-64cc8007 api 2 features wmi-10.x,has-wmi-mgmt-tx,mfp,txstatus-noack,wmi-10.x-CT,ratemask-CT,txrate-CT,get-temp-CT,tx-rc-CT,cust-stats-CT,retry-gt2-CT,txrate2-CT,beacon-cb-CT,wmi-block-ack-CT crc32 156478f0
Fri Nov 15 07:55:28 2019 kern.err kernel: [   28.173606] firmware ath10k!QCA988X!hw2.0!board-2.bin: firmware_loading_store: map pages failed
Fri Nov 15 07:55:28 2019 kern.info kernel: [   28.182884] ath10k_pci 0000:00:00.0: board_file api 1 bmi_id N/A crc32 bebc7c08
Fri Nov 15 07:55:28 2019 kern.warn kernel: [   29.185196] ath10k_pci 0000:00:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.201963] ath10k_pci 0000:00:00.0: wmi print 'P 128 V 8 T 410'
Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.208264] ath10k_pci 0000:00:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.216407] ath10k_pci 0000:00:00.0: wmi print 'alloc rem: 20904 iram: 26072'
Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.266256] ath10k_pci 0000:00:00.0: htt-ver 2.1 wmi-op 2 htt-op 2 cal file max-sta 128 raw 0 hwcrypto 1
Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.279137] ath10k_pci 0000:00:00.0: NOTE:  Firmware DBGLOG output disabled in debug_mask: 0x10000000
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414157] ath: EEPROM regdomain: 0x0
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414164] ath: EEPROM indicates default country code should be used
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414167] ath: doing EEPROM country->regdmn map search
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414179] ath: country maps to regdmn code: 0x3a
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414184] ath: Country alpha2 being used: US
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414188] ath: Regpair used: 0x3a
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510070] ath: EEPROM regdomain: 0x0
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510077] ath: EEPROM indicates default country code should be used
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510080] ath: doing EEPROM country->regdmn map search
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510093] ath: country maps to regdmn code: 0x3a
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510098] ath: Country alpha2 being used: US
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510101] ath: Regpair used: 0x3a
Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.527531] ieee80211 phy1: Selected rate control algorithm 'minstrel_ht'
Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.528563] ieee80211 phy1: Atheros AR9550 Rev:0 mem=0xb8100000, irq=12
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.974052] ath: EEPROM regdomain: 0x8114
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.978127] ath: EEPROM indicates we should expect a country code
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.984349] ath: doing EEPROM country->regdmn map search
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.989734] ath: country maps to regdmn code: 0x37
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.994608] ath: Country alpha2 being used: DE
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.999114] ath: Regpair used: 0x37
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.002664] ath: regdomain 0x8114 dynamically updated by user
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.008562] ath: EEPROM regdomain: 0x8114
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.012638] ath: EEPROM indicates we should expect a country code
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.018822] ath: doing EEPROM country->regdmn map search
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.024215] ath: country maps to regdmn code: 0x37
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.029074] ath: Country alpha2 being used: DE
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.033583] ath: Regpair used: 0x37
Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.037121] ath: regdomain 0x8114 dynamically updated by user
Fri Nov 15 07:55:54 2019 daemon.notice netifd: radio0 (2161): command failed: Too many open files in system (-23)
Fri Nov 15 07:55:54 2019 user.notice mac80211: Failed command: iw phy phy0 interface add wlan0 type __ap
Fri Nov 15 07:55:54 2019 daemon.notice hostapd: Configuration file: /var/run/hostapd-phy0.conf (phy wlan0) --> new PHY
Fri Nov 15 07:55:56 2019 kern.warn kernel: [   62.040719] ath10k_pci 0000:00:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
Fri Nov 15 07:55:56 2019 kern.info kernel: [   62.057521] ath10k_pci 0000:00:00.0: wmi print 'P 128 V 8 T 410'
Fri Nov 15 07:55:56 2019 kern.info kernel: [   62.063949] ath10k_pci 0000:00:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
Fri Nov 15 07:55:56 2019 kern.info kernel: [   62.072122] ath10k_pci 0000:00:00.0: wmi print 'alloc rem: 20904 iram: 26072'
Fri Nov 15 07:55:57 2019 kern.warn kernel: [   62.163141] ath10k_pci 0000:00:00.0: pdev param 0 not supported by firmware
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.182317] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Fri Nov 15 07:55:57 2019 daemon.notice netifd: radio1 (2181): command failed: Too many open files in system (-23)
Fri Nov 15 07:55:57 2019 user.notice mac80211: Failed command: iw phy phy1 interface add wlan1 type __ap
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.314691] br-lan: port 2(wlan0) entered blocking state
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.320087] br-lan: port 2(wlan0) entered disabled state
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.325793] device wlan0 entered promiscuous mode
Fri Nov 15 07:55:57 2019 daemon.notice hostapd: Configuration file: /var/run/hostapd-phy1.conf (phy wlan1) --> new PHY
Fri Nov 15 07:55:57 2019 daemon.notice hostapd: wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
Fri Nov 15 07:55:57 2019 daemon.notice hostapd: ACS: Automatic channel selection started, this may take a bit
Fri Nov 15 07:55:57 2019 daemon.notice hostapd: wlan0: interface state COUNTRY_UPDATE->ACS
Fri Nov 15 07:55:57 2019 daemon.notice hostapd: wlan0: ACS-STARTED
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.502671] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.736915] br-lan: port 3(wlan1) entered blocking state
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.742354] br-lan: port 3(wlan1) entered disabled state
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.748022] device wlan1 entered promiscuous mode
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.752922] br-lan: port 3(wlan1) entered blocking state
Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.758309] br-lan: port 3(wlan1) entered forwarding state
Fri Nov 15 07:55:57 2019 daemon.notice hostapd: wlan1: interface state UNINITIALIZED->COUNTRY_UPDATE
Fri Nov 15 07:55:57 2019 daemon.err hostapd: Using interface wlan1 with hwaddr xx:xx:xx:xx:xx:xx and ssid "WLAN-01"
Fri Nov 15 07:55:58 2019 user.notice root: ip link set dev wlan0 up
Fri Nov 15 07:55:58 2019 user.notice root: ip link set dev wlan0-1 up
Fri Nov 15 07:55:59 2019 kern.info kernel: [   64.431080] br-lan: port 3(wlan1) entered disabled state
Fri Nov 15 07:55:59 2019 daemon.notice netifd: radio0 (2161): Cannot find device "wlan0-1"
Fri Nov 15 07:55:59 2019 daemon.notice netifd: radio0 (2161): Interface 1 setup failed: IFUP_ERROR
Fri Nov 15 07:55:59 2019 user.notice root: ip link set dev wlan0-2 up
Fri Nov 15 07:56:00 2019 daemon.notice netifd: radio0 (2161): Cannot find device "wlan0-2"
Fri Nov 15 07:56:00 2019 daemon.notice netifd: radio0 (2161): Interface 2 setup failed: IFUP_ERROR
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing noise floor
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing channel time
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is missing RX and busy time (at least one is required)
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: wlan0: ACS-COMPLETED freq=5580 channel=116
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: wlan0: interface state ACS->HT_SCAN
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: wlan0: interface state HT_SCAN->DFS
Fri Nov 15 07:56:09 2019 daemon.notice hostapd: wlan0: DFS-CAC-START freq=5580 chan=116 sec_chan=1, width=1, seg0=122, seg1=0, cac_time=60s
Fri Nov 15 07:56:27 2019 daemon.notice netifd: radio1 (2181): Command failed: Request timed out
Fri Nov 15 07:56:27 2019 daemon.notice netifd: radio1 (2181): Device setup failed: HOSTAPD_START_FAILED
Fri Nov 15 07:56:29 2019 user.notice hostapd-test-1: primary_ap: ''
Fri Nov 15 07:56:29 2019 user.notice hostapd-test-2: primary_ap: ''
Fri Nov 15 07:56:29 2019 user.notice hostapd-test-3: mac80211_vap_cleanup hostapd ""
Fri Nov 15 07:56:29 2019 user.notice hostapd-test-4: mac80211_vap_cleanup wpa_supplicant ""
Fri Nov 15 07:56:29 2019 user.notice hostapd-test-5: wdev_phy: '../../ieee80211/phy1'
Fri Nov 15 07:56:29 2019 user.notice hostapd-test-6: wdev_phy: 'phy1' phy: 'phy1'
Fri Nov 15 07:56:29 2019 user.notice hostapd-test-7: ip link set dev "wlan1" down 2>/dev/null
Fri Nov 15 07:56:29 2019 kern.info kernel: [   94.739161] br-lan: port 3(wlan1) entered disabled state
Fri Nov 15 07:56:29 2019 user.notice hostapd-test-8: iw dev "wlan1" del
Fri Nov 15 07:56:29 2019 kern.info kernel: [   95.016035] device wlan1 left promiscuous mode
Fri Nov 15 07:56:29 2019 kern.info kernel: [   95.020554] br-lan: port 3(wlan1) entered disabled state
Sat Nov 16 08:01:59 2019 daemon.notice hostapd: wlan0: DFS-CAC-COMPLETED success=1 freq=5580 ht_enabled=0 chan_offset=0 chan_width=3 cf1=5610 cf2=0
Sat Nov 16 08:01:59 2019 daemon.err hostapd: Using interface wlan0 with hwaddr xx:xx:xx:xx:xx:xx and ssid "WLAN-02"
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.076820] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.083515] br-lan: port 2(wlan0) entered blocking state
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.088906] br-lan: port 2(wlan0) entered forwarding state
Sat Nov 16 08:02:00 2019 daemon.notice netifd: Network device 'wlan0' link is up
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.122541] br-xxx: port 1(wlan0-1) entered blocking state
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.128109] br-xxx: port 1(wlan0-1) entered disabled state
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.134009] device wlan0-1 entered promiscuous mode
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.198674] IPv6: ADDRCONF(NETDEV_UP): wlan0-1: link is not ready
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.204996] br-xxx: port 1(wlan0-1) entered blocking state
Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.210565] br-xxx: port 1(wlan0-1) entered forwarding state
Sat Nov 16 08:02:00 2019 daemon.err hostapd: Using interface wlan0-1 with hwaddr xx:xx:xx:xx:xx:xx and ssid "WLAN-03"
Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.551443] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0-1: link becomes ready
Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.581574] br-lan: port 3(wlan0-2) entered blocking state
Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.587332] br-lan: port 3(wlan0-2) entered disabled state
Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.593255] device wlan0-2 entered promiscuous mode
Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.631446] IPv6: ADDRCONF(NETDEV_UP): wlan0-2: link is not ready
Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.637662] br-lan: port 3(wlan0-2) entered blocking state
Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.643251] br-lan: port 3(wlan0-2) entered forwarding state
Sat Nov 16 08:02:01 2019 daemon.err hostapd: Using interface wlan0-2 with hwaddr xx:xx:xx:xx:xx:xx and ssid "WLAN-01"
Sat Nov 16 08:02:01 2019 kern.info kernel: [  138.081336] br-lan: port 3(wlan0-2) entered disabled state
Sat Nov 16 08:03:55 2019 daemon.err hostapd: Failed to set beacon parameters
Sat Nov 16 08:03:55 2019 daemon.warn hostapd: wlan1: Could not connect to kernel driver
Sat Nov 16 08:03:57 2019 daemon.err hostapd: Interface initialization failed
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1: interface state COUNTRY_UPDATE->DISABLED
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1: AP-DISABLED
Sat Nov 16 08:03:57 2019 daemon.err hostapd: wlan1: Unable to setup interface.
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: nl80211: deinit ifname=wlan1 disabled_11b_rates=0
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: nl80211: Failed to remove interface wlan1 from bridge br-lan: No such device
Sat Nov 16 08:03:57 2019 daemon.err hostapd: Could not read interface wlan1 flags: No such device
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1: CTRL-EVENT-TERMINATING
Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan1 wasn't started
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-1: CTRL-EVENT-TERMINATING
Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan1-1 wasn't started
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-2: CTRL-EVENT-TERMINATING
Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan1-2 wasn't started
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-3: CTRL-EVENT-TERMINATING
Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan1-3 wasn't started
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-4: CTRL-EVENT-TERMINATING
Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan1-4 wasn't started
Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-5: CTRL-EVENT-TERMINATING
Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data: Interface wlan1-5 wasn't started
Sat Nov 16 08:04:18 2019 kern.info kernel: [  274.841981] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0-2: link becomes ready
Sat Nov 16 08:04:18 2019 kern.info kernel: [  274.848883] br-lan: port 3(wlan0-2) entered blocking state
Sat Nov 16 08:04:18 2019 kern.info kernel: [  274.854491] br-lan: port 3(wlan0-2) entered forwarding state
Sat Nov 16 08:04:18 2019 daemon.notice hostapd: wlan0: interface state DFS->ENABLED
Sat Nov 16 08:04:18 2019 daemon.notice hostapd: wlan0: AP-ENABLED
Sat Nov 16 08:04:25 2019 daemon.info hostapd: wlan0-2: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Sat Nov 16 08:04:25 2019 daemon.info hostapd: wlan0-2: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Sat Nov 16 08:04:25 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-EAP-STARTED xx:xx:xx:xx:xx:xx
Sat Nov 16 08:04:25 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=1
Sat Nov 16 08:04:28 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-EAP-RETRANSMIT xx:xx:xx:xx:xx:xx
Sat Nov 16 08:04:28 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=25
Sat Nov 16 08:04:31 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-EAP-RETRANSMIT xx:xx:xx:xx:xx:xx
Sat Nov 16 08:04:31 2019 daemon.notice hostapd: EAP-PEAP: TLV Result - Success - requested Success
Sat Nov 16 08:04:31 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-EAP-SUCCESS xx:xx:xx:xx:xx:xx
Sat Nov 16 08:04:31 2019 daemon.info hostapd: wlan0-2: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Sat Nov 16 08:04:31 2019 daemon.notice hostapd: wlan0-2: AP-STA-CONNECTED xx:xx:xx:xx:xx:xx
Sat Nov 16 08:04:31 2019 daemon.info hostapd: wlan0-2: STA xx:xx:xx:xx:xx:xx RADIUS: starting accounting session 9A799A3ABAF7BA35
Sat Nov 16 08:04:31 2019 daemon.info hostapd: wlan0-2: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: authenticated - EAP type: 0 (unknown)

Regards,
Hartmut

Comments

Dirk Brenken Nov. 16, 2019, 3:50 p.m. UTC | #1
On Sat, 2019-11-16 at 09:17 +0100, e9hack wrote:
> Hi,
> 
> this commit
> 
> commit	000b7687bc50be5b0f1161f4bf8ceb85c495c395
> mac80211: restore mac80211_interface_cleanup()
> 
> breaks wifi on my tp-link archer C7 router. After update, only the 5G
> wifi will be activated. The 2.4G wifi doesn't start. I try to recover
> from this by shuting down and restart wifi by executing 'wifi down;
> sleep 30; wifi &'. Afterwards, wifi doesn't start anymore. I modify
> mac80211.sh to get some more log entries:
> 
> diff U3 D:/Download/carambola/mac80211.sh.old
> D:/Download/carambola/mac80211.sh
> --- D:/Download/carambola/mac80211.sh.old	Fri Nov 15 07:52:57
> 2019
> +++ D:/Download/carambola/mac80211.sh	Sat Nov 16 07:46:19 2019
> @@ -810,15 +810,23 @@
>  mac80211_interface_cleanup() {
>  	local phy="$1"
>  	local primary_ap=$(uci -q -P /var/state get
> wireless._${phy}.aplist)
> +	logger -t "hostapd-test-1" "primary_ap: '$primary_ap'"
>  	primary_ap=${primary_ap%% *}
> +	logger -t "hostapd-test-2" "primary_ap: '$primary_ap'"
>  
> +	logger -t "hostapd-test-3" "mac80211_vap_cleanup hostapd
> \"${primary_ap}\""
>  	mac80211_vap_cleanup hostapd "${primary_ap}"
> +	logger -t "hostapd-test-4" "mac80211_vap_cleanup wpa_supplicant
> \"$(uci -q -P /var/state get wireless._${phy}.splist)\""
>  	mac80211_vap_cleanup wpa_supplicant "$(uci -q -P /var/state get
> wireless._${phy}.splist)"
>  	for wdev in $(list_phy_interfaces "$phy"); do
>  		local wdev_phy="$(readlink
> /sys/class/net/${wdev}/phy80211)"
> +		logger -t "hostapd-test-5" "wdev_phy: '$wdev_phy'"
>  		wdev_phy="$(basename "$wdev_phy")"
> +		logger -t "hostapd-test-6" "wdev_phy: '$wdev_phy' phy:
> '$phy'"
>  		[ -n "$wdev_phy" -a "$wdev_phy" != "$phy" ] && continue
> +		logger -t "hostapd-test-7" "ip link set dev \"$wdev\"
> down 2>/dev/null"
>  		ip link set dev "$wdev" down 2>/dev/null
> +		logger -t "hostapd-test-8" "iw dev \"$wdev\" del"
>  		iw dev "$wdev" del
>  	done
>  }
>  
> If I disable the ip and iw command in the loop, both wifi does
> start. 
> 
> This is stripped log file till the first client is connected to the
> 5G wifi and 2.4G didn't start:
> 
> Fri Nov 15 07:55:28 2019 kern.notice kernel: [    0.000000] Linux
> version 4.19.82 (I@my-vbox) (gcc version 9.2.0 (OpenWrt GCC 9.2.0
> r11467-3ff3b044c0)) #0 Tue Nov 12 15:43:14 2019
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   24.994537] ath10k 4.19
> driver, optimized for CT firmware, probing pci device: 0x3c.
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   25.003619] ath10k_pci
> 0000:00:00.0: enabling device (0000 -> 0002)
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   25.012275] ath10k_pci
> 0000:00:00.0: pci irq legacy oper_irq_mode 1 irq_mode 0 reset_mode 0
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   25.493698] firmware
> ath10k!fwcfg-pci-0000:00:00.0.txt: firmware_loading_store: map pages
> failed
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   25.816942] firmware
> ath10k!pre-cal-pci-0000:00:00.0.bin: firmware_loading_store: map
> pages failed
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   26.144589] firmware
> ath10k!QCA988X!hw2.0!ct-firmware-5.bin: firmware_loading_store: map
> pages failed
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   26.469953] firmware
> ath10k!QCA988X!hw2.0!ct-firmware-2.bin: firmware_loading_store: map
> pages failed
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   26.796028] firmware
> ath10k!QCA988X!hw2.0!firmware-6.bin: firmware_loading_store: map
> pages failed
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   27.120785] firmware
> ath10k!QCA988X!hw2.0!firmware-5.bin: firmware_loading_store: map
> pages failed
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   27.445941] firmware
> ath10k!QCA988X!hw2.0!firmware-4.bin: firmware_loading_store: map
> pages failed
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   27.773006] firmware
> ath10k!QCA988X!hw2.0!firmware-3.bin: firmware_loading_store: map
> pages failed
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   27.786068] ath10k_pci
> 0000:00:00.0: qca988x hw2.0 target 0x4100016c chip_id 0x043202ff sub
> 0000:0000
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   27.795472] ath10k_pci
> 0000:00:00.0: kconfig debug 0 debugfs 0 tracing 0 dfs 1 testmode 0
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   27.807607] ath10k_pci
> 0000:00:00.0: firmware ver 10.1-ct-8x-__fW-022-64cc8007 api 2
> features wmi-10.x,has-wmi-mgmt-tx,mfp,txstatus-noack,wmi-10.x-
> CT,ratemask-CT,txrate-CT,get-temp-CT,tx-rc-CT,cust-stats-CT,retry-
> gt2-CT,txrate2-CT,beacon-cb-CT,wmi-block-ack-CT crc32 156478f0
> Fri Nov 15 07:55:28 2019 kern.err kernel: [   28.173606] firmware
> ath10k!QCA988X!hw2.0!board-2.bin: firmware_loading_store: map pages
> failed
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   28.182884] ath10k_pci
> 0000:00:00.0: board_file api 1 bmi_id N/A crc32 bebc7c08
> Fri Nov 15 07:55:28 2019 kern.warn kernel: [   29.185196] ath10k_pci
> 0000:00:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.201963] ath10k_pci
> 0000:00:00.0: wmi print 'P 128 V 8 T 410'
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.208264] ath10k_pci
> 0000:00:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.216407] ath10k_pci
> 0000:00:00.0: wmi print 'alloc rem: 20904 iram: 26072'
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.266256] ath10k_pci
> 0000:00:00.0: htt-ver 2.1 wmi-op 2 htt-op 2 cal file max-sta 128 raw
> 0 hwcrypto 1
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.279137] ath10k_pci
> 0000:00:00.0: NOTE:  Firmware DBGLOG output disabled in debug_mask:
> 0x10000000
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414157] ath:
> EEPROM regdomain: 0x0
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414164] ath:
> EEPROM indicates default country code should be used
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414167] ath: doing
> EEPROM country->regdmn map search
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414179] ath:
> country maps to regdmn code: 0x3a
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414184] ath:
> Country alpha2 being used: US
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.414188] ath:
> Regpair used: 0x3a
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510070] ath:
> EEPROM regdomain: 0x0
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510077] ath:
> EEPROM indicates default country code should be used
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510080] ath: doing
> EEPROM country->regdmn map search
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510093] ath:
> country maps to regdmn code: 0x3a
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510098] ath:
> Country alpha2 being used: US
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.510101] ath:
> Regpair used: 0x3a
> Fri Nov 15 07:55:28 2019 kern.debug kernel: [   29.527531] ieee80211
> phy1: Selected rate control algorithm 'minstrel_ht'
> Fri Nov 15 07:55:28 2019 kern.info kernel: [   29.528563] ieee80211
> phy1: Atheros AR9550 Rev:0 mem=0xb8100000, irq=12
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.974052] ath:
> EEPROM regdomain: 0x8114
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.978127] ath:
> EEPROM indicates we should expect a country code
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.984349] ath: doing
> EEPROM country->regdmn map search
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.989734] ath:
> country maps to regdmn code: 0x37
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.994608] ath:
> Country alpha2 being used: DE
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   55.999114] ath:
> Regpair used: 0x37
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.002664] ath:
> regdomain 0x8114 dynamically updated by user
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.008562] ath:
> EEPROM regdomain: 0x8114
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.012638] ath:
> EEPROM indicates we should expect a country code
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.018822] ath: doing
> EEPROM country->regdmn map search
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.024215] ath:
> country maps to regdmn code: 0x37
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.029074] ath:
> Country alpha2 being used: DE
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.033583] ath:
> Regpair used: 0x37
> Fri Nov 15 07:55:50 2019 kern.debug kernel: [   56.037121] ath:
> regdomain 0x8114 dynamically updated by user
> Fri Nov 15 07:55:54 2019 daemon.notice netifd: radio0 (2161): command
> failed: Too many open files in system (-23)
> Fri Nov 15 07:55:54 2019 user.notice mac80211: Failed command: iw phy
> phy0 interface add wlan0 type __ap
> Fri Nov 15 07:55:54 2019 daemon.notice hostapd: Configuration file:
> /var/run/hostapd-phy0.conf (phy wlan0) --> new PHY
> Fri Nov 15 07:55:56 2019 kern.warn kernel: [   62.040719] ath10k_pci
> 0000:00:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
> Fri Nov 15 07:55:56 2019 kern.info kernel: [   62.057521] ath10k_pci
> 0000:00:00.0: wmi print 'P 128 V 8 T 410'
> Fri Nov 15 07:55:56 2019 kern.info kernel: [   62.063949] ath10k_pci
> 0000:00:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
> Fri Nov 15 07:55:56 2019 kern.info kernel: [   62.072122] ath10k_pci
> 0000:00:00.0: wmi print 'alloc rem: 20904 iram: 26072'
> Fri Nov 15 07:55:57 2019 kern.warn kernel: [   62.163141] ath10k_pci
> 0000:00:00.0: pdev param 0 not supported by firmware
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.182317] IPv6:
> ADDRCONF(NETDEV_UP): wlan0: link is not ready
> Fri Nov 15 07:55:57 2019 daemon.notice netifd: radio1 (2181): command
> failed: Too many open files in system (-23)
> Fri Nov 15 07:55:57 2019 user.notice mac80211: Failed command: iw phy
> phy1 interface add wlan1 type __ap
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.314691] br-lan:
> port 2(wlan0) entered blocking state
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.320087] br-lan:
> port 2(wlan0) entered disabled state
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.325793] device
> wlan0 entered promiscuous mode
> Fri Nov 15 07:55:57 2019 daemon.notice hostapd: Configuration file:
> /var/run/hostapd-phy1.conf (phy wlan1) --> new PHY
> Fri Nov 15 07:55:57 2019 daemon.notice hostapd: wlan0: interface
> state UNINITIALIZED->COUNTRY_UPDATE
> Fri Nov 15 07:55:57 2019 daemon.notice hostapd: ACS: Automatic
> channel selection started, this may take a bit
> Fri Nov 15 07:55:57 2019 daemon.notice hostapd: wlan0: interface
> state COUNTRY_UPDATE->ACS
> Fri Nov 15 07:55:57 2019 daemon.notice hostapd: wlan0: ACS-STARTED
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.502671] IPv6:
> ADDRCONF(NETDEV_UP): wlan1: link is not ready
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.736915] br-lan:
> port 3(wlan1) entered blocking state
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.742354] br-lan:
> port 3(wlan1) entered disabled state
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.748022] device
> wlan1 entered promiscuous mode
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.752922] br-lan:
> port 3(wlan1) entered blocking state
> Fri Nov 15 07:55:57 2019 kern.info kernel: [   62.758309] br-lan:
> port 3(wlan1) entered forwarding state
> Fri Nov 15 07:55:57 2019 daemon.notice hostapd: wlan1: interface
> state UNINITIALIZED->COUNTRY_UPDATE
> Fri Nov 15 07:55:57 2019 daemon.err hostapd: Using interface wlan1
> with hwaddr xx:xx:xx:xx:xx:xx and ssid "WLAN-01"
> Fri Nov 15 07:55:58 2019 user.notice root: ip link set dev wlan0 up
> Fri Nov 15 07:55:58 2019 user.notice root: ip link set dev wlan0-1 up
> Fri Nov 15 07:55:59 2019 kern.info kernel: [   64.431080] br-lan:
> port 3(wlan1) entered disabled state
> Fri Nov 15 07:55:59 2019 daemon.notice netifd: radio0 (2161): Cannot
> find device "wlan0-1"
> Fri Nov 15 07:55:59 2019 daemon.notice netifd: radio0 (2161):
> Interface 1 setup failed: IFUP_ERROR
> Fri Nov 15 07:55:59 2019 user.notice root: ip link set dev wlan0-2 up
> Fri Nov 15 07:56:00 2019 daemon.notice netifd: radio0 (2161): Cannot
> find device "wlan0-2"
> Fri Nov 15 07:56:00 2019 daemon.notice netifd: radio0 (2161):
> Interface 2 setup failed: IFUP_ERROR
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing noise floor
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing channel time
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: ACS: Survey is
> missing RX and busy time (at least one is required)
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: wlan0: ACS-COMPLETED
> freq=5580 channel=116
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: wlan0: interface
> state ACS->HT_SCAN
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: wlan0: interface
> state HT_SCAN->DFS
> Fri Nov 15 07:56:09 2019 daemon.notice hostapd: wlan0: DFS-CAC-START
> freq=5580 chan=116 sec_chan=1, width=1, seg0=122, seg1=0,
> cac_time=60s
> Fri Nov 15 07:56:27 2019 daemon.notice netifd: radio1 (2181): Command
> failed: Request timed out
> Fri Nov 15 07:56:27 2019 daemon.notice netifd: radio1 (2181): Device
> setup failed: HOSTAPD_START_FAILED
> Fri Nov 15 07:56:29 2019 user.notice hostapd-test-1: primary_ap: ''
> Fri Nov 15 07:56:29 2019 user.notice hostapd-test-2: primary_ap: ''
> Fri Nov 15 07:56:29 2019 user.notice hostapd-test-3:
> mac80211_vap_cleanup hostapd ""
> Fri Nov 15 07:56:29 2019 user.notice hostapd-test-4:
> mac80211_vap_cleanup wpa_supplicant ""
> Fri Nov 15 07:56:29 2019 user.notice hostapd-test-5: wdev_phy:
> '../../ieee80211/phy1'
> Fri Nov 15 07:56:29 2019 user.notice hostapd-test-6: wdev_phy: 'phy1'
> phy: 'phy1'
> Fri Nov 15 07:56:29 2019 user.notice hostapd-test-7: ip link set dev
> "wlan1" down 2>/dev/null
> Fri Nov 15 07:56:29 2019 kern.info kernel: [   94.739161] br-lan:
> port 3(wlan1) entered disabled state
> Fri Nov 15 07:56:29 2019 user.notice hostapd-test-8: iw dev "wlan1"
> del
> Fri Nov 15 07:56:29 2019 kern.info kernel: [   95.016035] device
> wlan1 left promiscuous mode
> Fri Nov 15 07:56:29 2019 kern.info kernel: [   95.020554] br-lan:
> port 3(wlan1) entered disabled state
> Sat Nov 16 08:01:59 2019 daemon.notice hostapd: wlan0: DFS-CAC-
> COMPLETED success=1 freq=5580 ht_enabled=0 chan_offset=0 chan_width=3
> cf1=5610 cf2=0
> Sat Nov 16 08:01:59 2019 daemon.err hostapd: Using interface wlan0
> with hwaddr xx:xx:xx:xx:xx:xx and ssid "WLAN-02"
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.076820] IPv6:
> ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.083515] br-lan:
> port 2(wlan0) entered blocking state
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.088906] br-lan:
> port 2(wlan0) entered forwarding state
> Sat Nov 16 08:02:00 2019 daemon.notice netifd: Network device 'wlan0'
> link is up
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.122541] br-xxx:
> port 1(wlan0-1) entered blocking state
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.128109] br-xxx:
> port 1(wlan0-1) entered disabled state
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.134009] device
> wlan0-1 entered promiscuous mode
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.198674] IPv6:
> ADDRCONF(NETDEV_UP): wlan0-1: link is not ready
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.204996] br-xxx:
> port 1(wlan0-1) entered blocking state
> Sat Nov 16 08:02:00 2019 kern.info kernel: [  137.210565] br-xxx:
> port 1(wlan0-1) entered forwarding state
> Sat Nov 16 08:02:00 2019 daemon.err hostapd: Using interface wlan0-1
> with hwaddr xx:xx:xx:xx:xx:xx and ssid "WLAN-03"
> Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.551443] IPv6:
> ADDRCONF(NETDEV_CHANGE): wlan0-1: link becomes ready
> Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.581574] br-lan:
> port 3(wlan0-2) entered blocking state
> Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.587332] br-lan:
> port 3(wlan0-2) entered disabled state
> Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.593255] device
> wlan0-2 entered promiscuous mode
> Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.631446] IPv6:
> ADDRCONF(NETDEV_UP): wlan0-2: link is not ready
> Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.637662] br-lan:
> port 3(wlan0-2) entered blocking state
> Sat Nov 16 08:02:01 2019 kern.info kernel: [  137.643251] br-lan:
> port 3(wlan0-2) entered forwarding state
> Sat Nov 16 08:02:01 2019 daemon.err hostapd: Using interface wlan0-2
> with hwaddr xx:xx:xx:xx:xx:xx and ssid "WLAN-01"
> Sat Nov 16 08:02:01 2019 kern.info kernel: [  138.081336] br-lan:
> port 3(wlan0-2) entered disabled state
> Sat Nov 16 08:03:55 2019 daemon.err hostapd: Failed to set beacon
> parameters
> Sat Nov 16 08:03:55 2019 daemon.warn hostapd: wlan1: Could not
> connect to kernel driver
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: Interface initialization
> failed
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1: interface
> state COUNTRY_UPDATE->DISABLED
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1: AP-DISABLED
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: wlan1: Unable to setup
> interface.
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: nl80211: deinit
> ifname=wlan1 disabled_11b_rates=0
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: nl80211: Failed to
> remove interface wlan1 from bridge br-lan: No such device
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: Could not read interface
> wlan1 flags: No such device
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1: CTRL-EVENT-
> TERMINATING
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data:
> Interface wlan1 wasn't started
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-1: CTRL-EVENT-
> TERMINATING
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data:
> Interface wlan1-1 wasn't started
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-2: CTRL-EVENT-
> TERMINATING
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data:
> Interface wlan1-2 wasn't started
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-3: CTRL-EVENT-
> TERMINATING
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data:
> Interface wlan1-3 wasn't started
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-4: CTRL-EVENT-
> TERMINATING
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data:
> Interface wlan1-4 wasn't started
> Sat Nov 16 08:03:57 2019 daemon.notice hostapd: wlan1-5: CTRL-EVENT-
> TERMINATING
> Sat Nov 16 08:03:57 2019 daemon.err hostapd: hostapd_free_hapd_data:
> Interface wlan1-5 wasn't started
> Sat Nov 16 08:04:18 2019 kern.info kernel: [  274.841981] IPv6:
> ADDRCONF(NETDEV_CHANGE): wlan0-2: link becomes ready
> Sat Nov 16 08:04:18 2019 kern.info kernel: [  274.848883] br-lan:
> port 3(wlan0-2) entered blocking state
> Sat Nov 16 08:04:18 2019 kern.info kernel: [  274.854491] br-lan:
> port 3(wlan0-2) entered forwarding state
> Sat Nov 16 08:04:18 2019 daemon.notice hostapd: wlan0: interface
> state DFS->ENABLED
> Sat Nov 16 08:04:18 2019 daemon.notice hostapd: wlan0: AP-ENABLED
> Sat Nov 16 08:04:25 2019 daemon.info hostapd: wlan0-2: STA
> xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
> Sat Nov 16 08:04:25 2019 daemon.info hostapd: wlan0-2: STA
> xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
> Sat Nov 16 08:04:25 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-
> EAP-STARTED xx:xx:xx:xx:xx:xx
> Sat Nov 16 08:04:25 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-
> EAP-PROPOSED-METHOD vendor=0 method=1
> Sat Nov 16 08:04:28 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-
> EAP-RETRANSMIT xx:xx:xx:xx:xx:xx
> Sat Nov 16 08:04:28 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-
> EAP-PROPOSED-METHOD vendor=0 method=25
> Sat Nov 16 08:04:31 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-
> EAP-RETRANSMIT xx:xx:xx:xx:xx:xx
> Sat Nov 16 08:04:31 2019 daemon.notice hostapd: EAP-PEAP: TLV Result
> - Success - requested Success
> Sat Nov 16 08:04:31 2019 daemon.notice hostapd: wlan0-2: CTRL-EVENT-
> EAP-SUCCESS xx:xx:xx:xx:xx:xx
> Sat Nov 16 08:04:31 2019 daemon.info hostapd: wlan0-2: STA
> xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
> Sat Nov 16 08:04:31 2019 daemon.notice hostapd: wlan0-2: AP-STA-
> CONNECTED xx:xx:xx:xx:xx:xx
> Sat Nov 16 08:04:31 2019 daemon.info hostapd: wlan0-2: STA
> xx:xx:xx:xx:xx:xx RADIUS: starting accounting session
> 9A799A3ABAF7BA35
> Sat Nov 16 08:04:31 2019 daemon.info hostapd: wlan0-2: STA
> xx:xx:xx:xx:xx:xx IEEE 802.1X: authenticated - EAP type: 0 (unknown)
> 
> Regards,
> Hartmut
> 
> 
> 
> 
> 
> _______________________________________________
> openwrt-devel mailing list
> openwrt-devel@lists.openwrt.org
> 
> https://lists.openwrt.org/mailman/listinfo/openwrt-devel
> 
> 

Same symptoms here with a GL-AR300M (single radio 2.4G, travel router)
and travelmate.

Regards,
Dirk
Daniel Golle Nov. 16, 2019, 4:27 p.m. UTC | #2
Hi,

On Sat, Nov 16, 2019 at 09:17:08AM +0100, e9hack wrote:
> Hi,
> 
> this commit
> 
> commit	000b7687bc50be5b0f1161f4bf8ceb85c495c395
> mac80211: restore mac80211_interface_cleanup()
> 
> breaks wifi on my tp-link archer C7 router. After update, only the 5G wifi will be activated. The 2.4G wifi doesn't start. I try to recover from this by shuting down and restart wifi by executing 'wifi down; sleep 30; wifi &'. Afterwards, wifi doesn't start anymore. I modify mac80211.sh to get some more log entries:

I've reverted that commit and applied a more sophisticated fix instead.
Please retest and report if that works better.


Cheers

Daniel
Dirk Brenken Nov. 16, 2019, 7:05 p.m. UTC | #3
On Sat, 2019-11-16 at 17:27 +0100, Daniel Golle wrote:
> Hi,
> 
> On Sat, Nov 16, 2019 at 09:17:08AM +0100, e9hack wrote:
> > Hi,
> > 
> > this commit
> > 
> > commit	000b7687bc50be5b0f1161f4bf8ceb85c495c395
> > mac80211: restore mac80211_interface_cleanup()
> > 
> > breaks wifi on my tp-link archer C7 router. After update, only the
> > 5G wifi will be activated. The 2.4G wifi doesn't start. I try to
> > recover from this by shuting down and restart wifi by executing
> > 'wifi down; sleep 30; wifi &'. Afterwards, wifi doesn't start
> > anymore. I modify mac80211.sh to get some more log entries:
> 
> I've reverted that commit and applied a more sophisticated fix
> instead.
> Please retest and report if that works better.
> 
> 
> Cheers
> 
> Daniel
> 
Works better now - the AP now comes up after reboot (still with some
suspicios error messages):

[...]
Sat Nov 16 17:26:15 2019 daemon.notice netifd: radio0 (1262): sh: out
of range
Sat Nov 16 17:26:16 2019 daemon.err odhcpd[1331]: Failed to send to
ff02::1%lan@br-lan (Address not available)
Sat Nov 16 17:26:16 2019 daemon.notice netifd: radio0 (1262): command
failed: Too many open files in system (-23)
Sat Nov 16 17:26:17 2019 daemon.notice netifd: radio0 (1262): command
failed: Too many open files in system (-23)
Sat Nov 16 17:26:19 2019 user.notice firewall: Reloading firewall due
to ifup of lan (br-lan)
Sat Nov 16 17:26:19 2019 daemon.notice hostapd: Configuration file:
/var/run/hostapd-phy0.conf (phy wlan0) --> new PHY
Sat Nov 16 17:26:19 2019 kern.info kernel: [   48.375045] IPv6:
ADDRCONF(NETDEV_UP): wlan0: link is not ready
Sat Nov 16 17:26:19 2019 kern.info kernel: [   48.478057] br-lan: port
2(wlan0) entered blocking state
Sat Nov 16 17:26:19 2019 kern.info kernel: [   48.483739] br-lan: port
2(wlan0) entered disabled state
Sat Nov 16 17:26:19 2019 kern.info kernel: [   48.489606] device wlan0
entered promiscuous mode
Sat Nov 16 17:26:19 2019 daemon.notice hostapd: wlan0: interface state
UNINITIALIZED->COUNTRY_UPDATE
Sat Nov 16 17:26:19 2019 daemon.err hostapd: Using interface wlan0 with
hwaddr e4:95:6e:45:87:e3 and ssid "adb2go"
Sat Nov 16 17:26:21 2019 daemon.notice hostapd: wlan0: interface state
COUNTRY_UPDATE->ENABLED
Sat Nov 16 17:26:21 2019 daemon.notice hostapd: wlan0: AP-ENABLED
[...]

Regards,
Dirk

> _______________________________________________
> openwrt-devel mailing list
> openwrt-devel@lists.openwrt.org
> 
> https://lists.openwrt.org/mailman/listinfo/openwrt-devel
> 
>
e9hack Nov. 17, 2019, 4:18 p.m. UTC | #4
Am 16.11.2019 um 17:27 schrieb Daniel Golle:
> Hi,
> 
> On Sat, Nov 16, 2019 at 09:17:08AM +0100, e9hack wrote:
>> Hi,
>>
>> this commit
>>
>> commit	000b7687bc50be5b0f1161f4bf8ceb85c495c395
>> mac80211: restore mac80211_interface_cleanup()
>>
>> breaks wifi on my tp-link archer C7 router. After update, only the 5G wifi will be activated. The 2.4G wifi doesn't start. I try to recover from this by shuting down and restart wifi by executing 'wifi down; sleep 30; wifi &'. Afterwards, wifi doesn't start anymore. I modify mac80211.sh to get some more log entries:
> 
> I've reverted that commit and applied a more sophisticated fix instead.
> Please retest and report if that works better.

After your fix, both networks does start again. 

Thanks!

Regards,
Hartmut
Dirk Brenken Nov. 18, 2019, 7:37 a.m. UTC | #5
On Sat, 2019-11-16 at 17:27 +0100, Daniel Golle wrote:
> Hi,
> 
> On Sat, Nov 16, 2019 at 09:17:08AM +0100, e9hack wrote:
> > Hi,
> > 
> > this commit
> > 
> > commit	000b7687bc50be5b0f1161f4bf8ceb85c495c395
> > mac80211: restore mac80211_interface_cleanup()
> > 
> > breaks wifi on my tp-link archer C7 router. After update, only the
> > 5G wifi will be activated. The 2.4G wifi doesn't start. I try to
> > recover from this by shuting down and restart wifi by executing
> > 'wifi down; sleep 30; wifi &'. Afterwards, wifi doesn't start
> > anymore. I modify mac80211.sh to get some more log entries:
> 
> I've reverted that commit and applied a more sophisticated fix
> instead.
> Please retest and report if that works better.
> 
> 
> Cheers
> 
> Daniel
> 

Just another nitpick. Could you please expose the new "reconf" wifi
parameter in the wifi --help? That makes it much easier for external
scripts to check for that.

Thanks!
Dirk

> _______________________________________________
> openwrt-devel mailing list
> openwrt-devel@lists.openwrt.org
> 
> https://lists.openwrt.org/mailman/listinfo/openwrt-devel
> 
>

Patch
diff mbox series

diff U3 D:/Download/carambola/mac80211.sh.old D:/Download/carambola/mac80211.sh
--- D:/Download/carambola/mac80211.sh.old	Fri Nov 15 07:52:57 2019
+++ D:/Download/carambola/mac80211.sh	Sat Nov 16 07:46:19 2019
@@ -810,15 +810,23 @@ 
 mac80211_interface_cleanup() {
 	local phy="$1"
 	local primary_ap=$(uci -q -P /var/state get wireless._${phy}.aplist)
+	logger -t "hostapd-test-1" "primary_ap: '$primary_ap'"
 	primary_ap=${primary_ap%% *}
+	logger -t "hostapd-test-2" "primary_ap: '$primary_ap'"
 
+	logger -t "hostapd-test-3" "mac80211_vap_cleanup hostapd \"${primary_ap}\""
 	mac80211_vap_cleanup hostapd "${primary_ap}"
+	logger -t "hostapd-test-4" "mac80211_vap_cleanup wpa_supplicant \"$(uci -q -P /var/state get wireless._${phy}.splist)\""
 	mac80211_vap_cleanup wpa_supplicant "$(uci -q -P /var/state get wireless._${phy}.splist)"
 	for wdev in $(list_phy_interfaces "$phy"); do
 		local wdev_phy="$(readlink /sys/class/net/${wdev}/phy80211)"
+		logger -t "hostapd-test-5" "wdev_phy: '$wdev_phy'"
 		wdev_phy="$(basename "$wdev_phy")"
+		logger -t "hostapd-test-6" "wdev_phy: '$wdev_phy' phy: '$phy'"
 		[ -n "$wdev_phy" -a "$wdev_phy" != "$phy" ] && continue
+		logger -t "hostapd-test-7" "ip link set dev \"$wdev\" down 2>/dev/null"
 		ip link set dev "$wdev" down 2>/dev/null
+		logger -t "hostapd-test-8" "iw dev \"$wdev\" del"
 		iw dev "$wdev" del
 	done
 }