[RFC 0/5] Using l_notice for low level IWD state information

[RFC 0/5] Using l_notice for low level IWD state information

[James Prestwood]

Lots is explained in the commit description but being able to run
tooling over IWD logs would be very useful to gather statistics on
how IWD is behaving with respect to connections, roaming, or whatever
else is desired. With these patches I've written a tool that monitors
only the NOTICE log level in the journal and spits out much more
concise information about IWD, for example running it against one of
the FT autotests:

 connecting to TestFT (12:00:00:00:00:01) signal: -80 load: 127/255
 connected
     No scan issued to connect
     Connected SSID: TestFT
     Connected BSS: 12:00:00:00:00:01
     Connecting time: 0ms
 initiating roam to 12:00:00:00:00:02 signal: -30 load: 127/255
 failed to ft-roam to BSS 12:00:00:00:00:02 reason: association-timeout
 disconnected
     Time connected: 5739ms
 connecting to TestFT (12:00:00:00:00:01) signal: -80 load: 127/255
 connected
     Scan time: 5320ms
     Connected SSID: TestFT
     Connected BSS: 12:00:00:00:00:01
     Connecting time: 0ms
     Time disconnected: 5320ms
 initiating roam to 12:00:00:00:00:02 signal: -30 load: 127/255
 failed to ft-roam to 12:00:00:00:00:02 reason: authentication timeout
 initiating roam to 12:00:00:00:00:03 signal: -70 load: 127/255
 FT roamed
     Scan time: 12752ms
     Connected SSID: TestFT
     Connected BSS: 12:00:00:00:00:03
     Connecting time: 230ms
 disconnected
     Time connected: 1ms
 connecting to TestFT (12:00:00:00:00:01) signal: -80 load: 127/255
 connected
     Scan time: 5318ms
     Connected SSID: TestFT
     Connected BSS: 12:00:00:00:00:01
     Connecting time: 0ms
 initiating roam to 12:00:00:00:00:03 signal: -60 load: 127/255
 failed to ft-roam to 12:00:00:00:00:03 status: 53
 initiating roam to 12:00:00:00:00:03 signal: -60 load: 127/255
 roamed
     Scan time: 12758ms
     Connected SSID: TestFT
     Connected BSS: 12:00:00:00:00:03
     Connecting time: 210ms
 initiating roam to 12:00:00:00:00:02 signal: -75 load: 127/255
 FT roamed
     Scan time: 12759ms
     Connected SSID: TestFT
     Connected BSS: 12:00:00:00:00:02
     Connecting time: 10ms
 disconnected
     Time connected: 1ms
 connecting to TestFT (12:00:00:00:00:01) signal: -80 load: 127/255
 connected
     Scan time: 5318ms
     Connected SSID: TestFT
     Connected BSS: 12:00:00:00:00:01
     Connecting time: 0ms
 initiating roam to 12:00:00:00:00:03 signal: -71 load: 127/255
 failed to ft-roam to 12:00:00:00:00:03 status: 53
 initiating roam to 12:00:00:00:00:02 signal: -73 load: 127/255
 FT roamed
     Scan time: 12752ms
     Connected SSID: TestFT
     Connected BSS: 12:00:00:00:00:02
     Connecting time: 220ms
 disconnected
     Time connected: 1ms

James Prestwood (5):
  main: add runtime flag for setting the logger
  station: use l_notice for station_debug_event, allow arguments
  station: add additional station_debug_event's
  netdev: add notice events for connection timeouts
  doc: document use of l_log APIs

 doc/coding-style.txt | 24 ++++++++++++++++++++
 src/main.c           | 14 ++++++++++--
 src/netdev.c         |  6 ++---
 src/station.c        | 52 ++++++++++++++++++++++++++++++++------------
 4 files changed, 77 insertions(+), 19 deletions(-)

-- 
2.34.1

[RFC 1/5] 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

[RFC 2/5] station: use l_notice for station_debug_event, allow arguments

