brcmfmac: error messages while entering suspend

brcmfmac: error messages while entering suspend

[Stefan Wahren]

Hi,
I'm currently working on s2idle support for Raspberry Pi 3B+ (BCM43455
SDIO). During the tests with I noticed harmless, but annoying error
messages from brcmfmac like this:

[  383.186640] PM: suspend entry (s2idle)
[  383.190107] Filesystems sync: 0.003 seconds
[  383.247470] Freezing user space processes
[  383.250291] Freezing user space processes completed (elapsed 0.002
seconds)
[  383.250379] OOM killer disabled.
[  383.250385] Freezing remaining freezable tasks
[  383.251677] Freezing remaining freezable tasks completed (elapsed
0.001 seconds)
[  384.292071] ieee80211 phy0: brcmf_fil_cmd_data: bus is down. we have
nothing to do.
[  384.292079] ieee80211 phy0: brcmf_cfg80211_get_tx_power: error (-5)

These errors are not new and I assume they have always been there. I'm
not an expert here, so I want to know is the problem here that the SDIO
interface is shutdown before brcmfmac is suspended or lies the issue
within brcmfmac suspend itself?

Here is a calltrace for the error above:

[  384.291308]  brcmf_fil_cmd_data+0xe0/0x114 [brcmfmac] (P)
[  384.291347]  brcmf_fil_iovar_data_get+0xcc/0x134 [brcmfmac] (L)
[  384.291384]  brcmf_fil_iovar_data_get+0xcc/0x134 [brcmfmac]
[  384.291420]  brcmf_cfg80211_get_tx_power+0x58/0xd4 [brcmfmac]
[  384.291458]  nl80211_send_iface+0x1e8/0x584 [cfg80211]
[  384.291549]  nl80211_notify_iface+0x58/0xd4 [cfg80211]
[  384.291615]  _cfg80211_unregister_wdev+0x40/0x27c [cfg80211]
[  384.291682]  cfg80211_unregister_wdev+0x14/0x20 [cfg80211]
[  384.291748]  brcmf_p2p_ifp_removed+0x6c/0x98 [brcmfmac]
[  384.291785]  brcmf_remove_interface+0x170/0x1ec [brcmfmac]
[  384.291822]  brcmf_detach+0x60/0xfc [brcmfmac]
[  384.291859]  brcmf_sdio_remove+0x4c/0x188 [brcmfmac]
[  384.291896]  brcmf_sdiod_remove+0x24/0xa4 [brcmfmac]
[  384.291933]  brcmf_ops_sdio_suspend+0x100/0x1c8 [brcmfmac]
[  384.291971]  pm_generic_suspend+0x2c/0x44
[  384.291982]  dpm_run_callback.constprop.0+0x74/0x134
[  384.291993]  device_suspend+0x110/0x3d0
[  384.292002]  async_suspend+0x24/0x3c
[  384.292012]  async_run_entry_fn+0x34/0xe0
[  384.292022]  process_one_work+0x150/0x294
[  384.292032]  worker_thread+0x2dc/0x3dc
[  384.292041]  kthread+0x118/0x11c
[  384.292049]  ret_from_fork+0x10/0x20

Best regards

Re: brcmfmac: error messages while entering suspend

[Arend van Spriel]

On November 3, 2024 12:01:55 PM Stefan Wahren <wahrenst@gmx.net> wrote:

> Hi,
> I'm currently working on s2idle support for Raspberry Pi 3B+ (BCM43455
> SDIO). During the tests with I noticed harmless, but annoying error
> messages from brcmfmac like this:
>
> [  383.186640] PM: suspend entry (s2idle)
> [  383.190107] Filesystems sync: 0.003 seconds
> [  383.247470] Freezing user space processes
> [  383.250291] Freezing user space processes completed (elapsed 0.002
> seconds)
> [  383.250379] OOM killer disabled.
> [  383.250385] Freezing remaining freezable tasks
> [  383.251677] Freezing remaining freezable tasks completed (elapsed
> 0.001 seconds)
> [  384.292071] ieee80211 phy0: brcmf_fil_cmd_data: bus is down. we have
> nothing to do.
> [  384.292079] ieee80211 phy0: brcmf_cfg80211_get_tx_power: error (-5)
>
> These errors are not new and I assume they have always been there. I'm
> not an expert here, so I want to know is the problem here that the SDIO
> interface is shutdown before brcmfmac is suspended or lies the issue
> within brcmfmac suspend itself?

Hi Stefan,

