WPA writes possibly unnecessary messages to the system log

[Ryan]

Every once in a while (minute or so?) wpa supplicant writes "CTRL-EVENT-SCAN-RESULTS" in the system log.

This looks kind of unnecessary, though I'm not an expert in what it should and should not be logging, so I am filing a bug just in case.

I am on the Jaunty development branch.

[Per Ångström (autark)]

I found this too (Jaunty). What use is that information, without at least a timestamp?

[none (ubuntu-bugs-nullinfinity-deactivatedaccount)]

This still happens for me on Karmic.

[none (ubuntu-bugs-nullinfinity-deactivatedaccount)]

The attached patch fixes this issue by changing the CTRL-EVENT-SCAN-RESULTS message to a debug message and thus prevents it from showing up by default.

[arky (arky)]

Problem exists in karmic

Aug 3 10:56:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 10:58:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:00:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:02:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:04:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:06:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:08:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:10:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:12:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:14:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:16:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:18:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:20:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:22:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:24:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:26:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:28:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:30:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:32:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:34:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:36:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:38:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:40:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:44:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS
Aug 3 11:46:19 karmic-kola wpa_supplicant[2576]: CTRL-EVENT-SCAN-RESULTS

$ apt-cache policy wpasupplicant
wpasupplicant:
  Installed: 0.6.9-3
  Candidate: 0.6.9-3
  Version table:
 *** 0.6.9-3 0
        500 http://us.archive.ubuntu.com karmic/main Packages
        100 /var/lib/dpkg/status

[JP Vossen (jp-jpsdomain)]

Happening again on Karmic upgraded from Jaunty, but I did not notice this on Jaunty. Logcheck installed on both.

$ apt-cache policy wpasupplicant
wpasupplicant:
  Installed: 0.6.9-3ubuntu1
  Candidate: 0.6.9-3ubuntu1
  Version table:
 *** 0.6.9-3ubuntu1 0
        500 http://ports.ubuntu.com karmic/main Packages
        100 /var/lib/dpkg/status

$ grep 'CTRL-EVENT-SCAN-RESULTS' /var/log/syslog | tail
Oct 16 14:31:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:33:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:35:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:37:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:39:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:41:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:43:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:45:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:47:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS
Oct 16 14:49:21 mini9 wpa_supplicant[1455]: CTRL-EVENT-SCAN-RESULTS

Interesting, I am NOT seeing this in my archived Jaunty logs:

# zgrep -l 'CTRL-EVENT-SCAN-RESULTS' /var/log/syslog*
/var/log/syslog
/var/log/syslog.0

# ll syslog*
-rw-r----- 1 syslog adm 26K 2009-10-16 14:53 syslog
-rw-r----- 1 syslog adm 752K 2009-10-16 07:59 syslog.0

### Upgraded to Karmic 2009-10-14 to 2009-10-16 (upgrade was a bit ugly)
-rw-r----- 1 syslog adm 3.7K 2009-10-13 07:55 syslog.1.gz
-rw-r----- 1 syslog adm 3.7K 2009-10-12 07:52 syslog.2.gz
-rw-r----- 1 syslog adm 4.7K 2009-10-11 07:40 syslog.3.gz
-rw-r----- 1 syslog adm 4.6K 2009-10-10 07:49 syslog.4.gz
-rw-r----- 1 syslog adm 3.6K 2009-10-09 02:51 syslog.5.gz
-rw-r----- 1 syslog adm 4.2K 2009-10-08 07:53 syslog.6.gz

[snircher (deuteriumoxide)]

I have found the same thing, but it appears to be causing my computer to crash/freeze. I have posted a separate bug report with my specific problem where the system crashes.

[Martijn Kaandorp (m.a.j.w.kaandorp)]

I am experiencing the same problems (kern.log messages and freezes during streaming media over network).

