Re: [PATCH 1/2] netdev: Add logging for CQM messages

[Denis Kenzior <denkenz@gmail.com>]

Hi Michael,

>> I'm not sure 'above=%d' is going to work.  rssi_event is only set on
>> THRESHOLD_EVENT_LOW/THRESHOLD_EVENT_HIGH.  If RSSI_LEVEL is being reported, that
>> pointer is still NULL.
> 
> Should the top level `if (rssi_event) {` not cover that case? I
> believe it checks both
> pointers before the info statement. I didn't add any output in the case of an
> RSSI_LEVEL but no THRESHOLD_EVENT_* as I haven't seen this actually occurring
> so assumed iwd didn't set up non-threshold events?

Ah you're right.  I guess the kernel does send the threshold event attribute as 
well.  I'm really not sure why actually?  This seems useless since it depends on 
knowing the currently used high/low thresholds, and only the kernel knows those.
>>
>>> +                                                     *rssi_event, *rssi_val);
>>>                        netdev_cqm_event_rssi_value(netdev, *rssi_val);
>>
>> Hmm, I don't think wpa_s uses RSSI_LEVEL stuff in the kernel, does it?  The
>> reason I ask is that we do have UIs that setup RSSI level reporting for
>> displaying connection link quality (in number of bars for example).  Since such
>> events are quite common, I think you're going to get quite a bit of spam in the
>> logs.  Are you only interested in cases where the roaming threshold is reached?
>>    If so, you may need to modify netdev_cqm_event_rssi_value() instead.
> 
> Sorry, I should have included more reasoning behind the change.
> 
> In my use case the client is running headless and so the logs are
> really the only
> insight into why the network might have degraded to the point of causing issues.
> For example, if the client stops receiving data, it is useful to know
> what the rough
> signal level is that caused it as that might imply a dead zone or
> interference. All
> debugging is done remotely as well so we can't ever debug the network while
> it is currently in a bad state hence the log part.

I wonder if we should report this over D-Bus instead?  I mean you can always 
setup your own SignalLevelAgent, or we could even add more reporting via 
StationDiagnostic interface?

> 
> The useful data isn't just the threshold but the general signal level
> at the time of
> an incident. If all is working then we would have roamed before the signal gets
> bad enough  to cause issues (it follows that we don't really care about _good_
> signal values so maybe we could reduce spam there?)
> 
> As for the general spamminess, does the UI RSSI reporting cause more events
> than running normally? I believe I was only seeing events when the signal had
> changed more than the hysteresis value in netdev_build_cmd_cqm_rssi_update
> (5 dBm). This doesn't seem too frequent (for me at least) when the client is
> mostly static. When it is moving it is generally useful information.

It would.  By default we program only the low signal threshold value.  So you 
should only see signal changes around that value.  If an rssi agent is used, 
then multiple thresholds are programmed, so you'd see rssi events even when the 
signal is very good.

> 
> For wpa_supplicant, I'm not sure the exact mechanism it uses but it does report
> almost identical output at a fairly high frequency if the client is moving e.g.
> ```
> May 08 08:56:04 p3-2019 wpa_supplicant[842]: wlp2s0:
> CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-62 noise=-93 txrate=6000
> May 08 08:56:14 p3-2019 wpa_supplicant[842]: wlp2s0:
> CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-76 noise=-93 txrate=6000
> May 08 08:56:27 p3-2019 wpa_supplicant[842]: wlp2s0:
> CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-79 noise=-94 txrate=6000
> ```
> 

Right, but I think it sets a single CQM threshold, not multiple like we (might) 
do.  Also, wpa_s is very spammy since it is really (only) meant for testing wifi 
implementations in a lab ;)

> Finally, the reason I made this `info` level was in the hope that I could
> remove the `-d` flag from iwd which does produce a lot of spam in the logs.
> This isn't really feasible at the moment as there isn't enough `info` logging
> to track down any issues that might occur on production systems where
> changes are harder to make. If the `info` level becomes to verbose, maybe
> iwd could set the default logging level to `warn` to reduce spam?

You can use a glob match for the -d flag.  Something like:
	#iwd -d '*Signal change event*'

So you can make the rssi messages as 'debug', and have iwd only print those you 
want.  Multiple globs are supported too, separate them by ':' or ','.

Regards,
-Denis