Upon suspend we execute the remove path and cleaning the interfaces. We 
notify cfg80211 about the removal, which in turn will notify userspace, 
but is tries to obtain the tx power from brcmfmac. However, at this 
stage the communication with the dongle is already gone. These messages 
are also seen in the module unload scenario. It seems a bit redundant to 
query a device that is going to be removed. So it could be fixed by 
chiming down those message or avoid it completely by changing the 
behavior in cfg80211.

Regards,
Arend

> Here is a calltrace for the error above:
>
> [  384.291308]  brcmf_fil_cmd_data+0xe0/0x114 [brcmfmac] (P)
> [  384.291347]  brcmf_fil_iovar_data_get+0xcc/0x134 [brcmfmac] (L)
> [  384.291384]  brcmf_fil_iovar_data_get+0xcc/0x134 [brcmfmac]
> [  384.291420]  brcmf_cfg80211_get_tx_power+0x58/0xd4 [brcmfmac]
> [  384.291458]  nl80211_send_iface+0x1e8/0x584 [cfg80211]
> [  384.291549]  nl80211_notify_iface+0x58/0xd4 [cfg80211]
> [  384.291615]  _cfg80211_unregister_wdev+0x40/0x27c [cfg80211]
> [  384.291682]  cfg80211_unregister_wdev+0x14/0x20 [cfg80211]
> [  384.291748]  brcmf_p2p_ifp_removed+0x6c/0x98 [brcmfmac]
> [  384.291785]  brcmf_remove_interface+0x170/0x1ec [brcmfmac]
> [  384.291822]  brcmf_detach+0x60/0xfc [brcmfmac]
> [  384.291859]  brcmf_sdio_remove+0x4c/0x188 [brcmfmac]
> [  384.291896]  brcmf_sdiod_remove+0x24/0xa4 [brcmfmac]
> [  384.291933]  brcmf_ops_sdio_suspend+0x100/0x1c8 [brcmfmac]
> [  384.291971]  pm_generic_suspend+0x2c/0x44
> [  384.291982]  dpm_run_callback.constprop.0+0x74/0x134
> [  384.291993]  device_suspend+0x110/0x3d0
> [  384.292002]  async_suspend+0x24/0x3c
> [  384.292012]  async_run_entry_fn+0x34/0xe0
> [  384.292022]  process_one_work+0x150/0x294
> [  384.292032]  worker_thread+0x2dc/0x3dc
> [  384.292041]  kthread+0x118/0x11c
> [  384.292049]  ret_from_fork+0x10/0x20
>
> Best regards

Re: brcmfmac: error messages while entering suspend

[Stefan Wahren]

Hi Arend,

[add Johannes]

Am 04.11.24 um 11:06 schrieb Arend van Spriel:
> On November 3, 2024 12:01:55 PM Stefan Wahren <wahrenst@gmx.net> wrote:
>
>> Hi,
>> I'm currently working on s2idle support for Raspberry Pi 3B+ (BCM43455
>> SDIO). During the tests with I noticed harmless, but annoying error
>> messages from brcmfmac like this:
>>
>> [  383.186640] PM: suspend entry (s2idle)
>> [  383.190107] Filesystems sync: 0.003 seconds
>> [  383.247470] Freezing user space processes
>> [  383.250291] Freezing user space processes completed (elapsed 0.002
>> seconds)
>> [  383.250379] OOM killer disabled.
>> [  383.250385] Freezing remaining freezable tasks
>> [  383.251677] Freezing remaining freezable tasks completed (elapsed
>> 0.001 seconds)
>> [  384.292071] ieee80211 phy0: brcmf_fil_cmd_data: bus is down. we have
>> nothing to do.
>> [  384.292079] ieee80211 phy0: brcmf_cfg80211_get_tx_power: error (-5)
>>
>> These errors are not new and I assume they have always been there. I'm
>> not an expert here, so I want to know is the problem here that the SDIO
>> interface is shutdown before brcmfmac is suspended or lies the issue
>> within brcmfmac suspend itself?
>
> Hi Stefan,
>
> Upon suspend we execute the remove path and cleaning the interfaces.
> We notify cfg80211 about the removal, which in turn will notify
> userspace, but is tries to obtain the tx power from brcmfmac. However,
> at this stage the communication with the dongle is already gone. These
> messages are also seen in the module unload scenario. It seems a bit
> redundant to query a device that is going to be removed. So it could
> be fixed by chiming down those message or avoid it completely by
> changing the behavior in cfg80211.
chiming down all the affected messages (i reported only one example
here) sounds strange to me. Maybe Johannes has also a opinion about this.

