rework log handling
authorFelix Fietkau <nbd@nbd.name>
Fri, 16 Apr 2021 12:15:15 +0000 (14:15 +0200)
committerFelix Fietkau <nbd@nbd.name>
Fri, 16 Apr 2021 12:55:57 +0000 (14:55 +0200)
- 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>
CMakeLists.txt
event.c [new file with mode: 0644]
event.h [new file with mode: 0644]
local_node.c
main.c
policy.c
remote.c
sta.c
ubus.c
usteer.h
utils.h

index 59aa5cfa5654f671bee273f8ccf8f1ef3f992a88..e22b7ae5cef9c8bf37f38924547a79230a340dfe 100644 (file)
@@ -24,7 +24,7 @@ IF(NOT HAVE_PCAP_H)
        MESSAGE(FATAL_ERROR "pcap/pcap.h is not found")
 ENDIF()
 
-SET(SOURCES main.c local_node.c node.c sta.c policy.c ubus.c remote.c parse.c netifd.c timeout.c)
+SET(SOURCES main.c local_node.c node.c sta.c policy.c ubus.c remote.c parse.c netifd.c timeout.c event.c)
 
 IF(NL_CFLAGS)
        ADD_DEFINITIONS(${NL_CFLAGS})
diff --git a/event.c b/event.c
new file mode 100644 (file)
index 0000000..ba0d8ad
--- /dev/null
+++ b/event.c
@@ -0,0 +1,282 @@
+/*
+ *   This program is free software; you can redistribute it and/or modify
+ *   it under the terms of the GNU General Public License as published by
+ *   the Free Software Foundation; either version 2 of the License.
+ *
+ *   This program is distributed in the hope that it will be useful,
+ *   but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ *   GNU General Public License for more details.
+ *
+ *   You should have received a copy of the GNU General Public License
+ *   along with this program; if not, write to the Free Software
+ *   Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307, USA.
+ *
+ *   Copyright (C) 2020 embedd.ch 
+ *   Copyright (C) 2020 Felix Fietkau <nbd@nbd.name> 
+ *   Copyright (C) 2020 John Crispin <john@phrozen.org> 
+ */
+#include "usteer.h"
+#include "event.h"
+
+#define UEV_LOG_MAXLEN 256
+
+static struct blob_buf b;
+static const char * const uev_name[] = {
+       [UEV_PROBE_REQ_ACCEPT] = "probe_req_accept",
+       [UEV_PROBE_REQ_DENY] = "probe_req_deny",
+       [UEV_AUTH_REQ_ACCEPT] = "auth_req_accept",
+       [UEV_AUTH_REQ_DENY] = "auth_req_deny",
+       [UEV_ASSOC_REQ_ACCEPT] = "assoc_req_accept",
+       [UEV_ASSOC_REQ_DENY] = "assoc_req_deny",
+       [UEV_LOAD_KICK_TRIGGER] = "load_kick_trigger",
+       [UEV_LOAD_KICK_RESET] = "load_kick_reset",
+       [UEV_LOAD_KICK_MIN_CLIENTS] = "load_kick_min_clients",
+       [UEV_LOAD_KICK_NO_CLIENT] = "load_kick_no_client",
+       [UEV_LOAD_KICK_CLIENT] = "load_kick_client",
+       [UEV_SIGNAL_KICK] = "signal_kick",
+
+};
+static const char * const uev_reason[] = {
+       [UEV_REASON_NONE] = "none",
+       [UEV_REASON_RETRY_EXCEEDED] = "retry_exceeded",
+       [UEV_REASON_LOW_SIGNAL] = "low_signal",
+       [UEV_REASON_CONNECT_DELAY] = "connect_delay",
+       [UEV_REASON_BETTER_CANDIDATE] = "better_candidate",
+};
+
+static const char * const uev_select_reason[] = {
+       [UEV_SELECT_REASON_NUM_ASSOC] = "n_assoc",
+       [UEV_SELECT_REASON_SIGNAL] = "signal",
+       [UEV_SELECT_REASON_LOAD] = "load",
+};
+
+static void
+usteer_event_add_node_info(struct usteer_node *node)
+{
+       blobmsg_add_u32(&b, "load", node->load);
+       blobmsg_add_u32(&b, "assoc", node->n_assoc);
+}
+
+static void
+usteer_event_send_ubus(struct uevent *ev)
+{
+       void *c;
+       int i;
+
+       if (!usteer_obj.has_subscribers)
+               return;
+
+       blob_buf_init(&b, 0);
+
+       if (ev->node_local)
+               blobmsg_add_string(&b, "node", usteer_node_name(ev->node_local));
+
+       if (ev->sta)
+               blobmsg_printf(&b, "sta", MAC_ADDR_FMT, MAC_ADDR_DATA(ev->sta->addr));
+
+       if (ev->si_cur)
+               blobmsg_add_u32(&b, "signal", (int32_t)ev->si_cur->signal);
+
+       if (ev->reason)
+               blobmsg_add_string(&b, "reason", uev_reason[ev->reason]);
+
+       if (ev->threshold.ref) {
+               c = blobmsg_open_array(&b, "threshold");
+               blobmsg_add_u32(&b, NULL, ev->threshold.cur);
+               blobmsg_add_u32(&b, NULL, ev->threshold.ref);
+               blobmsg_close_array(&b, c);
+       }
+
+       if (ev->select_reasons) {
+               c = blobmsg_open_array(&b, "select_reason");
+               for (i = 0; i < ARRAY_SIZE(uev_select_reason); i++) {
+                       if (!(ev->select_reasons & (1 << i)) ||
+                               !uev_select_reason[i])
+                               continue;
+
+                       blobmsg_add_string(&b, NULL, uev_select_reason[i]);
+               }
+               blobmsg_close_array(&b, c);
+       }
+
+       if (ev->node_cur) {
+               c = blobmsg_open_table(&b, "local");
+               usteer_event_add_node_info(ev->node_cur);
+               blobmsg_close_table(&b, c);
+       }
+
+       if (ev->node_other) {
+               c = blobmsg_open_table(&b, "remote");
+               blobmsg_add_string(&b, "name", usteer_node_name(ev->node_other));
+               if (ev->si_other)
+                       blobmsg_add_u32(&b, "signal", (int32_t)ev->si_other->signal);
+               usteer_event_add_node_info(ev->node_other);
+               blobmsg_close_table(&b, c);
+       }
+
+       if (ev->count)
+               blobmsg_add_u32(&b, "count", ev->count);
+
+       ubus_notify(ubus_ctx, &usteer_obj, uev_name[ev->type], b.head, -1);
+}
+
+static int
+usteer_event_log_node(char *buf, int len, const char *prefix, struct usteer_node *node)
+{
+       char *cur = buf;
+       char *end = buf + len;
+
+       cur += snprintf(cur, end - cur, " %sassoc=%d %sload=%d",
+                       prefix, node->n_assoc,
+                       prefix, node->load);
+
+       return cur - buf;
+}
+
+static void
+usteer_event_log(struct uevent *ev)
+{
+       char *str, *cur, *end;
+       int i;
+
+       if (!(config.event_log_mask & (1 << ev->type)))
+               return;
+
+       blob_buf_init(&b, 0);
+       cur = str = blobmsg_alloc_string_buffer(&b, NULL, UEV_LOG_MAXLEN);
+       end = str + UEV_LOG_MAXLEN;
+       cur += snprintf(cur, end - cur, "usteer event=%s", uev_name[ev->type]);
+       if (ev->node_local)
+               cur += snprintf(cur, end - cur, " node=%s", usteer_node_name(ev->node_local));
+       if (ev->sta)
+               cur += snprintf(cur, end - cur, " sta=" MAC_ADDR_FMT, MAC_ADDR_DATA(ev->sta->addr));
+       if (ev->reason)
+               cur += snprintf(cur, end - cur, " reason=%s", uev_reason[ev->reason]);
+       if (ev->si_cur)
+               cur += snprintf(cur, end - cur, " signal=%d", ev->si_cur->signal);
+       if (ev->threshold.ref)
+               cur += snprintf(cur, end - cur, " thr=%d/%d", ev->threshold.cur, ev->threshold.ref);
+       if (ev->count)
+               cur += snprintf(cur, end - cur, " count=%d", ev->count);
+       if (ev->node_cur)
+               cur += usteer_event_log_node(cur, end - cur, "", ev->node_cur);
+       if (ev->select_reasons) {
+               bool first = true;
+
+               cur += snprintf(cur, end - cur, " select_reason");
+               for (i = 0; i < ARRAY_SIZE(uev_select_reason); i++) {
+                       if (!(ev->select_reasons & (1 << i)) ||
+                               !uev_select_reason[i])
+                               continue;
+
+                       cur += snprintf(cur, end - cur, "%c%s", first ? '=' : ',',
+                                                   uev_select_reason[i]);
+                       first = false;
+               }
+       }
+       if (ev->node_other) {
+               cur += snprintf(cur, end - cur, " remote=%s", usteer_node_name(ev->node_other));
+               if (ev->si_other)
+                       cur += snprintf(cur, end - cur, " remote_signal=%d",
+                                       ev->si_other->signal);
+               cur += usteer_event_log_node(cur, end - cur, "remote_", ev->node_other);
+       }
+
+       log_msg(str);
+}
+
+void usteer_event(struct uevent *ev)
+{
+       if (ev->type >= ARRAY_SIZE(uev_name) || !uev_name[ev->type])
+               return;
+
+       if (ev->reason >= ARRAY_SIZE(uev_reason) || !uev_reason[ev->reason])
+               return;
+
+       if (ev->si_cur) {
+               if (!ev->node_local)
+                       ev->node_local = ev->si_cur->node;
+               if (!ev->sta)
+                       ev->sta = ev->si_cur->sta;
+       }
+
+       if (!ev->node_local && ev->node_cur)
+               ev->node_local = ev->node_cur;
+
+       if (ev->si_other && ev->node_cur && !ev->node_other)
+               ev->node_other = ev->si_other->node;
+
+       usteer_event_send_ubus(ev);
+       usteer_event_log(ev);
+}
+
+void config_set_event_log_types(struct blob_attr *attr)
+{
+       struct blob_attr *cur;
+       int i, rem;
+
+       config.event_log_mask = 0;
+       if (!attr) {
+               static const uint32_t default_log[] = {
+                       [MSG_INFO] =
+                               (1 << UEV_LOAD_KICK_CLIENT) |
+                               (1 << UEV_SIGNAL_KICK) |
+                               (1 << UEV_AUTH_REQ_DENY) |
+                               (1 << UEV_ASSOC_REQ_DENY),
+                       [MSG_VERBOSE] =
+                               (1 << UEV_PROBE_REQ_DENY),
+                       [MSG_DEBUG] =
+                               (1 << UEV_AUTH_REQ_ACCEPT) |
+                               (1 << UEV_ASSOC_REQ_ACCEPT) |
+                               (1 << UEV_LOAD_KICK_TRIGGER) |
+                               (1 << UEV_LOAD_KICK_RESET) |
+                               (1 << UEV_LOAD_KICK_MIN_CLIENTS) |
+                               (1 << UEV_LOAD_KICK_NO_CLIENT),
+               };
+
+               if (config.debug_level >= MSG_DEBUG_ALL) {
+                       config.event_log_mask = ~0;
+                       return;
+               }
+
+               for (i = 0; i < ARRAY_SIZE(default_log) && i <= config.debug_level; i++)
+                       config.event_log_mask |= default_log[i];
+
+               return;
+       }
+
+       if (blobmsg_check_array(attr, BLOBMSG_TYPE_STRING) < 0)
+               return;
+
+       blobmsg_for_each_attr(cur, attr, rem) {
+               const char *name = blobmsg_get_string(cur);
+
+               for (i = 0; i < ARRAY_SIZE(uev_name); i++) {
+                       if (!uev_name[i] || strcmp(uev_name[i], name) != 0)
+                               continue;
+
+                       config.event_log_mask |= (1 << i);
+                       break;
+               }
+       }
+}
+
+void config_get_event_log_types(struct blob_buf *buf)
+{
+       uint32_t mask = config.event_log_mask;
+       void *c;
+       int i;
+
+       c = blobmsg_open_array(buf, "event_log_types");
+       for (i = 0; mask && i < ARRAY_SIZE(uev_name); i++) {
+               bool cur = mask & 1;
+
+               mask >>= 1;
+               if (!cur)
+                       continue;
+
+               blobmsg_add_string(buf, NULL, uev_name[i]);
+       }
+       blobmsg_close_array(buf, c);
+}
diff --git a/event.h b/event.h
new file mode 100644 (file)
index 0000000..57b35a0
--- /dev/null
+++ b/event.h
@@ -0,0 +1,59 @@
+#ifndef __USTEER_EVENT_H
+#define __USTEER_EVENT_H
+
+enum uevent_type {
+       UEV_PROBE_REQ_ACCEPT,
+       UEV_PROBE_REQ_DENY,
+       UEV_AUTH_REQ_ACCEPT,
+       UEV_AUTH_REQ_DENY,
+       UEV_ASSOC_REQ_ACCEPT,
+       UEV_ASSOC_REQ_DENY,
+       UEV_LOAD_KICK_TRIGGER,
+       UEV_LOAD_KICK_RESET,
+       UEV_LOAD_KICK_MIN_CLIENTS,
+       UEV_LOAD_KICK_NO_CLIENT,
+       UEV_LOAD_KICK_CLIENT,
+       UEV_SIGNAL_KICK,
+};
+
+enum uevent_reason {
+       UEV_REASON_NONE,
+       UEV_REASON_RETRY_EXCEEDED,
+       UEV_REASON_LOW_SIGNAL,
+       UEV_REASON_CONNECT_DELAY,
+       UEV_REASON_BETTER_CANDIDATE,
+};
+
+enum uevent_select_reason {
+       UEV_SELECT_REASON_NUM_ASSOC,
+       UEV_SELECT_REASON_SIGNAL,
+       UEV_SELECT_REASON_LOAD,
+};
+
+struct uevent {
+       enum uevent_type type;
+       enum uevent_reason reason;
+       uint32_t select_reasons;
+
+       struct usteer_node *node_local;
+       struct sta *sta;
+
+       struct sta_info *si_cur;
+       struct sta_info *si_other;
+
+       struct usteer_node *node_cur;
+       struct usteer_node *node_other;
+
+       unsigned int count;
+
+       struct {
+               int cur;
+               int ref;
+       } threshold;
+};
+
+void usteer_event(struct uevent *ev);
+void config_set_event_log_types(struct blob_attr *attr);
+void config_get_event_log_types(struct blob_buf *buf);
+
+#endif
index 07af00e2a3bab1090adc31634e41884658a9b678..40ae8718643906f1b07a738e5c55597d56c0bb0e 100644 (file)
@@ -340,9 +340,6 @@ usteer_local_node_update(struct uloop_timeout *timeout)
        ln = container_of(timeout, struct usteer_local_node, update);
        node = &ln->node;
 
