Re: NM fails to find access points

[Dan Williams <dcbw redhat com>]

On Wed, 2008-03-26 at 21:17 +0100, René Rask wrote:
> 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.

So this is pointing more towards a driver problem.  If you ever have to
rmmod/insmod and stuff starts magically working again, it is almost
always a driver issue.

One more question: does your AP almost always show with 'iwlist', but
usually never when doing the dbus-send to the supplicant?

You might also try to do an 'iwlist' and then right afterwards, poke the
supplicant with the dbus-send command and see if your AP is in the list.
If the iwconfig and the supplicant-reported APs are quite different,
then the supplicant is the problem.

If you can poke around a bit with these things, let me know what happens
so we can narrow down the issue further.

Dan

> >> 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.
> 
> 
> 
>