Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 356339 - net-misc/networkmanager ap scanning causes wireless network delays
Summary: net-misc/networkmanager ap scanning causes wireless network delays
Status: RESOLVED TEST-REQUEST
Alias: None
Product: Gentoo Linux
Classification: Unclassified
Component: Current packages (show other bugs)
Hardware: All Linux
: High normal (vote)
Assignee: Nirbheek Chauhan (RETIRED)
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-02-24 20:30 UTC by William L. Thomson Jr.
Modified: 2012-10-07 14:46 UTC (History)
2 users (show)

See Also:
Package list:
Runtime testing required: ---


Attachments
ping output showing slow times (ping_output.txt,2.40 KB, text/plain)
2011-02-27 02:10 UTC, William L. Thomson Jr.
Details
strace of NetworkManager process at time of slownless (strace_NetworkManager_process.txt,14.81 KB, text/plain)
2011-02-27 04:34 UTC, William L. Thomson Jr.
Details
strace of nm-applet process at time of slowness (strace_nm-applet_process.txt,9.14 KB, text/plain)
2011-02-27 04:35 UTC, William L. Thomson Jr.
Details

Note You need to log in before you can comment on or make changes to this bug.
Description William L. Thomson Jr. 2011-02-24 20:30:45 UTC
This has really been driving me nuts and almost made me ditch network manager a few times. I have been using wpa_supplicant for years without issue. I also changed the settings in /etc/NetworkManager/nm-system-settings.conf as follows

[main]
plugins=ifnet,keyfile

[ifnet]
managed=true
auto_refresh=false

Yet Network Manager is filling up logs as follows and causing disconnects every 5 minutes. The disconnects are much more of concern than filling up logs.

Feb 24 03:17:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Use WPA, but no psk received from NM
Feb 24 03:17:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: update_connection_setting_from_config_block: name:obsidianstudios, id:System (obsidianstudios), uuid: 36761fd5-383f-1fa4-b418-7240b567ad52
Feb 24 03:17:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Writing to /etc/conf.d/net
Feb 24 03:17:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Can't open file /etc/wpa_supplicant/wpa_supplicant.conf for writing
Feb 24 03:17:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Successfully updated obsidianstudios
Feb 24 03:17:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/conf.d/hostname
Feb 24 03:17:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/conf.d/net
Feb 24 03:17:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/wpa_supplicant/wpa_supplicant.conf
Feb 24 03:22:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Use WPA, but no psk received from NM
Feb 24 03:22:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: update_connection_setting_from_config_block: name:obsidianstudios, id:System (obsidianstudios), uuid: 36761fd5-383f-1fa4-b418-7240b567ad52
Feb 24 03:22:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Writing to /etc/conf.d/net
Feb 24 03:22:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Can't open file /etc/wpa_supplicant/wpa_supplicant.conf for writing
Feb 24 03:22:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Successfully updated obsidianstudios
Feb 24 03:22:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/conf.d/hostname
Feb 24 03:22:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/conf.d/net
Feb 24 03:22:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/wpa_supplicant/wpa_supplicant.conf
Feb 24 03:27:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Use WPA, but no psk received from NM
Feb 24 03:27:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: update_connection_setting_from_config_block: name:obsidianstudios, id:System (obsidianstudios), uuid: 36761fd5-383f-1fa4-b418-7240b567ad52
Feb 24 03:27:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Writing to /etc/conf.d/net
Feb 24 03:27:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Can't open file /etc/wpa_supplicant/wpa_supplicant.conf for writing
Feb 24 03:27:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Successfully updated obsidianstudios
Feb 24 03:27:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/conf.d/hostname
Feb 24 03:27:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/conf.d/net
Feb 24 03:27:16 wlt NetworkManager[2282]:    SCPlugin-Ifnet: Monitoring /etc/wpa_supplicant/wpa_supplicant.conf


It kept removing stuff from wpa_supplicant.conf instead of just leaving it alone. Thus after it wrote some stuff there I set attr +i on wpa_supplicant.conf so it won't mess up that file again. But thats another bug report for another day. Just going down the list of annoyances in order of how much they annoy me. That one I have a work around for, so its not as annoying as the other issues.