-       MSG_T("local_sta_udpate", "timeout (%u) expired\n",
-               config.local_sta_update);
-
        list_for_each_entry(h, &node_handlers, list) {
                if (!h->update_node)
                        continue;
@@ -476,9 +473,13 @@ node_list_cb(struct ubus_context *ctx, struct ubus_object_data *obj, void *priv)
 
 void config_set_node_up_script(struct blob_attr *data)
 {
-       const char *val = blobmsg_get_string(data);
+       const char *val;
        struct usteer_node *node;
 
+       if (!data)
+               return;
+
+       val = blobmsg_get_string(data);
        if (node_up_script && !strcmp(val, node_up_script))
                return;
 
diff --git a/main.c b/main.c
index b6dbffa5f937885f696485aa5270a95525416f90..a26818e0d3cc596cfe08f8e22fcc52b576c2ac6e 100644 (file)
--- a/main.c
+++ b/main.c
@@ -22,6 +22,7 @@
 #include <syslog.h>
 
 #include "usteer.h"
+#include "event.h"
 
 struct ubus_context *ubus_ctx;
 struct usteer_config config = {};
@@ -35,6 +36,14 @@ const char * const event_types[__EVENT_TYPE_MAX] = {
        [EVENT_TYPE_ASSOC] = "assoc",
 };
 
+void log_msg(char *msg)
+{
+       if (config.syslog)
+               syslog(LOG_INFO, "%s\n", msg);
+       else
+               fprintf(stderr, "%s\n", msg);
+}
+
 void debug_msg(int level, const char *func, int line, const char *format, ...)
 {
        va_list ap;
@@ -143,6 +152,7 @@ int main(int argc, char **argv)
 
        openlog("usteer", 0, LOG_USER);
 
+       config_set_event_log_types(NULL);
        usteer_update_time();
        uloop_init();
 
index f083dc3d4efd85ea5ae68c76e249eebe451b23d4..c1a992fc620c54af91d8a6d7eebf8b5cf56df7ca 100644 (file)
--- 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)
 {
+       uint32_t reasons = 0;
+
        if (!below_max_assoc(si_new))
-               return false;
+               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);
 
-       return below_assoc_threshold(si_cur, si_new) ||
-              better_signal_strength(si_cur, si_new) ||
-              has_better_load(si_cur, si_new);
+       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);
 }
