treewide: improve mutex handling

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

[cleanup commit message]
Signed-off-by: Nick Hainke <vincent@systemli.org>

src/include/utils.h

@@ -104,16 +104,27 @@ const char* dawnlog_basename(const char* file);
 /**
  ** Wrap mutex operations to help track down mis-matches
  */
+#if DAWNLOG_COMPILING(DAWNLOG_DEBUG)
 #define DAWN_MUTEX_WRAP
+#endif
 
-#ifndef DAWN_MUTEX_WRAP
+#ifdef DAWN_MUTEX_WRAP
-#define dawn_mutex_lock(m) pthread_mutex_lock(m)
+ // Log that a mutex managed resource is being accessed so that messages can be scrutinised for bugs
-#define dawn_mutex_unlock(m) pthread_mutex_unlock(m)
+ // Place these liberally near any code that accesses or retains a pointer to resources that could go away
-#else
+#define dawn_mutex_require(m) _dawn_mutex_require(m, __FILE__, __LINE__)
+void _dawn_mutex_require(pthread_mutex_t* m, char* f, int l);
+
+// Log that a mutex managed resource is being locked so that messages can be scrutinised for bugs
 #define dawn_mutex_lock(m) _dawn_mutex_lock(m, __FILE__, __LINE__)
 int _dawn_mutex_lock(pthread_mutex_t* m, char* f, int l);
 
+// Log that a mutex managed resource is being unlocked so that messages can be scrutinised for bugs
 #define dawn_mutex_unlock(m) _dawn_mutex_unlock(m, __FILE__, __LINE__)
 int _dawn_mutex_unlock(pthread_mutex_t* m, char* f, int l);
+#else
+#define dawn_mutex_require(m)
+#define dawn_mutex_lock(m) pthread_mutex_lock(m)
+#define dawn_mutex_unlock(m) pthread_mutex_unlock(m)
+#endif
+
 #endif
-#endif

src/storage/datastorage.c

@@ -49,6 +49,7 @@ struct client_s* client_set_bc = NULL; // Ordered by BSSID + client MAC
 pthread_mutex_t client_array_mutex;
 
 // TODO: How big does this get?
+// TODO: No mutex on this - is it required?
 struct mac_entry_s* mac_set = NULL;
 int mac_set_last = 0;
 