Regards
>
> Regards,
> Arend
>
>> Here is a calltrace for the error above:
>>
>> [  384.291308]  brcmf_fil_cmd_data+0xe0/0x114 [brcmfmac] (P)
>> [  384.291347]  brcmf_fil_iovar_data_get+0xcc/0x134 [brcmfmac] (L)
>> [  384.291384]  brcmf_fil_iovar_data_get+0xcc/0x134 [brcmfmac]
>> [  384.291420]  brcmf_cfg80211_get_tx_power+0x58/0xd4 [brcmfmac]
>> [  384.291458]  nl80211_send_iface+0x1e8/0x584 [cfg80211]
>> [  384.291549]  nl80211_notify_iface+0x58/0xd4 [cfg80211]
>> [  384.291615]  _cfg80211_unregister_wdev+0x40/0x27c [cfg80211]
>> [  384.291682]  cfg80211_unregister_wdev+0x14/0x20 [cfg80211]
>> [  384.291748]  brcmf_p2p_ifp_removed+0x6c/0x98 [brcmfmac]
>> [  384.291785]  brcmf_remove_interface+0x170/0x1ec [brcmfmac]
>> [  384.291822]  brcmf_detach+0x60/0xfc [brcmfmac]
>> [  384.291859]  brcmf_sdio_remove+0x4c/0x188 [brcmfmac]
>> [  384.291896]  brcmf_sdiod_remove+0x24/0xa4 [brcmfmac]
>> [  384.291933]  brcmf_ops_sdio_suspend+0x100/0x1c8 [brcmfmac]
>> [  384.291971]  pm_generic_suspend+0x2c/0x44
>> [  384.291982]  dpm_run_callback.constprop.0+0x74/0x134
>> [  384.291993]  device_suspend+0x110/0x3d0
>> [  384.292002]  async_suspend+0x24/0x3c
>> [  384.292012]  async_run_entry_fn+0x34/0xe0
>> [  384.292022]  process_one_work+0x150/0x294
>> [  384.292032]  worker_thread+0x2dc/0x3dc
>> [  384.292041]  kthread+0x118/0x11c
>> [  384.292049]  ret_from_fork+0x10/0x20
>>
>> Best regards
>
>

Re: brcmfmac: error messages while entering suspend

[Johannes Berg]

On Mon, 2024-11-04 at 12:59 +0100, Stefan Wahren wrote:
> 
> > > [  384.292071] ieee80211 phy0: brcmf_fil_cmd_data: bus is down. we have
> > > nothing to do.
> > > [  384.292079] ieee80211 phy0: brcmf_cfg80211_get_tx_power: error (-5)
> > > 
> > > These errors are not new and I assume they have always been there. I'm
> > > not an expert here, so I want to know is the problem here that the SDIO
> > > interface is shutdown before brcmfmac is suspended or lies the issue
> > > within brcmfmac suspend itself?

> > Upon suspend we execute the remove path and cleaning the interfaces.
> > We notify cfg80211 about the removal, which in turn will notify
> > userspace, but is tries to obtain the tx power from brcmfmac.

I guess "it tries to obtain" is some sort of event path that wants to
include the TX power in an event. That doesn't seem to make all that
much sense on removal events though, so perhaps we could remove the
get_channel and get_tx_power calls for NL80211_CMD_DEL_INTERFACE.


> >  However,
> > at this stage the communication with the dongle is already gone. These
> > messages are also seen in the module unload scenario. It seems a bit
> > redundant to query a device that is going to be removed. So it could
> > be fixed by chiming down those message or avoid it completely by
> > changing the behavior in cfg80211.

> chiming down all the affected messages (i reported only one example
> here) sounds strange to me. Maybe Johannes has also a opinion about this.

Dunno about the messages, I mean it's still possible to get those
messages when e.g. userspace manages to query just while it died, so
perhaps you wouldn't want to print it for all cases, but OTOH that's not
going to happen all the time.

But I don't have much opinion on driver messages :)

johannes

Re: brcmfmac: error messages while entering suspend

[Arend Van Spriel]

On November 4, 2024 1:18:44 PM Johannes Berg <johannes@sipsolutions.net> wrote:

> On Mon, 2024-11-04 at 12:59 +0100, Stefan Wahren wrote:
>>
>>>> [  384.292071] ieee80211 phy0: brcmf_fil_cmd_data: bus is down. we have
>>>> nothing to do.
>>>> [  384.292079] ieee80211 phy0: brcmf_cfg80211_get_tx_power: error (-5)
>>>>
>>>> These errors are not new and I assume they have always been there. I'm
>>>> not an expert here, so I want to know is the problem here that the SDIO
>>>> interface is shutdown before brcmfmac is suspended or lies the issue
>>>> within brcmfmac suspend itself?
>
>>> Upon suspend we execute the remove path and cleaning the interfaces.
>>> We notify cfg80211 about the removal, which in turn will notify
>>> userspace, but is tries to obtain the tx power from brcmfmac.
>
> I guess "it tries to obtain" is some sort of event path that wants to
> include the TX power in an event. That doesn't seem to make all that
> much sense on removal events though, so perhaps we could remove the
> get_channel and get_tx_power calls for NL80211_CMD_DEL_INTERFACE.

