Re: NM fails to find access points

[René Rask <rene grain dk>]

Dan Williams wrote:
> On Sat, 2008-03-22 at 21:58 +0100, René Rask wrote:
> > Hi list
> >
> > NetworkManager-0.7.0-0.9.1.svn3476.fc9.i386 fails to find access points
> > after restarting the NM daemon.
> > It used to find about 18 APs, but after the last update it only finds
> > about 5 and after restarting NM it very slowly finds some. And not the
> > one I want to use although it is in the same room.
> > Something has gone wrong with scanning in the last few weeks.
>
> Scanning depends on wpa_supplicant behavior as well; we'd need to figure
> out what results are coming out of the supplicant.  The next time you
> get in this situation, can you run:
>
> sudo dbus-send --system --dest=fi.epitest.hostap.WPASupplicant 
--print-reply /fi/epitest/hostap/WPASupplicant/Interfaces/1
fi.epitest.hostap.WPASupplicant.Interface.scanResults
> and report what it says?  Is the BSSID of your AP in that list?
>
> If it is, and you get a lot of APs returned from that command, then the
> problem likely lies in NetworkManager.
This is what I get and my AP is not in the list. It is not hidden and it
 is using WEP security. The APs that show up most of the time have
none,WPA1 and WPA2 encryption. And WEP too I think "iwlist scan" shows
"encryption: on" which I assume is WEP encryption.

[root rr-laptop ~]# dbus-send --system
--dest=fi.epitest.hostap.WPASupplicant --print-reply
/fi/epitest/hostap/WPASupplicant/Interfaces/1
fi.epitest.hostap.WPASupplicant.Interface.scanResults
method return sender=:1.772 -> dest=:1.785 reply_serial=2
   array [
      object path
"/fi/epitest/hostap/WPASupplicant/Interfaces/1/BSSIDs/00a0c5805fdf"
      object path
"/fi/epitest/hostap/WPASupplicant/Interfaces/1/BSSIDs/0019e332da87"
      object path
"/fi/epitest/hostap/WPASupplicant/Interfaces/1/BSSIDs/0006f403b936"
      object path
"/fi/epitest/hostap/WPASupplicant/Interfaces/1/BSSIDs/0013462734c5"
   ]

I can replicate this reliably by restarting the NM daemon. That always
leaves my AP off the list. I can also reliably find my AP again by using
"Create Net Wireless Network". When the new network fails to connect it
will always show my AP (and the rest of them) again. Sometimes it takes
a short while for it to appear, but it always does. Seems like a
scanning delay.

Stopping NM, removing the wireless kernel module, insmod it and starting
NM again also has the effect of making it find my AP again.

> > I tried "Create a new wireless network" which seems to want to connect
> > to an existing network and not create a new one?. Anyway, when it 
failed
> > to connect it found my AP again and connected to that. Great, but 
weird.
> > Seems, like a part of NM needs a good kick to get it moving.
>
> It might have caused the driver to probe-scan your SSID, which causes
> the card/driver to find it, which might not happen every time on a
> broadcast scan.  Is your AP hidden?

My AP isn't hidden.

> > Well. Since that works somewhat randomly, I have another problem. My 
usb
> > modem works (after guessing that using gconf-editor to insert a pin key
> > in the right place would allow it to connect), but most of the time I
> > have to connect, disconnect and connect again to make it work. The 
first
> > time it connects it passes the pin and initializes the modem correctly,
> > but it gets a garbage ip and dns config. It seems NM is a bit too fast
> > or pppd is too fast. It needs to wait a second or to before starting 
the
> > connection routine. (well, I think that is what is needed, but I can't
> > be certain)
>
> Interesting; what model of modem is this?  There are some issues with
> serial speed, but they shouldn't affect pppd or the IP and DNS.  That
> seems more like a pppd issue.  There's a patch to pppd that's required
> in some circumstances to work around ISPs returning bogus DNS servers
> when the client doesn't request some other attribute (WINS perhaps?).
> That might have something to do with it, but seems unlikely.  Could you
> get some logs (from /var/log/messages) of the connection attempts with
> the modem so we can diagnose further?

This is a Huawei e220 HSDPA usb modem.
Is has the latest firmware from my ISP which allows it to run at 7.2 Mbps.

This is the log from a regular connect-disconnect-connect session.
Sometimes this works though, but rarely.

