New PR on the way: mainly bugs, NRs and user messages

[Ian-Clowes]

I'm planning to have a new PR published over the weekend. Prior to me doing the final refactoring and tidy up I thought it'd be worth sharing what is in it in case I missed anything significant that can be addressed in time. Here's a summary of the notes for the overall PR, and what will become the commits witin it. Comments welcome.

Main Headlines

• Local Neighbor Report auto-generated for AP from current clients (works best in large network)
• Revise activity messages at basic and info levels to support user awareness and confidence in operation
• Added RRM capability info to hearing map to help understand how device should behave
• Streamline kicking algorithm to help ongoing evolution
• Address potential / actual bugs spotted by Coverity static analysis (thanks @Flole998)
• Resource mutex tracking to support code robustness
• Internal data structures simplified
• Continue to "flatten out" code to assist long term scalability
• Remove some unused parts of code (eg denied auth tracking)

Commits...

IEEE80211:

• Move some RRM utility functions around to simplify code structure / #includes

CLIENT_REQ:

• Remove the linked list of rejected auth / assoc as it was not used for any decision making
• Rename auth_req to client_req as it is also used by association requests

MAC:

• Simplify linked list search - code was unnecessarily complex for no benefit
• Adjust some MAC address handling to simplify code

AP:

• Simplify linked list search - code was unnecessarily complex for no benefit
• AP record is uniquely identified by BSSID, so remove unnecessary search on SSID as well
• Change some data handling to simplify passing of records, pointers, etc
• Assure sort order to simplify generating network map
• Removed unused fields for collision domain and bandwidth

PROBE / BEACON:

• New skipping linked list structure - possible bug in previous version
• Adjust some function names to better reflect what actually happens
• Remove redundant configurable sort elements
• Remove probe structure SSID field which is not set via BEACON, so is unreliable
• Adjust way the different fields from BEACON and PROBE reports are handled / merged
• Made client / BSSID paramater order consistent for probe / beacon functions to help avoid cut/ paste bugs
• Add RRM capability, RCPI and RSNI to client in hearing map (which is a summary of probe / beacon entries)

CLIENT:

• Simplify linked list search - code was unnecessarily complex for no benefit
• Refactored parse / kick logic to simplify functions

NETWORK:

• Merge encoded / plain messge handling to ensure fixes land in both
• Fix some potential resource leaks spotted by Coverity

MUTEX:

• Wrap mutex calls with traceable messages to help debugging resource locks

MAPS:

• Simplify loops and scans in generating hearing map

CLEANUP:

• Remove a few things that are no longer needed: #includes, etc

MSGS:

• Add messages that help users understand what PROBE and BEACON messages are being used

BUGS:

• Fix a couple of bugs in hardly ever (never?) used code paths that Coverity spotted
• Add comments for things that look a bit odd, but not sure if they are bugs

TESTS:

• Tighten up a bit of test path coding

MUTEX2:

• Add dawn_mutex_require() to indicate when code is accessing resources
• Use pthread_mutex_trylock() to actively test required mutex are locked

SCORING:

• Simplify how score is tracked
• Streamline some code paths for scoring evaluation

NEIGHBOR REPORT:

• Tweak disassociate / kick NR code to reduce build overhead
• Add set_hostapd_nrdynamic == 2 to build of AP local station NR from what current clients hear elsewhere
• Tighten up hex string length usage for strncpy(), etc

[Ian-Clowes]

I've pushed that to my fork: https://github.com/Ian-Clowes/DAWN

I've made vary minor typo type changes to what I'm currently running, but having been caught out by that before I won't open a PR until I've had the exact same code running for a few days. If others want to try it too in the meantime that'd be grand 😃.

[PolynomialDivision]

Wow! Awesome! Thanks a lot for your contributions. Sorry, I am so busy right now with other things.

[edrikk]

I've been running this build for a week now (actually on a Robimarko kernel 5.15 build) - it is working flawlessly.
In-fact the current set of changes in Ian-Clowes' git fixes my misbehaving IoT devices getting kicked repeatedly by DAWN if "kicking" is set to 1.
Will share this feedback once the PR is opened, but did want to share that here as well.
Great job!

[Ian-Clowes]

I'm pleased it is running well. I noticed a very slow memory leak from looking at the runtime memory auditing. I'll fix that plus a couple of other things on my mind and do the PR.

[Ian-Clowes]

A discussion on the OpenWrt forum led to a couple more changes, which delayed things, but have now pushed again to my fork. As ever I'm going to run that for a few days, and will then be happy to PR it.

Functional changes:

• New "soft" kick algorithm for 802.11v clients - always invite them to move within NR group if below absolute RSSI level (which is different to original algorithm which required them to share RSSI level with other APs)
• RSSI values handeld in slightly diffeent way to make them exposed more often (and RCPI, but they aren't really used)
• Refresh on parameters, including new default values that work well for me :). Also included sample config file.

@edrikk, if you're able to test that'd be great

[edrikk]

Perfect. Will do a build tonight and report back. :)

[edrikk]

@Ian-Clowes I have built and installed. My setup is:

Xiaomi AX3600 - Running Robimarko's latest build - Kernel 5.15. This is an AX Device.
3 Other AC only AP devices.

I can only build from code for the Xiaomi AX3600, so the other devices are all running 21.02 (latest DAWN versions in 21.02 snapshot).

I did a reset of all the configs given your config updates. The only adjustment I made was set kicking mode to 1 on the AC devices, since they are running the version of DAWN that doesn't support the new default mode 3. The AX router is set to kicking=3.

Everything appears to be working at first glance.

Only thing I've noticed is that on the AX device, the system log shows repeating:

Thu Feb 17 22:11:31 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.
Thu Feb 17 22:11:31 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.
Thu Feb 17 22:11:31 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.
Thu Feb 17 22:11:31 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.
Thu Feb 17 22:11:31 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.
Thu Feb 17 22:11:31 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.
Thu Feb 17 22:11:31 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.
Thu Feb 17 22:11:31 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.

I don't remember seeing this before, but in all honesty, maybe my log level wasn't set to show warnings.

EDIT: By resetting config I mean by running
ubus call dawn reload_config

[Ian-Clowes]

frequency 3014664 is beyond the last known band

I suspect I know what that is, and it'll be new. If I have it right it'll be harmless for all normal configurations.

[Ian-Clowes]

@edrikk, you can try this patch to see if it gets rid of that...

