rework log handling

- make logging events more structured - add fine grained control over log events - make it possible to receive more detailed events via ubus Signed-off-by: Felix Fietkau <nbd@nbd.name>
2021-04-16 14:15:15 +02:00
parent 6d62833ca1
commit 2b1c740ce3
11 changed files with 529 additions and 161 deletions
--- a/policy.c
+++ b/policy.c
@@ -19,6 +19,7 @@

 #include "usteer.h"
 #include "node.h"
+#include "event.h"

 static bool
 below_assoc_threshold(struct sta_info *si_cur, struct sta_info *si_new)
@@ -35,12 +36,6 @@ below_assoc_threshold(struct sta_info *si_cur, struct sta_info *si_new)

 	n_assoc_new += config.load_balancing_threshold;

-	if (n_assoc_new > n_assoc_cur) {
-		MSG_T_STA("band_steering_threshold,load_balancing_threshold",
-			si_cur->sta->addr, "exeeded (bs=%u, lb=%u)\n",
-			config.band_steering_threshold,
-			config.load_balancing_threshold);
-	}
 	return n_assoc_new <= n_assoc_cur;
 }

@@ -53,12 +48,6 @@ better_signal_strength(struct sta_info *si_cur, struct sta_info *si_new)
 	if (!config.signal_diff_threshold)
 		return false;

-	if (is_better) {
-		MSG_T_STA("signal_diff_threshold", si_cur->sta->addr,
-			"exceeded (config=%i) (real=%i)\n",
-			config.signal_diff_threshold,
-			si_new->signal - si_cur->signal);
-	}
 	return is_better;
 }

@@ -83,40 +72,60 @@ below_max_assoc(struct sta_info *si)
 	return !node->max_assoc || node->n_assoc < node->max_assoc;
 }

-static bool
+static uint32_t
 is_better_candidate(struct sta_info *si_cur, struct sta_info *si_new)
 {
-	if (!below_max_assoc(si_new))
-		return false;
+	uint32_t reasons = 0;

-	return below_assoc_threshold(si_cur, si_new) ||
-	       better_signal_strength(si_cur, si_new) ||
-	       has_better_load(si_cur, si_new);
+	if (!below_max_assoc(si_new))
+		return 0;
+
+	if (below_assoc_threshold(si_cur, si_new) &&
+	    !below_assoc_threshold(si_new, si_cur))
+		reasons |= (1 << UEV_SELECT_REASON_NUM_ASSOC);
+
+	if (better_signal_strength(si_cur, si_new))
+		reasons |= (1 << UEV_SELECT_REASON_SIGNAL);
+
+	if (has_better_load(si_cur, si_new) &&
+		!has_better_load(si_cur, si_new))
+		reasons |= (1 << UEV_SELECT_REASON_LOAD);
+
+	return reasons;
 }

 static struct sta_info *
-find_better_candidate(struct sta_info *si_ref)
+find_better_candidate(struct sta_info *si_ref, struct uevent *ev)
 {
 	struct sta_info *si;
 	struct sta *sta = si_ref->sta;
+	uint32_t reasons;

 	list_for_each_entry(si, &sta->nodes, list) {
 		if (si == si_ref)
 			continue;

-		if (current_time - si->seen > config.seen_policy_timeout) {
-			MSG_T_STA("seen_policy_timeout", si->sta->addr,
-				"timeout exceeded (%u)\n", config.seen_policy_timeout);
+		if (current_time - si->seen > config.seen_policy_timeout)
 			continue;
-		}

 		if (strcmp(si->node->ssid, si_ref->node->ssid) != 0)
 			continue;

-		if (is_better_candidate(si_ref, si) &&
-		    !is_better_candidate(si, si_ref))
-			return si;
+		reasons = is_better_candidate(si_ref, si);
+		if (!reasons)
+			continue;
+
+		if (is_better_candidate(si, si_ref))
+			continue;
+
+		if (ev) {
+			ev->si_other = si;
+			ev->select_reasons = reasons;
+		}
+
+		return si;
 	}
+
 	return NULL;
 }

