IssueTracker

Analyzing dynamic features on their own like that doesn't work properly since even though they "depend" on the app they're actually including into an app so for example the unused resource check only makes sense when you look at it from the app perspective, not the other way around.

I believe in 7.0 we've fixed this in the sense that there isn't a lint task on the individual dynamic features.

+1. In AGP 7.0 there are no lint tasks in dynamic-features; instead, any dynamic-features are analyzed when running lint on the app module. OP, can you try with AGP 7.0.0-rc01, run lintRelease on the corresponding application module, and see if you still hit the same issue?

Not using dynamic feature modules but have this with an application module and a library module, happening on 7.0.0-rc01. I haven't figured out a repro yet but will upload one if I manage.

Re #5, yes, a repro project would be very helpful, thanks!

Closing this bug as not reproducible, but please reopen if you have a repro project.

comment #3 mentioned upstream commits that could potentially help. We've recently uprev'd supplicant (bug 193926134) so those fixes should be included now. What are the next steps? See if the bug is still happening even after the uprev?

Relevant metrics have landed. I think at this point we should see if the customer is still experiencing the issue.

I'll repeat a note from comment #3: "It also requires a kernel upgrade, or backporting, for kernel<4.17."

So, since the Octopus family is still running kernel 4.14, nothing has taken effect there yet.

AI:

• billy to look into the effort required for backporting
• billy to monitor the metrics to evaluate the severity/impact of the bug. That could require waiting for the stable release (M99)

I believe this branch merge introduced the required functionality into kernel 4.17 https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?h=v4.17&id=1dd2eefb8efa97b6b495c4f09fa8232727b93db1

At first glance, It seems like backport effort seems tractable, but I lack experience with backporting so this effort would probably be non-trivial for me. If I get some help to help expedite the backport effort, it might make sense for us to backport this.

<triage> We'll wait until 2 weeks after M99 hits stable for Billy's metric to collect data and reassess the priority then.

Bugjuggler: wait until 2022-3-14 -> billyzhao

<Triage notes> Since the next steps are mentioned in comment #16 (wait 2 weeks after M99 hits stable), marking as triaged.

re comment #3 and ("nl80211: Control port over nl80211 helpers"), there's been upstream activity about specifically prioritizing control traffic (https://lore.kernel.org/r/20210206115112.567881-1-markus.theil@tu-ilmenau.de). I needed this for an unrelated bug (b/206865368), but it may be this is helpful for other types of control traffic.

I have taken a look at the metric stats (metric name : TimeFromRekeyToFailureSeconds, internal link not included due to this bug being on the public tracker). We do not see many reproductions of a connection failure shortly after rekey attempt. Marking untriaged and unassigning to discuss in triage.

<triage> Kernel uprev in M101 should mitigate the issue. Metric mentioned in comment #20 confirms that the priority is correct.

Assigning to bugjuggler, wait until 4 weeks after M101 reaches stable.

Bugjuggler: wait until 2022-05-31

<triage> Jun to verify whether or not kernel uprev fixed this issue.

The uprev schedule on octopus has been pushed back to kernel 5.15 on M107 according to go/uprev-cal

By looking at the other boards with the same wifi chipset Intel AC7265:

• asuka uprev 4.19
• cave uprev 4.19
• coral not uprev 4.4

https://screenshot.googleplex.com/A28vzP7SQBSED6m The curves showing normalized rekey failures per device indicate conflicted data. coral is on par with cave, while both of them are worst than asuka.

The factors may impact the rekey failures may be regions, pillars or etc. I still need the octopus UMA data after M107 stable to evaluate the kernel patch.

Bugjuggler: wait until 2022-10-27 -> junyuu@

Since current rekey metric isn't reliable because it doesn't consider the issue when roam between different BSSID, which itself should be distinguished from same BSSID rekey issue.

Billy is working in the CL https://chromium-review.googlesource.com/c/chromiumos/platform2/+/3989543