[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 l_notice. The
use of l_notice in IWD will be strictly for the type of messages
described above. Modules using l_notice should follow the same
log format so tooling can parse the messages generically. The
format should be zero or more comma-separated key value pairs,
starting with "event: <event name>".

station_debug_event is being modified to use l_notice as most of
the events are useful for debugging. This was modified slightly
to allow arguments to be passed in order to provide extra
information if available.
---
 src/station.c | 25 +++++++++++++++----------
 1 file changed, 15 insertions(+), 10 deletions(-)

diff --git a/src/station.c b/src/station.c
index ea505ca2..a097174e 100644
--- a/src/station.c
+++ b/src/station.c
@@ -215,15 +215,13 @@ static bool station_is_roaming(struct station *station)
 			station->state == STATION_STATE_FW_ROAMING;
 }
 
-static bool station_debug_event(struct station *station, const char *name)
+static bool station_emit_event(struct station *station, const char *name)
 {
 	struct l_dbus_message *signal;
 
 	if (!iwd_is_developer_mode())
 		return true;
 
-	l_debug("StationDebug.Event(%s)", name);
-
 	signal = l_dbus_message_new_signal(dbus_get_bus(),
 					netdev_get_path(station->netdev),
 					IWD_STATION_DEBUG_INTERFACE, "Event");
@@ -233,6 +231,12 @@ static bool station_debug_event(struct station *station, const char *name)
 	return l_dbus_send(dbus_get_bus(), signal) != 0;
 }
 
