[pkg-wpa-devel] Bug#539915: Bug#539915: wpasupplicant: Spams syslog with CTRL-EVENT-SCAN-RESULTS

[Kel Modderman]

tags 539915 pending
thanks

Hi Ted,

On Sunday 22 November 2009 10:04:12 tytso at mit.edu wrote:
> On Wed, Aug 05, 2009 at 08:30:08AM +1000, Kel Modderman wrote:
> > > I'm using wpa_supplicant via NetworkManager (autostarted by dbus).
> > > I get a lot (multiple hundreds) of those messages in my /var/log/syslog:
> > > 
> > > Aug  4 02:24:26 pluto wpa_supplicant[2781]: CTRL-EVENT-SCAN-RESULTS
> > > Aug  4 02:25:06 pluto wpa_supplicant[2781]: CTRL-EVENT-SCAN-RESULTS
> > > ....
> > > 
> > > Those messages don't look that terribly important to me and should
> > > probably only emitted in debug mode so they don't spam the syslog.
> > 
> > They are required by wpa_ctrl UNIX control socket clients to be notified
> > about new scan results (eg. wpa_gui), i *think*.
> > iirc, there is a launchpad bug for this too, i did patch wpa_supplicant
> > as per that bug to reduce the priority level of the scan-results event
> > to debug level, and wpa_gui seemed to fail to refresh scan results.
> > 
> > Maybe there is a way to special escape them from being logged, while
> > still serving purpose. Need to be forwarded upstream for discussion i guess.
> 
> I'm not sure this is really a upstream problem.

Its a problem, and it requires help from upstream to solve it in a way that
makes everyone happy.

> It's gross as all
> heck that the wpa_gui is using a facility originally from wpa_debug.c
> to communicate with wpa_supplicant.  That's an upstream problem, yes
> and they ought to be ashamed of themselves.  :-)

No idea why anyone needs to be ashamed about that.

> 
> However, it was Debian which added the patch which caused wpa_printf()
> (called from wpa_msg) to be routed to syslog.  That wasn't an upstream
> choice; that was Debian's choice.  And that is what caused the
> problem; although wpa_msg() looked like a syslog-like facility, it's
> not being used for syslog, and in fact they have to be sent at a
> sufficiently high priority for wpa_gui to receive them.  This is
> unfortunately, high enough that that it causes a real mess in syslog.

Yep. I added a patch to the D-Bus service activation file to turn on
logging via the syslog stuff backported from upstream in another patch
(backported from upstream) so that people debugging wpa_supplicant issues,
when using some D-Bus aware application, have an easier life. It was a bad
side effect that some messages are sent very frequently and are logged. This
side effect has been reported and upstream has reacted [1] by adding a
function which should be used for frequent events that avoids logging
anything unless in debug mode.

[1] http://w1.fi/gitweb/gitweb.cgi?p=hostap.git;a=commitdiff_plain;h=69856fadf77e680d01cac09da37e6bb3643ca427

> 
> So one workaround is to simply edit the file:
> 
>   /usr/share/dbus-1/system-services/fi.epitest.hostap.WPASupplicant.service
> 
> and remove the -s from from the exec line.  This will prevent all
> wpa_supplicant messages hitting the syslog, and that is what upstream
> wpa_supplicant binaries will do --- the -s option was added by
> debian/patches/11_syslog.patch.
> 
> The other thing we could do is to hack the 11_syslog.patch to filter
> out WPA_EVENT_SCAN_RESULTS (which is defined in src/common/wpa_ctrl.h)
> to be "CTRL-EVENT-SCAN-RESULTS", as being far too frequent to deserve
> to be syslogged at all.  That's probably the right fix, but I'm lazy,
> so I just used the workaround to prevent my SSD from being totally
> overwhelmed by massive numbers of syslogs.  :-(

Committed [2] as a round up of patches which reduce too frequent messages from
appearing in logs and the QT frontend.

[2] http://lists.alioth.debian.org/pipermail/pkg-wpa-devel/2009-November/002383.html

Thanks, Kel.