| Message ID | 20240214193743.963349-3-prestwoj@gmail.com (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | Using l_notice for low level IWD state information | expand |
| Context | Check | Description |
|---|---|---|
| tedd_an/pre-ci_am | success | Success |
| prestwoj/iwd-ci-gitlint | success | GitLint |
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
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 >
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
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;