So current metric is premature to verify whether kernel uprev can really fix this rekey issue caused by EAPOL out-of-order. Pushing back the work.

Bugjuggler: -> junyuu

Billy's improvement to rekey UMA metrics landed https://chromium-review.googlesource.com/c/chromiumos/platform2/+/3989543. Wait 3 months until enough new UMA data has been collected.

Xamine shows the log signature wlan0: Not associated - Delay processing of received EAPOL frame still exists on uprev-ed devices like grunt and kernel > 4.17 ones like dedede. xamine Link. There is no clear metric to check for the user impact regard the behaviors depicted by this kind log messages.

The UPSTREAM patch partially fix the problems during rekeying https://chromium-review.googlesource.com/c/chromiumos/third_party/hostap/+/4017982. One of metric can be checked is the number of disconnections with reason rekey failure before and after the CL landed. So this is the next step.

A couple things:

1. I think we need to refocus this bug - it's not clear how widespread the user impact of this symptom is. Just because we see Delay processing of ..., it doesn't mean that there's user impact. There's a retry mechanism such that as long as the assoc event comes in "soon", we'll still catch the next retransmission of the EAPOL packet. In fact, just spot-checking a couple of the feedback reports, I wasn't able to see any connection issues. It would be better to use FRA to check how often that log line is shortly succeeded by a handshake timeout (possibly look at bugs that Brian worked on in the past linked above where he was able to repro the issue to extract the correct signature).
2. This bug has nothing to do with rekeying in particular. In fact, I'm struggling to see how this would actually impact rekeying given that this bug is about EAPOL dropping before "associated" message, which we don't need during a rekey. Again, FRA could help us determine whether this actually ever happens during a rekey.

Jun, can you use FRA to run a couple queries so we can correctly set the priority here and potentially just close this bug out if we can't tie to any discernible user impact?

Investigation of logs "Delay processing ..."

I queried the Feedback reports with following SQLs in Xamine

system_logs.name = 'syslog' AND REGEXP_CONTAINS(log_lines.content, "Delay processing of received EAPOL frame") AND "network_connection_failure" IN UNNEST(analyzer_tags)

And the same log line with network_disconnect in FRQ tags.

Found zero matched report. The Delay processing ... logs almost have no correlation with WiFi disconnections.

Revisited Brian's bug and repro.

After reading through the original bug, according to https://bugs.chromium.org/p/chromium/issues/detail?id=1044396#c26, the correct signature worths persuing should be Process pending EAPOL if the latency of EAP message is longer than 200ms.

I ran some queried with Xamine and FRA

system_logs.name = 'netlog' AND REGEXP_CONTAINS(log_lines.content, "Process pending EAPOL") AND "network_connection_failure" IN UNNEST(analyzer_tags)

I did find some usable feedback reports that depicting the logs "Process pending EAPOL " and close WiFi disconnections. For examples:

• https://listnr.corp.google.com/product/208/report/90749777747

2023-02-12T23:50:29.762176Z DEBUG wpa_supplicant[680]: wlan0: Process pending EAPOL frame that was received just before association notification
2023-02-12T23:50:29.762190Z DEBUG wpa_supplicant[680]: wlan0: RX EAPOL from [MAC OUI=a8:9a:93 IFACE=27]
...
2023-02-12T23:50:38.800219Z DEBUG wpa_supplicant[680]: WPA: Derived Key MIC - hexdump(len=16): 7d 15 09 eb b3 85 6e e0 24 d2 ff 11 4f c1 a5 27
2023-02-12T23:50:39.762401Z NOTICE wpa_supplicant[680]: wlan0: Authentication with [MAC OUI=a8:9a:93 IFACE=27] timed out.

• And https://listnr.corp.google.com/product/208/report/90750242542

