Received-SPF: pass (google.com: domain of linux-wireless-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Subject: Re: [PATCH v3] mac80211: fix regression in sta connection monitor
To:     Georgi Valkov <gvalkov@abv.bg>
Cc:     linux-wireless@vger.kernel.org, johannes@sipsolutions.net
References: <20200927105605.97954-1-nbd@nbd.name>
 <4ED2AADF-092B-424E-A5B5-C2A371C88A92@abv.bg>
 <FC3CA053-0DB9-41B9-AEC6-0AE189AEFE17@abv.bg>
From:   Felix Fietkau <nbd@nbd.name>
Message-ID: <98daee02-b277-2850-6bc2-16f4d8971fac@nbd.name>
Date:   Tue, 29 Sep 2020 14:13:11 +0200
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:78.0)
 Gecko/20100101 Thunderbird/78.2.2
MIME-Version: 1.0
In-Reply-To: <FC3CA053-0DB9-41B9-AEC6-0AE189AEFE17@abv.bg>
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Precedence: bulk


On 2020-09-28 19:09, Georgi Valkov wrote:
> Hi Felix!
> 
> Unfortunately it disconnected again after 21 hours and 44 minutes of uptime, and remained offline for 5 minutes again.
> I will add some code to ieee80211_sta_work() to trace more info when a disconnect occurs.
> Do you have any ideas? Why does it remain offline for exactly 5 minutes every time? Do we need to reset probe_send_count in rx.c? Do we have to send probe requests or nullfunc while there is active communication, e.g. acknowledged ICMP traffic?
> 
> This is the most common event in the trace, it occurs every 30 seconds, we called ieee80211_sta_tx_notify(ack: true), and ieee80211_is_any_nullfunc() returned true, so probe_send_count is reset:
> --- ack  probe_send_count: 1  vif.type 2:2
> 
> These events are rare, I could not find any pattern. probe_send_count is reset inside status.c
> reset connection monitor  probe_send_count: 1  nullfunc: 0
> 
> These events are rare and appear randomly. The first indicates that we called ieee80211_sta_tx_notify(ack: false), and ieee80211_is_any_nullfunc() returned true, so probe_send_count is not reset, while the second always appears 10ms later with ack = true, and ieee80211_is_any_nullfunc() returned true, so probe_send_count is reset.
> probe_send_count: 1  vif.type 2:2
> --- ack  probe_send_count: 2  vif.type 2:2
So far I don't see any strong indication that these disconnects are
related to this patch. The debug messages you added seem normal to me.
More comments on the disconnects below.

> Here are some interesting parts from the trace:
> 
> [STA kernel log]
> [55045.254528] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [55075.971445] wifi: reset connection monitor  probe_send_count: 1  nullfunc: 0
> [55106.699439] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> ...
> [57812.177775] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [57842.894483] wifi: reset connection monitor  probe_send_count: 1  nullfunc: 0
> [57873.610852] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> ...
> [78172.681502] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78203.398703] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78234.118347] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78264.834126] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78282.530133] wifi: deauthenticated from 60:38:e0:xx:xx:xx (Reason: 16=GROUP_KEY_HANDSHAKE_TIMEOUT)
This one is definitely not related to the connection monitor.

> [78282.539463] br-lan: port 3(wifi) entered disabled state
> [78282.544987] br-lan: topology change detected, propagating
> [78283.514078] wifi: authenticate with 60:38:e0:xx:xx:xx
> [78283.533405] wifi: send auth to 60:38:e0:xx:xx:xx (try 1/3)
> [78283.577391] wifi: authenticated
> [78283.583874] wifi: associate with 60:38:e0:xx:xx:xx (try 1/3)
> [78283.610166] wifi: RX AssocResp from 60:38:e0:xx:xx:xx (capab=0x431 status=0 aid=1)
> [78283.618322] wifi: associated
> [78283.628908] br-lan: port 3(wifi) entered blocking state
> [78283.634358] br-lan: port 3(wifi) entered listening state
> [78285.663507] br-lan: port 3(wifi) entered learning state
> [78287.679338] br-lan: port 3(wifi) entered forwarding state
> [78287.684939] br-lan: topology change detected, sending tcn bpdu
> [78313.981348] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78316.028959] br-lan: port 3(wifi) neighbor 7fff.60:38:e0:xx:xx:xy lost
> [78316.035630] br-lan: topology change detected, propagating
> [78346.746657] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78377.464074] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78408.181527] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78438.898977] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78471.664287] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78502.381794] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78533.099298] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78563.816824] wifi: --- ack  probe_send_count: 1  vif.type 2:2
> [78583.518337] wifi: disassociated from 60:38:e0:xx:xx:xx (Reason: 4=DISASSOC_DUE_TO_INACTIVITY)
Are you sure that this one is even related to the connection monitor? It
seems to me that the client may have been kicked from the AP due to
inactivity (might be AP probing, not STA probing).

- Felix