wpasupplicant:
  Installed: 0.6.9-3ubuntu1
  Candidate: 0.6.9-3ubuntu1
  Version table:
 *** 0.6.9-3ubuntu1 0
        500 http://nl.archive.ubuntu.com karmic/main Packages
        100 /var/lib/dpkg/status

Nov 6 17:44:40 balfrin kernel: [ 1314.692783] ===>rt_ioctl_giwscan. 4(4) BSS returned, data->length = 443
Nov 6 17:46:40 balfrin kernel: [ 1434.696526] ===>rt_ioctl_giwscan. 4(4) BSS returned, data->length = 443
Nov 6 17:48:40 balfrin kernel: [ 1554.690414] ===>rt_ioctl_giwscan. 4(4) BSS returned, data->length = 443
Nov 6 17:50:40 balfrin kernel: [ 1674.694448] ===>rt_ioctl_giwscan. 4(4) BSS returned, data->length = 443
Nov 6 17:52:40 balfrin kernel: [ 1794.692641] ===>rt_ioctl_giwscan. 5(5) BSS returned, data->length = 607
Nov 6 17:54:40 balfrin kernel: [ 1914.689157] ===>rt_ioctl_giwscan. 4(4) BSS returned, data->length = 443
Nov 6 17:56:40 balfrin kernel: [ 2034.692489] ===>rt_ioctl_giwscan. 4(4) BSS returned, data->length = 443

Network controller: RaLink RT2860

Linux balfrin 2.6.31-14-generic #48-Ubuntu SMP Fri Oct 16 14:04:26 UTC 2009 i686 GNU/Linux

Any solutions?

[Alepippirimerlo (ablueg333)]

[quote]
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.
[/quote]
that workaround worked for me.
quoting Ted in http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=539915

[JP Vossen (jp-jpsdomain)]

Hummmm... Until Wireless Just Works (which has never been my experience, even with F/OSS drives and Intel cards), turning off *all* wpa_supplicant logging to syslog sounds like a really bad idea. I do a 'tail -f /var/log/syslog' when attempting to get wireless cards working all the time, and no logging would be a problem.

It's just the useless logging that we're talking about here. And maybe that's what you are talking about with -s, but that isn't clear.

[Gergely Csépány (cheoppy)]

It's still the same on latest Karmic, and since these messages doesn't seem very important and doesn't help me if I need to find out why my wifi is not working they shouldn't be in the syslog. Now all I can do is to read syslog with a 'grep -v CTRL-EVENT-SCAN-RESULTS' filter to see the meaningful messages.

[Schwert (schw3rt)]

i also find a lot of those messages in daemon.log

[Launchpad Janitor (janitor)]

This bug was fixed in the package wpasupplicant - 0.6.9-3ubuntu2

---------------
wpasupplicant (0.6.9-3ubuntu2) lucid; urgency=low

  * debian/patches/12_no_syslog_flood.patch:
    - Upstream GIT change to not flood syslog with CTRL-EVENT-SCAN-RESULTS
      messages (LP: #352118)
 -- Chris Coulson <email address hidden> Fri, 05 Mar 2010 12:45:09 +0000

[VS (storvann)]

Will the fix be uploaded to karmic too?

[Tuomas Lukinmaa (w-launchpad-tumu-iki-fi)]

Shouldn't the service exec line include -qq as well to suppress debug logging?

[Francois Gouget (fgouget)]

There are obviously two different issues in this report:
 * The first one is the CTRL-EVENT-SCAN-RESULTS messages coming from wpa_supplicant.
   I'm not seeing this issue but apparently it's fixed.

 * The second issue is the rt_ioctl_giwscan messages coming from the kernel. It is unrelated to the first one (except for having the same effect in preventing the disk from sleeping) and is thus not fixed. So it should probably be moved to another bug report. For this one I may have found a workaround which is to tell rsyslog to not log these messages. Unfortunately this either failed to prevent syslog from waking my disk or something else is still waking my disk.

# cat /etc/rsyslog.d/00.local-wlan.conf
:msg, contains, "rt_ioctl_giwscan." ~