Mar 25 22:00:55 rr-laptop NetworkManager: <info>  User request for
activation of ttyUSB0.
Mar 25 22:00:55 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
starting connection 'Auto GSM network connection'
Mar 25 22:00:55 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 1 of 5 (Device Prepare) scheduled...
Mar 25 22:00:55 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 1 of 5 (Device Prepare) started...
Mar 25 22:00:55 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 1 of 5 (Device Prepare) complete.
Mar 25 22:00:57 rr-laptop NetworkManager: <info>  Registered on Home network
Mar 25 22:00:57 rr-laptop NetworkManager: <info>  Associated with
network: +COPS: 0,0,"3",2
Mar 25 22:00:57 rr-laptop NetworkManager: <info>  Connected, Woo!
Mar 25 22:00:57 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 2 of 5 (Device Configure) scheduled...
Mar 25 22:00:57 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 2 of 5 (Device Configure) starting...
Mar 25 22:00:57 rr-laptop NetworkManager: <info>  Starting pppd connection
Mar 25 22:00:57 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 2 of 5 (Device Configure) complete.
Mar 25 22:00:57 rr-laptop pppd[8502]: Plugin
/usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Mar 25 22:00:58 rr-laptop kernel: PPP generic driver version 2.4.2
Mar 25 22:00:58 rr-laptop pppd[8502]: pppd 2.4.4 started by root, uid 0
Mar 25 22:00:58 rr-laptop pppd[8502]: Using interface ppp0
Mar 25 22:00:58 rr-laptop pppd[8502]: Connect: ppp0 <--> /dev/ttyUSB0
Mar 25 22:00:58 rr-laptop NetworkManager: <WARN>
impl_ppp_manager_need_secrets(): Cleared secrets, but setting didn't
need any secrets.
Mar 25 22:00:58 rr-laptop kernel: PPP Deflate Compression module registered
Mar 25 22:01:03 rr-laptop pppd[8502]: Could not determine remote IP
address: defaulting to 10.64.64.64
Mar 25 22:01:03 rr-laptop pppd[8502]: local  IP address 10.176.244.188
Mar 25 22:01:03 rr-laptop pppd[8502]: remote IP address 10.64.64.64
Mar 25 22:01:03 rr-laptop pppd[8502]: primary   DNS address 10.11.12.13
Mar 25 22:01:03 rr-laptop pppd[8502]: secondary DNS address 10.11.12.14
Mar 25 22:01:03 rr-laptop NetworkManager: <info>  PPP manager(IP Config
Get) reply received.
Mar 25 22:01:03 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 4 of 5 (IP Configure Get) scheduled...
Mar 25 22:01:03 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 4 of 5 (IP Configure Get) started...
Mar 25 22:01:03 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 5 of 5 (IP Configure Commit) scheduled...
Mar 25 22:01:03 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 4 of 5 (IP Configure Get) complete.
Mar 25 22:01:03 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 5 of 5 (IP Configure Commit) started...
Mar 25 22:01:03 rr-laptop NetworkManager: <WARN>
nm_system_device_set_from_ip4_config(): (ppp0) error -17 returned from
rtnl_addr_add():#012Missing link name TLV (errno = Invalid argument)
Mar 25 22:01:04 rr-laptop NetworkManager: <info>  Policy set (ttyUSB0)
as default device for routing and DNS.
Mar 25 22:01:04 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
successful, device activated.
Mar 25 22:01:04 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 5 of 5 (IP Configure Commit) complete.
Mar 25 22:01:43 rr-laptop NetworkManager: <info>  Deactivating device
ttyUSB0.
Mar 25 22:01:43 rr-laptop pppd[8502]: Terminating on signal 15
Mar 25 22:01:43 rr-laptop pppd[8502]: Connect time 0.7 minutes.
Mar 25 22:01:43 rr-laptop pppd[8502]: Sent 472 bytes, received 0 bytes.
Mar 25 22:01:43 rr-laptop pppd[8502]: Connection terminated.
Mar 25 22:01:43 rr-laptop pppd[8502]: Exit.
Mar 25 22:01:45 rr-laptop yum-updatesd-helper: error getting update
info: Cannot retrieve repository metadata (repomd.xml) for repository:
livna-development. Please verify its path and try again
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  User request for
activation of ttyUSB0.
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
starting connection 'Auto GSM network connection'
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 1 of 5 (Device Prepare) scheduled...
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 1 of 5 (Device Prepare) started...
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 1 of 5 (Device Prepare) complete.
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Registered on Home network
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Associated with
network: +COPS: 0,0,"3",2
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Connected, Woo!
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 2 of 5 (Device Configure) scheduled...
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 2 of 5 (Device Configure) starting...
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Starting pppd connection
Mar 25 22:01:46 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 2 of 5 (Device Configure) complete.
Mar 25 22:01:46 rr-laptop pppd[8616]: Plugin
/usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Mar 25 22:01:46 rr-laptop pppd[8616]: pppd 2.4.4 started by root, uid 0
Mar 25 22:01:46 rr-laptop pppd[8616]: Using interface ppp0
Mar 25 22:01:46 rr-laptop pppd[8616]: Connect: ppp0 <--> /dev/ttyUSB0
Mar 25 22:01:46 rr-laptop NetworkManager: <WARN>
impl_ppp_manager_need_secrets(): Cleared secrets, but setting didn't
need any secrets.
Mar 25 22:01:49 rr-laptop pppd[8616]: Could not determine remote IP
address: defaulting to 10.64.64.64
Mar 25 22:01:49 rr-laptop pppd[8616]: local  IP address 10.176.252.50
Mar 25 22:01:49 rr-laptop pppd[8616]: remote IP address 10.64.64.64
Mar 25 22:01:49 rr-laptop pppd[8616]: primary   DNS address 80.251.192.244
Mar 25 22:01:49 rr-laptop pppd[8616]: secondary DNS address 80.251.192.245
Mar 25 22:01:49 rr-laptop NetworkManager: <info>  PPP manager(IP Config
Get) reply received.
Mar 25 22:01:49 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 4 of 5 (IP Configure Get) scheduled...
Mar 25 22:01:49 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 4 of 5 (IP Configure Get) started...
Mar 25 22:01:49 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 5 of 5 (IP Configure Commit) scheduled...
Mar 25 22:01:49 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 4 of 5 (IP Configure Get) complete.
Mar 25 22:01:49 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 5 of 5 (IP Configure Commit) started...
Mar 25 22:01:49 rr-laptop NetworkManager: <WARN>
nm_system_device_set_from_ip4_config(): (ppp0) error -17 returned from
rtnl_addr_add():#012Missing link name TLV (errno = Invalid argument)
Mar 25 22:01:50 rr-laptop NetworkManager: <info>  Policy set (ttyUSB0)
as default device for routing and DNS.
Mar 25 22:01:50 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
successful, device activated.
Mar 25 22:01:50 rr-laptop NetworkManager: <info>  Activation (ttyUSB0)
Stage 5 of 5 (IP Configure Commit) complete.