+#define station_debug_event(station, name, fmt, ...)			\
+({									\
+	l_notice("event: %s, " fmt, name, ##__VA_ARGS__);		\
+	station_emit_event(station, name);				\
+})
+
 static void station_property_set_scanning(struct station *station,
 								bool scanning)
 {
@@ -1565,7 +1569,7 @@ static void station_enter_state(struct station *station,
 			station_state_to_string(station->state),
 			station_state_to_string(state));
 
-	station_debug_event(station, station_state_to_string(state));
+	station_debug_event(station, station_state_to_string(state), "");
 
 	disconnected = !station_is_busy(station);
 
@@ -2351,13 +2355,14 @@ static bool station_ft_work_ready(struct wiphy_radio_work_item *item)
 		l_queue_insert(station->roam_bss_list, rbss,
 				roam_bss_rank_compare, NULL);
 
-		station_debug_event(station, "ft-fallback-to-reassoc");
+		station_debug_event(station, "ft-fallback-to-reassoc", "");
 
 		station_transition_start(station);
 		l_steal_ptr(rbss);
 		break;
 	case -ENOENT:
-		station_debug_event(station, "ft-roam-failed");
+		station_debug_event(station, "ft-roam-failed",
+					"reason: authentication timeout");
 try_next:
 		station_transition_start(station);
 		break;
@@ -2560,7 +2565,7 @@ static void station_roam_scan_triggered(int err, void *user_data)
 		return;
 	}
 
-	station_debug_event(station, "roam-scan-triggered");
+	station_debug_event(station, "roam-scan-triggered", "");
 
 	/*
 	 * Do not update the Scanning property as we won't be updating the
@@ -2704,7 +2709,7 @@ next:
 
 	/* See if we have anywhere to roam to */
 	if (l_queue_isempty(station->roam_bss_list)) {
-		station_debug_event(station, "no-roam-candidates");
+		station_debug_event(station, "no-roam-candidates", "");
 		goto fail;
 	}
 
@@ -3393,7 +3398,7 @@ static void station_packets_lost(struct station *station, uint32_t num_pkts)
 	if (station_cannot_roam(station))
 		return;
 
-	station_debug_event(station, "packet-loss-roam");
+	station_debug_event(station, "packet-loss-roam", "count: %u", num_pkts);
 
 	elapsed = l_time_diff(station->last_roam_scan, l_time_now());
 
@@ -3423,7 +3428,7 @@ static void station_beacon_lost(struct station *station)
 	if (station_cannot_roam(station))
 		return;
 
-	station_debug_event(station, "beacon-loss-roam");
+	station_debug_event(station, "beacon-loss-roam", "");
 
 	if (station->roam_trigger_timeout)
 		return;
-- 
2.34.1

[RFC 3/5] station: add additional station_debug_event's

[James Prestwood]

Add events/notifications for roaming, connecting and disconnecting
information.
---
 src/station.c | 27 +++++++++++++++++++++++----
 1 file changed, 23 insertions(+), 4 deletions(-)

diff --git a/src/station.c b/src/station.c
index a097174e..7d6a8023 100644
--- a/src/station.c
+++ b/src/station.c
@@ -2389,8 +2389,11 @@ disassociate:
 		station_disassociated(station);
 		break;
 	default:
-		if (ret > 0)
+		if (ret > 0) {
+			station_debug_event(station, "ft-roam-failed",
+						"status: %d", ret);
 			goto try_next;
+		}
 
 		station_roam_failed(station);
 		break;
@@ -2462,8 +2465,11 @@ 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));
+	station_debug_event(station, "roaming-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;
@@ -3164,6 +3170,9 @@ static bool station_retry_owe_default_group(struct station *station)
 static bool station_retry_with_reason(struct station *station,
 					uint16_t reason_code)
 {
+	station_debug_event(station, "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.
@@ -3214,6 +3223,9 @@ static bool station_retry_with_status(struct station *station,
 	else
 		blacklist_add_bss(station->connected_bss->addr);
 
+	station_debug_event(station, "connect-failed", "status: %u",
+				status_code);
+
 	return station_try_next_bss(station);
 }
 
@@ -3374,6 +3386,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:
+		station_debug_event(station, "disconnected-info", "reason: %u",
+					l_get_u16(event_data));
 		station_disassociated(station);
 		return;
 	default:
@@ -3513,7 +3527,12 @@ int __station_connect_network(struct station *station, struct network *network,
 		return r;
 	}
 
-	l_debug("connecting to BSS "MAC, MAC_STR(bss->addr));
+	station_debug_event(station, "connecting-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

[RFC 4/5] 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 | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/src/netdev.c b/src/netdev.c
index 48fb15df..a213b606 100644
--- a/src/netdev.c
+++ b/src/netdev.c
@@ -2639,7 +2639,7 @@ 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);
+		l_notice("event: connect-timeout, reason: %u", timeout_reason);
 		goto error;
 	}
 
@@ -2931,7 +2931,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");
+			l_notice("event: authentication-timeout");
 
 			if (auth_proto_auth_timeout(netdev->ap))
 				return;
@@ -3032,7 +3032,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");
+			l_notice("event: association-timeout");
 
 			if (auth_proto_assoc_timeout(netdev->ap))
 				return;
-- 
2.34.1

[RFC 5/5] 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 | 24 ++++++++++++++++++++++++
 1 file changed, 24 insertions(+)

diff --git a/doc/coding-style.txt b/doc/coding-style.txt
index bf0535c5..fdd9e0e3 100644
--- a/doc/coding-style.txt
+++ b/doc/coding-style.txt
@@ -317,6 +317,30 @@ 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_info    Information that is expected during normal operation. l_info's use
+          should be very limited so non-debug logs are concise
+l_warn    An unexpected, but non-fatal condition ocurred
+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_debug   General debugging. These can be used relatively freely but should
+          provide some piece of useful information.
+l_notice  Reserved for specific event-type notifications about IWD's internal
+          state. These are logs that are mean to be both human-readable and
+          parsed by tooling so they are required to be of a certain syntax. They
+          should start with "event: <name>" followed by comma separated key
+          value pairs containing the data of interest. Event names and their
+          arguments should be consistent across the code base, i.e. two events
+          called in different locations should have the same arguments.
+
+          For example:
+
+          l_notice("event: mycondition, arg1: value1, arg2: value2, ...");
 
 O1: Shorten the name
 ====================
-- 
2.34.1

Re: [RFC 2/5] station: use l_notice for station_debug_event, allow arguments

[Marcel Holtmann]

Hi James,

> 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 l_notice. The
> use of l_notice in IWD will be strictly for the type of messages
> described above. Modules using l_notice should follow the same
> log format so tooling can parse the messages generically. The
> format should be zero or more comma-separated key value pairs,
> starting with "event: <event name>".
> 
> station_debug_event is being modified to use l_notice as most of
> the events are useful for debugging. This was modified slightly
> to allow arguments to be passed in order to provide extra
> information if available.
> ---
> src/station.c | 25 +++++++++++++++----------
> 1 file changed, 15 insertions(+), 10 deletions(-)
> 
> diff --git a/src/station.c b/src/station.c
> index ea505ca2..a097174e 100644
> --- a/src/station.c
> +++ b/src/station.c
> @@ -215,15 +215,13 @@ static bool station_is_roaming(struct station *station)
> station->state == STATION_STATE_FW_ROAMING;
> }
> 
> -static bool station_debug_event(struct station *station, const char *name)
> +static bool station_emit_event(struct station *station, const char *name)
> {
> struct l_dbus_message *signal;
> 
> if (!iwd_is_developer_mode())
> return true;
> 
> - l_debug("StationDebug.Event(%s)", name);
> -
> signal = l_dbus_message_new_signal(dbus_get_bus(),
> netdev_get_path(station->netdev),
> IWD_STATION_DEBUG_INTERFACE, "Event");
> @@ -233,6 +231,12 @@ static bool station_debug_event(struct station *station, const char *name)
> return l_dbus_send(dbus_get_bus(), signal) != 0;
> }
> 
> +#define station_debug_event(station, name, fmt, ...) \
> +({ \
> + l_notice("event: %s, " fmt, name, ##__VA_ARGS__); \
> + station_emit_event(station, name); \
> +})
> +
> static void station_property_set_scanning(struct station *station,
> bool scanning)
> {
> @@ -1565,7 +1569,7 @@ static void station_enter_state(struct station *station,
> station_state_to_string(station->state),
> station_state_to_string(state));
> 
> - station_debug_event(station, station_state_to_string(state));
> + station_debug_event(station, station_state_to_string(state), "");
> 
> disconnected = !station_is_busy(station);
> 
> @@ -2351,13 +2355,14 @@ static bool station_ft_work_ready(struct wiphy_radio_work_item *item)
> l_queue_insert(station->roam_bss_list, rbss,
> roam_bss_rank_compare, NULL);
> 
> - station_debug_event(station, "ft-fallback-to-reassoc");
> + station_debug_event(station, "ft-fallback-to-reassoc", "");
> 
> station_transition_start(station);
> l_steal_ptr(rbss);
> break;
> case -ENOENT:
> - station_debug_event(station, "ft-roam-failed");
> + station_debug_event(station, "ft-roam-failed",
> + "reason: authentication timeout");
> try_next:
> station_transition_start(station);
> break;
> @@ -2560,7 +2565,7 @@ static void station_roam_scan_triggered(int err, void *user_data)
> return;
> }
> 
> - station_debug_event(station, "roam-scan-triggered");
> + station_debug_event(station, "roam-scan-triggered", "");

this is really awful.

Lets have the event / state name as enum or something so that it is const.

And then having the empty “” all the time is insane. That is horrible API and in 2 month you wonder what the “” is for. So let’s not do that. Rather have station_debug_event and station_debug_event_printf.

Or just shorten it into STATION_DBG_EVT and STATION_DEBUG_EVT_PRINTF. I mean, the assumption is that this code is purely for debug and has not functional meaning. So if left out, the code will do the right thing. If not, then never ever call it debug.

Regards

Marcel

Re: [RFC 5/5] doc: document use of l_log APIs

[Marcel Holtmann]

Hi James,

> 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 | 24 ++++++++++++++++++++++++
> 1 file changed, 24 insertions(+)
> 
> diff --git a/doc/coding-style.txt b/doc/coding-style.txt
> index bf0535c5..fdd9e0e3 100644
> --- a/doc/coding-style.txt
> +++ b/doc/coding-style.txt
> @@ -317,6 +317,30 @@ 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_info    Information that is expected during normal operation. l_info's use
> +          should be very limited so non-debug logs are concise
> +l_warn    An unexpected, but non-fatal condition ocurred
> +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_debug   General debugging. These can be used relatively freely but should
> +          provide some piece of useful information.
> +l_notice  Reserved for specific event-type notifications about IWD's internal
> +          state. These are logs that are mean to be both human-readable and
> +          parsed by tooling so they are required to be of a certain syntax. They
> +          should start with "event: <name>" followed by comma separated key
> +          value pairs containing the data of interest. Event names and their
> +          arguments should be consistent across the code base, i.e. two events
> +          called in different locations should have the same arguments.

and now they are not even in order of their log level. That confuses people.

> +
> +          For example:
> +
> +          l_notice("event: mycondition, arg1: value1, arg2: value2, ...");

Please no semantics for the freeform text. If you want that, then better build some proper iwd_log functionality that does that.

Regards

Marcel

Re: [RFC 5/5] doc: document use of l_log APIs

[James Prestwood]

Hi Marcel,

On 2/14/24 11:49 AM, Marcel Holtmann wrote:
> Hi James,
>
>> 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 | 24 ++++++++++++++++++++++++
>> 1 file changed, 24 insertions(+)
>>
>> diff --git a/doc/coding-style.txt b/doc/coding-style.txt
>> index bf0535c5..fdd9e0e3 100644
>> --- a/doc/coding-style.txt
>> +++ b/doc/coding-style.txt
>> @@ -317,6 +317,30 @@ 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_info    Information that is expected during normal operation. l_info's use
>> +          should be very limited so non-debug logs are concise
>> +l_warn    An unexpected, but non-fatal condition ocurred
>> +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_debug   General debugging. These can be used relatively freely but should
>> +          provide some piece of useful information.
>> +l_notice  Reserved for specific event-type notifications about IWD's internal
>> +          state. These are logs that are mean to be both human-readable and
>> +          parsed by tooling so they are required to be of a certain syntax. They
>> +          should start with "event: <name>" followed by comma separated key
>> +          value pairs containing the data of interest. Event names and their
>> +          arguments should be consistent across the code base, i.e. two events
>> +          called in different locations should have the same arguments.
> and now they are not even in order of their log level. That confuses people.
You mean just the order they appear in this document or using l_notice 
for this purpose in general?
>
>> +
>> +          For example:
>> +
>> +          l_notice("event: mycondition, arg1: value1, arg2: value2, ...");
> Please no semantics for the freeform text. If you want that, then better build some proper iwd_log functionality that does that.
The intent was to use l_notice only for this purpose so I felt 
describing the specific semantics was appropriate. I can remove the 
example but since the intended use is very specific and has some syntax 
requirements I think describing those here is needed.
>
> Regards
>
> Marcel
>

Re: [RFC 2/5] station: use l_notice for station_debug_event, allow arguments

[James Prestwood]

Hi Marcel,

On 2/14/24 11:46 AM, Marcel Holtmann wrote:
> Hi James,
>
>> 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 l_notice. The
>> use of l_notice in IWD will be strictly for the type of messages
>> described above. Modules using l_notice should follow the same
>> log format so tooling can parse the messages generically. The
>> format should be zero or more comma-separated key value pairs,
>> starting with "event: <event name>".
>>
>> station_debug_event is being modified to use l_notice as most of
>> the events are useful for debugging. This was modified slightly
>> to allow arguments to be passed in order to provide extra
>> information if available.
>> ---
>> src/station.c | 25 +++++++++++++++----------
>> 1 file changed, 15 insertions(+), 10 deletions(-)
>>
>> diff --git a/src/station.c b/src/station.c
>> index ea505ca2..a097174e 100644
>> --- a/src/station.c
>> +++ b/src/station.c
>> @@ -215,15 +215,13 @@ static bool station_is_roaming(struct station *station)
>> station->state == STATION_STATE_FW_ROAMING;
>> }
>>
>> -static bool station_debug_event(struct station *station, const char *name)
>> +static bool station_emit_event(struct station *station, const char *name)
>> {
>> struct l_dbus_message *signal;
>>
>> if (!iwd_is_developer_mode())
>> return true;
>>
>> - l_debug("StationDebug.Event(%s)", name);
>> -
>> signal = l_dbus_message_new_signal(dbus_get_bus(),
>> netdev_get_path(station->netdev),
>> IWD_STATION_DEBUG_INTERFACE, "Event");
>> @@ -233,6 +231,12 @@ static bool station_debug_event(struct station *station, const char *name)
>> return l_dbus_send(dbus_get_bus(), signal) != 0;
>> }
>>
>> +#define station_debug_event(station, name, fmt, ...) \
>> +({ \
>> + l_notice("event: %s, " fmt, name, ##__VA_ARGS__); \
>> + station_emit_event(station, name); \
>> +})
>> +
>> static void station_property_set_scanning(struct station *station,
>> bool scanning)
>> {
>> @@ -1565,7 +1569,7 @@ static void station_enter_state(struct station *station,
>> station_state_to_string(station->state),
>> station_state_to_string(state));
>>
>> - station_debug_event(station, station_state_to_string(state));
>> + station_debug_event(station, station_state_to_string(state), "");
>>
>> disconnected = !station_is_busy(station);
>>
>> @@ -2351,13 +2355,14 @@ static bool station_ft_work_ready(struct wiphy_radio_work_item *item)
>> l_queue_insert(station->roam_bss_list, rbss,
>> roam_bss_rank_compare, NULL);
>>
>> - station_debug_event(station, "ft-fallback-to-reassoc");
>> + station_debug_event(station, "ft-fallback-to-reassoc", "");
>>
>> station_transition_start(station);
>> l_steal_ptr(rbss);
>> break;
>> case -ENOENT:
>> - station_debug_event(station, "ft-roam-failed");
>> + station_debug_event(station, "ft-roam-failed",
>> + "reason: authentication timeout");
>> try_next:
>> station_transition_start(station);
>> break;
>> @@ -2560,7 +2565,7 @@ static void station_roam_scan_triggered(int err, void *user_data)
>> return;
>> }
>>
>> - station_debug_event(station, "roam-scan-triggered");
>> + station_debug_event(station, "roam-scan-triggered", "");
> this is really awful.
>
> Lets have the event / state name as enum or something so that it is const.
>
> And then having the empty “” all the time is insane. That is horrible API and in 2 month you wonder what the “” is for. So let’s not do that. Rather have station_debug_event and station_debug_event_printf.

So, I can separate station_debug_event from this l_notice stuff, it just 
fit nicely together from the standpoint of these "debug events" are 
useful, and I didn't want have repeated calls like:

station_debug_event(...)

l_notice(...)

The extra argument was to avoid manually parsing some arbitrary number 
of args by always passing in a format string but we could avoid this by 
separating the two and making them independent calls.

>
> Or just shorten it into STATION_DBG_EVT and STATION_DEBUG_EVT_PRINTF. I mean, the assumption is that this code is purely for debug and has not functional meaning. So if left out, the code will do the right thing. If not, then never ever call it debug.
>
> Regards
>
> Marcel
>

Re: [RFC 2/5] station: use l_notice for station_debug_event, allow arguments

[Marcel Holtmann]

Hi James,

>>> 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 l_notice. The
>>> use of l_notice in IWD will be strictly for the type of messages
>>> described above. Modules using l_notice should follow the same
>>> log format so tooling can parse the messages generically. The
>>> format should be zero or more comma-separated key value pairs,
>>> starting with "event: <event name>".
>>> 
>>> station_debug_event is being modified to use l_notice as most of
>>> the events are useful for debugging. This was modified slightly
>>> to allow arguments to be passed in order to provide extra
>>> information if available.
>>> ---
>>> src/station.c | 25 +++++++++++++++----------
>>> 1 file changed, 15 insertions(+), 10 deletions(-)
>>> 
>>> diff --git a/src/station.c b/src/station.c
>>> index ea505ca2..a097174e 100644
>>> --- a/src/station.c
>>> +++ b/src/station.c
>>> @@ -215,15 +215,13 @@ static bool station_is_roaming(struct station *station)
>>> station->state == STATION_STATE_FW_ROAMING;
>>> }
>>> 
>>> -static bool station_debug_event(struct station *station, const char *name)
>>> +static bool station_emit_event(struct station *station, const char *name)
>>> {
>>> struct l_dbus_message *signal;
>>> 
>>> if (!iwd_is_developer_mode())
>>> return true;
>>> 
>>> - l_debug("StationDebug.Event(%s)", name);
>>> -
>>> signal = l_dbus_message_new_signal(dbus_get_bus(),
>>> netdev_get_path(station->netdev),
>>> IWD_STATION_DEBUG_INTERFACE, "Event");
>>> @@ -233,6 +231,12 @@ static bool station_debug_event(struct station *station, const char *name)
>>> return l_dbus_send(dbus_get_bus(), signal) != 0;
>>> }
>>> 
>>> +#define station_debug_event(station, name, fmt, ...) \
>>> +({ \
>>> + l_notice("event: %s, " fmt, name, ##__VA_ARGS__); \
>>> + station_emit_event(station, name); \
>>> +})
>>> +
>>> static void station_property_set_scanning(struct station *station,
>>> bool scanning)
>>> {
>>> @@ -1565,7 +1569,7 @@ static void station_enter_state(struct station *station,
>>> station_state_to_string(station->state),
>>> station_state_to_string(state));
>>> 
>>> - station_debug_event(station, station_state_to_string(state));
>>> + station_debug_event(station, station_state_to_string(state), "");
>>> 
>>> disconnected = !station_is_busy(station);
>>> 
>>> @@ -2351,13 +2355,14 @@ static bool station_ft_work_ready(struct wiphy_radio_work_item *item)
>>> l_queue_insert(station->roam_bss_list, rbss,
>>> roam_bss_rank_compare, NULL);
>>> 
>>> - station_debug_event(station, "ft-fallback-to-reassoc");
>>> + station_debug_event(station, "ft-fallback-to-reassoc", "");
>>> 
>>> station_transition_start(station);
>>> l_steal_ptr(rbss);
>>> break;
>>> case -ENOENT:
>>> - station_debug_event(station, "ft-roam-failed");
>>> + station_debug_event(station, "ft-roam-failed",
>>> + "reason: authentication timeout");
>>> try_next:
>>> station_transition_start(station);
>>> break;
>>> @@ -2560,7 +2565,7 @@ static void station_roam_scan_triggered(int err, void *user_data)
>>> return;
>>> }
>>> 
>>> - station_debug_event(station, "roam-scan-triggered");
>>> + station_debug_event(station, "roam-scan-triggered", "");
>> this is really awful.
>> 
>> Lets have the event / state name as enum or something so that it is const.
>> 
>> And then having the empty “” all the time is insane. That is horrible API and in 2 month you wonder what the “” is for. So let’s not do that. Rather have station_debug_event and station_debug_event_printf.
> 
> So, I can separate station_debug_event from this l_notice stuff, it just fit nicely together from the standpoint of these "debug events" are useful, and I didn't want have repeated calls like:
> 
> station_debug_event(...)
> 
> l_notice(...)

problem is that this turns into spaghetti code. And more complicated the calling function has _debug_ in it, while the action purpose is to actually send a debug event via D-Bus. So the naming is bad.

> The extra argument was to avoid manually parsing some arbitrary number of args by always passing in a format string but we could avoid this by separating the two and making them independent calls.

Yes. This avoids argument guessing. If the majority of cases you use “” or NULL, then it is worth while to have a separate function for it.

Regards

Marcel

Re: [RFC 5/5] doc: document use of l_log APIs

[Marcel Holtmann]

Hi James,

>>> 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 | 24 ++++++++++++++++++++++++
>>> 1 file changed, 24 insertions(+)
>>> 
>>> diff --git a/doc/coding-style.txt b/doc/coding-style.txt
>>> index bf0535c5..fdd9e0e3 100644
>>> --- a/doc/coding-style.txt
>>> +++ b/doc/coding-style.txt
>>> @@ -317,6 +317,30 @@ 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_info    Information that is expected during normal operation. l_info's use
>>> +          should be very limited so non-debug logs are concise
>>> +l_warn    An unexpected, but non-fatal condition ocurred
>>> +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_debug   General debugging. These can be used relatively freely but should
>>> +          provide some piece of useful information.
>>> +l_notice  Reserved for specific event-type notifications about IWD's internal
>>> +          state. These are logs that are mean to be both human-readable and
>>> +          parsed by tooling so they are required to be of a certain syntax. They
>>> +          should start with "event: <name>" followed by comma separated key
>>> +          value pairs containing the data of interest. Event names and their
>>> +          arguments should be consistent across the code base, i.e. two events
>>> +          called in different locations should have the same arguments.
>> and now they are not even in order of their log level. That confuses people.
> You mean just the order they appear in this document or using l_notice for this purpose in general?

the order number / priority they have in reality according to syslog.

>> 
>>> +
>>> +          For example:
>>> +
>>> +          l_notice("event: mycondition, arg1: value1, arg2: value2, ...");
>> Please no semantics for the freeform text. If you want that, then better build some proper iwd_log functionality that does that.
> The intent was to use l_notice only for this purpose so I felt describing the specific semantics was appropriate. I can remove the example but since the intended use is very specific and has some syntax requirements I think describing those here is needed.

If you want something like that then lets enforce that with iwd_log or iwd_notice helper and not via some one line example in the coding style document.

Regards

Marcel