Can't connect 5GHz WiFi when using 1.13.1

[pojiro]

Environment

• Elixir version (elixir -v): Elixir 1.11.2 (compiled with Erlang/OTP 23)
• Nerves environment: (mix nerves.env --info)

|nerves_bootstrap| Environment Package List

  Pkg:         nerves_toolchain_ctng
  Vsn:         1.7.2
  Type:        toolchain_platform
  BuildRunner: {nil, []}

  Pkg:         nerves_system_br
  Vsn:         1.13.4
  Type:        system_platform
  BuildRunner: {nil, []}

  Pkg:         nerves_toolchain_aarch64_unknown_linux_gnu
  Vsn:         1.3.2
  Type:        toolchain
  BuildRunner: {Nerves.Artifact.BuildRunners.Local, []}

  Pkg:         nerves_system_rpi4
  Vsn:         1.13.1
  Type:        system
  BuildRunner: {Nerves.Artifact.BuildRunners.Local, []}

|nerves_bootstrap| Loadpaths Start


Nerves environment
  MIX_TARGET:   rpi4
  MIX_ENV:      dev

|nerves_bootstrap| Environment Variable List
  target:     rpi4
  toolchain:  /home/pojiro/.nerves/artifacts/nerves_toolchain_aarch64_unknown_linux_gnu-linux_x86_64-1.3.2
  system:     /home/pojiro/.nerves/artifacts/nerves_system_rpi4-portable-1.13.1

• Additional information about your host, target hardware or environment that
  may help

Current behavior

Connecting 5GHz WiFi is failed, cause of below error, when we use nerves_system_rpi4 1.13.1.
This doesn't happen on nerves_system_rpi4 1.13.0.

I asked my friends to reproduce this, then it also happened with friend's WiFI 5GHz AP.

13:55:41.858 [info]  WPASupplicant ignoring {:event, "WPS-AP-AVAILABLE"}

13:55:41.858 [info]  WPASupplicant ignoring {:event, "CTRL-EVENT-NETWORK-NOT-FOUND"}

13:56:11.393 [error] ieee80211 phy0: brcmf_fw_crashed: Firmware has halted or crashed

13:56:13.929 [error] brcmfmac: brcmf_sdio_bus_rxctl: resumed on timeout

