wpa_supplicant: Add debug info for eloop functions

components/wpa_supplicant/port/eloop.c

@@ -23,6 +23,10 @@ struct eloop_timeout {
 	void *eloop_data;
 	void *user_data;
 	eloop_timeout_handler handler;
+#ifdef ELOOP_DEBUG
+	char func_name[100];
+	int line;
+#endif
 };
 
 struct eloop_data {
@@ -56,12 +60,21 @@ int eloop_init(void)
 	return 0;
 }
 
+#ifdef ELOOP_DEBUG
+int eloop_register_timeout_debug(unsigned int secs, unsigned int usecs,
+				 eloop_timeout_handler handler, void *eloop_data,
+				 void *user_data, const char *func, int line)
+#else
 int eloop_register_timeout(unsigned int secs, unsigned int usecs,
 			   eloop_timeout_handler handler,
 			   void *eloop_data, void *user_data)
+#endif
 {
 	struct eloop_timeout *timeout, *tmp;
 	os_time_t now_sec;
+#ifdef ELOOP_DEBUG
+	int count = 0;
+#endif
 
 	timeout = os_zalloc(sizeof(*timeout));
 	if (timeout == NULL)
@@ -84,6 +97,10 @@ int eloop_register_timeout(unsigned int secs, unsigned int usecs,
 	timeout->eloop_data = eloop_data;
 	timeout->user_data = user_data;
 	timeout->handler = handler;
+#ifdef ELOOP_DEBUG
+	os_strlcpy(timeout->func_name, func, 100);
+	timeout->line = line;
+#endif
 
 	/* Maintain timeouts in order of increasing time */
 	dl_list_for_each(tmp, &eloop.timeout, struct eloop_timeout, list) {
@@ -93,12 +110,19 @@ int eloop_register_timeout(unsigned int secs, unsigned int usecs,
 			ELOOP_UNLOCK();
 			goto run;
 		}
+#ifdef ELOOP_DEBUG
+		count++;
+#endif
 	}
 	ELOOP_LOCK();
 	dl_list_add_tail(&eloop.timeout, &timeout->list);
 	ELOOP_UNLOCK();
 
 run:
+#ifdef ELOOP_DEBUG
+	wpa_printf(MSG_DEBUG, "ELOOP: Added one timer from %s:%d to call %p, current order=%d",
+			timeout->func_name, line, timeout->handler, count);
+#endif
 	os_timer_disarm(&eloop.eloop_timer);
 	os_timer_arm(&eloop.eloop_timer, 0, 0);
 
@@ -126,8 +150,13 @@ static void eloop_remove_timeout(struct eloop_timeout *timeout)
 }
 
 
+#ifdef ELOOP_DEBUG
+int eloop_cancel_timeout_debug(eloop_timeout_handler handler, void *eloop_data,
+			       void *user_data, const char *func, int line)
+#else
 int eloop_cancel_timeout(eloop_timeout_handler handler,
 			 void *eloop_data, void *user_data)
+#endif
 {
 	struct eloop_timeout *timeout, *prev;
 	int removed = 0;
@@ -143,6 +172,10 @@ int eloop_cancel_timeout(eloop_timeout_handler handler,
 			removed++;
 		}
 	}
+#ifdef ELOOP_DEBUG
+	wpa_printf(MSG_DEBUG, "ELOOP: %s:%d called to remove timer handler=%p, removed count=%d",
+			func, line, handler, removed);
+#endif
 
 	return removed;
 }
@@ -286,7 +319,16 @@ void eloop_run(void)
 				void *user_data = timeout->user_data;
 				eloop_timeout_handler handler =
 					timeout->handler;
+#ifdef ELOOP_DEBUG
+				char fn_name[100] = {0};
+				int line = timeout->line;
+				os_strlcpy(fn_name, timeout->func_name, 100);
+#endif
 				eloop_remove_timeout(timeout);
+#ifdef ELOOP_DEBUG
+				wpa_printf(MSG_DEBUG, "ELOOP: Running timer fn:%p scheduled by %s:%d ",
+						handler, fn_name, line);
+#endif
 				handler(eloop_data, user_data);
 			}
 		}

components/wpa_supplicant/port/include/supplicant_opt.h