That's what I was considering.

>
>
>>> However,
>>> at this stage the communication with the dongle is already gone. These
>>> messages are also seen in the module unload scenario. It seems a bit
>>> redundant to query a device that is going to be removed. So it could
>>> be fixed by chiming down those message or avoid it completely by
>>> changing the behavior in cfg80211.
>
>> chiming down all the affected messages (i reported only one example
>> here) sounds strange to me. Maybe Johannes has also a opinion about this.
>
> Dunno about the messages, I mean it's still possible to get those
> messages when e.g. userspace manages to query just while it died, so
> perhaps you wouldn't want to print it for all cases, but OTOH that's not
> going to happen all the time.
>
> But I don't have much opinion on driver messages :)

Sure. The two messages mentioned above are the ones I meant with coming 
down. Not all driver messages. At least the message in brcmf_fil_cmd_data() 
is not very useful. Could just be a debug print iso error print.

Regards,
Arend

Re: brcmfmac: error messages while entering suspend

[Stefan Wahren]

Hi,

Am 04.11.24 um 13:18 schrieb Johannes Berg:
> On Mon, 2024-11-04 at 12:59 +0100, Stefan Wahren wrote:
>>>> [  384.292071] ieee80211 phy0: brcmf_fil_cmd_data: bus is down. we have
>>>> nothing to do.
>>>> [  384.292079] ieee80211 phy0: brcmf_cfg80211_get_tx_power: error (-5)
>>>>
>>>> These errors are not new and I assume they have always been there. I'm
>>>> not an expert here, so I want to know is the problem here that the SDIO
>>>> interface is shutdown before brcmfmac is suspended or lies the issue
>>>> within brcmfmac suspend itself?
>>> Upon suspend we execute the remove path and cleaning the interfaces.
>>> We notify cfg80211 about the removal, which in turn will notify
>>> userspace, but is tries to obtain the tx power from brcmfmac.
> I guess "it tries to obtain" is some sort of event path that wants to
> include the TX power in an event. That doesn't seem to make all that
> much sense on removal events though, so perhaps we could remove the
> get_channel and get_tx_power calls for NL80211_CMD_DEL_INTERFACE.
>
Not sure if I get it right, but the follow patch make the errors go away:

diff --git a/net/wireless/nl80211.c b/net/wireless/nl80211.c
index 1ac8a196f376..52120cce2f7e 100644
--- a/net/wireless/nl80211.c
+++ b/net/wireless/nl80211.c
@@ -4006,23 +4006,25 @@ static int nl80211_send_iface(struct sk_buff
*msg, u32 portid, u32 seq, int flag
          nla_put_u32(msg, NL80211_ATTR_VIF_RADIO_MASK, wdev->radio_mask))
          goto nla_put_failure;

