spews logs with "supplicant connection state change"

I also wonder why my connection changes state all the time... If it really does.

yes, those messages should become "debug" level.

... we should forward this bug appropriately (after checking that final
0.7 still has the same issue -> intrepid/jaunty packages available in ~network-manager PPA)

Are these messages even necessary? Why?

Wait... is this part of the reason why my hard drive has 1.4 million load cycles?

"I needed to find out who was accessing the disk so frequently. iotop is a nice utility for this. wpa-supplicant was at the top of the list. I am using a wireless connection, and wpa-supplicant frequently logs something. Next was gconf-d, followed by gnome-do and console-kit-daemon."

http://www.botcyb.org/2008/12/linux-hard-disk-issue-excessive.html

This looks like the logger line, if that's any help:

2180 nm_info ("(%s): supplicant connection state change: %d -> %d",
2181 nm_device_get_iface (dev), old_state, new_state);

http://bazaar.launchpad.net/~network-manager/network-manager/main.resolvconf/annotate/head%3A/src/nm-device-wifi.c

I don't know where the log level is determined, but there's a switch for it in /src/nm-logging.c

Just to be sure: this bug only affects some specific configurations. I'm in Intrepid with an Intel ipw2200 wireless card, and my logs don't show this at all. Can you give us some details about your hardware?

Anyway, this should not really kill your hard disk since it happens every 2 minutes, with about 5-7 lines at the same time. So if the drive spins up more often than that, it may be another issue.

Intrepid, Dell Inspiron 8600, Intel® PRO/Wireless 2915ABG, network is WPA2 AES (botcyb.org cites wpa_supplicant as the offender, though that may be unrelated to this?)

It's not just about killing the hard drive; it's about filling up the system logs with unnecessary information. Are these logs actually useful for someone or were they left on by the developers accidentally?

Yes, these logs are obviously useless and should be removed ASAP. I was just noting that the hard drive issue comes from other factors (too).

ya i have some problem. I using rt2570 driver.

Jan 18 09:37:23 user NetworkManager: <info> (wlan0): supplicant connection state change: 2 -> 0
Jan 18 09:37:26 user NetworkManager: <info> (wlan0): supplicant connection state change: 0 -> 2
Jan 18 09:37:35 user NetworkManager: <info> (wlan0): supplicant connection state change: 2 -> 3
Jan 18 09:37:35 user NetworkManager: <info> (wlan0): supplicant connection state change: 3 -> 0
Jan 18 09:37:36 user NetworkManager: <info> (wlan0): supplicant connection state change: 0 -> 4
Jan 18 09:37:36 user NetworkManager: <info> (wlan0): supplicant connection state change: 4 -> 7

anyway by using manual ifconfig rausb0 ap,channel,key , is working fine.

This is apparently caused by wpa_supplicant alone and NetworkManager has no control over it, despite the text of the log messages.

So wpa_supplicant is logging these messages despite being started without the -d option:

/sbin/wpa_supplicant -u -f /var/log/wpa_supplicant.log

  -d = increase debugging verbosity (-dd even more)
  -u = enable DBus control interface
  -f = log output to debug file instead of stdout

Actually:

  -q = decrease debugging verbosity (-qq even less)

Maybe NetworkManager should start it with this option?

It could. But maybe NM could also decide to redirect these messages to its own log or to discard them according to the debug level the user chooses. Anyway we need somebody that knows a little how this is done in NM and in wpa_supplicant to decide upon this.

This message is _not_ from wpa_supplicant nor controlled by wpa_supplicant. This state change is an internal event in wpa_supplicant it is logged at debug level there. Notification about the change is made available over dbus, but I see no point in logging that by default. Anyway, the control over what to do with that message is not in wpa_supplicant. For this particular message, that control is in NetworkManager.

So this logging needs to be removed or switched off in Network Manager?

yes, at least it should go to "debug" not info. should be rather a simple patch.

I guess it is not wpa_supplicant's fault. On Intrepid a

ps -ef | grep wpa_suppli

reveals the start options:

/sbin/wpa_supplicant -u -f /var/log/wpa_supplicant.log

These are written in the file:
/usr/share/dbus-1/system-services/fi.epitest.hostap.WPASupplicant.service

I added a "-qq" here:
/sbin/wpa_supplicant -qq -u -f /var/log/wpa_supplicant.log

But even after wpa_supplicant has been restartet, syslog is dumped with these connection-state messages. So, I guess, it has got to be NetworkManager itself.

I guess the verbose/quiet options only affect the logging to standard output, and not the DBus messages it sends to Network Manager?

I don't know which file the nm_info function is in

Is there any good reason why it's still logging this?

At the very least, you could get rid of the numbers so it just says

    NetworkManager: <info> (eth1): supplicant connection state change
    last message repeated 5437 times

I would like to have this issued resolved. It is preventing my system from allowing my hard disks to spindown.

Still a problem with Ubuntu 9.10

Nov 1 03:17:33 ggv-desktop wpa_supplicant[1448]: CTRL-EVENT-SCAN-RESULTS
Nov 1 03:19:33 ggv-desktop wpa_supplicant[1448]: CTRL-EVENT-SCAN-RESULTS
Nov 1 03:21:33 ggv-desktop wpa_supplicant[1448]: CTRL-EVENT-SCAN-RESULTS
Nov 1 03:23:33 ggv-desktop wpa_supplicant[1448]: CTRL-EVENT-SCAN-RESULTS

Lucid is still missing the -qq parameter from service command line to suppress unnecessary debug messages. NetworkManager UI is already provided to catch and notify the warnings and state changes logged by wpasupplicant.

I believe this is fixed at least in trusty, isn't it?

This bug was marked Incomplete some time ago and was supposed to autoclose after 90 days. I'm going to close it manually due to no activity (and likely the issue has gone away/been fixed).