* Funny log entries for rtw88_8821ce @ 2022-01-31 22:53 Larry Finger 2022-02-01 6:26 ` Pkshih 0 siblings, 1 reply; 7+ messages in thread From: Larry Finger @ 2022-01-31 22:53 UTC (permalink / raw) To: Pkshih; +Cc: linux-wireless 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Funny log entries for rtw88_8821ce 2022-01-31 22:53 Funny log entries for rtw88_8821ce Larry Finger @ 2022-02-01 6:26 ` Pkshih 2022-02-03 20:06 ` Larry Finger 0 siblings, 1 reply; 7+ messages in thread From: Pkshih @ 2022-02-01 6:26 UTC (permalink / raw) To: Larry.Finger@lwfinger.net; +Cc: linux-wireless@vger.kernel.org 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Funny log entries for rtw88_8821ce 2022-02-01 6:26 ` Pkshih @ 2022-02-03 20:06 ` Larry Finger 2022-02-08 9:01 ` Kalle Valo 0 siblings, 1 reply; 7+ messages in thread From: Larry Finger @ 2022-02-03 20:06 UTC (permalink / raw) To: Pkshih; +Cc: linux-wireless@vger.kernel.org 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Funny log entries for rtw88_8821ce 2022-02-03 20:06 ` Larry Finger @ 2022-02-08 9:01 ` Kalle Valo 2022-02-08 12:02 ` Pkshih 0 siblings, 1 reply; 7+ messages in thread From: Kalle Valo @ 2022-02-08 9:01 UTC (permalink / raw) To: Larry Finger; +Cc: Pkshih, linux-wireless@vger.kernel.org Larry Finger <Larry.Finger@lwfinger.net> 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* RE: Funny log entries for rtw88_8821ce 2022-02-08 9:01 ` Kalle Valo @ 2022-02-08 12:02 ` Pkshih 2022-02-10 14:26 ` Kalle Valo 0 siblings, 1 reply; 7+ messages in thread From: Pkshih @ 2022-02-08 12:02 UTC (permalink / raw) To: kvalo@kernel.org, Larry.Finger@lwfinger.net Cc: linux-wireless@vger.kernel.org > -----Original Message----- > From: Kalle Valo <kvalo@kernel.org> > Sent: Tuesday, February 8, 2022 5:02 PM > To: Larry Finger <Larry.Finger@lwfinger.net> > Cc: Pkshih <pkshih@realtek.com>; linux-wireless@vger.kernel.org > Subject: Re: Funny log entries for rtw88_8821ce > > Larry Finger <Larry.Finger@lwfinger.net> 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: Funny log entries for rtw88_8821ce 2022-02-08 12:02 ` Pkshih @ 2022-02-10 14:26 ` Kalle Valo 2022-02-11 0:25 ` Pkshih 0 siblings, 1 reply; 7+ messages in thread From: Kalle Valo @ 2022-02-10 14:26 UTC (permalink / raw) To: Pkshih; +Cc: Larry.Finger@lwfinger.net, linux-wireless@vger.kernel.org Pkshih <pkshih@realtek.com> writes: >> -----Original Message----- >> From: Kalle Valo <kvalo@kernel.org> >> Sent: Tuesday, February 8, 2022 5:02 PM >> To: Larry Finger <Larry.Finger@lwfinger.net> >> Cc: Pkshih <pkshih@realtek.com>; linux-wireless@vger.kernel.org >> Subject: Re: Funny log entries for rtw88_8821ce >> >> Larry Finger <Larry.Finger@lwfinger.net> 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* RE: Funny log entries for rtw88_8821ce 2022-02-10 14:26 ` Kalle Valo @ 2022-02-11 0:25 ` Pkshih 0 siblings, 0 replies; 7+ messages in thread From: Pkshih @ 2022-02-11 0:25 UTC (permalink / raw) To: Kalle Valo; +Cc: Larry.Finger@lwfinger.net, linux-wireless@vger.kernel.org > -----Original Message----- > From: Kalle Valo <kvalo@kernel.org> > Sent: Thursday, February 10, 2022 10:27 PM > To: Pkshih <pkshih@realtek.com> > Cc: Larry.Finger@lwfinger.net; linux-wireless@vger.kernel.org > Subject: Re: Funny log entries for rtw88_8821ce > > Pkshih <pkshih@realtek.com> 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2022-02-11 0:25 UTC | newest] Thread overview: 7+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2022-01-31 22:53 Funny log entries for rtw88_8821ce Larry Finger 2022-02-01 6:26 ` Pkshih 2022-02-03 20:06 ` Larry Finger 2022-02-08 9:01 ` Kalle Valo 2022-02-08 12:02 ` Pkshih 2022-02-10 14:26 ` Kalle Valo 2022-02-11 0:25 ` Pkshih
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.