13:56:16.291 [error] GenServer {VintageNet.Interface.Registry, {VintageNetWiFi.WPASupplicant, "wlan0"}} terminating
** (stop) exited in: GenServer.call(#PID<0.1525.0>, {:control_request, "BSS 12:66:82:09:bf:3a"}, 5000)
    ** (EXIT) time out
    (elixir 1.11.2) lib/gen_server.ex:1027: GenServer.call/3
    (vintage_net_wifi 0.9.1) lib/vintage_net_wifi/wpa_supplicant.ex:486: VintageNetWiFi.WPASupplicant.get_access_point_info/2
    (vintage_net_wifi 0.9.1) lib/vintage_net_wifi/wpa_supplicant.ex:212: VintageNetWiFi.WPASupplicant.handle_notification/2
    (vintage_net_wifi 0.9.1) lib/vintage_net_wifi/wpa_supplicant.ex:197: VintageNetWiFi.WPASupplicant.handle_info/2
    (stdlib 3.13.2) gen_server.erl:680: :gen_server.try_dispatch/4
    (stdlib 3.13.2) gen_server.erl:756: :gen_server.handle_msg/6
    (stdlib 3.13.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Last message: {VintageNetWiFi.WPASupplicantLL, 3, "CTRL-EVENT-BSS-ADDED 9 12:66:82:09:bf:3a"}
State: %{access_points: %{"10:66:82:09:bf:3a" => %VintageNetWiFi.AccessPoint{band: :wifi_2_4_ghz, bssid: "10:66:82:09:bf:3a", channel: 1, flags: [:wpa2_psk_ccmp, :wps, :ess], frequency: 2412, signal_dbm: -81, signal_percent: 28, ssid: "ctc-g-00d190"}, "10:66:82:09:bf:3b" => %VintageNetWiFi.AccessPoint{band: :wifi_5_ghz, bssid: "10:66:82:09:bf:3b", channel: 36, flags: [:wpa2_psk_ccmp, :wps, :ess], frequency: 5180, signal_dbm: -85, signal_percent: 34, ssid: "ctc-a-00d190"}, "30:f7:72:b1:97:72" => %VintageNetWiFi.AccessPoint{band: :wifi_2_4_ghz, bssid: "30:f7:72:b1:97:72", channel: 6, flags: [:wpa2_psk_ccmp, :wps, :ess], frequency: 2437, signal_dbm: -74, signal_percent: 42, ssid: "30F772B19770-2G"}, "34:3d:c4:4f:72:28" => %VintageNetWiFi.AccessPoint{band: :wifi_2_4_ghz, bssid: "34:3d:c4:4f:72:28", channel: 11, flags: [:wpa2_psk_ccmp, :wps, :ess], frequency: 2462, signal_dbm: -82, signal_percent: 26, ssid: "Buffalo-G-7228"}, "60:84:bd:4f:1b:21" => %VintageNetWiFi.AccessPoint{band: :wifi_2_4_ghz, bssid: "60:84:bd:4f:1b:21", channel: 2, flags: [:wpa2_psk_ccmp, :wps, :ess], frequency: 2417, signal_dbm: -80, signal_percent: 30, ssid: "Buffalo-G-1B20"}, "60:84:bd:4f:1b:24" => %VintageNetWiFi.AccessPoint{band: :wifi_5_ghz, bssid: "60:84:bd:4f:1b:24", channel: 56, flags: [:wpa2_psk_ccmp, :wps, :ess], frequency: 5280, signal_dbm: -87, signal_percent: 29, ssid: "Buffalo-A-1B20"}, "c0:25:a2:b1:4c:8e" => %VintageNetWiFi.AccessPoint{band: :wifi_2_4_ghz, bssid: "c0:25:a2:b1:4c:8e", channel: 7, flags: [:wpa2_psk_ccmp, :wps, :ess], frequency: 2442, signal_dbm: -50, signal_percent: 79, ssid: "ctc-g-a6f52c"}, "c2:25:a2:82:dc:4e" => %VintageNetWiFi.AccessPoint{band: :wifi_2_4_ghz, bssid: "c2:25:a2:82:dc:4e", channel: 5, flags: [:ess], frequency: 2432, signal_dbm: -84, signal_percent: 22, ssid: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>}, "c2:25:a2:b1:4c:8e" => %VintageNetWiFi.AccessPoint{band: :wifi_2_4_ghz, bssid: "c2:25:a2:b1:4c:8e", channel: 7, flags: [:ess], frequency: 2442, signal_dbm: -47, signal_percent: 82, ssid: <<0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0>>}}, ap_mode: false, clients: [], control_dir: "/tmp/vintage_net/wpa_supplicant", current_ap: nil, eap_status: %VintageNet.Interface.EAPStatus{method: nil, remote_certificate_verified?: false, status: nil, timestamp: nil}, ifname: "wlan0", keep_alive_interval: 60000, ll: #PID<0.1525.0>, peers: [], verbose: false, wpa_supplicant: "wpa_supplicant", wpa_supplicant_conf_path: "/tmp/vintage_net/wpa_supplicant.conf.wlan0"}

13:56:16.309 [error] ieee80211 phy0: brcmf_pno_clean: failed code -512

Expected behavior

This phenomenon may be due to rpi4 drivers rather than "Nerves", but user should know.
Please let me know if there is any other information you need. Thanks.

[fhunleth]

Thanks for reporting this! I am preparing an update to the Raspberry Pi 4 that fixes GPIO pullups and adds GPU support via DRM, so this is timely. Perhaps it is as easy as getting the latest firmware from the Raspberry Pi OS or perhaps the linux-firmware project has a fix.

[fhunleth]

I'm trying to reproduce, but 5 GHz seems to work for me. Here's my connection to my test AP:

iex(18)> VintageNet.get_by_prefix(["interface", "wlan0", "wifi", "current_ap"])
[
  {["interface", "wlan0", "wifi", "current_ap"],
   %VintageNetWiFi.AccessPoint{
     band: :wifi_5_ghz,
     bssid: "8a:8a:20:88:7a:50",
     channel: 116,
     flags: [:ess],
     frequency: 5580,
     signal_dbm: -73,
     signal_percent: 64,
     ssid: "FlakyWiFi"
   }}
]

This access point is currently set to WPA2 PSK. Do you see anything that might be different between my setup and yours?

[pojiro]

Below is my config, . I'm in Japan, the regulatory_domain is different from yours.
With this rpi4 can't grab the AP. So, VintageNet.get_by_prefix(["interface", "wlan0", "wifi", "current_ap"]) return [].

config :vintage_net,
  regulatory_domain: "JP",
  config: [
    {"usb0", %{type: VintageNetDirect}},
    {"eth0",
     %{
       type: VintageNetEthernet,
       ipv4: %{method: :dhcp}
     }},
    {"wlan0",
     %{
       type: VintageNetWiFi,
       vintage_net_wifi: %{
         networks: [
           %{
             key_mgmt: :wpa_psk,
             ssid: "ctc-a-a6f52c",
             psk: "secret"
           }
         ]
       },
       ipv4: %{method: :dhcp}
     }}
  ]

I change regulatory_domain to US, then rpi4 grab the AP and return below.

iex(1)> VintageNet.get_by_prefix(["interface", "wlan0", "wifi", "current_ap"])
{["interface", "wlan0", "wifi", "current_ap"],
   %VintageNetWiFi.AccessPoint{
     band: :wifi_5_ghz,
     bssid: "c0:25:a2:b1:4c:8f",
     channel: 116,
     flags: [:wpa2_psk_ccmp, :wps, :ess],
     frequency: 5580,
     signal_dbm: -61,
     signal_percent: 85,
     ssid: "ctc-a-a6f52c"
   }}

Still, this connection is unstable, so rpi4 connect and disconnect repeatedly. Below is the log.

01:37:49.116 [info]  RouteManager: set_connection_status wlan0 -> :internet
        
01:37:52.668 [debug] wpa_supplicant: wlan0: CTRL-EVENT-DISCONNECTED bssid=c0:25:a2:b1:4c:8f reason=0 locally_generated=1
        
01:37:52.670 [warn]  AP disconnected: c0:25:a2:b1:4c:8f
        
01:37:52.696 [info]  RouteManager: set_connection_status wlan0 -> :disconnected
        
01:37:52.697 [debug] wpa_supplicant: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
        
01:37:52.698 [info]  WPASupplicant ignoring {:event, "CTRL-EVENT-REGDOM-CHANGE", %{"init" => "CORE", "type" => "WORLD"}}
        
01:37:52.701 [debug] wpa_supplicant: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US
        
01:37:52.702 [info]  WPASupplicant ignoring {:event, "CTRL-EVENT-REGDOM-CHANGE", %{"alpha2" => "US", "init" => "USER", "type" => "COUNTRY"}}
        
01:37:55.128 [debug] wpa_supplicant: wlan0: Trying to associate with SSID 'ctc-a-a6f52c'
        
01:37:55.149 [info]  WPASupplicant ignoring {:event, "WPS-AP-AVAILABLE"}
        
01:37:55.150 [info]  wpa_supplicant(wlan0): Trying to associate with SSID 'ctc-a-a6f52c'
        
01:37:57.587 [info]  RouteManager: set_connection_status wlan0 -> :lan
        
01:37:57.610 [debug] wpa_supplicant: wlan0: Associated with c0:25:a2:b1:4c:8f
        
01:37:57.612 [info]  wpa_supplicant(wlan0): Associated with c0:25:a2:b1:4c:8f
        
01:37:57.612 [debug] wpa_supplicant: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
        
01:37:57.612 [debug] wpa_supplicant: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=JP
        
01:37:57.613 [info]  WPASupplicant ignoring {:event, "CTRL-EVENT-SUBNET-STATUS-UPDATE", %{"status" => "0"}}
        
01:37:57.614 [info]  WPASupplicant ignoring {:event, "CTRL-EVENT-REGDOM-CHANGE", %{"alpha2" => "JP", "init" => "COUNTRY_IE", "type" => "COUNTRY"}}
        
01:37:57.618 [debug] wpa_supplicant: wlan0: WPA: Key negotiation completed with c0:25:a2:b1:4c:8f [PTK=CCMP GTK=CCMP]
        
01:37:57.618 [debug] wpa_supplicant: wlan0: CTRL-EVENT-CONNECTED - Connection to c0:25:a2:b1:4c:8f completed [id=0 id_str=]
        
01:37:57.619 [info]  wpa_supplicant(wlan0): WPA: Key negotiation completed with c0:25:a2:b1:4c:8f [PTK=CCMP GTK=CCMP]
        
01:37:57.620 [info]  Connected to AP: c0:25:a2:b1:4c:8f
        
01:38:01.176 [info]  RouteManager: set_connection_status wlan0 -> :internet
        
01:38:06.698 [info]  RouteManager: set_connection_status wlan0 -> :disconnected

[fhunleth]

I think that the firmware is out of date. Due to a missing firmware file and looking out-of-date, I switched wifi firmware repositories in this release to the linux-firmwareone. I assumed that the linux-firmware files would be more current since they had the missing file, but they are not. It looks like the latest firmware files from the Raspberry Pi Foundation are maintained at https://github.com/RPi-Distro/firmware-nonfree/tree/master/brcm. They have recent timestamps so I'm hopeful. It's getting late here, but my next try would be to try these by putting them in /lib/firmware/brcm and seeing if that works.

[fhunleth]

Just saw this commit that's timestamped yesterday:

* New clm_blob for BCM43456
    - An updated clm_blob to open up the 80MHz channels.
  * Use BCM43456 clm_blob on CYW43455
    - The previous CYW43455 clm_blob provides limited access to the higher
      5GHz channels (100+) - the BCM43456 (surprisingly) seems to work and
      doesn't have this problem.

This would affect the RPi4 WiFi and sounds interesting.

[fhunleth]

@pojiro Could you try this firmware? It has the new WiFi firmware and I hope that it works for you!

[pojiro]

@fhunleth I tried the fw and I confirm it works with 5GHz WiFi AP which is I mentioned earlier.
I see RingLogger, it seems no errors, no disconnects so far, seems nice :) .

[fhunleth]

Great! Thanks for verifying that it works. Once I verify that the RPi Zero still works, I'll merge and start the process of getting new Nerves systems out. Shouldn't be much longer!

[takasehideki]

Hi @fhunleth
I am a @pojiro's friend who reproduced this issue :)
As just FYI, I've confirmed new firmware also worked well and fixed this issue in my environment. I'm really thankful to you!