Executes wpa_supplicant in too verbose mode

I would agree that it is really quite spammy, but I would imagine it's because it's still very new and the debugging information is useful to collect when it goes wrong.
Having said that, it would be great to be able to get more control about how wpa_supplicant is run and also when - I seem to get little pauses in my network traffic every few minutes while it scans for Access Points, even though I am already connected to one (the only one in range, as it happens).

NM is still beta software. Therefore, the debugging output is necessary for support.

Future versions of NM will reduce the verbosity, as reported upstream.

The claim that the output is needed for support is specious. The messages in question are not very important. However, the messages filling the log *is* a very serious issue.

The entire method that NetworkManager is using to execute wpa_supplicant, to whit, hard coding options in an array in an obscure source file, is a bad move. It completely prevents the user from being able to do debugging by altering options (ironic, isn't it?), it eliminates the ability to execute other versions of the program during testing, it causes large amounts of unneeded crud to be spewed into syslog, thus preventing the user from seeing actual important messages in syslog (this is a serious security threat by the way since subsystems like logcheck get jammed up with the unneeded messages), etc. Ultimately this needs to be fixed. NetworkManager needs to either invoke programs based on configuration file information or needs to execute scripts -- hard coded inline in the code is not good architecture.

Shorter term, I understand that some people might view not filling syslog with junk in a near-default configuration a "wishlist" item, but it is not a minor issue. This is a serious problem because it masks important log messages. I'd like to ask that someone at the very least patch the file to remove the -dd in the Ubuntu version of the package.

We should really fix this for Gutsy.

So how do we want this fixed? is -d ok or too much output as well?

Alexander Sack <email address hidden> writes:
> So how do we want this fixed? is -d ok or too much output as well?

-d is too much in ordinary circumstances.

I think it would be best if it was configurable, say with a command
line flag to network manager or a config file change. That way, it
would be possible to run without heavy debugging output most of the
time, and to turn up the level when one needs it.

In general, network manager relies far too much on hard coded
behaviors. It should be invoking scripts and following user supplied
configuration files. However, fixing this fully is beyond the scope of
the current bug report.

Perry

Is changing syslog facility/level an redirecting all the output to /var/log/debug (or similar) an alternative?

On Fri, May 25, 2007 at 07:59:26AM -0000, Stefan Björk wrote:
> Is changing syslog facility/level an redirecting all the output to
> /var/log/debug (or similar) an alternative?
>

I don't think that all output should go to debug ... I agree that we
should have a less verbose level of output. The question is what level
verbosity is still acceptable?

 - Alexander

Alexander Sack <email address hidden> writes:
> On Fri, May 25, 2007 at 07:59:26AM -0000, Stefan Björk wrote:
>> Is changing syslog facility/level an redirecting all the output to
>> /var/log/debug (or similar) an alternative?
>
> I don't think that all output should go to debug ... I agree that we
> should have a less verbose level of output. The question is what level
> verbosity is still acceptable?

If you make it configurable, there is no issue. People doing debugging
can jack it up and people who are not doing debugging can turn it
down. By default, normal operations should not spew anything at all
into logs that humans pay attention to, but anyone can change that if
they have the ability to configure it.

Perry

i somehow must be blind ... can you tell me where those log messages end up for you?

Alexander Sack <email address hidden> writes:
> i somehow must be blind ... can you tell me where those log messages end
> up for you?

grep for them in /var/log if you're running NetworkManager. They're
pretty unmistakable.

Perry

0.6.5 doesn't do this anymore. Closing.

NetworkManager is certainly still spamming syslog, and the priority of the spam is "notice", not "debug". Is there something wrong with my configuration (Hardy) or has it regressed since this bug was closed?

This is still not fixed. Can it be re-opened?

Since the open bug 294190 was marked as a duplicate of this one, I reopen it.

On Tue, Jan 06, 2009 at 01:47:57AM -0000, Endolith wrote:
> This is still not fixed. Can it be re-opened?

Where do you see this verbosity? Since intrepid most stuff goes to its
own log, so it shouldnt clutter syslog anymore.

 - Alexander

> Where do you see this verbosity?

 > tail /var/log/syslog
Jan 6 12:12:13 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 5 -> 6
Jan 6 12:12:13 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 6 -> 7
Jan 6 12:14:12 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 7 -> 0
Jan 6 12:14:12 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 0 -> 2
Jan 6 12:14:13 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 2 -> 3
Jan 6 12:14:13 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 3 -> 4
Jan 6 12:14:13 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 4 -> 5
Jan 6 12:14:13 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 5 -> 6
Jan 6 12:14:13 inspiron NetworkManager: <info> (eth1): supplicant connection state change: 6 -> 7

 > cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=8.10
DISTRIB_CODENAME=intrepid
DISTRIB_DESCRIPTION="Ubuntu 8.10"

Why would it be sent to its own log anyway? I don't see anyone saying that this information is actually useful for anything. Why is this being logged in the first place?

And the priority is still "notice", not "debug".

On Tue, Jan 06, 2009 at 05:30:24PM -0000, Endolith wrote:
> And the priority is still "notice", not "debug".
>

Yes, thats a different bug then this one (this was about debug
logging). Plesae file a new bug. Thanks!

 - Alexander

Why is that a different bug? This one is about verbose logging.

On Thu, Jan 08, 2009 at 02:44:14PM -0000, Endolith wrote:
> Why is that a different bug? This one is about verbose logging.
>

Because this one is closed and was about debug output ... not messages
that should be debug messages and are not.

 - Alexander

This bug is about the log messages being too verbose, which is still the problem and should not be marked closed. I believe this is the same problem as the bug that I filed Bug #294190. If not, please separate them.

Can someone please explain why these messages are being produced in the first place? What purpose does it serve to the user to have these messages logged?

What Alexander means is that the present report is about NetworkManager starting wpa_supplicant with the -d option, which makes it print debug messages. What you complain about is that wpa_supplicant considers this log message as 'notice' then it should be 'debug'. Those problems are tightly related, of course but don't come from the same package, and deserve different reports.

I agree your original report was more about the result (remove those logs) than technical details, but it was commented upon as a NetworkManager problem, so it's better to open a new report against wpa_supplicant. This doesn't mean nobody will bother about it - cleaner bugs are always more attractive for developers, you know... ;-)