2023-02-09T09:42:20.906586Z DEBUG wpa_supplicant[692]: wlan0: Process pending EAPOL frame that was received just before association notification
2023-02-09T09:42:20.906600Z DEBUG wpa_supplicant[692]: wlan0: RX EAPOL from [MAC OUI=80:2a:a8 IFACE=25]
...
2023-02-09T09:42:24.922652Z DEBUG wpa_supplicant[692]: nl80211: Delete station [MAC OUI=80:2a:a8 IFACE=25]
2023-02-09T09:42:24.929000Z DEBUG wpa_supplicant[692]: nl80211: Drv Event 39 (NL80211_CMD_DEAUTHENTICATE) received for wlan0
2023-02-09T09:42:24.929025Z DEBUG wpa_supplicant[692]: nl80211: Deauthenticate event
2023-02-09T09:42:24.929050Z DEBUG wpa_supplicant[692]: wlan0: Event DEAUTH (11) received
2023-02-09T09:42:24.929080Z DEBUG wpa_supplicant[692]: wlan0: Deauthentication notification
2023-02-09T09:42:24.929119Z DEBUG wpa_supplicant[692]: wlan0:  * reason 2 (PREV_AUTH_NOT_VALID)

Reconsidering the priority

Need using more of Xamine to determin the priority.

Nice, thanks Jun!

Removing triage because it seems like we're waiting on priority assessment

<Triage notes> Jun to investigate the data to evaluate the priority.

Re-run the unioned query mentioned in comment#30 in Xamine Advanced Search

system_logs.name = 'netlog' AND (REGEXP_CONTAINS(log_lines.content, "Process pending EAPOL") OR REGEXP_CONTAINS(log_lines.content, "Delay processing of received EAPOL frame")) AND "network_connection_failure" IN UNNEST(analyzer_tags)

And found out the latest feedback reports matching above query dated on 2023-02-13, which is 2 month early. While I can search the same error messages in feedback reports without connection_failure tag filed today in Xamine. So I think the sympotm I tried to address in comment#30 went away at some point.

By looking at the code, the message "Delay processing of received EAPOL frame" and "Process pending EAPOL" are two phases of one control flow, with the former creating queue for the latter to consume. In case of "Process pending EAPOL", the EAPOL is deliver before ASSOC however it's still within grace period (200ms) before ASSOC, which is accepted by wpa_supplicant. For EAPOL delivered more than 200ms before the ASSOC, wpa_supplicant doesn't consider it's valid for EAPOL flow. Generally speaking, "Process pending EAPOL" isn't an indicator of connection failure. In the opposite, it's a signal that wpa_supplicant is processing it in the expected path.

Regarding the FR filed 2 month ago with message "Process pending EAPOL" and a network_connection_failure FR tag, for example this one, the message was actually seen after the connection_failure. The root cause of connection failure is unclear to me from what I can see from the logs.

2023-02-10 13:34:11.666 5 wpa_supplicant[843]: BSSID [MAC OUI=10:06:ed IFACE=13] ignore list count incremented to 2, ignoring for 10 seconds
2023-02-10 13:34:11.667 6 shill[1045]: INFO shill: [wifi.cc(1162)] WiFi wlan0 supplicant updated DisconnectReason to 15 (4-Way Handshake timeout)
...
2023-02-10 13:34:12.424 7 wpa_supplicant[843]: wlan0: Process pending EAPOL frame that was received just before association notification
2023-02-10 13:34:12.424 7 wpa_supplicant[843]: wlan0: RX EAPOL from [MAC OUI=10:06:ed IFACE=2]

In conclusion: as of today, I found no evidence that "Process pending EAPOL" is related to the likelihood of connection failure. And since FR's don't see such message coincides with connection failure, my suggestion is to close this bug as obsolete.

PS: If FRA and Xamine can compare timestamp of logs with starting/ending time of FRA events, it will be helpful to do deeper analysis.

Can you instead directly right some FRA queries instead of using analyzer tags? I'm not convinced analyzer tags are giving you the best signal. The second report you linked in comment #30 looks like good signal, would you be able to grab similar reports?

This bug is 3 years old and it's unclear if there's meaningful impact. Unassigning and backlogging.