Now back to the above, unless it loses connection, it should never disconnect and re-establish, surely not every 5 minutes. Why it needs to write to /etc/conf.d/net and /etc/wpa_supplicant/wpa_supplicant.conf every 5 minutes is completely unnecessary. It should only write to those files when something changes, which it has not.
Comment 1 Mu Qiao (RETIRED) gentoo-dev 2011-02-25 03:07:20 UTC
First, I'd like to apologize that ifnet plug-in caused this issue. 

I'm searching the reason now. Which version of NM do you use? Though something is written to /var/log/message every 5 minutes, I don't experience any connection disconnect.
Comment 2 William L. Thomson Jr. 2011-02-25 03:22:56 UTC
(In reply to comment #1)
> First, I'd like to apologize that ifnet plug-in caused this issue.

No worries, no need to apologize and thanks for your efforts on ifnet plug-in.

> I'm searching the reason now. Which version of NM do you use?

net-misc/networkmanager-0.8.2-r6

But it does not seem to be specific to any version. Used a few now, not sure any 7.x. Pretty much avoided it till I came across your blog and saw there was active development effort for it to work properly on Gentoo.

> Though something is written to /var/log/message every 5 minutes, I don't 
> experience any connection disconnect.

It might not be a disconnection per se, but more a cough or choke. It happens every 5 minutes or so, thus I assumed its related to the activity I saw in the logs, as previously shown. I just know allot when typing or doing other things with synergy, I will have a delay every 5 minutes or so. Only last a few seconds, and NM never shows it being disconnect. Really not sure whats going on. I just know if I stop using NM and just use regular gentoo stuff to bring up the wireless interface as I had been for years. No problem, no cough, choke, or what ever you want to call it.

I looked around for the 5 minute timing thing and seems to be more related to NM than any thing ifnet plugin or Gentoo related. Not sure why it can't be configured and seems hard coded in sources. I seem to recall from when I was googling around about this some time ago, others running into similar issues. Or wanting to adjust the 5 minute interval thing. I don't really care so long as its not interrupting the connection. Though the log activity is a bit excessive. Almost seems like there should be no action, unless there is a change in network status, disconnect, connect to another network, configuration change, etc.
Comment 3 Mu Qiao (RETIRED) gentoo-dev 2011-02-25 10:01:50 UTC
I've made some changes so that ifnet plugin won't write anything to /etc/conf.d/net when nothing changed. Please try whether networkmanager-0.8.2-r7 solves your problem.
Comment 4 William L. Thomson Jr. 2011-02-25 19:18:17 UTC
Sounds like a good modification, but I am not sure that changed anything. Will have to give it more time, but thus far seems like the problem remains. I think its from the following lines


Feb 25 14:11:05 wlt NetworkManager[2216]:    SCPlugin-Ifnet: Use WPA, but no psk received from NM
Feb 25 14:11:05 wlt NetworkManager[2216]:    SCPlugin-Ifnet: update_connection_setting_from_config_block: name:obsidianstudios, id:System (obsidianstudios), uuid: 36761fd5-383f-1fa4-b418-7240b567ad52
Feb 25 14:11:05 wlt NetworkManager[2216]:    SCPlugin-Ifnet: Successfully updated obsidianstudios

Which is followed by three monitoring lines as previously shown. I don't think the monitoring is causing a problem, and possibly not even the writing to conf.d/net and wpa_supplicant.conf.

I do question why its saying use WPA when its already connected, and the it says update_connection_setting_from_config_block. Then the last line successfully updated. Not sure what its doing but doesn't seem like it needs to update while its connected. That seems a bit odd.

Comment 5 William L. Thomson Jr. 2011-02-25 20:08:02 UTC
More info, this just popped into logs can't recall seeing this. Before switching to NM used wpa_supplicant for years without issues, no interruptions, delays, etc once connected to a WAP. Unless the WAP went away or something like that

Feb 25 14:43:33 wlt NetworkManager[2216]: <info> (wlan0): supplicant connection state:  completed -> group handshake
Feb 25 14:43:33 wlt NetworkManager[2216]: <info> (wlan0): supplicant connection state:  group handshake -> completed

Before that the last log entry was the monitoring at 14:41:05, then the stuff in comment #4 shows again at 14:46:05. Those lines above at 14:43 were in between the 5 minute cycle. I do experience some oddities at times in between  the 5 minute cycles. Which this could explain that, but not seeing it consistently in logs, seem some what random.

Also as mentioned on another bug incorrectly. Are the monitoring log lines necessary? Seems like excessive and repeat logging of the same information. If not necessary might silence that, or maybe provide a verbosity level as part of config.

Finally just now I noticed that NM is changing my connection speed, it dropped from 54 down to 48 and then went back to 54. This was not related to the 5 minute interval. This happened a minute or so after the last log entry so not related to that. I just took to screenshots of it doing that with the same date, not even a second apart. Its continuing to go back and forth between speeds. Not sure why NM is doing that. I could be wrong, but I do not believe I have ever seen this behavior using wpa_supplicant alone. Once I set a speed it remains at that.

This could be the entire problem, not sure. Though it could be the stuff above, or both. Which if both could really start to explain why my network connection is interrupted to the point of annoying me while I work :)
Comment 6 Mu Qiao (RETIRED) gentoo-dev 2011-02-26 03:58:52 UTC
I find one method call:
priv->timestamp_update_id = g_timeout_add_seconds (300, (GSourceFunc) periodic_update_active_connection_timestamps, manager);

