Bug 483883

Summary: NetworkManager times out whilst waiting for unnecessary passwords
Product: [Fedora] Fedora Reporter: David Anderson <david>
Component: NetworkManagerAssignee: Dan Williams <dcbw>
Status: CLOSED WONTFIX QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 9CC: arxs, dcbw, wtogami
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-07-14 15:15:43 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description David Anderson 2009-02-04 05:07:30 UTC
The first time my computer comes back from hibernating and I try to connect with NetworkManager using a smartphone as a GPRS modem, it asks me for a password to unlock the keyring. There are 2 problems:

1) If I don't type the password into the keyring agent within a few seconds, NetworkManager decides that the connection attempt timed out. This happens often, as the computer runs slowly in the seconds after coming back from hibernate whilst it does lots of swapping.

2) Normally after supplying this password, NetworkManager then asks me for a code to unlock the phone. But the phone is never locked (this feature is not turned on). If I supply a blank password it normally then asks again. This continues until the timeout in 1) occurs. After this, I try again and no passwords are asked for any more. (So it seems that it only asks for this "unlock phone" password if the GNOME keyring needed unlocking).

It seems to me that NM ought to unlock the keyring before starting the talking to the modem. In any case, though, no password is needed by as it's stored on the phone.

$ rpm -q NetworkManager NetworkManager-gnome
NetworkManager-0.7.0-0.12.svn4326.fc9.x86_64
NetworkManager-gnome-0.7.0-0.12.svn4326.fc9.x86_64

Comment 1 Dan Williams 2009-02-17 11:45:55 UTC
This may be fixed in recent F9 updates-testing RPMs; the git20090207 ones at least.  Any chance you'd be willing to try them out?

Comment 2 David Anderson 2009-02-26 07:28:44 UTC
This bug still exists with git20090207 - with no change to any of the details reported.

Comment 3 Dan Williams 2009-03-03 20:42:21 UTC
Could you attach /var/log/messages from the point of resume to the point where NM fails the connection?  I'd like to see a bit more about what NM thinks its doing.  Thanks!

Comment 4 David Anderson 2009-03-06 05:12:47 UTC
Here it is. This time, the GNOME keyring prompt didn't show, but the device PIN prompt did, once. What I've seen is that this line normally appears once in /var/log/messages for every time the PIN prompt appears (normally it appears up to 3 times - after that it either logs in or a timeout occurs).

Mar  6 08:03:50 hodge NetworkManager: <WARN>  update_one_setting(): Failed to update connection secrets: 2 username

Here's the log:

Mar  6 08:03:02 hodge kernel: Restarting tasks ... done.
Mar  6 08:03:02 hodge gnome-power-manager: (david) Resuming computer
Mar  6 08:03:05 hodge kernel: ALSA sound/pci/hda/patch_sigmatel.c:1712: hda_codec: pin nid 08 pin config 40c003fa
Mar  6 08:03:05 hodge kernel: ALSA sound/pci/hda/patch_sigmatel.c:1712: hda_codec: pin nid 09 pin config 404003fb
Mar  6 08:03:05 hodge kernel: ALSA sound/pci/hda/patch_sigmatel.c:1712: hda_codec: pin nid 0d pin config 0421121f
Mar  6 08:03:05 hodge kernel: ALSA sound/pci/hda/patch_sigmatel.c:1712: hda_codec: pin nid 0e pin config 90170310
Mar  6 08:03:05 hodge kernel: ALSA sound/pci/hda/patch_sigmatel.c:1712: hda_codec: pin nid 0f pin config 408003fc
Mar  6 08:03:05 hodge kernel: ALSA sound/pci/hda/patch_sigmatel.c:1712: hda_codec: pin nid 10 pin config 04a11020
Mar  6 08:03:05 hodge kernel: ALSA sound/pci/hda/patch_sigmatel.c:1712: hda_codec: pin nid 11 pin config 401003fd
Mar  6 08:03:05 hodge kernel: ALSA sound/pci/hda/patch_sigmatel.c:1712: hda_codec: pin nid 12 pin config 403003fe
Mar  6 08:03:05 hodge console-kit-daemon[1941]: WARNING: Couldn't read /proc/32578/environ: Failed to open file '/proc/32578/environ': No such file or directory
Mar  6 08:03:05 hodge NetworkManager: <info>  Waking up...
Mar  6 08:03:05 hodge NetworkManager: <info>  (eth0): now managed
Mar  6 08:03:05 hodge NetworkManager: <info>  (eth0): device state change: 1 -> 2
Mar  6 08:03:05 hodge NetworkManager: <info>  (eth0): bringing up device.
Mar  6 08:03:05 hodge NetworkManager: <info>  (eth0): preparing device.
Mar  6 08:03:05 hodge kernel: ADDRCONF(NETDEV_UP): eth0: link is not ready
Mar  6 08:03:05 hodge NetworkManager: <info>  (eth0): deactivating device (reason: 2).
Mar  6 08:03:05 hodge NetworkManager: <info>  (wlan0): now managed
Mar  6 08:03:05 hodge NetworkManager: <info>  (wlan0): device state change: 1 -> 2
Mar  6 08:03:05 hodge NetworkManager: <info>  (wlan0): bringing up device.
Mar  6 08:03:05 hodge acpid: client connected from 2375[0:0]
Mar  6 08:03:05 hodge kernel: input: b43-phy0 as /devices/virtual/input/input21
Mar  6 08:03:05 hodge kernel: b43-phy0: Loading firmware version 410.2160 (2007-05-26 15:32:10)
Mar  6 08:03:05 hodge kernel: Registered led device: b43-phy0::tx
Mar  6 08:03:05 hodge kernel: Registered led device: b43-phy0::rx
Mar  6 08:03:05 hodge kernel: Registered led device: b43-phy0::radio
Mar  6 08:03:05 hodge kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Mar  6 08:03:05 hodge NetworkManager: <info>  (wlan0): preparing device.
Mar  6 08:03:05 hodge NetworkManager: <info>  (wlan0): deactivating device (reason: 2).
Mar  6 08:03:06 hodge kernel: b43-phy0: Radio hardware status changed to DISABLED
Mar  6 08:03:06 hodge kernel: b43-phy0: Radio turned on by software
Mar  6 08:03:06 hodge kernel: b43-phy0: The hardware RF-kill button still turns the radio physically off. Press the button to turn it on.
Mar  6 08:03:36 hodge kernel: hub 1-0:1.0: unable to enumerate USB device on port 7
Mar  6 08:03:37 hodge kernel: usb 5-1: new full speed USB device using ohci_hcd and address 7
Mar  6 08:03:37 hodge kernel: usb 5-1: configuration #1 chosen from 1 choice
Mar  6 08:03:37 hodge kernel: ipaq 5-1:1.0: PocketPC PDA converter detected
Mar  6 08:03:37 hodge kernel: usb 5-1: PocketPC PDA converter now attached to ttyUSB0
Mar  6 08:03:37 hodge kernel: usb 5-1: New USB device found, idVendor=0bb4, idProduct=00cf
Mar  6 08:03:37 hodge kernel: usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Mar  6 08:03:37 hodge kernel: usb 5-1: Product: Generic Serial
Mar  6 08:03:37 hodge kernel: usb 5-1: Manufacturer: HTC
Mar  6 08:03:38 hodge NetworkManager: <info>  ttyUSB0: driver is 'ipaq'.
Mar  6 08:03:38 hodge NetworkManager: <info>  Found new Modem device 'ttyUSB0'.
Mar  6 08:03:38 hodge NetworkManager: <info>  (ttyUSB0): exported as /org/freedesktop/Hal/devices/usb_device_bb4_cf_noserial_if0_serial_usb_0
Mar  6 08:03:43 hodge NetworkManager: <info>  (ttyUSB0): device state change: 1 -> 2
Mar  6 08:03:43 hodge NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 2).
Mar  6 08:03:43 hodge NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0' failed
Mar  6 08:03:43 hodge NetworkManager: nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >= 0' failed
Mar  6 08:03:43 hodge NetworkManager: <info>  (ttyUSB0): device state change: 2 -> 3
Mar  6 08:03:44 hodge NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Auto CDMA network connection'
Mar  6 08:03:44 hodge NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4
Mar  6 08:03:44 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Mar  6 08:03:44 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Mar  6 08:03:44 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Mar  6 08:03:45 hodge NetworkManager: <info>  (ttyUSB0): powering up...
Mar  6 08:03:45 hodge NetworkManager: <info>  Connected, Woo!
Mar  6 08:03:45 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
Mar  6 08:03:45 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
Mar  6 08:03:45 hodge NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5
Mar  6 08:03:46 hodge NetworkManager: <info>  Starting pppd connection
Mar  6 08:03:46 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Mar  6 08:03:46 hodge pppd[32696]: Warning: can't open options file /root/.ppprc: Permission denied
Mar  6 08:03:46 hodge pppd[32696]: Plugin /usr/lib64/pppd/2.4.4/nm-pppd-plugin.so loaded.
Mar  6 08:03:46 hodge pppd[32696]: pppd 2.4.4 started by root, uid 0
Mar  6 08:03:46 hodge pppd[32696]: Using interface ppp0
Mar  6 08:03:46 hodge pppd[32696]: Connect: ppp0 <--> /dev/ttyUSB0
Mar  6 08:03:48 hodge NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 6
Mar  6 08:03:50 hodge NetworkManager: <WARN>  update_one_setting(): Failed to update connection secrets: 2 username
Mar  6 08:03:50 hodge pppd[32696]: CHAP authentication succeeded
Mar  6 08:03:50 hodge pppd[32696]: CHAP authentication succeeded
Mar  6 08:03:50 hodge NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 7
Mar  6 08:03:53 hodge pppd[32696]: Could not determine remote IP address: defaulting to 10.64.64.64
Mar  6 08:03:53 hodge pppd[32696]: local  IP address 172.27.67.229
Mar  6 08:03:53 hodge pppd[32696]: remote IP address 10.64.64.64
Mar  6 08:03:53 hodge pppd[32696]: primary   DNS address (snip)
Mar  6 08:03:53 hodge pppd[32696]: secondary DNS address (snip)
Mar  6 08:03:53 hodge NetworkManager: <info>  PPP manager(IP Config Get) reply received.
Mar  6 08:03:53 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) scheduled...
Mar  6 08:03:53 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) started...
Mar  6 08:03:53 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled...
Mar  6 08:03:53 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP Configure Get) complete.
Mar  6 08:03:53 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started...
Mar  6 08:03:54 hodge NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 8
Mar  6 08:03:54 hodge NetworkManager: <info>  Policy set 'Auto CDMA network connection' (ppp0) as default for routing and DNS.
Mar  6 08:03:54 hodge NetworkManager: <info>  Activation (ttyUSB0) successful, device activated.
Mar  6 08:03:54 hodge NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) complete.

Comment 5 Niels Haase 2009-04-08 21:50:05 UTC
Reporter, are you still running Fedora 9, or have you upgraded to Fedora 10 or
Rawhide? In either case, can you let us know whether the issue is still
happening, and give the current version of the kernel and NM packages you're
using. Thank you.


-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 6 David Anderson 2009-04-09 08:26:30 UTC
NetworkManager-0.7.0-2.git20090207.fc9.x86_64
Issue still exists, no changes.

Comment 7 David Anderson 2009-04-09 08:29:29 UTC
Kernel 2.6.25.11-97.fc9.x86_64

Comment 8 Bug Zapper 2009-06-10 03:32:20 UTC
This message is a reminder that Fedora 9 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 9.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '9'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 9's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 9 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 9 Bug Zapper 2009-07-14 15:15:43 UTC
Fedora 9 changed to end-of-life (EOL) status on 2009-07-10. Fedora 9 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.