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

[James Prestwood <prestwoj@gmail.com>]

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
>