So this is the reason why NM keep updating connection every 5 minutes(update timestamp of connection :P), but I can say that it shouldn't interrupt your work. When the plug-in is informed that it should update the connection, it just write something to /etc/conf.d/net when there is any change. There's nearly nothing that would be done if there were no change (And this is exactly what happened for the 5 minutes cycle).

I will make the log less excessive as you suggested.
Comment 7 William L. Thomson Jr. 2011-02-26 04:08:51 UTC
(In reply to comment #6)
>
> So this is the reason why NM keep updating connection every 5 minutes(update
> timestamp of connection :P),

Yes, that was the area I saw mentioned else where some time back. I am not sure why its hard coded. Seems that should be user adjustable.

> but I can say that it shouldn't interrupt your
> work. When the plug-in is informed that it should update the connection, it
> just write something to /etc/conf.d/net when there is any change. There's
> nearly nothing that would be done if there were no change (And this is exactly
> what happened for the 5 minutes cycle).

I am starting to think more and more its NM changing speeds for some reason. I am not sure why. I will see about switching back to just regular gentoo wireless networking stuff with wpa_supplicant, and see if the speeds change like that and cause any interruption. I really do not recall such in the past, and only seemed to noticed delay/disconnect what ever you want to call it after switching to NM.

> I will make the log less excessive as you suggested.

That would be great, and if need be maybe a config setting to adjust logging verbosity.

All in all really do appreciate your efforts with NM. Avoided it for years till I came across your blog some time back. Also glad to see your on board as a Gentoo dev. Still waiting for recruiting to re-process me, was a dev some time ago, but ran into drama, been trying for close to a year to get back on, but more drama ;)


Comment 8 William L. Thomson Jr. 2011-02-26 22:46:16 UTC
I have no disabled NM entirely. I switched back to just regular Gentoo stuff for wireless interfaces. I can see my speed is still changing. But I am do not have any noticeable interruption in connection, as I had experienced before. Not sure whats going on, but something NM is doing is causing interruptions in my wireless connection. It does not seem to be related to the 5 minute interval, as I have seen delays in between the 5 minute interval, as previously mentioned.

Not sure how to debug this, and need to find out how my connection is interrupted. Will start running some pings in the background and seeing what happens there.

NM never shows the connection as disconnected. But there are noticeable delays. I use synergy and mostly use the keyboard and mouse from my desktop to do stuff on my laptop. At times while I am typing or moving the mouse around, things become unresponsive for a few seconds and then resume. Any characters I typed or mouse movement does occur when things resume.

I would blame synergy, but again its not happening now. I am able to type this bug report without issues, and I have been doing other things as well without issue. This is likely something more specific to NM in general than anything ifnet-plugin related.

Will see what I can do to gather some more useful information, and try to track down the problem. Not sure if there is a debugging mode for NM, to increase the verbosity of the logs. I know you modified things to log less, which is good. On a normal things working basis, don't want much written to logs. But in this situation, the more the better, for debugging purposes.

Stay tuned, more to come :)
Comment 9 William L. Thomson Jr. 2011-02-27 02:10:30 UTC
More information, but not sure its really useful. Looks like I will need to do tcpdump, or something to get any useful information to resolve this issue. I will attach some output from pinging the wap.  Though most useful is the following

Gentoo managed wireless
1015 packets transmitted, 1010 received, 0% packet loss, time 1024087ms
rtt min/avg/max/mdev = 1.333/2.190/41.434/2.257 ms

