Wifi-3237: Fix missing and duplicate client events

Some client events are duplicated and some of them are missing in the
client event report.

Root Cause 1: Processed clients events were not tagged in hostapd and
were thus getting duplicated during subsequent polling of client events.
Root Cause 2: Race between processing and clearing of client sessions
was leading to missing events.

Solution 1: Processed client events are tagged in hostapd and are reported only once.
Solution 2: Sessions are cleared only after they are processed by SM.

Also got rid of some unnecessary logs.

Acceptance Criteria: No duplicate client events in the mqtt report send by AP.
Sessions in the hostapd are successfully cleared after being processed by SM.

Signed-off-by: Yashvardhan <yashvardhan@netexperience.com>

feeds/wifi-ax/hostapd/patches/f00-019-ubus-fix-client-events.patch

@@ -0,0 +1,112 @@
+--- a/src/ap/ubus.c
++++ b/src/ap/ubus.c
+@@ -580,6 +580,7 @@ static int hostapd_clear_session(struct
+ 	{
+ 		if (session_id == rec->session_id) {
+ 			/* dec counter and delete */
++			wpa_printf(MSG_INFO, "%s Deleting client session with session id %llu", __func__, session_id);
+ 			cached_events_nr -= rec->rec_nr;
+ 			avl_delete(&hapd->ubus.rt_events, &rec->avl);
+ 			os_free(rec->records);
+@@ -633,6 +634,11 @@ static int hostapd_sessions(struct ubus_
+ 		/* messages for current session */
+ 		for (size_t i = 0; i < rec->rec_nr; i++) {
+ 			c_rec = &rec->records[i];
++			if (c_rec->processed) {
++				/* Record is already reported, continue */
++				continue;
++			}
++
+ 			/* check message type */
+ 			switch (c_rec->type) {
+ 			/* ClientAuthEvent */
+@@ -646,6 +652,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_u32(&b_ev, "auth_status", p->auth_status);
+ 				blobmsg_add_string(&b_ev, "ssid", p->ssid);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -665,6 +672,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_u8(&b_ev, "using11v", p->using11v);
+ 				blobmsg_add_string(&b_ev, "ssid", p->ssid);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -680,6 +688,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_u32(&b_ev, "internal_rc", p->internal_rc);
+ 				blobmsg_add_string(&b_ev, "ssid", p->ssid);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -693,6 +702,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_u64(&b_ev, "fdata_tx_up_ts_in_us", p->tx_ts.tv_sec * (uint64_t)1000000);
+ 				blobmsg_add_u64(&b_ev, "fdata_rx_up_ts_in_us", p->rx_ts.tv_sec * (uint64_t)1000000);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -705,6 +715,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_string(&b_ev, "sta_mac", p->sta_mac);
+ 				blobmsg_add_string(&b_ev, "ip_address", p->ip_addr);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -1912,6 +1923,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_AUTH;
+ 		rp->u.auth.session_id = rec->session_id;
++		rp->processed = false;
+ 
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+@@ -1942,6 +1954,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_ASSOC;
+ 		rp->u.assoc.session_id = rec->session_id;
++		rp->processed = false;
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+ 		/* frequency */
+@@ -1986,6 +1999,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_DISASSOC;
+ 		rp->u.disassoc.session_id = rec->session_id;
++		rp->processed = false;
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+ 		/* frequency */
+@@ -2017,6 +2031,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_FDATA;
+ 		rp->u.fdata.session_id = rec->session_id;
++		rp->processed = false;
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+ 		/* STA MAC */
+@@ -2045,6 +2060,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_IP;
+ 		rp->u.ip.session_id = rec->session_id;
++		rp->processed = false;
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+ 		/* STA MAC */
+--- a/src/ap/ubus.h
++++ b/src/ap/ubus.h
+@@ -110,6 +110,7 @@ struct client_ip_event {
+ };
+ 
+ struct client_session_record {
++	bool processed;
+ 	int type;
+ 	uint64_t timestamp;
+ 	union {

feeds/wifi-trunk/hostapd/patches/908-ubus-fix-client-events.patch

@@ -0,0 +1,111 @@
+--- a/src/ap/ubus.c
++++ b/src/ap/ubus.c
+@@ -578,6 +578,7 @@ static int hostapd_clear_session(struct
+ 	{
+ 		if (session_id == rec->session_id) {
+ 			/* dec counter and delete */
++			wpa_printf(MSG_INFO, "%s Deleting client session with session id %llu", __func__, session_id);
+ 			cached_events_nr -= rec->rec_nr;
+ 			avl_delete(&hapd->ubus.rt_events, &rec->avl);
+ 			os_free(rec->records);
+@@ -631,6 +632,10 @@ static int hostapd_sessions(struct ubus_
+ 		/* messages for current session */
+ 		for (size_t i = 0; i < rec->rec_nr; i++) {
+ 			c_rec = &rec->records[i];
++			if (c_rec->processed) {
++				/* Record is already reported, continue */
++				continue;
++			}
+ 			/* check message type */
+ 			switch (c_rec->type) {
+ 			/* ClientAuthEvent */
+@@ -644,6 +649,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_u32(&b_ev, "auth_status", p->auth_status);
+ 				blobmsg_add_string(&b_ev, "ssid", p->ssid);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -663,6 +669,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_u8(&b_ev, "using11v", p->using11v);
+ 				blobmsg_add_string(&b_ev, "ssid", p->ssid);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -678,6 +685,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_u32(&b_ev, "internal_rc", p->internal_rc);
+ 				blobmsg_add_string(&b_ev, "ssid", p->ssid);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -691,6 +699,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_u64(&b_ev, "fdata_tx_up_ts_in_us", p->tx_ts.tv_sec * (uint64_t)1000000);
+ 				blobmsg_add_u64(&b_ev, "fdata_rx_up_ts_in_us", p->rx_ts.tv_sec * (uint64_t)1000000);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -703,6 +712,7 @@ static int hostapd_sessions(struct ubus_
+ 				blobmsg_add_string(&b_ev, "sta_mac", p->sta_mac);
+ 				blobmsg_add_string(&b_ev, "ip_address", p->ip_addr);
+ 				blobmsg_close_table(&b_ev, t_msg);
++				c_rec->processed = true;
+ 				break;
+ 			}
+ 
+@@ -1911,6 +1921,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_AUTH;
+ 		rp->u.auth.session_id = rec->session_id;
++		rp->processed = false;
+ 
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+@@ -1941,6 +1952,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_ASSOC;
+ 		rp->u.assoc.session_id = rec->session_id;
++		rp->processed = false;
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+ 		/* frequency */
+@@ -1985,6 +1997,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_DISASSOC;
+ 		rp->u.disassoc.session_id = rec->session_id;
++		rp->processed = false;
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+ 		/* frequency */
+@@ -2016,6 +2029,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_FDATA;
+ 		rp->u.fdata.session_id = rec->session_id;
++		rp->processed = false;
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+ 		/* STA MAC */
+@@ -2044,6 +2058,7 @@ int hostapd_ubus_handle_rt_event(struct
+ 		struct client_session_record *rp = &rec->records[rec->rec_nr - 1];
+ 		rp->type = CST_IP;
+ 		rp->u.ip.session_id = rec->session_id;
++		rp->processed = false;
+ 		/* timestamp */
+ 		rp->timestamp = timestamp;
+ 		/* STA MAC */
+--- a/src/ap/ubus.h
++++ b/src/ap/ubus.h
+@@ -110,6 +110,7 @@ struct client_ip_event {
+ };
+ 
+ struct client_session_record {
++	bool processed;
+ 	int type;
+ 	uint64_t timestamp;
+ 	union {

feeds/wlan-ap/opensync/src/src/sm/src/ubus_collector.c

@@ -6,18 +6,16 @@
 /* Global list of events received from hostapd */
 dpp_event_report_data_t g_event_report;
 
-/* Internal list of processed events ready to be deleted from hostapd */
-static ds_dlist_t deletion_pending_list;
 static ds_dlist_t bss_list;
 static struct ubus_context *ubus = NULL;
 
 typedef struct {
 	uint64_t session_id;
 	char bss[UBUS_OBJ_LEN];
-
-	ds_dlist_node_t node;
 } delete_entry_t;
 
+static void ubus_garbage_collector(void *arg);
+
 static const struct blobmsg_policy ubus_collector_chan_switch_event_policy[__CHANNEL_SWITCH_EVENT_MAX] = {
 	[CHAN_SWITCH_EVENT] = {.name = "chan_switch_event", .type = BLOBMSG_TYPE_TABLE},
 };
@@ -166,6 +164,7 @@ static int client_first_data_event_cb(struct blob_attr *msg,
 	if (tb_client_first_data_event[CLIENT_FIRST_DATA_STA_MAC]) {
 		mac_address = blobmsg_get_string(tb_client_first_data_event[CLIENT_FIRST_DATA_STA_MAC]);
 		memcpy(dpp_session->first_data_event->sta_mac, mac_address, MAC_ADDRESS_STRING_LEN);
+		LOG(DEBUG, "ubus: Received FDATA event session_id:%llu client mac:%s", event_session_id, mac_address);
 	}
 
 	if (tb_client_first_data_event[CLIENT_FIRST_DATA_TIMESTAMP])
@@ -209,6 +208,7 @@ static int client_disconnect_event_cb(struct blob_attr *msg,
 	if (tb_client_disconnect_event[CLIENT_DISCONNECT_STA_MAC]) {
 		mac_address = blobmsg_get_string(tb_client_disconnect_event[CLIENT_DISCONNECT_STA_MAC]);
 		memcpy(dpp_session->disconnect_event->sta_mac, mac_address, MAC_ADDRESS_STRING_LEN);
+		LOG(DEBUG, "ubus: Received DISCONNECT event with session_id:%llu client mac:%s", event_session_id, mac_address);
 	}
 
 	if (tb_client_disconnect_event[CLIENT_DISCONNECT_BAND])
@@ -258,6 +258,7 @@ static int client_auth_event_cb(struct blob_attr *msg,
 	if (tb_client_auth_event[CLIENT_AUTH_STA_MAC]) {
 		mac_address = blobmsg_get_string(tb_client_auth_event[CLIENT_AUTH_STA_MAC]);
 		memcpy(dpp_session->auth_event->sta_mac, mac_address, MAC_ADDRESS_STRING_LEN);
+		LOG(DEBUG, "ubus: Received AUTH event with session_id:%llu client mac:%s", event_session_id, mac_address);
 	}
 
 	if (tb_client_auth_event[CLIENT_AUTH_BAND])
@@ -304,6 +305,7 @@ static int client_assoc_event_cb(struct blob_attr *msg,
 	if (tb_client_assoc_event[CLIENT_ASSOC_STA_MAC]) {
 		mac_address = blobmsg_get_string(tb_client_assoc_event[CLIENT_ASSOC_STA_MAC]);
 		memcpy(dpp_session->assoc_event->sta_mac, mac_address, MAC_ADDRESS_STRING_LEN);
+		LOG(DEBUG, "ubus: Received ASSOC event with session_id:%llu client mac:%s", event_session_id, mac_address);
 	}
 
 	if (tb_client_assoc_event[CLIENT_ASSOC_SSID]) {
@@ -365,6 +367,7 @@ static int client_ip_event_cb(struct blob_attr *msg,
 	if (tb_client_ip_event[CLIENT_IP_STA_MAC]) {
 		mac_address = blobmsg_get_string(tb_client_ip_event[CLIENT_IP_STA_MAC]);
 		memcpy(dpp_session->ip_event->sta_mac, mac_address, MAC_ADDRESS_STRING_LEN);
+		LOG(DEBUG, "ubus: Received IP event with session_id:%llu client mac:%s", event_session_id, mac_address);
 	}
 
 	if (tb_client_ip_event[CLIENT_IP_IP_ADDRESS]) {
@@ -390,22 +393,21 @@ static int (*client_event_handler_list[__CLIENT_EVENTS_MAX - 1])(
 
 static void ubus_collector_complete_session_cb(struct ubus_request *req, int ret)
 {
-	LOG(DEBUG, "ubus_collector_complete_session_cb");
 	if (req)
 		free(req);
 }
 
-static bool ubus_collector_is_session_processed(uint64_t session_id)
+static void session_delete(uint64_t session_id, char *ifname)
 {
 	delete_entry_t *delete_entry = NULL;
-
-	ds_dlist_foreach(&deletion_pending_list, delete_entry) {
-		if ( delete_entry && (delete_entry->session_id == session_id)) {
-			return true;
-		}
+	delete_entry = calloc(1, sizeof(delete_entry_t));
+	if (delete_entry) {
+		memset(delete_entry, 0, sizeof(delete_entry_t));
+		delete_entry->session_id = session_id;
+		strncpy(delete_entry->bss, ifname, UBUS_OBJ_LEN);
+		evsched_task(&ubus_garbage_collector, delete_entry,
+				EVSCHED_SEC(SESSION_DELETE_TIMEOUT));
 	}
-
-	return false;
 }
 
 static void ubus_collector_session_cb(struct ubus_request *req, int type,
@@ -418,9 +420,9 @@ static void ubus_collector_session_cb(struct ubus_request *req, int type,
 	struct blob_attr *tb_client_events[__CLIENT_EVENTS_MAX] = {};
 	dpp_event_record_t *event_record = NULL;
 	uint64_t session_id = 0;
-	delete_entry_t *delete_entry = NULL;
 	int i = 0;
 	(void)type;
+	bool is_session_empty = true;
 
 	char *ifname = (char *)req->priv;
 
@@ -466,12 +468,6 @@ static void ubus_collector_session_cb(struct ubus_request *req, int type,
 			continue;
 		}
 
-		/* Check if the session is already processed */
-		if (ubus_collector_is_session_processed(session_id) == true) {
-			LOG(DEBUG, "ubus_collector: Session already processed");
-			continue;
-		}
-
 		event_record = dpp_event_record_alloc();
 		if (!event_record) {
 			LOG(ERR, "ubus_collector: not enough memory for event_record");
@@ -489,21 +485,19 @@ static void ubus_collector_session_cb(struct ubus_request *req, int type,
 				client_event_handler_list[i](
 					tb_client_events[i], &event_record->client_session,
 					session_id);
-				}
+				is_session_empty = false;
 			}
-		event_record->hasSMProcessed = false;
-		ds_dlist_insert_tail(&g_event_report.client_event_list, event_record);
-		event_record = NULL;
+		}
+		if (is_session_empty) {
+			dpp_event_record_free(event_record);
+		} else {
+			event_record->hasSMProcessed = false;
+			ds_dlist_insert_tail(&g_event_report.client_event_list, event_record);
+			event_record = NULL;
+		}
 
 		/* Schedule session for deletion */
-		delete_entry = calloc(1, sizeof(delete_entry_t));
-		if (delete_entry) {
-			memset(delete_entry, 0, sizeof(delete_entry_t));
-			delete_entry->session_id = session_id;
-			strncpy(delete_entry->bss, ifname, UBUS_OBJ_LEN);
-			ds_dlist_insert_tail(&deletion_pending_list, delete_entry);
-			delete_entry = NULL;
-		}
+		session_delete(session_id, ifname);
 	}
 }
 
@@ -543,7 +537,6 @@ static void ubus_collector_hostapd_invoke(void *object_path)
 
 static void ubus_collector_complete_bss_cb(struct ubus_request *req, int ret)
 {
-	LOG(DEBUG, "ubus_collector_complete_bss_cb");
 	if (req)
 		free(req);
 }
@@ -639,8 +632,6 @@ static void ubus_collector_chan_switch_events_cb(struct ubus_request *req, int t
 	if (!msg)
 		return;
 
-	LOG(DEBUG, "ubus_collector: received ubus collector chan event message");
-
 	error = blobmsg_parse(ubus_collector_chan_switch_event_policy,
 			      __CHANNEL_SWITCH_EVENT_MAX, tb_chan_event_lst,
 			      blobmsg_data(msg), blobmsg_data_len(msg));
@@ -682,7 +673,6 @@ static void ubus_collector_chan_switch_events_cb(struct ubus_request *req, int t
 
 static void ubus_collector_complete_channel_switch_cb(struct ubus_request *req, int ret)
 {
-	LOG(DEBUG, "ubus_collector_complete_channel_switch_cb");
 	if (req)
 		free(req);
 }
@@ -702,8 +692,6 @@ static void ubus_collector_hostapd_channel_switch_invoke(void *arg)
 		return;
 	}
 
-	LOG(DEBUG, "ubus_collector: requesting hostapd channel switch data");
-
 	ubus_invoke_async(ubus, ubus_object_id, hostapd_method, NULL, req);
 
 	req->data_cb = (ubus_data_handler_t)ubus_collector_chan_switch_events_cb;
@@ -770,24 +758,12 @@ static void ubus_collector_hostapd_clear(uint64_t session_id, char *object_path)
 
 static void ubus_garbage_collector(void *arg)
 {
-	delete_entry_t *delete_entry = NULL;
+	delete_entry_t *delete_session = (delete_entry_t *)arg;
 
-	if (ds_dlist_is_empty(&deletion_pending_list)) {
-		evsched_task_reschedule();
-		return;
+	if (delete_session) {
+		ubus_collector_hostapd_clear(delete_session->session_id, delete_session->bss);
+		free(delete_session);
 	}
-
-	/* Remove a single session from the deletion list */
-
-	delete_entry = ds_dlist_head(&deletion_pending_list);
-	if (delete_entry) {
-		ubus_collector_hostapd_clear(delete_entry->session_id, delete_entry->bss);
-		ds_dlist_remove_head(&deletion_pending_list);
-		free(delete_entry);
-		delete_entry = NULL;
-	}
-
-	evsched_task_reschedule();
 }
 
 int ubus_collector_init(void)
@@ -803,7 +779,6 @@ int ubus_collector_init(void)
 	/* Initialize the global events, session deletion and bss object lists */
 	ds_dlist_init(&g_event_report.client_event_list, dpp_event_record_t, node);
 	ds_dlist_init(&g_event_report.channel_switch_list, dpp_event_channel_switch_t, node);
-	ds_dlist_init(&deletion_pending_list, delete_entry_t, node);
 	ds_dlist_init(&bss_list, bss_obj_t, node);
 
 	/* Schedule an event: invoke hostapd ubus get bss list method  */
@@ -824,15 +799,6 @@ int ubus_collector_init(void)
 		return -1;
 	}
 
-	/* Schedule an event: clear the hostapd sessions from opensync */
-	sched_status = evsched_task(&ubus_garbage_collector, NULL,
-				    EVSCHED_SEC(UBUS_GARBAGE_COLLECTION_DELAY));
-	if (sched_status < 1) {
-		LOG(ERR, "ubus_collector: failed at task creation, status %d",
-		    sched_status);
-		return -1;
-	}
-
 	/* Schedule an event: invoke hostapd ubus channel switch method */
 	sched_status = evsched_task(&ubus_collector_hostapd_channel_switch_invoke, NULL,
 				    EVSCHED_SEC(UBUS_CHANNEL_SWITCH_POLLING_DELAY));

feeds/wlan-ap/opensync/src/src/sm/src/ubus_collector.h

@@ -31,8 +31,8 @@ void ubus_collector_cleanup(void);
 /* Poll sessions after this many seconds */
 #define UBUS_SESSIONS_POLLING_DELAY 9
 
-/* Poll the session clearing 'garbage collector' after this many seconds */
-#define UBUS_GARBAGE_COLLECTION_DELAY 1
+/* Delete session after this many seconds of receiving any first event of the session */
+#define SESSION_DELETE_TIMEOUT 30
 
 #define UBUS_OBJ_LEN 64