index 3fad95f1a20d7b72c669d270e537c20980af16f9..fe412b09cc37c5f0d3c47222f6201d1637b7ffe1 100644 (file)
--- a/remote.c
+++ b/remote.c
@@ -123,6 +123,9 @@ void config_set_interfaces(struct blob_attr *data)
        struct blob_attr *cur;
        int rem;
 
+       if (!data)
+               return;
+
        if (!blobmsg_check_attr_list(data, BLOBMSG_TYPE_STRING))
                return;
 
@@ -485,9 +488,6 @@ usteer_send_update_timer(struct uloop_timeout *t)
        struct usteer_node *node;
        void *c;
 
-       MSG_T("remote_update_interval", "start remote update (interval=%u)\n",
-               config.remote_update_interval);
-
        usteer_update_time();
        uloop_timeout_set(t, config.remote_update_interval);
 
diff --git a/sta.c b/sta.c
index d9fcb60bbe833c52c56bf5dbdceeb8226e6a2557..869019d7ad872e113356012800c497fca94c6309 100644 (file)
--- a/sta.c
+++ b/sta.c
@@ -72,9 +72,6 @@ usteer_sta_info_timeout(struct usteer_timeout_queue *q, struct usteer_timeout *t
 {
        struct sta_info *si = container_of(t, struct sta_info, timeout);
 
-       MSG_T_STA("local_sta_timeout", si->sta->addr,
-               "timeout expired, deleting sta info\n");
-
        usteer_sta_info_del(si);
 }
 
@@ -183,10 +180,8 @@ usteer_handle_sta_event(struct usteer_node *node, const uint8_t *addr,
        si->stats[type].requests++;
 
        diff = si->stats[type].blocked_last_time - current_time;
-       if (diff > config.sta_block_timeout) {
+       if (diff > config.sta_block_timeout)
                si->stats[type].blocked_cur = 0;
-               MSG_T_STA("sta_block_timeout", addr, "timeout expired\n");
-       }
 
        ret = usteer_check_request(si, type);
        if (!ret) {
diff --git a/ubus.c b/ubus.c
index 9bd1cc0708ddb2d8394b2afb5d90608ecd3be09d..7ec724f7c13600de4eb29ab987f744a3d6237838 100644 (file)
--- a/ubus.c
+++ b/ubus.c
@@ -26,6 +26,7 @@
 
 #include "usteer.h"
 #include "node.h"
+#include "event.h"
 
 static struct blob_buf b;
 
@@ -165,7 +166,8 @@ struct cfg_item {
        _cfg(U32, load_kick_min_clients), \
        _cfg(U32, load_kick_reason_code), \
        _cfg(ARRAY_CB, interfaces), \
-       _cfg(STRING_CB, node_up_script)
+       _cfg(STRING_CB, node_up_script), \
+       _cfg(ARRAY_CB, event_log_types)
 
 enum cfg_items {
 #define _cfg(_type, _name) CFG_##_name
@@ -239,15 +241,18 @@ usteer_ubus_set_config(struct ubus_context *ctx, struct ubus_object *obj,
 
        blobmsg_parse(config_policy, __CFG_MAX, tb, blob_data(msg), blob_len(msg));
        for (i = 0; i < __CFG_MAX; i++) {
-               if (!tb[i])
-                       continue;
-
                switch(config_data[i].type) {
                case CFG_BOOL:
+                       if (!tb[i])
+                               continue;
+
                        *config_data[i].ptr.BOOL = blobmsg_get_u8(tb[i]);
                        break;
                case CFG_I32:
                case CFG_U32:
+                       if (!tb[i])
+                               continue;
+
                        *config_data[i].ptr.U32 = blobmsg_get_u32(tb[i]);
                        break;
                case CFG_ARRAY_CB:
@@ -325,7 +330,7 @@ static const struct ubus_method usteer_methods[] = {
 static struct ubus_object_type usteer_obj_type =
        UBUS_OBJECT_TYPE("usteer", usteer_methods);
 
-static struct ubus_object usteer_obj = {
+struct ubus_object usteer_obj = {
        .name = "usteer",
        .type = &usteer_obj_type,
        .methods = usteer_methods,
@@ -384,10 +389,6 @@ int usteer_ubus_trigger_client_scan(struct sta_info *si)
 
        si->scan_band = !si->scan_band;
 
-       MSG_T_STA("load_kick_reason_code", si->sta->addr,
-               "tell hostapd to issue a client beacon request (5ghz: %d)\n",
-               si->scan_band);
-
        blob_buf_init(&b, 0);
        blobmsg_printf(&b, "addr", MAC_ADDR_FMT, MAC_ADDR_DATA(si->sta->addr));
        blobmsg_add_u32(&b, "mode", 1);
@@ -401,10 +402,6 @@ void usteer_ubus_kick_client(struct sta_info *si)
 {
        struct usteer_local_node *ln = container_of(si->node, struct usteer_local_node, node);
 
-       MSG_T_STA("load_kick_reason_code", si->sta->addr,
-               "tell hostapd to kick client with reason code %u\n",
-               config.load_kick_reason_code);
-
        blob_buf_init(&b, 0);
        blobmsg_printf(&b, "addr", MAC_ADDR_FMT, MAC_ADDR_DATA(si->sta->addr));
        blobmsg_add_u32(&b, "reason", config.load_kick_reason_code);
index 2efc3383984280ae042b6cdcdd078ad8f83560be..4306873f8550ad1a82939ce82313e44b00eaf164 100644 (file)
--- a/usteer.h
+++ b/usteer.h
@@ -156,6 +156,7 @@ struct usteer_config {
        uint32_t load_kick_reason_code;
 
        const char *node_up_script;
+       uint32_t event_log_mask;
 };
 
 struct sta_info_stats {
@@ -165,18 +166,13 @@ struct sta_info_stats {
        uint32_t blocked_last_time;
 };
 
-#define __roam_trigger_states \
-       _S(IDLE) \
-       _S(SCAN) \
-       _S(SCAN_DONE) \
-       _S(WAIT_KICK) \
-       _S(NOTIFY_KICK) \
-       _S(KICK)
-
 enum roam_trigger_state {
-#define _S(n) ROAM_TRIGGER_##n,
-       __roam_trigger_states
-#undef _S
+       ROAM_TRIGGER_IDLE,
+       ROAM_TRIGGER_SCAN,
+       ROAM_TRIGGER_SCAN_DONE,
+       ROAM_TRIGGER_WAIT_KICK,
+       ROAM_TRIGGER_NOTIFY_KICK,
+       ROAM_TRIGGER_KICK,
 };
 
 struct sta_info {
@@ -219,6 +215,7 @@ extern struct ubus_context *ubus_ctx;
 extern struct usteer_config config;
 extern struct list_head node_handlers;
 extern struct avl_tree stations;
+extern struct ubus_object usteer_obj;
 extern uint64_t current_time;
 extern const char * const event_types[__EVENT_TYPE_MAX];
 
diff --git a/utils.h b/utils.h
index 9b34add4229f0f09c41a99451055eab581cfae02..75e1e2df57b67790f91eeec782ca0da814c6b42e 100644 (file)
--- a/utils.h
+++ b/utils.h
        ((const uint8_t *)(_a))[4], \
        ((const uint8_t *)(_a))[5]
 
-#define MSG_T_STA(_option, _sta_addr, _format, ...) \
-       MSG(DEBUG_ALL, "TESTCASE=" _option ",STA=" MAC_ADDR_FMT ": "  _format, \
-       MAC_ADDR_DATA(_sta_addr), ##__VA_ARGS__)
-
-#define MSG_T(_option,  _format, ...) \
-       MSG(DEBUG_ALL, "TESTCASE=" _option ": "  _format,  ##__VA_ARGS__)
-
 enum usteer_debug {
        MSG_FATAL,
        MSG_INFO,
@@ -48,6 +41,7 @@ enum usteer_debug {
        MSG_DEBUG_ALL,
 };
 
+extern void log_msg(char *msg);
 extern void debug_msg(int level, const char *func, int line, const char *format, ...);
 extern void debug_msg_cont(int level, const char *format, ...);