Hi,
We are having an issue where DHCP is always timeout at every roaming using the TI latest driver.
When doing any reassociation (wpa_cli reassociate or wpa_cli roam or bgscan roams), networkd sends a DHCP Request on the wlan0 interface to renew its previously allocated IP address. This is the first packet after the 4-way handshake. However, the TI radio never transmit this packet after the 4-way handshake. Neither the wireless packet capture or the AP logs have recorded any trace of a first DHCP Request. Then all the other packet sent to wlan0 are succesfully sent to the wireless.
After 3 seconds, networkd is timing-out DHCP, restarts DHCP and makes a delayed full DHCP process (Discover, Offer, Request, ACK) successfully but delayed.
CPU: armv7l
Kernel: 5.4.47
wlcore: PHY firmware version: Rev 8.2.0.0.246
wlcore: firmware booted (Rev 8.9.0.0.90)
The tcpdump of wlan0 shows that the first DHCP Request is sent through the wlan0 interface:
see tcpdump-wlan0.png (attached logs)
The wireless packet capture or the AP logs never shows the first DHCP Request, but only the following full DHCP process from DHCP Discovery.
see wireless-packet-capture.png (attached logs)
Here are the system-networkd logs:
Jan 19 03:07:29.708137 imx6sleg-mcg systemd-networkd[370]: wlan0: Flags change: -LOWER_UP Jan 19 03:07:29.887551 imx6sleg-mcg systemd-networkd[370]: wlan0: Flags change: -RUNNING Jan 19 03:07:29.887822 imx6sleg-mcg systemd-networkd[370]: wlan0: Lost carrier Jan 19 03:07:31.456054 imx6sleg-mcg systemd-networkd[370]: wlan0: Flags change: +LOWER_UP Jan 19 03:07:32.256157 imx6sleg-mcg systemd-networkd[370]: wlan0: Flags change: +RUNNING Jan 19 03:07:32.256438 imx6sleg-mcg systemd-networkd[370]: wlan0: Gained carrier Jan 19 03:07:32.307444 imx6sleg-mcg systemd-networkd[370]: wlan0: Connected WiFi access point: TestSSID (a4:b2:39:84:b6:6e) Jan 19 03:07:32.307561 imx6sleg-mcg systemd-networkd[370]: wlan0: Acquiring DHCPv4 lease Jan 19 03:07:32.307862 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0x8de2fb6): STARTED on ifindex 10 Jan 19 03:07:32.307896 imx6sleg-mcg systemd-networkd[370]: wlan0: State changed: configured -> configuring Jan 19 03:07:32.322649 imx6sleg-mcg systemd-networkd[370]: wlan0: link_check_ready(): static addresses are not configured. Jan 19 03:07:32.322787 imx6sleg-mcg systemd-networkd[370]: wlan0: link_check_ready(): dhcp4:yes dhcp6_addresses:no dhcp_routes:no dhcp_pd_addresses:no dhcp_pd_routes:no ndisc_addresses:no ndisc_routes:no Jan 19 03:07:32.322816 imx6sleg-mcg systemd-networkd[370]: wlan0: State changed: configuring -> configured Jan 19 03:07:32.334156 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0x8de2fb6): REQUEST (init-reboot) Jan 19 03:07:35.106940 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0xcd9d2529): REBOOTED Jan 19 03:07:35.127263 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0xcd9d2529): DISCOVER Jan 19 03:07:35.253437 imx6sleg-mcg systemd-networkd[370]: rtnl: received non-static neighbor, ignoring. Jan 19 03:07:36.182907 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0xcd9d2529): OFFER Jan 19 03:07:36.194880 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0xcd9d2529): REQUEST (requesting) Jan 19 03:07:36.290903 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0xcd9d2529): ACK Jan 19 03:07:36.306735 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0xcd9d2529): lease expires in 23h 59min 57s Jan 19 03:07:36.306804 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0xcd9d2529): T2 expires in 20h 59min 59s Jan 19 03:07:36.306841 imx6sleg-mcg systemd-networkd[370]: DHCP CLIENT (0xcd9d2529): T1 expires in 12h Jan 19 03:07:36.306978 imx6sleg-mcg systemd-networkd[370]: wlan0: State changed: configured -> configuring Jan 19 03:07:36.307254 imx6sleg-mcg systemd-networkd[370]: wlan0: DHCPv4 address 192.168.203.54/24 via 192.168.203.2 Jan 19 03:07:36.307303 imx6sleg-mcg systemd-networkd[370]: wlan0: Updating address: 192.168.203.54 Jan 19 03:07:36.461704 imx6sleg-mcg systemd-networkd[370]: wlan0: Remembering updated address: 192.168.203.54/24 (valid for 1d)
The wpa_supplicant logs shows the reassociation with the Driver events (noticing that there is one more Regulatory change after the Connect event):
Jan 19 03:07:28.841071 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0 Jan 19 03:07:28.951953 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0 Jan 19 03:07:29.909930 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 39 (NL80211_CMD_DEAUTHENTICATE) received for wlan0 Jan 19 03:07:30.325769 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 48 (NL80211_CMD_DISCONNECT) received for wlan0 Jan 19 03:07:30.325769 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 19 (NL80211_CMD_NEW_STATION) received for wlan0 Jan 19 03:07:30.325769 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 37 (NL80211_CMD_AUTHENTICATE) received for wlan0 Jan 19 03:07:30.596609 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 36 (NL80211_CMD_REG_CHANGE) received for wlan0 Jan 19 03:07:30.625301 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 36 (NL80211_CMD_REG_CHANGE) received for wlan0 Jan 19 03:07:30.625301 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0 Jan 19 03:07:30.625301 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 19 (NL80211_CMD_NEW_STATION) received for wlan0 Jan 19 03:07:31.470005 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 38 (NL80211_CMD_ASSOCIATE) received for wlan0 Jan 19 03:07:31.504747 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0 Jan 19 03:07:31.504747 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 36 (NL80211_CMD_REG_CHANGE) received for wlan0 Jan 19 03:07:32.750574 imx6sleg-mcg wpa_supplicant[239]: nl80211: Drv Event 64 (NL80211_CMD_NOTIFY_CQM) received for wlan0
And here are the driver logs enabled with 0xFFFFE debug level:
Jan 19 03:07:28.966614 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=4->3 Jan 19 03:07:29.367267 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=3->2 Jan 19 03:07:29.367555 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=2->1 Jan 19 03:07:29.388965 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=1->0 Jan 19 03:07:29.856852 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=0->1 Jan 19 03:07:29.983541 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=1->2 Jan 19 03:07:30.156828 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=2->1 Jan 19 03:07:30.324871 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=1->0 Jan 19 03:07:30.569701 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=0->1 Jan 19 03:07:30.577437 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=1->2 Jan 19 03:07:30.749322 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=2->3 Jan 19 03:07:32.480423 imx6sleg-mcg kernel: wlcore: mac80211 sta 0 state=3->4 Jan 19 03:07:32.480713 imx6sleg-mcg kernel: wlcore: cmd set peer state (hlid=1) Jan 19 03:07:32.500466 imx6sleg-mcg kernel: wlcore: Association completed. Jan 19 03:07:32.516747 imx6sleg-mcg kernel: wlcore: cmd croc (0) Jan 19 03:07:32.526584 imx6sleg-mcg kernel: wlcore: rx skb 0x8594e952: 375 B beacon seq 3416 hlid 1 Jan 19 03:07:32.548544 imx6sleg-mcg kernel: wlcore: mac80211 get_rssi Jan 19 03:07:32.548876 imx6sleg-mcg kernel: wlcore: acx roaming statistics Jan 19 03:07:32.549062 imx6sleg-mcg kernel: wlcore: cmd interrogate Jan 19 03:07:32.638272 imx6sleg-mcg kernel: wlcore: queue skb hlid 1 q 0 len 86 Jan 19 03:07:32.638589 imx6sleg-mcg kernel: wlcore: rx skb 0x417c4e09: 375 B beacon seq 3418 hlid 1 Jan 19 03:07:32.638780 imx6sleg-mcg kernel: wlcore: tx_allocate: size: 102, blocks: 2, id: 0 Jan 19 03:07:32.638954 imx6sleg-mcg kernel: wlcore: tx_fill_hdr: hlid: 1 len: 102 life: 2000 mem: 2 Jan 19 03:07:32.652248 imx6sleg-mcg kernel: wlcore: last released desc = 19, current idx = 20 Jan 19 03:07:32.652472 imx6sleg-mcg kernel: wlcore: tx status id 0 skb 0x3dfc3c3a success 1 Jan 19 03:07:32.678812 imx6sleg-mcg kernel: wlcore: rx skb 0x5af57da9: 78 B seq 3423 hlid 1 Jan 19 03:07:32.749230 imx6sleg-mcg kernel: wlcore: rx skb 0x1acd26ba: 375 B beacon seq 3425 hlid 1 Jan 19 03:07:32.749524 imx6sleg-mcg kernel: wlcore: EVENT on mbox 0 Jan 19 03:07:32.749706 imx6sleg-mcg kernel: wlcore: MBOX vector: 0x1 Jan 19 03:07:32.749881 imx6sleg-mcg kernel: wlcore: RSSI trigger metric: -67 Jan 19 03:07:32.750083 imx6sleg-mcg kernel: wlcore: mac80211 get_rssi Jan 19 03:07:32.750256 imx6sleg-mcg kernel: wlcore: acx roaming statistics Jan 19 03:07:32.750414 imx6sleg-mcg kernel: wlcore: cmd interrogate Jan 19 03:07:32.836729 imx6sleg-mcg kernel: wlcore: rx skb 0xc6ba9c37: 375 B beacon seq 3427 hlid 1 Jan 19 03:07:32.897319 imx6sleg-mcg kernel: wlcore: queue skb hlid 1 q 0 len 138 Jan 19 03:07:32.897625 imx6sleg-mcg kernel: wlcore: tx_allocate: size: 154, blocks: 2, id: 0 Jan 19 03:07:32.909907 imx6sleg-mcg kernel: wlcore: tx_fill_hdr: hlid: 1 len: 154 life: 2000 mem: 2 Jan 19 03:07:32.948001 imx6sleg-mcg kernel: wlcore: rx skb 0x0c749475: 375 B beacon seq 3429 hlid 1 Jan 19 03:07:32.948294 imx6sleg-mcg kernel: wlcore: last released desc = 20, current idx = 21 Jan 19 03:07:32.948479 imx6sleg-mcg kernel: wlcore: tx status id 0 skb 0xdd944f29 success 1 Jan 19 03:07:33.046778 imx6sleg-mcg kernel: wlcore: rx skb 0xa38c1e9e: 375 B beacon seq 3433 hlid 1 Jan 19 03:07:33.146686 imx6sleg-mcg kernel: wlcore: rx skb 0xacd6d363: 375 B beacon seq 3435 hlid 1 Jan 19 03:07:33.279414 imx6sleg-mcg kernel: wlcore: mac80211 get_rssi Jan 19 03:07:33.279725 imx6sleg-mcg kernel: wlcore: acx roaming statistics Jan 19 03:07:33.310152 imx6sleg-mcg kernel: wlcore: cmd interrogate Jan 19 03:07:33.347672 imx6sleg-mcg kernel: wlcore: mac80211 get_rssi Jan 19 03:07:33.347953 imx6sleg-mcg kernel: wlcore: rx skb 0x1a88fce8: 375 B beacon seq 3439 hlid 1 Jan 19 03:07:33.348145 imx6sleg-mcg kernel: wlcore: acx roaming statistics Jan 19 03:07:33.376702 imx6sleg-mcg kernel: wlcore: cmd interrogate
Logs are attachedjournal.txtsystemd-networkd.txt3531.wpa_supplicant.txt
Wireless-capture-Decrypted.pcapng.txtnetlog.pcap.txt
