[PATCH 1/7] auto-t: fix failed_roam_test to pass when run on its own

[PATCH 1/7] auto-t: fix failed_roam_test to pass when run on its own

[James Prestwood]

When running this test with others the hostapd neighbors are already
grouped which lets the test pass. On its own this does not happen
and it fails.
---
 autotests/testPSK-roam/failed_roam_test.py | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/autotests/testPSK-roam/failed_roam_test.py b/autotests/testPSK-roam/failed_roam_test.py
index 12e439f6..8cce8bb5 100644
--- a/autotests/testPSK-roam/failed_roam_test.py
+++ b/autotests/testPSK-roam/failed_roam_test.py
@@ -221,6 +221,8 @@ class Test(unittest.TestCase):
         cls.rule_bss2 = hwsim.rules.create()
         cls.rule_bss2.source = hwsim.get_radio('rad2').addresses[0]
 
+        HostapdCLI.group_neighbors(*cls.bss_hostapd)
+
     @classmethod
     def tearDownClass(cls):
         IWD.clear_storage()
-- 
2.34.1

[PATCH 2/7] auto-t: timestamp log files in test-runner

[James Prestwood]

The log files become much more useful when there are timestamps
associated with each log.
---
 tools/utils.py | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/tools/utils.py b/tools/utils.py
index 8219542e..5984fc69 100644
--- a/tools/utils.py
+++ b/tools/utils.py
@@ -6,6 +6,7 @@ import traceback
 import shutil
 import dbus
 
+from datetime import datetime
 from gi.repository import GLib
 from weakref import WeakValueDictionary
 from re import fullmatch
@@ -125,7 +126,11 @@ class Process(subprocess.Popen):
 	@staticmethod
 	def _write_io(instance, data, stdout=True):
 		for f in instance.write_fds:
-			f.write(data)
+			for c in data:
+				f.write(c)
+				if c == '\n':
+					stamp = datetime.strftime(datetime.now(), "%Y-%m-%d %H:%M:%S.%f")
+					f.write(stamp + ': ')
 
 			# Write out a separator so multiple process calls per
 			# test are easer to read.
-- 
2.34.1

[PATCH 3/7] main: add runtime flag for setting the logger

[James Prestwood]

The --logger,-l flag can now be used to specify the logger type.
Unset (default) will set log output to stderr as it is today. The
other valid options are "syslog" and "journal".
---
 src/main.c | 14 ++++++++++++--
 1 file changed, 12 insertions(+), 2 deletions(-)

diff --git a/src/main.c b/src/main.c
index 3ce8340f..acbfdc0c 100644
--- a/src/main.c
+++ b/src/main.c
@@ -63,6 +63,7 @@ static const char *nointerfaces;
 static const char *phys;
 static const char *nophys;
 static const char *debugopt;
+static const char *logger;
 static bool developeropt;
 static bool terminating;
 static bool nl80211_complete;