There's some kind of miscommunication here.

In Ubuntu Intrepid, does NetworkManager still start wpa_supplicant with either -d or -dd?
If it still does, then why is this bug marked Fixed?
If it doesn't, then why is it still logging "supplicant connection state change" messages several times per minute?
If I understand correctly, wpa_supplicant started *without* -d or -dd will not log these messages *anywhere*. Do I understand correctly?

My complaint is that these messages are still being logged. I don't care whether they are notice or debug, or which log file they end up in. I care that they're being logged on users' computers by default when they serve no purpose.

You can run 'ps -ef | grep wpa_ | grep -v grep' to get the command line used by NM to start wpa_supplicant.

But the point is that while you may not care where the messages come from, which I understand perfectly, but *we* care for clarity's sake. Open a new report, because if your problem is still here, it's because another bug about bad message priority setting. Why is that a problem for you to separate reports? You know, reports are divided not based on visible problems for users, but about root causes for programmers: this is the best way to provide patches that apply to a precise software.

Now, what I'd like to know is whether this latter bug comes from NM or wpa_supplicant. Alexander, do you have an idea?

wpa_supplicant in Intrepid is *not* being started with -d or -dd, so this bug is fixed.

There is a separate issue with wpa_supplicant being arguably too noisy in its normal operation. That should be filed and fixed separately. AFAIK it's nothing to do with NetworkManager, it's just wpa_supplicant logging state changes. It may well be that the wpa_supplicant developers intend for this to be logged. In the normal course of things people generally don't tail their own syslog, so the impact is fairly low, and it may be useful in debugging poor network performance. Not my call, I just wanted to try and cut through the confusion here: This bug is Fix Released.

"There is a separate issue with wpa_supplicant being arguably too noisy in its normal operation."

Got it. Thanks.

> In the normal course of things people generally don't tail their own syslog, so the impact is fairly low

Unnecessary logging is not good on laptops which try to save energy and spin down hard drivers, for instance.

On Tue, Jan 20, 2009 at 03:45:45PM -0000, Chris Jones wrote:
> wpa_supplicant in Intrepid is *not* being started with -d or -dd, so
> this bug is fixed.
>
> There is a separate issue with wpa_supplicant being arguably too noisy
> in its normal operation. That should be filed and fixed separately.
> AFAIK it's nothing to do with NetworkManager, it's just wpa_supplicant
> logging state changes. It may well be that the wpa_supplicant developers
> intend for this to be logged. In the normal course of things people
> generally don't tail their own syslog, so the impact is fairly low, and
> it may be useful in debugging poor network performance. Not my call, I
> just wanted to try and cut through the confusion here: This bug is Fix
> Released.
>

Thanks Chris and Milan for explaining ...

 - Alexander

On Tue, Jan 20, 2009 at 08:11:36PM -0000, Tormod Volden wrote:
> > In the normal course of things people generally don't tail their own
> syslog, so the impact is fairly low
>
> Unnecessary logging is not good on laptops which try to save energy and
> spin down hard drivers, for instance.
>

Please listen: this bug is closed. whatever you dislike about
wpasupplicant logging behaviour, please file a new bug against
wpasupplicant package. Thanks!

 - Alexander

Note that wpasupplicant has quiet switches as well as verbose switches. Calling it with the quiet switch is probably the solution, so this bug should not be closed.

On Thu, Jan 29, 2009 at 01:42:01AM -0000, Endolith wrote:
> Note that wpasupplicant has quiet switches as well as verbose switches.
> Calling it with the quiet switch is probably the solution, so this bug
> should not be closed.
>

If you continue to do that I will have no other chance but ignore you
... so please dont mistrust my judgement. either do what i say or
dont do anything.

 - Alexander

By the way, the author of wpa_supplicant has confirmed that this is a problem with Network Manager. wpa_supplicant sends messages about state changes over D-Bus, and then Network Manager generates the logs based on those messages (nm-device-wifi.c ), though he feels there is no reason for NM to log these by default.

http://w1.fi/bugz/show_bug.cgi?id=296
https://bugs.launchpad.net/network-manager/+bug/294190

On Sat, Jan 31, 2009 at 07:12:46PM -0000, Endolith wrote:
> By the way, the author of wpa_supplicant has confirmed that this is a
> problem with Network Manager. wpa_supplicant sends messages about state
> changes over D-Bus, and then Network Manager generates the logs based on
> those messages (nm-device-wifi.c ), though he feels there is no reason
> for NM to log these by default.
>
> http://w1.fi/bugz/show_bug.cgi?id=296
> https://bugs.launchpad.net/network-manager/+bug/294190

Thanks. lets continue discussion in that bug.

 - Alexander