NM
1295 packets transmitted, 1295 received, 0% packet loss, time 16199641ms
rtt min/avg/max/mdev = 1.320/3.790/241.538/16.451 ms


NM is clearly doing something that is slowing down my connection. Its not causing packet loss, or any errors on the interface. But it is doing something not good :)

Its not related to when it writes to the log file, or any change in speed. I observed changes in speed with both Gentoo managed wireless and NM. When I saw slow pings using NM it was not tied to writing to the logs or changes in speed. I noticed two times it happened to be slow when writing to log as previously posted, less the monitoring stuff no longer being logged. Since it was so inconsistent and other writes to log did not have slow ping times. I cannot relate it to that unfortunately, not the log writing but the activity being logged.

I have no idea what is causing the problem, I just know one exists, shown with the ping times above. Laptop is in a fixed position, and only difference was how my connection was setup and managed. I assume its some monitoring aspect or something NM is doing to check or monitor the connection, maybe renegotiation, not sure.
Comment 10 William L. Thomson Jr. 2011-02-27 02:10:59 UTC
Created attachment 264001 [details]
ping output showing slow times
Comment 11 Mu Qiao (RETIRED) gentoo-dev 2011-02-27 03:47:56 UTC
(In reply to comment #9)
> I have no idea what is causing the problem, I just know one exists, shown with
> the ping times above. Laptop is in a fixed position, and only difference was
> how my connection was setup and managed. I assume its some monitoring aspect or
> something NM is doing to check or monitor the connection, maybe renegotiation,
> not sure.
> 

I think monitoring won't cause the problem because nothing happens when there's
no change made to configuration files. I can't reproduce your problem. Let's
see whether other devs have some opinions. Or maybe this should go to upstream.
Comment 12 William L. Thomson Jr. 2011-02-27 04:33:33 UTC
Well tcpdump provided no useful information. I also ran strace against both NetworkManager and nm-applet processes. I saw some interesting things there, but not sure its related to the problem. I will add a couple attachments for review. This stuff was spit out right around the time of the delay. I kept hitting return to add spaces between segments of output. The attachments contain the bit that seemed to be spit out at the time of the delay. Both show a few -1 EAGAIN (Resource temporarily unavailable) on read operations, but that might be normal.

This very likely is an upstream bug more than ifnet-plugin. However we can still see about resolving the issue, and providing a patch to upstream. Better than just filing a bug with them and dumping it on them. If thats what it takes, I don't have a problem filing a bug with and taking the matter up with upstream.
Comment 13 William L. Thomson Jr. 2011-02-27 04:34:44 UTC
Created attachment 264011 [details]
strace of NetworkManager process at time of slownless
Comment 14 William L. Thomson Jr. 2011-02-27 04:35:11 UTC
Created attachment 264013 [details]
strace of nm-applet process at time of slowness
Comment 15 William L. Thomson Jr. 2011-03-01 00:01:09 UTC
Ok here we go after having fun in the haystack. Looks like this is a upstream issue, though I haven't looked at the referenced upstream bugs. Its surely not with ifnet-plugin or anything Gentoo specific. A bunch of Ubuntu users have been reporting the same problem, on the following bug
https://bugs.launchpad.net/ubuntu/lucid/+source/network-manager/+bug/373680

It seems to be related to scanning for access points periodically, every few (maybe 2) minutes. A temporary work around is to disable that via entering in a BSSID, which is the APs MAC address. Mentioned in comments #34 and #37 in that bug. Its not an ideal solution, but seems to and will work for me for now. However I agree more with comment #40. They provide some patches, but I am not clear on the function of those patches, and I am not using them.

The Ubuntu bug talks about allot of things, and not sure where upstream NM developers are at with this. Ubuntu has closed the bug, but I am not sure Gentoo should do the same. I do not believe this problem has been resolved upstream, and till it is this bug should likely remain open. Ideally would be nice to provide upstream with a patch that resolves this issue if they do not have a solution already.

For now the bssid route seems to have resolved the delays that I was experiencing, but at a price. In my situation I am only connected to the one AP, and its not a very big deal to specify the BSSID. I still do not believe that is a solution, or reason to close bug. But that is up to others to decide.
Comment 16 Pacho Ramos gentoo-dev 2012-10-07 14:46:26 UTC
It should be fixed in latest version per pointed bug report, please restest