@@ -137,56 +146,68 @@ snr_to_signal(struct usteer_node *node, int snr)
 bool
 usteer_check_request(struct sta_info *si, enum usteer_event_type type)
 {
-	struct sta_info *si_new;
+	struct uevent ev = {
+		.si_cur = si,
+	};
 	int min_signal;
+	bool ret = true;

 	if (type == EVENT_TYPE_AUTH)
-		return true;
+		goto out;

 	if (type == EVENT_TYPE_ASSOC && !config.assoc_steering)
-		return true;
-
-	if (si->stats[type].blocked_cur >= config.max_retry_band) {
-		MSG_T_STA("max_retry_band", si->sta->addr,
-			"max retry (%u) exceeded\n", config.max_retry_band);
-		return true;
-	}
+		goto out;

 	min_signal = snr_to_signal(si->node, config.min_connect_snr);
 	if (si->signal < min_signal) {
-		if (type != EVENT_TYPE_PROBE || config.debug_level >= MSG_DEBUG)
-			MSG(VERBOSE, "Ignoring %s request from "MAC_ADDR_FMT" due to low signal (%d < %d)\n",
-			    event_types[type], MAC_ADDR_DATA(si->sta->addr),
-			    si->signal, min_signal);
-		MSG_T_STA("min_connect_snr", si->sta->addr,
-			"snr to low (config=%i) (real=%i)\n",
-			min_signal, si->signal);
-		return false;
+		ev.reason = UEV_REASON_LOW_SIGNAL;
+		ev.threshold.cur = si->signal;
+		ev.threshold.ref = min_signal;
+		ret = false;
+		goto out;
 	}

 	if (current_time - si->created < config.initial_connect_delay) {
-		if (type != EVENT_TYPE_PROBE || config.debug_level >= MSG_DEBUG)
-			MSG(VERBOSE, "Ignoring %s request from "MAC_ADDR_FMT" during initial connect delay\n",
-			    event_types[type], MAC_ADDR_DATA(si->sta->addr));
-		MSG_T_STA("initial_connect_delay", si->sta->addr,
-			"is below delay (%u)\n", config.initial_connect_delay);
-		return false;
+		ev.reason = UEV_REASON_CONNECT_DELAY;
+		ev.threshold.cur = current_time - si->created;
+		ev.threshold.ref = config.initial_connect_delay;
+		ret = false;
+		goto out;
 	}

-	si_new = find_better_candidate(si);
-	if (!si_new)
-		return true;
+	if (!find_better_candidate(si, &ev))
+		goto out;

-	if (type != EVENT_TYPE_PROBE || config.debug_level >= MSG_DEBUG)
-		MSG(VERBOSE, "Ignoring %s request from "MAC_ADDR_FMT", "
-			"node (local/remote): %s/%s, "
-			"signal=%d/%d, n_assoc=%d/%d\n", event_types[type],
-			MAC_ADDR_DATA(si->sta->addr),
-			usteer_node_name(si->node), usteer_node_name(si_new->node),
-			si->signal, si_new->signal,
-			si->node->n_assoc, si_new->node->n_assoc);
+	ev.reason = UEV_REASON_BETTER_CANDIDATE;
+	ev.node_cur = si->node;
+	ret = false;

-	return false;
+out:
+	switch (type) {
+	case EVENT_TYPE_PROBE:
+		ev.type = UEV_PROBE_REQ_ACCEPT;
+		break;
+	case EVENT_TYPE_ASSOC:
+		ev.type = UEV_ASSOC_REQ_ACCEPT;
+		break;
+	case EVENT_TYPE_AUTH:
+		ev.type = UEV_AUTH_REQ_ACCEPT;
+		break;
+	default:
+		break;
+	}
+
+	if (!ret)
+		ev.type++;
+
+	if (!ret && si->stats[type].blocked_cur >= config.max_retry_band) {
+		ev.reason = UEV_REASON_RETRY_EXCEEDED;
+		ev.threshold.cur = si->stats[type].blocked_cur;
+		ev.threshold.ref = config.max_retry_band;
+	}
+	usteer_event(&ev);
+
+	return ret;
 }

 static bool
@@ -202,14 +223,9 @@ is_more_kickable(struct sta_info *si_cur, struct sta_info *si_new)
 }

 static void