diff --git a/src/storage/datastorage.c b/src/storage/datastorage.c
index b847d42..5d08577 100644
--- a/src/storage/datastorage.c
+++ b/src/storage/datastorage.c
@@ -822,6 +822,18 @@ probe_entry* probe_array_update_rssi(struct dawn_mac client_addr, struct dawn_ma
 {
     dawnlog_debug_func("Entering...");

+    int freq = 0;
+
+    dawn_mutex_lock(&ap_array_mutex);
+    dawn_mutex_require(&ap_array_mutex);
+
+    ap *this_ap = ap_array_get_ap(bssid_addr);
+
+    if (this_ap)
+        freq = this_ap->freq;
+
+    dawn_mutex_unlock(&ap_array_mutex);
+
     dawn_mutex_require(&probe_array_mutex);
     probe_entry* probe_req_new = dawn_malloc(sizeof(probe_entry));
     probe_entry* probe_req_updated = NULL;
@@ -831,6 +843,7 @@ probe_entry* probe_array_update_rssi(struct dawn_mac client_addr, struct dawn_ma
         probe_req_new->client_addr = client_addr;
         probe_req_new->bssid_addr = bssid_addr;
         probe_req_new->signal = rssi;
+        probe_req_new->freq = freq;

         // Other fields in case entry is new
         probe_req_new->ht_capabilities = false;

[edrikk]

Ok will do. Likely will be a couple of days until I can report back though.

It looks like a mutex lock you've added as well, which may be related to what I came to post. Seeing a lot of the below in syslog.
The ratio of "42A7E8" to "42A790" is probably close to 10 to 1. These are the only two I see though.

Fri Feb 18 14:02:09 2022 daemon.warn dawn: MUTEX require = 42A7E8@datastorage.c:120[2514967648l] - appears to be UNLOCKED!
Fri Feb 18 14:02:09 2022 daemon.warn dawn: MUTEX require = 42A7E8@ubus.c:2034[2514967648l] - appears to be UNLOCKED!
Fri Feb 18 14:02:09 2022 daemon.warn dawn: MUTEX require = 42A7E8@datastorage.c:120[2514967648l] - appears to be UNLOCKED!
Fri Feb 18 14:02:10 2022 daemon.warn dawn: MUTEX require = 42A790@ubus.c:1991[2514967648l] - appears to be UNLOCKED!

I don't believe I see any combinations other than:

42A7E8@datastorage.c:120
42A7E8@ubus.c:2034
42A790@ubus.c:1991

[Ian-Clowes]

It looks like a mutex lock you've added as well, which may be related to what I came to post.

Thanks. As far as I can see thay are all related to using ubus call dawn get_network, which had slipped out of my manual test cases.

This should fix it:

diff --git a/src/utils/ubus.c b/src/utils/ubus.c
index 8c6c2e9..c7eb641 100644
--- a/src/utils/ubus.c
+++ b/src/utils/ubus.c
@@ -1489,7 +1489,15 @@ static int get_network(struct ubus_context *ctx_local, struct ubus_object *obj,

     blob_buf_init(&b, 0);
     dawn_regmem(&b);
+
+    dawn_mutex_lock(&ap_array_mutex);
+    dawn_mutex_lock(&client_array_mutex);
+
     build_network_overview(&b);
+
+    dawn_mutex_unlock(&client_array_mutex);
+    dawn_mutex_unlock(&ap_array_mutex);
+
     ret = ubus_send_reply(ctx_local, req, b.head);
     if (ret)
         dawnlog_error("Failed to send network overview: %s\n", ubus_strerror(ret));

[edrikk]

Hi @Ian-Clowes

Compiled and has been running overnight.
The mutex unlocked issue is gone.

Although the number of the occurrences seems to be lower, there are still several frequency is beyond last known band messages.

Sun Feb 20 08:24:22 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.
Sun Feb 20 08:24:32 2022 daemon.warn dawn: frequency 3014664 is beyond the last known band. Using '802_11a' band parameters.

Will bump up logging verbosity in case you need more info.

[elmr91]

Hi @Ian-Clowes,

I have a very a similar setup to Edrikk's one:

• 3 dumb AP on same subnet with 802.11r (same SSID/password) on 2.4 Ghz and 5 Ghz
  2 AP are running dawn from 21.02.02 repo.
  Third one is running 21.02.02 + your dawn version (archer c7v2 with wpad-wolfssl / option kicking=3)

I had the same errors:

Sun Feb 20 16:39:31 2022 daemon.warn dawn: frequency 1645370357 is beyond the last known band. Using '802_11a' band parameters.
Sun Feb 20 16:39:31 2022 daemon.warn dawn: frequency 1645370357 is beyond the last known band. Using '802_11a' band parameters.
Sun Feb 20 16:39:41 2022 daemon.warn dawn: frequency 1645370357 is beyond the last known band. Using '802_11a' band parameters.

So I applied fix you suggested (in addition to the mutex fix).
It fixed the problem.

Edit: still some occurrence (but far less)

Sun Feb 20 18:01:21 2022 daemon.warn dawn[10911]: frequency 1645370357 is beyond the last known band. Using '802_11a' band parameters.
Sun Feb 20 18:01:31 2022 daemon.warn dawn[10911]: frequency 1645370357 is beyond the last known band. Using '802_11a' band parameters.

I have another problem :
It seems kicking is not always effective:

I have seen dawn trying to kick a device (3/3 kicking message repeatedly).
kicking counter increased in logs, but device remains connected.
(I'll try to reproduce and provide logs for this case / I didn't save logs)

I have another device with low RSSI (-80 db):
Dawn logs multiple messages:

Sun Feb 20 16:52:00 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000
Sun Feb 20 16:53:01 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000
Sun Feb 20 16:53:24 2022 daemon.notice hostapd: wlan1: BEACON-REQ-TX-STATUS 04:b1:67:27:ba:0a 87 ack=0
Sun Feb 20 16:53:42 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000
Sun Feb 20 16:54:12 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000
Sun Feb 20 16:54:53 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000
Sun Feb 20 16:55:23 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000

No deauthenticate message in the logs....

Clients disconnects by itself (inactivity) few minutes later

Sun Feb 20 17:05:52 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000
Sun Feb 20 17:06:22 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000
Sun Feb 20 17:06:53 2022 daemon.info dawn: Client 04:B1:67:27:BA:0A: Kicking as probably NOT in active transmission. RxRate is: 6.000000
Sun Feb 20 17:06:59 2022 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 04:b1:67:27:ba:0a
Sun Feb 20 17:06:59 2022 daemon.info hostapd: wlan1: STA 04:b1:67:27:ba:0a IEEE 802.11: disassociated due to inactivity
Sun Feb 20 17:07:00 2022 daemon.info hostapd: wlan1: STA 04:b1:67:27:ba:0a IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

May be I missed something.
Is there something to configure in addition to kicking=3 in config file ?

[elmr91]

It may be worth downgrading log level for the "No station connected" message.
It is currently set to warning : dawnlog_warning("No station connected\n");
It may be lowered to info level.
When a SSID is empty (guest SSID for example), logs are filled with "No station connected" message even when running with minimal log level.