@@ -164,6 +165,7 @@ static const struct option main_options[] = {
 	{ "nointerfaces", required_argument, NULL, 'I' },
 	{ "phys",         required_argument, NULL, 'p' },
 	{ "nophys",       required_argument, NULL, 'P' },
+	{ "logger",       required_argument, NULL, 'l' },
 	{ "debug",        optional_argument, NULL, 'd' },
 	{ "help",         no_argument,       NULL, 'h' },
 	{ }
@@ -474,7 +476,7 @@ int main(int argc, char *argv[])
 	for (;;) {
 		int opt;
 
-		opt = getopt_long(argc, argv, "Ei:I:p:P:d::vh",
+		opt = getopt_long(argc, argv, "Ei:I:p:P:d::vhl:",
 							main_options, NULL);
 		if (opt < 0)
 			break;
@@ -503,6 +505,9 @@ int main(int argc, char *argv[])
 			else
 				debugopt = "*";
 			break;
+		case 'l':
+			logger = optarg;
+			break;
 		case 'v':
 			printf("%s\n", VERSION);
 			return EXIT_SUCCESS;
@@ -519,7 +524,12 @@ int main(int argc, char *argv[])
 		return EXIT_FAILURE;
 	}
 
-	l_log_set_stderr();
+	if (logger && !strcmp(logger, "syslog"))
+		l_log_set_syslog();
+	else if (logger && !strcmp(logger, "journal"))
+		l_log_set_journal();
+	else
+		l_log_set_stderr();
 
 	if (check_crypto() < 0)
 		return EXIT_FAILURE;
-- 
2.34.1

Re: [PATCH 3/7] main: add runtime flag for setting the logger

[Denis Kenzior]

Hi James,

On 2/22/24 09:24, James Prestwood wrote:
> The --logger,-l flag can now be used to specify the logger type.
> Unset (default) will set log output to stderr as it is today. The
> other valid options are "syslog" and "journal".
> ---
>   src/main.c | 14 ++++++++++++--
>   1 file changed, 12 insertions(+), 2 deletions(-)
> 

Patches 3-7 applied.  1-2 should have been applied using an earlier series.

Regards,
-Denis

[PATCH 4/7] iwd: add iwd_notice for special event/state type of logging

[James Prestwood]

iwd_notice is being added so modules can communicate internal
state or event information via the NOTICE log level. This log
level will be reserved in IWD for only these type of messages.

The iwd_notice macro aims to help enforce some formatting
requirements for these type of log messages. The messages
should be one or more comma-separated "key: value" pairs starting
with "event: <name>" and followed by any additional info that
pertains to that event.

iwd_notice only enforces the initial event key/value format and
additional arguments are left to the caller to be formatted
correctly.
---
 src/iwd.h | 14 ++++++++++++++
 1 file changed, 14 insertions(+)

diff --git a/src/iwd.h b/src/iwd.h
index 1be20df3..a8e2c5db 100644
--- a/src/iwd.h
+++ b/src/iwd.h
@@ -42,3 +42,17 @@ const char *iwd_get_iface_blacklist(void);
 const char *iwd_get_phy_whitelist(void);
 const char *iwd_get_phy_blacklist(void);
 bool iwd_is_developer_mode(void);
+
+#define IWD_NOTICE_STATE		"state"
+#define IWD_NOTICE_CONNECT_INFO		"connect-info"
+#define IWD_NOTICE_ROAM_INFO		"roam-info"
+#define IWD_NOTICE_DISCONNECT_INFO	"disconnect-info"
+#define IWD_NOTICE_FT_ROAM_FAILED	"ft-roam-failed"
+#define IWD_NOTICE_CONNECT_FAILED	"connect-failed"
+#define IWD_NOTICE_AUTH_TIMEOUT		"authentication-timeout"
+#define IWD_NOTICE_ASSOC_TIMEOUT	"association-timeout"
+#define IWD_NOTICE_CONNECT_TIMEOUT	"connect-timeout"
+#define IWD_NOTICE_ROAM_SCAN		"roam-scan"
+
+#define iwd_notice(event, ...) \
+	l_notice("event: " event ", " __VA_ARGS__)
-- 
2.34.1

[PATCH 5/7] doc: document use of l_log APIs

[James Prestwood]

With the introduction of l_notice in IWD some guidelines need to be
set for l_info, l_warn, l_error, l_debug and l_notice.
---
 doc/coding-style.txt | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/doc/coding-style.txt b/doc/coding-style.txt
index bf0535c5..882de026 100644
--- a/doc/coding-style.txt
+++ b/doc/coding-style.txt
@@ -317,6 +317,21 @@ Functions that are static should not be forward-declared.  The only exception
 to this rule is if a circular dependency condition exists, and the forward
 declaration cannot be avoided.
 
+M18: Use appropriate logging levels
+===================================
+An appropriate log level should be used depending on the type of message
+being logged. Logging is done using the l_log APIs in ELL:
+
+l_error   An unexpected condition ocurred. These are generally fatal to the
+          current connection/protocol that is running but not generally to IWD's
+          overall operation.
+l_warn    An unexpected, but non-fatal condition ocurred
+l_notice  Should not be used directly. This log level is reserved for special
+          event type notifications which is handled by iwd_notice().
+l_info    Information that is expected during normal operation. l_info's use
+          should be very limited so non-debug logs are concise
+l_debug   General debugging. These can be used relatively freely but should
+          provide some piece of useful information.
 
 O1: Shorten the name
 ====================
-- 
2.34.1

[PATCH 6/7] station: use iwd_notice for state/event information

[James Prestwood]

For anyone debugging or trying to identify network infrastructure
problems the IWD DBus API isn't all that useful and ultimately
requires going through debug logs to figure out exactly what
happened. Having a concise set of debug logs containing only
relavent information would be very useful. In addition, having
some kind of syntax for these logs to be parsed by tooling could
automate these tasks.

This is being done, starting with station, by using iwd_notice
which internally uses l_notice. The use of the notice log level
(5) in IWD will be strictly for the type of messages described
above.
---
 src/station.c | 34 +++++++++++++++++++++++++++-------
 1 file changed, 27 insertions(+), 7 deletions(-)

diff --git a/src/station.c b/src/station.c
index ea505ca2..8817637b 100644
--- a/src/station.c
+++ b/src/station.c
@@ -1561,9 +1561,9 @@ static void station_enter_state(struct station *station,
 	bool disconnected;
 	int ret;
 
-	l_debug("Old State: %s, new state: %s",
-			station_state_to_string(station->state),
-			station_state_to_string(state));
+	iwd_notice(IWD_NOTICE_STATE, "old: %s, new: %s",
+					station_state_to_string(station->state),
+					station_state_to_string(state));
 
 	station_debug_event(station, station_state_to_string(state));
 
@@ -2352,12 +2352,16 @@ static bool station_ft_work_ready(struct wiphy_radio_work_item *item)
 				roam_bss_rank_compare, NULL);
 
 		station_debug_event(station, "ft-fallback-to-reassoc");
+		iwd_notice(IWD_NOTICE_FT_ROAM_FAILED, "status: %d",
+					MMPDU_STATUS_CODE_INVALID_PMKID);
 
 		station_transition_start(station);
 		l_steal_ptr(rbss);
 		break;
 	case -ENOENT:
 		station_debug_event(station, "ft-roam-failed");
+		iwd_notice(IWD_NOTICE_FT_ROAM_FAILED,
+				"status: authentication timeout");
 try_next:
 		station_transition_start(station);
 		break;
@@ -2384,8 +2388,10 @@ disassociate:
 		station_disassociated(station);
 		break;
 	default:
-		if (ret > 0)
+		if (ret > 0) {
+			iwd_notice(IWD_NOTICE_FT_ROAM_FAILED, "status: %d", ret);
 			goto try_next;
+		}
 
 		station_roam_failed(station);
 		break;
@@ -2457,8 +2463,10 @@ static bool station_try_next_transition(struct station *station,
 	struct handshake_state *new_hs;
 	struct ie_rsn_info cur_rsne, target_rsne;
 
-	l_debug("%u, target %s", netdev_get_ifindex(station->netdev),
-			util_address_to_string(bss->addr));
+	iwd_notice(IWD_NOTICE_ROAM_INFO, "bss: "MAC", signal: %d, load: %d/255",
+					MAC_STR(bss->addr),
+					bss->signal_strength / 100,
+					bss->utilization);
 
 	/* Reset AP roam flag, at this point the roaming behaves the same */
 	station->ap_directed_roaming = false;
@@ -2561,6 +2569,7 @@ static void station_roam_scan_triggered(int err, void *user_data)
 	}
 
 	station_debug_event(station, "roam-scan-triggered");
+	iwd_notice(IWD_NOTICE_ROAM_SCAN);
 
 	/*
 	 * Do not update the Scanning property as we won't be updating the
@@ -3159,6 +3168,8 @@ static bool station_retry_owe_default_group(struct station *station)
 static bool station_retry_with_reason(struct station *station,
 					uint16_t reason_code)
 {
+	iwd_notice(IWD_NOTICE_CONNECT_FAILED, "reason: %u", reason_code);
+
 	/*
 	 * We don't want to cause a retry and blacklist if the password was
 	 * incorrect. Otherwise we would just continue to fail.
@@ -3209,6 +3220,8 @@ static bool station_retry_with_status(struct station *station,
 	else
 		blacklist_add_bss(station->connected_bss->addr);
 
+	iwd_notice(IWD_NOTICE_CONNECT_FAILED, "status: %u", status_code);
+
 	return station_try_next_bss(station);
 }
 
@@ -3369,6 +3382,8 @@ static void station_disconnect_event(struct station *station, void *event_data)
 	case STATION_STATE_FT_ROAMING:
 	case STATION_STATE_FW_ROAMING:
 	case STATION_STATE_NETCONFIG:
+		iwd_notice(IWD_NOTICE_DISCONNECT_INFO, "reason: %u",
+					l_get_u16(event_data));
 		station_disassociated(station);
 		return;
 	default:
@@ -3508,7 +3523,12 @@ int __station_connect_network(struct station *station, struct network *network,
 		return r;
 	}
 
-	l_debug("connecting to BSS "MAC, MAC_STR(bss->addr));
+	iwd_notice(IWD_NOTICE_CONNECT_INFO, "ssid: %s, bss: "MAC", "
+					"signal: %d, load: %d/255",
+					network_get_ssid(network),
+					MAC_STR(bss->addr),
+					bss->signal_strength / 100,
+					bss->utilization);
 
 	station->connected_bss = bss;
 	station->connected_network = network;
-- 
2.34.1

[PATCH 7/7] netdev: add notice events for connection timeouts

[James Prestwood]

The information specific to auth/assoc/connect timeouts isn't
communicated to station so emit the notice events within netdev.
We could communicate this to station by adding separate netdev
events, but this does not seem worth it for this use case as
these notice events aren't strictly limited to station.
---
 src/netdev.c | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

diff --git a/src/netdev.c b/src/netdev.c
index 48fb15df..8a7ff092 100644
--- a/src/netdev.c
+++ b/src/netdev.c
@@ -2639,7 +2639,8 @@ static void netdev_connect_event(struct l_genl_msg *msg, struct netdev *netdev)
 	}
 
 	if (timeout) {
-		l_warn("connect event timed out, reason=%u", timeout_reason);
+		iwd_notice(IWD_NOTICE_CONNECT_TIMEOUT, "reason: %u",
+				timeout_reason);
 		goto error;
 	}
 
@@ -2931,7 +2932,7 @@ static void netdev_authenticate_event(struct l_genl_msg *msg,
 	while (l_genl_attr_next(&attr, &type, &len, &data)) {
 		switch (type) {
 		case NL80211_ATTR_TIMED_OUT:
-			l_warn("authentication event timed out");
+			iwd_notice(IWD_NOTICE_AUTH_TIMEOUT);
 
 			if (auth_proto_auth_timeout(netdev->ap))
 				return;
@@ -3032,7 +3033,7 @@ static void netdev_associate_event(struct l_genl_msg *msg,
 	while (l_genl_attr_next(&attr, &type, &len, &data)) {
 		switch (type) {
 		case NL80211_ATTR_TIMED_OUT:
-			l_warn("association timed out");
+			iwd_notice(IWD_NOTICE_ASSOC_TIMEOUT);
 
 			if (auth_proto_assoc_timeout(netdev->ap))
 				return;
-- 
2.34.1