Ping-Ke and list,
Within the last couple of days, I was testing rtw88 with an rtl8821ce card. I
noticed that whenever the device is not connected to an AP, the log is flooded
with messages like the following:
[130462.603539] rtw_8821ce 0000:02:00.0: stop vif ee:a4:95:4e:53:8b on port 0
[130463.116843] rtw_8821ce 0000:02:00.0: start vif aa:fc:19:66:5e:e2 on port 0
[130874.613430] rtw_8821ce 0000:02:00.0: stop vif aa:fc:19:66:5e:e2 on port 0
[130875.122641] rtw_8821ce 0000:02:00.0: start vif d2:e6:23:ba:98:76 on port 0
[131286.677828] rtw_8821ce 0000:02:00.0: stop vif d2:e6:23:ba:98:76 on port 0
[131287.192108] rtw_8821ce 0000:02:00.0: start vif 82:c4:33:96:2e:c6 on port 0\
After ~411 secs, the callback routine for remove_interface() in struct
ieee80211_ops is called. After <1 sec, the add_interface() callback is called to
restart the vif. Is this normal behavior and I see it in the logs because this
driver is the only one that logs the start/stop calls, or is something else
going on? It would be easy to disable those log entries, but I would like to
know if there is some other condition?
On my kernel, HZ is 250, thus the interval is roughly 103,000 jiffies.
Thanks,
Larry
Hi,
On Mon, 2022-01-31 at 16:53 -0600, Larry Finger wrote:
> Ping-Ke and list,
>
> Within the last couple of days, I was testing rtw88 with an rtl8821ce card. I
> noticed that whenever the device is not connected to an AP, the log is flooded
> with messages like the following:
> [130462.603539] rtw_8821ce 0000:02:00.0: stop vif ee:a4:95:4e:53:8b on port 0
> [130463.116843] rtw_8821ce 0000:02:00.0: start vif aa:fc:19:66:5e:e2 on port 0
> [130874.613430] rtw_8821ce 0000:02:00.0: stop vif aa:fc:19:66:5e:e2 on port 0
> [130875.122641] rtw_8821ce 0000:02:00.0: start vif d2:e6:23:ba:98:76 on port 0
> [131286.677828] rtw_8821ce 0000:02:00.0: stop vif d2:e6:23:ba:98:76 on port 0
> [131287.192108] rtw_8821ce 0000:02:00.0: start vif 82:c4:33:96:2e:c6 on port 0\
I turn off UI network-manager, and it can show the same messages if I use
'ifconfig' to up and down the interfaces. I think add_interface()/remove_interface()
are called by ieee80211_do_open()/ieee80211_do_stop() in my test cases.
Please check if your network-manager does the things. If so, check syslog to
know why it does.
>
> After ~411 secs, the callback routine for remove_interface() in struct
> ieee80211_ops is called. After <1 sec, the add_interface() callback is called to
> restart the vif. Is this normal behavior and I see it in the logs because this
> driver is the only one that logs the start/stop calls, or is something else
> going on? It would be easy to disable those log entries, but I would like to
> know if there is some other condition?
>
> On my kernel, HZ is 250, thus the interval is roughly 103,000 jiffies.
>
Ping-Ke
On 2/1/22 00:26, Pkshih wrote:
> Hi,
>
> On Mon, 2022-01-31 at 16:53 -0600, Larry Finger wrote:
>> Ping-Ke and list,
>>
>> Within the last couple of days, I was testing rtw88 with an rtl8821ce card. I
>> noticed that whenever the device is not connected to an AP, the log is flooded
>> with messages like the following:
>> [130462.603539] rtw_8821ce 0000:02:00.0: stop vif ee:a4:95:4e:53:8b on port 0
>> [130463.116843] rtw_8821ce 0000:02:00.0: start vif aa:fc:19:66:5e:e2 on port 0
>> [130874.613430] rtw_8821ce 0000:02:00.0: stop vif aa:fc:19:66:5e:e2 on port 0
>> [130875.122641] rtw_8821ce 0000:02:00.0: start vif d2:e6:23:ba:98:76 on port 0
>> [131286.677828] rtw_8821ce 0000:02:00.0: stop vif d2:e6:23:ba:98:76 on port 0
>> [131287.192108] rtw_8821ce 0000:02:00.0: start vif 82:c4:33:96:2e:c6 on port 0\
>
> I turn off UI network-manager, and it can show the same messages if I use
> 'ifconfig' to up and down the interfaces. I think add_interface()/remove_interface()
> are called by ieee80211_do_open()/ieee80211_do_stop() in my test cases.
>
> Please check if your network-manager does the things. If so, check syslog to
> know why it does.
Utility journalctl show the following for a couple of cycles from start- to
stop-vif:
Feb 03 12:02:10 localhost.localdomain NetworkManager[608]: <info>
[1643911330.5997] device (wls1): supplicant interface state: disconnected ->
interface_disabled
Feb 03 12:02:10 localhost.localdomain kernel: rtw_8821ce 0000:02:00.0: start vif
9a:cd:df:5f:24:13 on port 0
Feb 03 12:02:10 localhost.localdomain NetworkManager[608]: <info>
[1643911330.6179] device (wls1): supplicant interface state: interface_disabled
-> disconnected
Feb 03 12:09:02 localhost.localdomain kernel: rtw_8821ce 0000:02:00.0: stop vif
9a:cd:df:5f:24:13 on port 0
Feb 03 12:09:02 localhost.localdomain NetworkManager[608]: <info>
[1643911742.0704] device (wls1): set-hw-addr: set MAC address to
1A:73:93:A8:7E:9C (scanning)
Feb 03 12:09:02 localhost.localdomain kernel: rtw_8821ce 0000:02:00.0: start vif
1a:73:93:a8:7e:9c on port 0
Feb 03 12:09:02 localhost.localdomain NetworkManager[608]: <info>
[1643911742.5891] device (wls1): supplicant interface state: disconnected ->
interface_disabled
Feb 03 12:09:02 localhost.localdomain NetworkManager[608]: <info>
[1643911742.5946] device (wls1): supplicant interface state: interface_disabled
-> disconnected
Feb 03 12:15:54 localhost.localdomain NetworkManager[608]: <info>
[1643912154.0710] device (wls1): set-hw-addr: set MAC address to
42:CB:4C:C7:CB:00 (scanning)
Feb 03 12:15:54 localhost.localdomain kernel: rtw_8821ce 0000:02:00.0: stop vif
1a:73:93:a8:7e:9c on port 0
From these log entries, I see no reason why there should be a stop-vif 412
seconds after the interface is set from disabled to disconnected. This cycling
does not cause any problems. Perhaps the statements that do the logging should
be removed.
Larry
Larry Finger <[email protected]> writes:
> On 2/1/22 00:26, Pkshih wrote:
>> On Mon, 2022-01-31 at 16:53 -0600, Larry Finger wrote:
>>> Ping-Ke and list,
>>>
>>> Within the last couple of days, I was testing rtw88 with an rtl8821ce card. I
>>> noticed that whenever the device is not connected to an AP, the log is flooded
>>> with messages like the following:
>>> [130462.603539] rtw_8821ce 0000:02:00.0: stop vif ee:a4:95:4e:53:8b on port 0
>>> [130463.116843] rtw_8821ce 0000:02:00.0: start vif aa:fc:19:66:5e:e2 on port 0
>>> [130874.613430] rtw_8821ce 0000:02:00.0: stop vif aa:fc:19:66:5e:e2 on port 0
>>> [130875.122641] rtw_8821ce 0000:02:00.0: start vif d2:e6:23:ba:98:76 on port 0
>>> [131286.677828] rtw_8821ce 0000:02:00.0: stop vif d2:e6:23:ba:98:76 on port 0
>>> [131287.192108] rtw_8821ce 0000:02:00.0: start vif 82:c4:33:96:2e:c6 on port 0\
>>
>> I turn off UI network-manager, and it can show the same messages if I use
>> 'ifconfig' to up and down the interfaces. I think add_interface()/remove_interface()
>> are called by ieee80211_do_open()/ieee80211_do_stop() in my test cases.
>>
>> Please check if your network-manager does the things. If so, check syslog to
>> know why it does.
>
> Utility journalctl show the following for a couple of cycles from
> start- to stop-vif:
>
> Feb 03 12:02:10 localhost.localdomain NetworkManager[608]: <info>
> [1643911330.5997] device (wls1): supplicant interface state:
> disconnected ->
> interface_disabled
> Feb 03 12:02:10 localhost.localdomain kernel: rtw_8821ce 0000:02:00.0:
> start vif 9a:cd:df:5f:24:13 on port 0
> Feb 03 12:02:10 localhost.localdomain NetworkManager[608]: <info>
> [1643911330.6179] device (wls1): supplicant interface state:
> interface_disabled -> disconnected
> Feb 03 12:09:02 localhost.localdomain kernel: rtw_8821ce 0000:02:00.0:
> stop vif 9a:cd:df:5f:24:13 on port 0
> Feb 03 12:09:02 localhost.localdomain NetworkManager[608]: <info>
> [1643911742.0704] device (wls1): set-hw-addr: set MAC address to
> 1A:73:93:A8:7E:9C (scanning)
> Feb 03 12:09:02 localhost.localdomain kernel: rtw_8821ce 0000:02:00.0:
> start vif 1a:73:93:a8:7e:9c on port 0
> Feb 03 12:09:02 localhost.localdomain NetworkManager[608]: <info>
> [1643911742.5891] device (wls1): supplicant interface state:
> disconnected ->
> interface_disabled
> Feb 03 12:09:02 localhost.localdomain NetworkManager[608]: <info>
> [1643911742.5946] device (wls1): supplicant interface state:
> interface_disabled -> disconnected
> Feb 03 12:15:54 localhost.localdomain NetworkManager[608]: <info>
> [1643912154.0710] device (wls1): set-hw-addr: set MAC address to
> 42:CB:4C:C7:CB:00 (scanning)
> Feb 03 12:15:54 localhost.localdomain kernel: rtw_8821ce 0000:02:00.0:
> stop vif 1a:73:93:a8:7e:9c on port 0
>
> From these log entries, I see no reason why there should be a stop-vif
> 412 seconds after the interface is set from disabled to disconnected.
> This cycling does not cause any problems. Perhaps the statements that
> do the logging should be removed.
I did a quick check on how rtw88 uses rtw_info() and indeed that should
be cleaned up.
These should be warning or error messages:
rtw_info(rtwdev, "invalid H2C command format for debug\n");
rtw_info(rtwdev, "incorrect lna index (%d)\n", lna_idx);
rtw_info(rtwdev, "unsupported tx path 0x%x\n", antenna_tx);
rtw_info(rtwdev, "unsupported rx path 0x%x\n", antenna_rx);
rtw_info(rtwdev, "unsupported tx path 0x%x\n", antenna_tx);
rtw_info(rtwdev, "unsupported rx path 0x%x\n", antenna_rx);
Not sure if warn or debug, most likely debug:
rtw_info(rtwdev, "HW scan aborted with code: %d\n", rc);
These should be debug messages to avoid spamming the logs:
rtw_info(rtwdev, "start vif %pM on port %d\n", vif->addr, rtwvif->port);
rtw_info(rtwdev, "stop vif %pM on port %d\n", vif->addr, rtwvif->port);
rtw_info(rtwdev, "change vif %pM (%d)->(%d), p2p (%d)->(%d)\n",
rtw_info(rtwdev, "sta %pM joined with macid %d\n",
rtw_info(rtwdev, "sta %pM with macid %d left\n",
rtw_info(rtwdev, "On freq %u to %u, set SAR %d in 1/%lu dBm\n"
This is ok:
rtw_info(rtwdev, "Firmware version %u.%u.%u, H2C version %u\n",
--
https://patchwork.kernel.org/project/linux-wireless/list/
https://wireless.wiki.kernel.org/en/developers/documentation/submittingpatches
> -----Original Message-----
> From: Kalle Valo <[email protected]>
> Sent: Tuesday, February 8, 2022 5:02 PM
> To: Larry Finger <[email protected]>
> Cc: Pkshih <[email protected]>; [email protected]
> Subject: Re: Funny log entries for rtw88_8821ce
>
> Larry Finger <[email protected]> writes:
>
> > From these log entries, I see no reason why there should be a stop-vif
> > 412 seconds after the interface is set from disabled to disconnected.
> > This cycling does not cause any problems. Perhaps the statements that
> > do the logging should be removed.
>
> I did a quick check on how rtw88 uses rtw_info() and indeed that should
> be cleaned up.
>
> These should be warning or error messages:
>
> rtw_info(rtwdev, "invalid H2C command format for debug\n");
> rtw_info(rtwdev, "incorrect lna index (%d)\n", lna_idx);
> rtw_info(rtwdev, "unsupported tx path 0x%x\n", antenna_tx);
> rtw_info(rtwdev, "unsupported rx path 0x%x\n", antenna_rx);
> rtw_info(rtwdev, "unsupported tx path 0x%x\n", antenna_tx);
> rtw_info(rtwdev, "unsupported rx path 0x%x\n", antenna_rx);
>
> Not sure if warn or debug, most likely debug:
>
> rtw_info(rtwdev, "HW scan aborted with code: %d\n", rc);
>
> These should be debug messages to avoid spamming the logs:
>
> rtw_info(rtwdev, "start vif %pM on port %d\n", vif->addr, rtwvif->port);
> rtw_info(rtwdev, "stop vif %pM on port %d\n", vif->addr, rtwvif->port);
> rtw_info(rtwdev, "change vif %pM (%d)->(%d), p2p (%d)->(%d)\n",
> rtw_info(rtwdev, "sta %pM joined with macid %d\n",
> rtw_info(rtwdev, "sta %pM with macid %d left\n",
> rtw_info(rtwdev, "On freq %u to %u, set SAR %d in 1/%lu dBm\n"
>
> This is ok:
>
> rtw_info(rtwdev, "Firmware version %u.%u.%u, H2C version %u\n",
>
I will fix them as well as rtw89. To avoid mistakes, I do google search for
KERN_INFO, and find [1]
KERN_INFO: this is the log level used for informational messages
about the action performed by the kernel.
Then, I have a question about the message of setting SAR:
rtw_info(rtwdev, "On freq %u to %u, set SAR %d in 1/%lu dBm\n"
When a user sets SAR via iw, this message can reflect the action performed
by driver. Is this rtw_info acceptable?
[1] https://linuxconfig.org/introduction-to-the-linux-kernel-log-levels
--
Ping-Ke
Pkshih <[email protected]> writes:
>> -----Original Message-----
>> From: Kalle Valo <[email protected]>
>> Sent: Tuesday, February 8, 2022 5:02 PM
>> To: Larry Finger <[email protected]>
>> Cc: Pkshih <[email protected]>; [email protected]
>> Subject: Re: Funny log entries for rtw88_8821ce
>>
>> Larry Finger <[email protected]> writes:
>>
>> > From these log entries, I see no reason why there should be a stop-vif
>> > 412 seconds after the interface is set from disabled to disconnected.
>> > This cycling does not cause any problems. Perhaps the statements that
>> > do the logging should be removed.
>>
>> I did a quick check on how rtw88 uses rtw_info() and indeed that should
>> be cleaned up.
>>
>> These should be warning or error messages:
>>
>> rtw_info(rtwdev, "invalid H2C command format for debug\n");
>> rtw_info(rtwdev, "incorrect lna index (%d)\n", lna_idx);
>> rtw_info(rtwdev, "unsupported tx path 0x%x\n", antenna_tx);
>> rtw_info(rtwdev, "unsupported rx path 0x%x\n", antenna_rx);
>> rtw_info(rtwdev, "unsupported tx path 0x%x\n", antenna_tx);
>> rtw_info(rtwdev, "unsupported rx path 0x%x\n", antenna_rx);
>>
>> Not sure if warn or debug, most likely debug:
>>
>> rtw_info(rtwdev, "HW scan aborted with code: %d\n", rc);
>>
>> These should be debug messages to avoid spamming the logs:
>>
>> rtw_info(rtwdev, "start vif %pM on port %d\n", vif->addr, rtwvif->port);
>> rtw_info(rtwdev, "stop vif %pM on port %d\n", vif->addr, rtwvif->port);
>> rtw_info(rtwdev, "change vif %pM (%d)->(%d), p2p (%d)->(%d)\n",
>> rtw_info(rtwdev, "sta %pM joined with macid %d\n",
>> rtw_info(rtwdev, "sta %pM with macid %d left\n",
>> rtw_info(rtwdev, "On freq %u to %u, set SAR %d in 1/%lu dBm\n"
>>
>> This is ok:
>>
>> rtw_info(rtwdev, "Firmware version %u.%u.%u, H2C version %u\n",
>>
>
> I will fix them as well as rtw89. To avoid mistakes, I do google search for
> KERN_INFO, and find [1]
> KERN_INFO: this is the log level used for informational messages
> about the action performed by the kernel.
Not following you here.
> Then, I have a question about the message of setting SAR:
> rtw_info(rtwdev, "On freq %u to %u, set SAR %d in 1/%lu dBm\n"
>
> When a user sets SAR via iw, this message can reflect the action performed
> by driver. Is this rtw_info acceptable?
In general the preference for user space commands is not to print
anything to the log when debug messages are disabled, but of course
there can be exceptions if the reasons are good. Why do you want to
print this always? What benefit does it bring for the user?
--
https://patchwork.kernel.org/project/linux-wireless/list/
https://wireless.wiki.kernel.org/en/developers/documentation/submittingpatches
> -----Original Message-----
> From: Kalle Valo <[email protected]>
> Sent: Thursday, February 10, 2022 10:27 PM
> To: Pkshih <[email protected]>
> Cc: [email protected]; [email protected]
> Subject: Re: Funny log entries for rtw88_8821ce
>
> Pkshih <[email protected]> writes:
>
> > Then, I have a question about the message of setting SAR:
> > rtw_info(rtwdev, "On freq %u to %u, set SAR %d in 1/%lu dBm\n"
> >
> > When a user sets SAR via iw, this message can reflect the action performed
> > by driver. Is this rtw_info acceptable?
>
> In general the preference for user space commands is not to print
> anything to the log when debug messages are disabled, but of course
> there can be exceptions if the reasons are good. Why do you want to
> print this always? What benefit does it bring for the user?
>
Understand. My original thinking still focus on debug purpose.
Because the SAR doesn't have a 'get' method to check status, and it affects
TX power but a user can't be aware that clearly. If someone told me his
laptop has low wifi performance, this message can be a good clue to address
the problem.
Fortunately, I still can use debugfs to debug this case, so I will change
this message to debug level.
--
Ping-Ke