Received-SPF: pass (google.com: domain of linux-wireless-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
From:   Kalle Valo <kvalo@kernel.org>
To:     Larry Finger <Larry.Finger@lwfinger.net>
Cc:     Pkshih <pkshih@realtek.com>,
        "linux-wireless\@vger.kernel.org" <linux-wireless@vger.kernel.org>
Subject: Re: Funny log entries for rtw88_8821ce
References: <c356d5ae-a7b3-3065-1121-64c446e70333@lwfinger.net>
        <32f2ece8acdb67f74757cb705e5467847d6bcae0.camel@realtek.com>
        <ef7361eb-17ce-5ecf-a46a-a9f0c5aab35b@lwfinger.net>
Date:   Tue, 08 Feb 2022 11:01:32 +0200
In-Reply-To: <ef7361eb-17ce-5ecf-a46a-a9f0c5aab35b@lwfinger.net> (Larry
        Finger's message of "Thu, 3 Feb 2022 14:06:08 -0600")
Message-ID: <87czjxbukz.fsf@tynnyri.adurom.net>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/26.1 (gnu/linux)
MIME-Version: 1.0
Content-Type: text/plain
Precedence: bulk

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