-    if (rdev->ops->get_channel && !wdev->valid_links) {
-        struct cfg80211_chan_def chandef = {};
-        int ret;
+    if (cmd != NL80211_CMD_DEL_INTERFACE) {
+        if (rdev->ops->get_channel && !wdev->valid_links) {
+            struct cfg80211_chan_def chandef = {};
+            int ret;

-        ret = rdev_get_channel(rdev, wdev, 0, &chandef);
-        if (ret == 0 && nl80211_send_chandef(msg, &chandef))
-            goto nla_put_failure;
-    }
+            ret = rdev_get_channel(rdev, wdev, 0, &chandef);
+            if (ret == 0 && nl80211_send_chandef(msg, &chandef))
+                goto nla_put_failure;
+        }

-    if (rdev->ops->get_tx_power) {
-        int dbm, ret;
+        if (rdev->ops->get_tx_power) {
+            int dbm, ret;

-        ret = rdev_get_tx_power(rdev, wdev, &dbm);
-        if (ret == 0 &&
-            nla_put_u32(msg, NL80211_ATTR_WIPHY_TX_POWER_LEVEL,
-                DBM_TO_MBM(dbm)))
-            goto nla_put_failure;
+            ret = rdev_get_tx_power(rdev, wdev, &dbm);
+            if (ret == 0 &&
+                nla_put_u32(msg, NL80211_ATTR_WIPHY_TX_POWER_LEVEL,
+                    DBM_TO_MBM(dbm)))
+                goto nla_put_failure;
+        }
      }

      switch (wdev->iftype) {

But this change doesn't consider get_txq_stats and the further calls
rdev_get_channel for the valid_links.

Do we actually need nl80211_send_iface() for NL80211_CMD_DEL_INTERFACE?

Regards

Re: brcmfmac: error messages while entering suspend

[Arend Van Spriel]

On November 4, 2024 9:06:04 PM Stefan Wahren <wahrenst@gmx.net> wrote:

> Hi,
>
> Am 04.11.24 um 13:18 schrieb Johannes Berg:
>> On Mon, 2024-11-04 at 12:59 +0100, Stefan Wahren wrote:
>>>>> [  384.292071] ieee80211 phy0: brcmf_fil_cmd_data: bus is down. we have
>>>>> nothing to do.
>>>>> [  384.292079] ieee80211 phy0: brcmf_cfg80211_get_tx_power: error (-5)
>>>>>
>>>>> These errors are not new and I assume they have always been there. I'm
>>>>> not an expert here, so I want to know is the problem here that the SDIO
>>>>> interface is shutdown before brcmfmac is suspended or lies the issue
>>>>> within brcmfmac suspend itself?
>>>> Upon suspend we execute the remove path and cleaning the interfaces.
>>>> We notify cfg80211 about the removal, which in turn will notify
>>>> userspace, but is tries to obtain the tx power from brcmfmac.
>> I guess "it tries to obtain" is some sort of event path that wants to
>> include the TX power in an event. That doesn't seem to make all that
>> much sense on removal events though, so perhaps we could remove the
>> get_channel and get_tx_power calls for NL80211_CMD_DEL_INTERFACE.
> Not sure if I get it right, but the follow patch make the errors go away:
>
> diff --git a/net/wireless/nl80211.c b/net/wireless/nl80211.c
> index 1ac8a196f376..52120cce2f7e 100644
> --- a/net/wireless/nl80211.c
> +++ b/net/wireless/nl80211.c
> @@ -4006,23 +4006,25 @@ static int nl80211_send_iface(struct sk_buff
> *msg, u32 portid, u32 seq, int flag
>          nla_put_u32(msg, NL80211_ATTR_VIF_RADIO_MASK, wdev->radio_mask))
>          goto nla_put_failure;
>
> -    if (rdev->ops->get_channel && !wdev->valid_links) {
> -        struct cfg80211_chan_def chandef = {};
> -        int ret;
> +    if (cmd != NL80211_CMD_DEL_INTERFACE) {
> +        if (rdev->ops->get_channel && !wdev->valid_links) {
> +            struct cfg80211_chan_def chandef = {};
> +            int ret;
>
> -        ret = rdev_get_channel(rdev, wdev, 0, &chandef);
> -        if (ret == 0 && nl80211_send_chandef(msg, &chandef))
> -            goto nla_put_failure;
> -    }
> +            ret = rdev_get_channel(rdev, wdev, 0, &chandef);
> +            if (ret == 0 && nl80211_send_chandef(msg, &chandef))
> +                goto nla_put_failure;
> +        }
>
> -    if (rdev->ops->get_tx_power) {
> -        int dbm, ret;
> +        if (rdev->ops->get_tx_power) {
> +            int dbm, ret;
>
> -        ret = rdev_get_tx_power(rdev, wdev, &dbm);
> -        if (ret == 0 &&
> -            nla_put_u32(msg, NL80211_ATTR_WIPHY_TX_POWER_LEVEL,
> -                DBM_TO_MBM(dbm)))
> -            goto nla_put_failure;
> +            ret = rdev_get_tx_power(rdev, wdev, &dbm);
> +            if (ret == 0 &&
> +                nla_put_u32(msg, NL80211_ATTR_WIPHY_TX_POWER_LEVEL,
> +                    DBM_TO_MBM(dbm)))
> +                goto nla_put_failure;
> +        }
>      }
>
>      switch (wdev->iftype) {
>
> But this change doesn't consider get_txq_stats and the further calls
> rdev_get_channel for the valid_links.
>
> Do we actually need nl80211_send_iface() for NL80211_CMD_DEL_INTERFACE?

In term of user-space API the answer would (probably) be yes. At least the 
primitive should be send. What attributes should be included is debatable. 
The primitive is probably used by user-space to cleanup or disable 
functionality using the given interface. So only attributes identifying the 
interface are likely sufficient (wdev-id, if-index).

Regards,
Arend