@@ -11,6 +11,9 @@
 
 #if CONFIG_WPA_DEBUG_PRINT
 #define DEBUG_PRINT
+#if defined(CONFIG_LOG_DEFAULT_LEVEL_DEBUG) || defined(CONFIG_LOG_DEFAULT_LEVEL_VERBOSE)
+#define ELOOP_DEBUG
+#endif
 #endif
 
 #if CONFIG_WPA_SCAN_CACHE

components/wpa_supplicant/port/os_xtensa.c

@@ -24,7 +24,6 @@
 
 #include "os.h"
 #include <stdlib.h>
-#include <time.h>
 #include <unistd.h>
 #include <sys/time.h>
 #include "esp_random.h"

components/wpa_supplicant/src/utils/eloop.h

@@ -176,9 +176,19 @@ void eloop_unregister_event(void *event, size_t event_size);
  * Register a timeout that will cause the handler function to be called after
  * given time.
  */
+
+#ifdef ELOOP_DEBUG
+int eloop_register_timeout_debug(unsigned int secs, unsigned int usecs,
+				 eloop_timeout_handler handler, void *eloop_data,
+				 void *user_data, const char *func, int line);
+
+#define eloop_register_timeout(secs, usecs, handler, eloop_data, user_data) \
+	eloop_register_timeout_debug(secs, usecs, handler, eloop_data, user_data, __func__, __LINE__)
+#else
 int eloop_register_timeout(unsigned int secs, unsigned int usecs,
 			   eloop_timeout_handler handler,
 			   void *eloop_data, void *user_data);
+#endif
 
 /**
  * eloop_cancel_timeout - Cancel timeouts
@@ -191,8 +201,15 @@ int eloop_register_timeout(unsigned int secs, unsigned int usecs,
  * eloop_register_timeout(). ELOOP_ALL_CTX can be used as a wildcard for
  * cancelling all timeouts regardless of eloop_data/user_data.
  */
+#ifdef ELOOP_DEBUG
+int eloop_cancel_timeout_debug(eloop_timeout_handler handler, void *eloop_data,
+			       void *user_data, const char *func, int line);
+#define eloop_cancel_timeout(handler, eloop_data, user_data) \
+	eloop_cancel_timeout_debug(handler, eloop_data, user_data, __func__, __LINE__)
+#else
 int eloop_cancel_timeout(eloop_timeout_handler handler,
 			 void *eloop_data, void *user_data);
+#endif
 
 /**
  * eloop_cancel_timeout_one - Cancel a single timeout

components/wpa_supplicant/test/test_eloop.c

@@ -16,6 +16,7 @@
 #include "esp_log.h"
 #include "test_utils.h"
 #include "memory_checks.h"
+#include <time.h>
 
 uint32_t timeouts_usec[6] = { 10000, 1000, 10000, 5000, 15000, 1000 };
 uint32_t timeouts_sec[6] = { 10, 1, 10, 5, 15, 1 };
@@ -23,6 +24,7 @@ int executed_order[6];
 int t;
 struct os_reltime ts;
 
+
 /* there is only single instance of esp_timer so no need of protection */
 void callback(void *a, void *b)
 {
@@ -32,15 +34,19 @@ void callback(void *a, void *b)
 	os_get_reltime(&now);
 	os_time_sub(&now, &ts, &age);
 
-	/* let's give 5 ms offset for this small block */
-	if ((age.sec - timeouts_sec[*i]) || age.usec - timeouts_usec[*i] > 5000) {
+	int32_t ms_diff = (age.sec - timeouts_sec[*i]) * 1000 +
+		(age.usec - timeouts_usec[*i]) / 1000;
+
+	/* let's give 50 ms offset for this small block */
+	if (ms_diff > 50) {
 		executed_order[t] = -1;
 	} else {
 		executed_order[t] = *i;
 	}
 	t++;
 
-	ESP_LOGI("Eloop Test", "timer ran after %lu sec and %lu usec of scheduled time", age.sec - timeouts_sec[*i], age.usec - timeouts_usec[*i]);
+	ESP_LOGI("Eloop Test", "timer[%d] ran after %d msec of scheduled time",
+				*i, ms_diff);
 
 }