-usteer_roam_set_state(struct sta_info *si, enum roam_trigger_state state)
+usteer_roam_set_state(struct sta_info *si, enum roam_trigger_state state,
+		      struct uevent *ev)
 {
-	static const char * const state_names[] = {
-#define _S(n) [ROAM_TRIGGER_##n] = #n,
-		__roam_trigger_states
-#undef _S
-	};
-
 	si->roam_event = current_time;

 	if (si->roam_state == state) {
@@ -224,15 +240,15 @@ usteer_roam_set_state(struct sta_info *si, enum roam_trigger_state state)
 	}

 	si->roam_state = state;
-
-	MSG(VERBOSE, "Roam trigger SM for client "MAC_ADDR_FMT": state=%s, tries=%d, signal=%d\n",
-	    MAC_ADDR_DATA(si->sta->addr), state_names[state], si->roam_tries, si->signal);
+	usteer_event(ev);
 }

 static bool
 usteer_roam_trigger_sm(struct sta_info *si)
 {
-	struct sta_info *si_new;
+	struct uevent ev = {
+		.si_cur = si,
+	};
 	int min_signal;

 	min_signal = snr_to_signal(si->node, config.roam_trigger_snr);
@@ -242,61 +258,59 @@ usteer_roam_trigger_sm(struct sta_info *si)
 		if (current_time - si->roam_event < config.roam_scan_interval)
 			break;

-		if (find_better_candidate(si) ||
+		if (find_better_candidate(si, &ev) ||
 		    si->roam_scan_done > si->roam_event) {
-			usteer_roam_set_state(si, ROAM_TRIGGER_SCAN_DONE);
+			usteer_roam_set_state(si, ROAM_TRIGGER_SCAN_DONE, &ev);
 			break;
 		}

 		if (config.roam_scan_tries &&
 		    si->roam_tries >= config.roam_scan_tries) {
-			usteer_roam_set_state(si, ROAM_TRIGGER_WAIT_KICK);
+			usteer_roam_set_state(si, ROAM_TRIGGER_WAIT_KICK, &ev);
 			break;
 		}

 		usteer_ubus_trigger_client_scan(si);
-		usteer_roam_set_state(si, ROAM_TRIGGER_SCAN);
+		usteer_roam_set_state(si, ROAM_TRIGGER_SCAN, &ev);
 		break;

 	case ROAM_TRIGGER_IDLE:
-		if (find_better_candidate(si)) {
-			usteer_roam_set_state(si, ROAM_TRIGGER_SCAN_DONE);
+		if (find_better_candidate(si, &ev)) {
+			usteer_roam_set_state(si, ROAM_TRIGGER_SCAN_DONE, &ev);
 			break;
 		}

-		usteer_roam_set_state(si, ROAM_TRIGGER_SCAN);
+		usteer_roam_set_state(si, ROAM_TRIGGER_SCAN, &ev);
 		break;

 	case ROAM_TRIGGER_SCAN_DONE:
 		/* Check for stale scan results, kick back to SCAN state if necessary */
 		if (current_time - si->roam_scan_done > 2 * config.roam_scan_interval) {
-			usteer_roam_set_state(si, ROAM_TRIGGER_SCAN);
+			usteer_roam_set_state(si, ROAM_TRIGGER_SCAN, &ev);
 			break;
 		}

-		si_new = find_better_candidate(si);
-		if (!si_new)
-			break;
+		if (find_better_candidate(si, &ev))
+			usteer_roam_set_state(si, ROAM_TRIGGER_WAIT_KICK, &ev);

-		usteer_roam_set_state(si, ROAM_TRIGGER_WAIT_KICK);
 		break;

 	case ROAM_TRIGGER_WAIT_KICK:
 		if (si->signal > min_signal)
 			break;

-		usteer_roam_set_state(si, ROAM_TRIGGER_NOTIFY_KICK);
+		usteer_roam_set_state(si, ROAM_TRIGGER_NOTIFY_KICK, &ev);
 		usteer_ubus_notify_client_disassoc(si);
 		break;
 	case ROAM_TRIGGER_NOTIFY_KICK:
 		if (current_time - si->roam_event < config.roam_kick_delay * 100)
 			break;

-		usteer_roam_set_state(si, ROAM_TRIGGER_KICK);
+		usteer_roam_set_state(si, ROAM_TRIGGER_KICK, &ev);
 		break;
 	case ROAM_TRIGGER_KICK:
 		usteer_ubus_kick_client(si);
-		usteer_roam_set_state(si, ROAM_TRIGGER_IDLE);
+		usteer_roam_set_state(si, ROAM_TRIGGER_IDLE, &ev);
 		return true;
 	}

@@ -304,7 +318,7 @@ usteer_roam_trigger_sm(struct sta_info *si)
 }

 static void
-usteer_local_node_roam_check(struct usteer_local_node *ln)
+usteer_local_node_roam_check(struct usteer_local_node *ln, struct uevent *ev)
 {
 	struct sta_info *si;
 	int min_signal;
@@ -322,7 +336,7 @@ usteer_local_node_roam_check(struct usteer_local_node *ln)
 	list_for_each_entry(si, &ln->node.sta_info, node_list) {
 		if (!si->connected || si->signal >= min_signal ||
 		    current_time - si->roam_kick < config.roam_trigger_interval) {
-			usteer_roam_set_state(si, ROAM_TRIGGER_IDLE);
+			usteer_roam_set_state(si, ROAM_TRIGGER_IDLE, ev);
 			continue;
 		}

@@ -338,6 +352,9 @@ usteer_local_node_roam_check(struct usteer_local_node *ln)
 static void
 usteer_local_node_snr_kick(struct usteer_local_node *ln)
 {
+	struct uevent ev = {
+		.node_local = &ln->node,
+	};
 	struct sta_info *si;
 	int min_signal;

@@ -345,6 +362,7 @@ usteer_local_node_snr_kick(struct usteer_local_node *ln)
 		return;

 	min_signal = snr_to_signal(&ln->node, config.min_snr);
+	ev.threshold.ref = min_signal;

 	list_for_each_entry(si, &ln->node.sta_info, node_list) {
 		if (!si->connected)
@@ -355,8 +373,10 @@ usteer_local_node_snr_kick(struct usteer_local_node *ln)

 		si->kick_count++;

-		MSG(VERBOSE, "Kicking client "MAC_ADDR_FMT" due to low SNR, signal=%d\n",
-			MAC_ADDR_DATA(si->sta->addr), si->signal);
+		ev.type = UEV_SIGNAL_KICK;
+		ev.threshold.cur = si->signal;
+		ev.count = si->kick_count;
+		usteer_event(&ev);

 		usteer_ubus_kick_client(si);
 		return;
@@ -370,8 +390,12 @@ usteer_local_node_kick(struct usteer_local_node *ln)
 	struct sta_info *kick1 = NULL, *kick2 = NULL;
 	struct sta_info *candidate = NULL;
 	struct sta_info *si;
+	struct uevent ev = {
+		.node_local = &ln->node,
+	};
+	unsigned int min_count = DIV_ROUND_UP(config.load_kick_delay, config.local_sta_update);

-	usteer_local_node_roam_check(ln);
+	usteer_local_node_roam_check(ln, &ev);
 	usteer_local_node_snr_kick(ln);

 	if (!config.load_kick_enabled || !config.load_kick_threshold ||
@@ -379,30 +403,32 @@ usteer_local_node_kick(struct usteer_local_node *ln)
 		return;

 	if (node->load < config.load_kick_threshold) {
-		MSG_T("load_kick_threshold",
-			"is below load for this node (config=%i) (real=%i)\n",
-			config.load_kick_threshold, node->load);
+		if (!ln->load_thr_count)
+			return;
+
 		ln->load_thr_count = 0;
-		return;
+		ev.type = UEV_LOAD_KICK_RESET;
+		ev.threshold.cur = node->load;
+		ev.threshold.ref = config.load_kick_threshold;
+		goto out;
 	}

-	if (++ln->load_thr_count <=
-	    DIV_ROUND_UP(config.load_kick_delay, config.local_sta_update)) {
-		MSG_T("load_kick_delay", "delay kicking (config=%i)\n",
-			config.load_kick_delay);
-		return;
-	}
+	if (++ln->load_thr_count <= min_count) {
+		if (ln->load_thr_count > 1)
+			return;

-	MSG(VERBOSE, "AP load threshold exceeded on %s (%d), try to kick a client\n",
-	    usteer_node_name(node), node->load);
+		ev.type = UEV_LOAD_KICK_TRIGGER;
+		ev.threshold.cur = node->load;
+		ev.threshold.ref = config.load_kick_threshold;
+		goto out;
+	}

 	ln->load_thr_count = 0;
 	if (node->n_assoc < config.load_kick_min_clients) {
-		MSG_T("load_kick_min_clients",
-			"min limit reached, stop kicking clients on this node "
-			"(n_assoc=%i) (config=%i)\n",
-			node->n_assoc, config.load_kick_min_clients);
-		return;
+		ev.type = UEV_LOAD_KICK_MIN_CLIENTS;
+		ev.threshold.cur = node->n_assoc;
+		ev.threshold.ref = config.load_kick_min_clients;
+		goto out;
 	}

 	list_for_each_entry(si, &ln->node.sta_info, node_list) {
@@ -414,7 +440,7 @@ usteer_local_node_kick(struct usteer_local_node *ln)
 		if (is_more_kickable(kick1, si))
 			kick1 = si;

-		tmp = find_better_candidate(si);
+		tmp = find_better_candidate(si, NULL);
 		if (!tmp)
 			continue;

@@ -424,16 +450,23 @@ usteer_local_node_kick(struct usteer_local_node *ln)
 		}
 	}

-	if (!kick1)
-		return;
+	if (!kick1) {
+		ev.type = UEV_LOAD_KICK_NO_CLIENT;
+		goto out;
+	}

 	if (kick2)
 		kick1 = kick2;

-	MSG(VERBOSE, "Kicking client "MAC_ADDR_FMT", signal=%d, better_candidate=%s\n",
-	    MAC_ADDR_DATA(kick1->sta->addr), kick1->signal,
-		candidate ? usteer_node_name(candidate->node) : "(none)");
-
 	kick1->kick_count++;
+
+	ev.type = UEV_LOAD_KICK_CLIENT;
+	ev.si_cur = kick1;
+	ev.si_other = candidate;
+	ev.count = kick1->kick_count;
+
 	usteer_ubus_kick_client(kick1);
+
+out:
+	usteer_event(&ev);
 }