@@ -70,6 +71,7 @@ probe_entry* probe_array_find_first_entry(struct dawn_mac client_mac, struct daw
 {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_require(&probe_array_mutex);
     struct probe_entry_s* curr_node = probe_set.first_probe;
     struct probe_entry_s* curr_skip = probe_set.first_probe_skip;
 
@@ -115,6 +117,7 @@ client** client_find_first_bc_entry(struct dawn_mac bssid_mac, struct dawn_mac c
 {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_require(&client_array_mutex);
     client** ret = &client_set_bc;
 
     while ((*ret != NULL))
@@ -160,6 +163,7 @@ struct mac_entry_s* mac_find_entry(struct dawn_mac mac)
 }
 
 void send_beacon_requests(ap *a, int id) {
+    dawn_mutex_require(&ap_array_mutex);
     dawn_mutex_lock(&client_array_mutex);
 
     dawnlog_debug_func("Entering...");
@@ -202,6 +206,9 @@ int get_band(int freq) {
 // TODO: Can metric be cached once calculated? Add score_fresh indicator and reset when signal changes
 // TODO: as rest of values look to be static fr any given entry.
 int eval_probe_metric(struct probe_entry_s* probe_entry, ap* ap_entry) {
+    dawnlog_debug_func("Entering...");
+    dawn_mutex_require(&ap_array_mutex);
+    dawn_mutex_require(&probe_array_mutex);
 
     int band, score = 0;
 
@@ -245,13 +252,17 @@ static int compare_station_count(ap* ap_entry_own, ap* ap_entry_to_compare, stru
 
     dawnlog_info("Comparing own %d to %d\n", ap_entry_own->station_count, ap_entry_to_compare->station_count);
 
+    dawn_mutex_require(&ap_array_mutex);
     int sta_count = ap_entry_own->station_count;
     int sta_count_to_compare = ap_entry_to_compare->station_count;
+
+    dawn_mutex_require(&client_array_mutex);
     if (client_array_get_client_for_bssid(ap_entry_own->bssid_addr, client_addr)) {
         dawnlog_debug("Own is already connected! Decrease counter!\n");
         sta_count--;
     }
 
+    dawn_mutex_require(&client_array_mutex);
     if (client_array_get_client_for_bssid(ap_entry_to_compare->bssid_addr, client_addr)) {
         dawnlog_debug("Comparing station is already connected! Decrease counter!\n");
         sta_count_to_compare--;
@@ -331,8 +342,11 @@ static struct kicking_nr *insert_kicking_nr(struct kicking_nr *head, char *nr, i
 int better_ap_available(ap *kicking_ap, struct dawn_mac client_mac, struct kicking_nr **neighbor_report) {
 
     dawnlog_debug_func("Entering...");
+    dawn_mutex_require(&ap_array_mutex);
+    dawn_mutex_require(&probe_array_mutex);
 
     // This remains set to the current AP of client for rest of function
+    dawn_mutex_require(&probe_array_mutex);
     probe_entry* own_probe = probe_array_get_entry(client_mac, kicking_ap->bssid_addr);
     int own_score = -1;
     if (own_probe != NULL) {
@@ -348,9 +362,12 @@ int better_ap_available(ap *kicking_ap, struct dawn_mac client_mac, struct kicki
     }
 
     int max_score = own_score;
+    dawn_mutex_require(&ap_array_mutex);
+    dawn_mutex_require(&probe_array_mutex);
     int kick = 0;
     int ap_count = 0;
     // Now go through all probe entries for this client looking for better score
+    dawn_mutex_require(&probe_array_mutex);
     probe_entry* i = probe_array_find_first_entry(client_mac, dawn_mac_null, false);
 
     while (i != NULL && mac_is_equal_bb(i->client_addr, client_mac)) {
@@ -360,6 +377,7 @@ int better_ap_available(ap *kicking_ap, struct dawn_mac client_mac, struct kicki
             continue;
         }
 
+        dawn_mutex_require(&ap_array_mutex);
         ap* candidate_ap = ap_array_get_ap(i->bssid_addr);
 
         if (candidate_ap == NULL) {
@@ -444,10 +462,12 @@ int better_ap_available(ap *kicking_ap, struct dawn_mac client_mac, struct kicki
 int kick_clients(struct dawn_mac bssid_mac, uint32_t id) {
     dawnlog_debug_func("Entering...");
 
-    ap* kicking_ap = ap_array_get_ap(bssid_mac);
-
     dawn_mutex_lock(&client_array_mutex);
     dawn_mutex_lock(&probe_array_mutex);
+    dawn_mutex_lock(&ap_array_mutex);
+
+    dawn_mutex_require(&ap_array_mutex);
+    ap* kicking_ap = ap_array_get_ap(bssid_mac);
 
     int kicked_clients = 0;
 
@@ -560,6 +580,7 @@ int kick_clients(struct dawn_mac bssid_mac, uint32_t id) {
 
     dawnlog_trace("KICKING: --------- AP Finished ---------\n");
 
+    dawn_mutex_unlock(&ap_array_mutex);
     dawn_mutex_unlock(&probe_array_mutex);
     dawn_mutex_unlock(&client_array_mutex);
 
@@ -602,6 +623,7 @@ client *client_array_get_client(const struct dawn_mac client_addr)
 {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_require(&client_array_mutex);
     client* ret = client_set_bc;
     while (ret != NULL && !mac_is_equal_bb(client_addr, ret->client_addr))
     {
@@ -637,6 +659,7 @@ client* client_array_delete_bc(struct dawn_mac bssid_mac, struct dawn_mac client
     client* ret = NULL;
     client** client_entry = client_find_first_bc_entry(bssid_mac, client_mac, true);
 
+    dawn_mutex_require(&client_array_mutex);
     if (*client_entry && mac_is_equal_bb(bssid_mac, (*client_entry)->bssid_addr) && mac_is_equal_bb(client_mac, (*client_entry)->client_addr))
         ret = client_array_unlink_entry(client_entry, false);
 
@@ -650,6 +673,7 @@ client* client_array_delete(client* entry, int unlink_only) {
     client** ref_bc = NULL;
 
     // Bodyless for-loop: test done in control logic
+    dawn_mutex_require(&client_array_mutex);
     for (ref_bc = &client_set_bc; (*ref_bc != NULL) && (*ref_bc != entry); ref_bc = &((*ref_bc)->next_entry_bc));
 
     // Should never fail, but better to be safe...
@@ -661,6 +685,7 @@ client* client_array_delete(client* entry, int unlink_only) {
 
 int probe_array_delete(struct dawn_mac client_mac, struct dawn_mac bssid_mac) {
     int found_in_array = false;
+    dawn_mutex_require(&probe_array_mutex);
     struct probe_entry_s** node_ref = &probe_set.first_probe;
     struct probe_entry_s** skip_ref = &probe_set.first_probe_skip;
 
@@ -722,6 +747,7 @@ int probe_array_set_all_probe_count(struct dawn_mac client_addr, uint32_t probe_
 
     // MUSTDO: Has some code been lost here?  updated never set... Certain to hit not found...
     dawn_mutex_lock(&probe_array_mutex);
+    dawn_mutex_require(&probe_array_mutex);
     for (probe_entry *i = probe_array_find_first_entry(client_addr, dawn_mac_null, false);
             i != NULL && mac_is_equal_bb(client_addr, i->client_addr); 
             i = i->next_probe) {
@@ -737,6 +763,7 @@ probe_entry* probe_array_update_rssi(struct dawn_mac client_addr, struct dawn_ma
 {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_require(&probe_array_mutex);
     probe_entry* entry = probe_array_get_entry(client_addr, bssid_addr);
 
     if (entry) {
@@ -753,6 +780,7 @@ probe_entry* probe_array_update_rcpi_rsni(struct dawn_mac client_addr, struct da
 {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_require(&probe_array_mutex);
     probe_entry* entry = probe_array_get_entry(client_addr, bssid_addr);
 
     if (entry) {
@@ -773,6 +801,7 @@ probe_entry* probe_array_update_rcpi_rsni(struct dawn_mac client_addr, struct da
 probe_entry *probe_array_get_entry(struct dawn_mac client_mac, struct dawn_mac bssid_mac) {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_require(&probe_array_mutex);
     probe_entry* ret = probe_array_find_first_entry(client_mac, bssid_mac, true);
 
     return ret;
@@ -783,6 +812,7 @@ void print_probe_array() {
     {
         dawnlog_debug("------------------\n");
         // dawnlog_debug("Probe Entry Last: %d\n", probe_entry_last);
+        dawn_mutex_require(&probe_array_mutex);
         for (probe_entry* i = probe_set.first_probe; i != NULL; i = i->next_probe) {
             print_probe_entry(DAWNLOG_DEBUG, i);
         }
@@ -793,8 +823,7 @@ void print_probe_array() {
 probe_entry* insert_to_probe_array(probe_entry* entry, int is_local, int save_80211k, int is_beacon, time_t expiry) {
     dawnlog_debug_func("Entering...");
 
-    dawn_mutex_lock(&probe_array_mutex);
+    dawn_mutex_require(&probe_array_mutex);
-
     struct probe_entry_s** node_ref = &probe_set.first_probe;
     struct probe_entry_s** skip_ref = &probe_set.first_probe_skip;
 
@@ -883,8 +912,6 @@ probe_entry* insert_to_probe_array(probe_entry* entry, int is_local, int save_80
         entry->time = expiry;
     }
 
-    dawn_mutex_unlock(&probe_array_mutex);
-
     return entry;  // return pointer to what we used, which may not be what was passed in
 }
 
@@ -902,6 +929,7 @@ static ap* ap_array_update_entry(ap* entry) {
     dawnlog_debug_func("Entering...");
 
     ap* old_entry = NULL;
+    dawn_mutex_require(&ap_array_mutex);
     ap** i = &ap_set;
     while (*i != NULL && mac_compare_bb(entry->bssid_addr, (*i)->bssid_addr) != 0) {
         i = &((*i)->next_ap);
@@ -954,14 +982,16 @@ ap *insert_to_ap_array(ap* entry, time_t expiry) {
     entry->time = expiry;
 
     dawn_mutex_lock(&ap_array_mutex);
-    ap* old_entry = ap_array_update_entry(entry);
-    dawn_mutex_unlock(&ap_array_mutex);
 
+    dawn_mutex_require(&ap_array_mutex);
+    ap* old_entry = ap_array_update_entry(entry);
     if (old_entry)
         dawn_free(old_entry);
 
     print_ap_array();
 
+    dawn_mutex_unlock(&ap_array_mutex);
+
     return entry;
 }
 
@@ -970,6 +1000,7 @@ ap *insert_to_ap_array(ap* entry, time_t expiry) {
  void ap_array_insert(ap* entry) {
     dawnlog_debug_func("Entering...");;
 
+    dawn_mutex_require(&ap_array_mutex);
     ap** insert_pos = &ap_set;
 
     while (*insert_pos != NULL)
@@ -996,16 +1027,13 @@ ap* ap_array_get_ap(struct dawn_mac bssid_mac) {
 
     dawnlog_debug_func("Entering...");;
 
-    dawn_mutex_lock(&ap_array_mutex);
+    dawn_mutex_require(&ap_array_mutex);
-
     ap* ret = ap_set;
 
     while (ret && mac_compare_bb(bssid_mac, ret->bssid_addr) != 0) {
         ret = ret->next_ap;
     }
 
-    dawn_mutex_unlock(&ap_array_mutex);
-
     return ret;
 }
 
@@ -1014,6 +1042,7 @@ int ap_array_delete(ap* entry) {
 
     dawnlog_debug_func("Entering...");;
 
+    dawn_mutex_require(&ap_array_mutex);
     ap** i = &ap_set;
     while (*i != NULL) {
         if (*i == entry) {
@@ -1031,6 +1060,7 @@ int ap_array_delete(ap* entry) {
 void remove_old_client_entries(time_t current_time, long long int threshold) {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_require(&client_array_mutex);
     client **i = &client_set_bc;
     while (*i  != NULL) {
         if ((*i)->time < current_time - threshold) {
@@ -1045,9 +1075,12 @@ void remove_old_client_entries(time_t current_time, long long int threshold) {
 void remove_old_probe_entries(time_t current_time, long long int threshold) {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_require(&probe_array_mutex);
     probe_entry** i = &(probe_set.first_probe);
     probe_entry** s = &(probe_set.first_probe_skip);
 
+    dawn_mutex_lock(&client_array_mutex);
+
     while (*i != NULL ) {
         if (((*i)->time < current_time - threshold) && !client_array_get_client_for_bssid((*i)->bssid_addr, (*i)->client_addr)) {
             probe_entry* victim = *i;
@@ -1071,9 +1104,12 @@ void remove_old_probe_entries(time_t current_time, long long int threshold) {
             i = &((*i)->next_probe);
         }
     }
+
+    dawn_mutex_unlock(&client_array_mutex);
 }
 
 void remove_old_ap_entries(time_t current_time, long long int threshold) {
+    dawn_mutex_require(&ap_array_mutex);
     ap **i = &ap_set;
     while (*i != NULL) {
         if (((*i)->time) < (current_time - threshold)) {
@@ -1087,6 +1123,7 @@ void remove_old_ap_entries(time_t current_time, long long int threshold) {
 
 client* client_array_update_entry(client* entry, time_t expiry) {
     dawnlog_debug_func("Entering...");
+    dawn_mutex_require(&client_array_mutex);
 
     client* old_entry = NULL;
     client** entry_pos = client_find_first_bc_entry(entry->bssid_addr, entry->client_addr, true);
@@ -1118,9 +1155,10 @@ client* client_array_update_entry(client* entry, time_t expiry) {
 }
 
 client *insert_client_to_array(client *entry, time_t expiry) {
-client * ret = NULL;
-
     dawnlog_debug_func("Entering...");
+    dawn_mutex_require(&client_array_mutex);
+
+    client * ret = NULL;
 
     client **client_tmp = client_find_first_bc_entry(entry->bssid_addr, entry->client_addr, true);
 
@@ -1230,6 +1268,7 @@ struct mac_entry_s *insert_to_maclist(struct dawn_mac mac) {
 }
 
 void print_probe_entry(int level, probe_entry *entry) {
+    dawn_mutex_require(&probe_array_mutex);
     if (dawnlog_showing(level))
     {
         dawnlog(level,
@@ -1251,6 +1290,7 @@ void print_client_req_entry(int level, client_req_entry *entry) {
 }
 
 void print_client_entry(int level, client *entry) {
+    dawn_mutex_require(&client_array_mutex);
     if (dawnlog_showing(level))
     {
         dawnlog(level, "bssid_addr: " MACSTR ", client_addr: " MACSTR ", freq: %d, ht_supported: %d, vht_supported: %d, ht: %d, vht: %d, kick: %d\n",
@@ -1264,6 +1304,7 @@ void print_client_array() {
     {
         dawnlog_debug("--------Clients------\n");
         //dawnlog_debug("Client Entry Last: %d\n", client_entry_last);
+        dawn_mutex_require(&client_array_mutex);
         for (client* i = client_set_bc; i != NULL; i = i->next_entry_bc) {
             print_client_entry(DAWNLOG_DEBUG, i);
         }
@@ -1272,6 +1313,7 @@ void print_client_array() {
 }
 
 static void print_ap_entry(int level, ap *entry) {
+    dawn_mutex_require(&ap_array_mutex);
     if (dawnlog_showing(DAWNLOG_INFO))
     {
         dawnlog_info("ssid: %s, bssid_addr: " MACSTR ", freq: %d, ht: %d, vht: %d, chan_utilz: %d, neighbor_report: %s\n",
@@ -1286,6 +1328,7 @@ void print_ap_array() {
     if (dawnlog_showing(DAWNLOG_DEBUG))
     {
         dawnlog_debug("--------APs------\n");
+        dawn_mutex_require(&ap_array_mutex);
         for (ap* i = ap_set; i != NULL; i = i->next_ap) {
             print_ap_entry(DAWNLOG_DEBUG, i);
         }

src/test/test_storage.c

@@ -11,6 +11,18 @@
 #include "test_storage.h"
 
 /*** Test Stub Functions - Called by SUT ***/
+
+// It is an accident of Uni* / C history that the below is not stubbed in libc...
+int pthread_mutex_trylock(pthread_mutex_t* m)
+{
+    return EBUSY;  // Tell SUT that it was locked, so no errors, warnings, etc
+}
+
+void ubus_set_nr_from_clients(struct kicking_nr* ap_list) {
+    printf("ubus_set_nr_from_clients() was called...\n");
+}
+
+
 void ubus_send_beacon_request(client *c, ap *a, int id)
 {
     printf("ubus_send_beacon_request() was called...\n");

src/utils/msghandler.c

@@ -298,10 +298,13 @@ int handle_network_msg(char* msg) {
     if (strncmp(method, "probe", 5) == 0) {
         probe_entry *entry = parse_to_probe_req(data_buf.head);
         if (entry != NULL) {
+            dawn_mutex_lock(&probe_array_mutex);
+
+            dawn_mutex_require(&probe_array_mutex);
             if (entry != insert_to_probe_array(entry, false, true, false, time(0))) // use 802.11k values
             {
                 dawnlog_info("Remote PROBE updated client / BSSID = " MACSTR " / " MACSTR " \n",
-		        MAC2STR(entry->client_addr.u8), MAC2STR(entry->bssid_addr.u8));
+                        MAC2STR(entry->client_addr.u8), MAC2STR(entry->bssid_addr.u8));
 
                 // insert found an existing entry, rather than linking in our new one
                 dawn_free(entry);
@@ -310,8 +313,10 @@ int handle_network_msg(char* msg) {
             else
             {
                 dawnlog_info("Remote PROBE is for new client / BSSID = " MACSTR " / " MACSTR " \n",
-		        MAC2STR(entry->client_addr.u8), MAC2STR(entry->bssid_addr.u8));
+                        MAC2STR(entry->client_addr.u8), MAC2STR(entry->bssid_addr.u8));
             }
+
+            dawn_mutex_unlock(&probe_array_mutex);
         }
     }
     else if (strncmp(method, "clients", 5) == 0) {

src/utils/ubus.c

@@ -286,6 +286,9 @@ static probe_entry* parse_to_beacon_rep(struct blob_attr *msg) {
     }
     else
     {
+        dawn_mutex_lock(&ap_array_mutex);
+
+        dawn_mutex_require(&ap_array_mutex);
         ap* ap_entry_rep = ap_array_get_ap(msg_bssid);
 
         // no client from network!!
@@ -317,6 +320,8 @@ static probe_entry* parse_to_beacon_rep(struct blob_attr *msg) {
                 beacon_rep->vht_capabilities = false; // that is very problematic!!!
             }
         }
+
+        dawn_mutex_unlock(&ap_array_mutex);
     }
 
     return beacon_rep;
@@ -354,7 +359,7 @@ bool discard_entry = true;
 
         probe_entry *tmp = probe_array_get_entry(auth_req->client_addr, auth_req->bssid_addr);
 
-        dawn_mutex_unlock(&probe_array_mutex);
+            dawn_mutex_require(&probe_array_mutex);
 
         /*** Deprecated function decide_function() removed here ***/
         int deny_request = 0;
@@ -370,7 +375,9 @@ bool discard_entry = true;
         }
         else
         {
-            // find own probe entry and calculate score
+            dawn_mutex_lock(&ap_array_mutex);
+
+                dawn_mutex_require(&ap_array_mutex);
             ap* this_ap = ap_array_get_ap(tmp->bssid_addr);
             if (this_ap != NULL && better_ap_available(this_ap, tmp->client_addr, NULL) > 0) {
                 dawnlog_trace(MACSTR " Deny authentication due to better AP available", MAC2STR(auth_req->client_addr.u8));
@@ -379,12 +386,16 @@ bool discard_entry = true;
             else
                 // maybe send here that the client is connected?
                 dawnlog_trace(MACSTR " Allow authentication!\n", MAC2STR(auth_req->client_addr.u8));
+
+            dawn_mutex_unlock(&ap_array_mutex);
         }
         /*** End of decide_function() rework ***/
 
         if (deny_request) {
             ret = dawn_metric.deny_auth_reason;
         }
+
+        dawn_mutex_unlock(&probe_array_mutex);
     }
 
     if (discard_entry)
@@ -426,7 +437,7 @@ int discard_entry = true;
 
         probe_entry *tmp = probe_array_get_entry(assoc_req->client_addr, assoc_req->bssid_addr);
 
-        dawn_mutex_unlock(&probe_array_mutex);
+            dawn_mutex_require(&probe_array_mutex);
 
         /*** Deprecated function decide_function() removed here ***/
         int deny_request = 0;
@@ -443,6 +454,9 @@ int discard_entry = true;
         else
         {
             // find own probe entry and calculate score
+            dawn_mutex_lock(&ap_array_mutex);
+
+                dawn_mutex_require(&ap_array_mutex);
             ap* this_ap = ap_array_get_ap(assoc_req->bssid_addr);
             if (this_ap != NULL && better_ap_available(this_ap, assoc_req->client_addr, NULL) > 0) {
                 dawnlog_trace(MACSTR " Deny association due to better AP available", MAC2STR(assoc_req->client_addr.u8));
@@ -451,6 +465,7 @@ int discard_entry = true;
             else { // TODO: Should we reset probe counter to zero here?  Does active client do probe and if so what would a deny lead to?
                 dawnlog_trace(MACSTR " Allow association!\n", MAC2STR(assoc_req->client_addr.u8));
             }
+            dawn_mutex_unlock(&ap_array_mutex);
         }
         /*** End of decide_function() rework ***/
 
@@ -460,6 +475,8 @@ int discard_entry = true;
 
             ret = dawn_metric.deny_assoc_reason;
         }
+
+        dawn_mutex_unlock(&probe_array_mutex);
     }
 
     if (discard_entry)
@@ -484,6 +501,9 @@ static int handle_probe_req(struct blob_attr* msg) {
     }
     else
     {
+        dawn_mutex_lock(&probe_array_mutex);
+
+        dawn_mutex_require(&probe_array_mutex);
         probe_entry* probe_req_updated = insert_to_probe_array(probe_req, true, true, false, time(0));
         // If insert finds an existing entry, rather than linking in our new one,
         // send new probe req because we want to stay synced.
@@ -518,6 +538,9 @@ static int handle_probe_req(struct blob_attr* msg) {
         else
         {
             // find own probe entry and calculate score
+            dawn_mutex_lock(&ap_array_mutex);
+
+            dawn_mutex_require(&ap_array_mutex);
             ap* this_ap = ap_array_get_ap(probe_req_updated->bssid_addr);
             if (this_ap != NULL && better_ap_available(this_ap, probe_req_updated->client_addr, NULL) > 0) {
                 dawnlog_trace(MACSTR " Deny probe due to better AP available", MAC2STR(probe_req_updated->client_addr.u8));
@@ -527,12 +550,14 @@ static int handle_probe_req(struct blob_attr* msg) {
             {
                 dawnlog_trace(MACSTR " Allow probe request!", MAC2STR(probe_req_updated->client_addr.u8));
             }
+
+            dawn_mutex_unlock(&ap_array_mutex);
         }
         /*** End of decide_function() rework ***/
-
         if (deny_request) {
             return WLAN_STATUS_AP_UNABLE_TO_HANDLE_NEW_STA; // no reason needed...
         }
+        dawn_mutex_unlock(&probe_array_mutex);
     }
 
     // TODO: Return for dawn_malloc() failure?
@@ -557,10 +582,9 @@ static int handle_beacon_rep(struct blob_attr *msg) {
             // Update RxxI of current entry if it exists
             dawn_mutex_lock(&probe_array_mutex);
 
+            dawn_mutex_require(&probe_array_mutex);
             probe_entry* entry_updated = probe_array_update_rcpi_rsni(entry->client_addr, entry->bssid_addr, entry->rcpi, entry->rsni, true);
 
-            dawn_mutex_unlock(&probe_array_mutex);
-
             if (entry_updated)
             {
                 dawnlog_info("Local BEACON used to update RCPI and RSNI for client / BSSID = " MACSTR " / " MACSTR " \n", MAC2STR(entry->client_addr.u8), MAC2STR(entry->bssid_addr.u8));
@@ -571,12 +595,14 @@ static int handle_beacon_rep(struct blob_attr *msg) {
                 dawnlog_info("Local BEACON is for new client / BSSID = " MACSTR " / " MACSTR " \n", MAC2STR(entry->client_addr.u8), MAC2STR(entry->bssid_addr.u8));
 
                 // BEACON will never set RSSI, but may have RCPI and RSNI
+                dawn_mutex_require(&probe_array_mutex);
                 entry = insert_to_probe_array(entry, false, false, true, time(0));
-
                 ubus_send_probe_via_network(entry);
 
                 ret = 0;
             }
+
+            dawn_mutex_unlock(&probe_array_mutex);
         }
     }
 
@@ -744,11 +770,16 @@ static int get_band_from_bssid(struct dawn_mac bssid) {
 int ret = -1;
 
     dawnlog_debug_func("Entering...");
+    dawn_mutex_lock(&ap_array_mutex);
+
+    dawn_mutex_require(&ap_array_mutex);
     ap* a = ap_array_get_ap(bssid);
 
     if (a)
         ret = get_band(a->freq);
 
+    dawn_mutex_unlock(&ap_array_mutex);
+
     return ret;
 }
 
@@ -813,8 +844,13 @@ static void ubus_get_clients_cb(struct ubus_request *req, int type, struct blob_
 
     parse_to_clients(b.head);
 
+    dawn_mutex_lock(&client_array_mutex);
     print_client_array();
+    dawn_mutex_unlock(&client_array_mutex);
+
+    dawn_mutex_lock(&ap_array_mutex);
     print_ap_array();
+    dawn_mutex_unlock(&ap_array_mutex);
 
     dawn_free(data_str);
     data_str = NULL;
@@ -965,6 +1001,7 @@ static int get_mode_from_capability(int capability) {
 
 void ubus_send_beacon_request(client *c, ap *a, int id)
 {
+    dawn_mutex_require(&ap_array_mutex);
     struct blob_buf b = {0};
     dawnlog_debug_func("Entering...");
 
@@ -999,10 +1036,15 @@ void update_beacon_reports(struct uloop_timeout *t) {
     struct hostapd_sock_entry *sub;
     list_for_each_entry(sub, &hostapd_sock_list, list)
     {
+        dawn_mutex_lock(&ap_array_mutex);
+
+        dawn_mutex_require(&ap_array_mutex);
         if (sub->subscribed && (a = ap_array_get_ap(sub->bssid_addr))) {
             dawnlog_debug("Sending beacon request Sub!\n");
             send_beacon_requests(a, sub->id);
         }
+
+        dawn_mutex_unlock(&ap_array_mutex);
     }
     uloop_timeout_set(&beacon_reports_timer, timeout_config.update_beacon_reports * 1000);
 }
@@ -1752,16 +1794,19 @@ static void blobmsg_add_rrm_string(struct blob_buf* b, char* n, uint8_t caps)
 int build_hearing_map_sort_client(struct blob_buf *b) {
     dawnlog_debug_func("Entering...");
 
+    dawn_mutex_lock(&probe_array_mutex);
+    dawn_mutex_lock(&ap_array_mutex);
+
     if (dawnlog_showing(DAWNLOG_DEBUG))
         print_probe_array();
 
-    dawn_mutex_lock(&probe_array_mutex);
-
     // Build a linked list of probe entried in correct order for hearing map
     struct probe_sort_entry *hearing_list = NULL;
+    dawn_mutex_require(&probe_array_mutex);
     probe_entry* i = probe_set.first_probe;
     while (i != NULL) {
         // check if ap entry is available - returns NULL if not in list
+        dawn_mutex_require(&ap_array_mutex);
         ap *ap_k = ap_array_get_ap(i->bssid_addr);
 
         if (ap_k)
@@ -1813,6 +1858,7 @@ int build_hearing_map_sort_client(struct blob_buf *b) {
         }
 
         // Find the client if it is actually connected somewhere...
+        dawn_mutex_require(&client_array_mutex);
         client* this_client = client_array_get_client(this_entry->k->client_addr);
 
         // Add the probe details
@@ -1874,6 +1920,7 @@ int build_hearing_map_sort_client(struct blob_buf *b) {
         this_entry = next_entry;
     }
 
+    dawn_mutex_unlock(&ap_array_mutex);
     dawn_mutex_unlock(&probe_array_mutex);
 
     return 0;
@@ -1890,6 +1937,7 @@ int build_network_overview(struct blob_buf *b) {
     struct hostapd_sock_entry *sub;
 
     bool add_ssid = true;
+    dawn_mutex_require(&ap_array_mutex);
     for (ap* m = ap_set; m != NULL; m = m->next_ap) {
         if(add_ssid)
         {
@@ -1932,6 +1980,7 @@ int build_network_overview(struct blob_buf *b) {
         blobmsg_add_string_buffer(b);
 
         // TODO: Could optimise this by exporting search func, but not a core process
+        dawn_mutex_require(&client_array_mutex);
         client *k = *client_find_first_bc_entry(m->bssid_addr, dawn_mac_null, false);
         while (k != NULL && mac_is_equal_bb(m->bssid_addr, k->bssid_addr)) {
 
@@ -1979,7 +2028,9 @@ int build_network_overview(struct blob_buf *b) {
 }
 
 
-static void blobmsg_add_nr(struct blob_buf *b_local, ap *i) {
+
+static void blobmsg_add_nr(struct blob_buf* b_local, ap* i) {
+    dawn_mutex_require(&ap_array_mutex);
     void* nr_entry = blobmsg_open_array(b_local, NULL);
     char mac_buf[20];
 
@@ -2016,6 +2067,7 @@ int ap_get_nr(struct blob_buf *b_local, struct dawn_mac own_bssid_addr, const ch
 
     void* nbs = blobmsg_open_array(b_local, "list");
 
+    dawn_mutex_require(&ap_array_mutex);
     own_ap = ap_array_get_ap(own_bssid_addr);
     if (!own_ap)
         return -1;
@@ -2024,7 +2076,6 @@ int ap_get_nr(struct blob_buf *b_local, struct dawn_mac own_bssid_addr, const ch
         if (own_ap->freq <= max_band_freq[band])
            break;
     }
-    dawn_mutex_lock(&ap_array_mutex);
 
     for (i = ap_set; i != NULL; i = i->next_ap) {
         if (i != own_ap && !strncmp((char *)i->ssid, ssid, SSID_MAX_LEN) &&
@@ -2033,7 +2084,6 @@ int ap_get_nr(struct blob_buf *b_local, struct dawn_mac own_bssid_addr, const ch
             blobmsg_add_nr(b_local, i);
         }
     }
-    dawn_mutex_unlock(&ap_array_mutex);
 
     for (n = preferred_list; n; n = n->next_mac) {
         if ((i = ap_array_get_ap(n->mac)))

src/utils/utils.c

@@ -130,14 +130,57 @@ const char* dawnlog_basename(const char* file)
     return(xfile ? xfile + 1 : file);
 }
 
-int _dawn_mutex_lock(pthread_mutex_t* m, char * f, int l)
+
+#ifdef DAWN_MUTEX_WRAP
+// Log that a mutex managed resource is being accessed so that messages can be scrutinised for bugs
+void _dawn_mutex_require(pthread_mutex_t* m, char* f, int l)
 {
-    dawnlog_debug("MUTEX   lock = %" PRIXPTR "@%s:%d", m, dawnlog_basename(f), l);
+    // Rely on compile time hack that we can see pthread_t is unsigned long on this dev platform
+    if (sizeof(pthread_t) == sizeof(unsigned long))
+    {
+        pthread_t moi = pthread_self();
+
+        if (0 == pthread_mutex_trylock(m))
+        {
+            pthread_mutex_unlock(m);
+            dawnlog_warning("MUTEX require = %" PRIXPTR "@%s:%d[%ul] - appears to be UNLOCKED!", m, dawnlog_basename(f), l, moi);
+        }
+        else
+            dawnlog_debug("MUTEX require = %" PRIXPTR "@%s:%d[%ul]", m, dawnlog_basename(f), l, moi);
+    }
+
+    return;
+}
+
+// Log that a mutex managed resource is being locked so that messages can be scrutinised for bugs
+int _dawn_mutex_lock(pthread_mutex_t* m, char* f, int l)
+{
+    // Rely on compile time hack that we can see pthread_t is unsigned long on this dev platform
+    if (sizeof(pthread_t) == sizeof(unsigned long))
+    {
+        pthread_t moi = pthread_self();
+
+        dawnlog_debug("MUTEX    lock = %" PRIXPTR "@%s:%d[%ul]", m, dawnlog_basename(f), l, moi);
+    }
+    else
+        dawnlog_debug("MUTEX    lock = %" PRIXPTR "@%s:%d", m, dawnlog_basename(f), l);
+
     return pthread_mutex_lock(m);
 }
 
+// Log that a mutex managed resource is being unlocked so that messages can be scrutinised for bugs
 int _dawn_mutex_unlock(pthread_mutex_t* m, char* f, int l)
 {
-    dawnlog_debug("MUTEX unlock = %" PRIXPTR "@%s:%d", m, dawnlog_basename(f), l);
+    // Rely on compile time hack that we can see pthread_t is unsigned long on this dev platform
+    if (sizeof(pthread_t) == sizeof(unsigned long))
+    {
+        pthread_t moi = pthread_self();
+
+        dawnlog_debug("MUTEX  unlock = %" PRIXPTR "@%s:%d[%ul]", m, dawnlog_basename(f), l, moi);
+    }
+    else
+        dawnlog_debug("MUTEX  unlock = %" PRIXPTR "@%s:%d", m, dawnlog_basename(f), l);
+
     return pthread_mutex_unlock(m);
 }
+#endif