Bug 149004

Summary: NetworkManager-vpnc fails to start on first invocation
Product: [openSUSE] SUSE Linux 10.1 Reporter: Michael Meeks <mmeeks>
Component: NetworkAssignee: Robert Love <rml>
Status: RESOLVED WORKSFORME QA Contact: E-mail List <nld10-bugs-qa>
Severity: Normal    
Priority: P5 - None    
Version: Beta 3   
Target Milestone: ---   
Hardware: i686   
OS: Other   
Whiteboard:
Found By: Other Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---

Description Michael Meeks 2006-02-08 08:45:01 UTC
Login, from clean boot.
Click nm-applet, select VPN connections->Cambridge:

error dialog:

"VPN Start Failure

Could not start the VPN connection 'Cambridge' due to a failure launching the VPN program.

The VPN service said: "The VPN login failed because the VPN program could not be started.""

Dismiss dialog, try exactly the same thing again:

this time one gets the 'Authenticate VPN' dialog instead & it works fine.
Comment 1 Michael Meeks 2006-02-08 08:58:31 UTC
So - syslog has tons of stuff wrt. NetworkManager that may be helpful:

Feb  8 08:40:11 (none) network: Starting the NetworkManager
Feb  8 08:40:11 (none) network: Starting the NetworkManagerDispatcher
Feb  8 08:40:12 (none) NetworkManager: <information>	starting...
Feb  8 08:40:13 (none) NetworkManager: <information>	Adding VPN service 'org.freedesktop.NetworkManager.novellvpn' with name 'novellvpn' and program '/usr/bin/nm-novellvpn-service'
Feb  8 08:40:13 (none) NetworkManager: <information>	Adding VPN service 'org.freedesktop.NetworkManager.openvpn' with name 'openvpn' and program '/usr/bin/nm-openvpn-service'
Feb  8 08:40:13 (none) NetworkManager: <information>	Adding VPN service 'org.freedesktop.NetworkManager.vpnc' with name 'vpnc' and program '/usr/bin/nm-vpnc-service'
Feb  8 08:40:21 (none) NetworkManager: <debug info>	[1139388021.328417] nm_system_device_get_system_config (): found config /etc/sysconfig/network/ifcfg-wlan-id-00:02:8a:a9:5e:8b for if eth0
Feb  8 08:40:21 (none) NetworkManager: <debug info>	[1139388021.328873] nm_system_device_get_system_config (): BOOTPROTO=dhcp
Feb  8 08:40:21 (none) NetworkManager: <debug info>	[1139388021.329060] nm_system_device_get_system_config (): ------ Config (eth0)
Feb  8 08:40:21 (none) NetworkManager: <debug info>	[1139388021.329200] nm_system_device_get_system_config (): dhcp=1
Feb  8 08:40:21 (none) NetworkManager: <debug info>	[1139388021.329413] nm_system_device_get_system_config (): addr=0.0.0.0
Feb  8 08:40:21 (none) NetworkManager: <debug info>	[1139388021.329566] nm_system_device_get_system_config (): gw=0.0.0.0
Feb  8 08:40:21 (none) NetworkManager: <debug info>	[1139388021.329711] nm_system_device_get_system_config (): mask=0.0.0.0
Feb  8 08:40:21 (none) NetworkManager: <debug info>	[1139388021.329855] nm_system_device_get_system_config (): --------------------- 
Feb  8 08:40:21 (none) NetworkManager: <information>	eth0: Device is fully-supported using driver 'airo'.
Feb  8 08:40:21 (none) NetworkManager: <information>	nm_device_init(): waiting for device's worker thread to start
Feb  8 08:40:21 (none) NetworkManager: <information>	nm_device_init(): device's worker thread started, continuing.
Feb  8 08:40:21 (none) NetworkManager: <information>	Now managing wireless (802.11) device 'eth0'.
Feb  8 08:40:21 (none) NetworkManager: <information>	Deactivating device eth0.
Feb  8 08:40:21 (none) NetworkManager: <information>	Stopping ypbind.
Feb  8 08:40:21 (none) NetworkManager: <information>	Restarting autofs.
Feb  8 08:40:24 (none) NetworkManager: <information>	eth1: Device is fully-supported using driver 'e100'.
Feb  8 08:40:24 (none) NetworkManager: <information>	nm_device_init(): waiting for device's worker thread to start
Feb  8 08:40:24 (none) NetworkManager: <information>	nm_device_init(): device's worker thread started, continuing.
Feb  8 08:40:24 (none) NetworkManager: <information>	Now managing wired Ethernet (802.3) device 'eth1'.
Feb  8 08:40:24 (none) NetworkManager: <information>	Deactivating device eth1.
Feb  8 08:40:24 (none) NetworkManager: <information>	Stopping ypbind.
Feb  8 08:40:24 (none) NetworkManager: <information>	Restarting autofs.
Feb  8 08:40:25 (none) NetworkManager: <information>	Activated the DHCP daemon /usr/sbin/dhcdbd with PID 3657.
Feb  8 08:40:26 (none) NetworkManager: <information>	Will activate wired connection 'eth1' because it now has a link.
Feb  8 08:40:26 (none) NetworkManager: <information>	SWITCH: no current connection, found better connection 'eth1'.
Feb  8 08:40:26 (none) NetworkManager: <information>	Will activate connection 'eth1'.
Feb  8 08:40:26 (none) NetworkManager: <information>	Device eth1 activation scheduled...
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) started...
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 1 (Device Prepare) scheduled...
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 1 (Device Prepare) started...
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 2 (Device Configure) scheduled...
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 1 (Device Prepare) complete.
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 2 (Device Configure) starting...
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 2 (Device Configure) successful.
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 3 (IP Configure Start) scheduled.
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 2 (Device Configure) complete.
Feb  8 08:40:26 (none) NetworkManager: <information>	Activation (eth1) Stage 3 (IP Configure Start) started...
Feb  8 08:40:27 (none) NetworkManager: <information>	Activation (eth1) Beginning DHCP transaction.
Feb  8 08:40:27 (none) NetworkManager: <information>	Activation (eth1) Stage 3 (IP Configure Start) complete.
Feb  8 08:40:27 (none) NetworkManager: <information>	DHCP daemon state now 12 for interface eth1
Feb  8 08:40:29 (none) NetworkManager: <information>	DHCP daemon state now 1 for interface eth1
Feb  8 08:40:38 (none) NetworkManager: <information>	DHCP daemon state now 2 for interface eth1
Feb  8 08:40:38 (none) NetworkManager: <information>	Activation (eth1) Stage 4 (IP Configure Get) scheduled...
Feb  8 08:40:38 (none) NetworkManager: <information>	Activation (eth1) Stage 4 (IP Configure Get) started...
Feb  8 08:40:38 (none) NetworkManager: <information>	Retrieved the following IP4 configuration from the DHCP daemon:
Feb  8 08:40:38 (none) NetworkManager: <information>	  address 192.168.0.2
Feb  8 08:40:38 (none) NetworkManager: <information>	  netmask 255.255.255.0
Feb  8 08:40:38 (none) NetworkManager: <information>	  broadcast 192.168.0.255
Feb  8 08:40:38 (none) NetworkManager: <information>	  gateway 192.168.0.1
Feb  8 08:40:38 (none) NetworkManager: <information>	  nameserver 213.208.106.212
Feb  8 08:40:38 (none) NetworkManager: <information>	  nameserver 213.208.106.213
Feb  8 08:40:38 (none) NetworkManager: <information>	Activation (eth1) Stage 5 (IP Configure Commit) scheduled...
Feb  8 08:40:38 (none) NetworkManager: <information>	Activation (eth1) Stage 4 (IP Configure Get) complete.
Feb  8 08:40:38 (none) NetworkManager: <information>	Activation (eth1) Stage 5 (IP Configure Commit) started...
Feb  8 08:40:39 (none) NetworkManager: <information>	Activation (eth1) Finish handler scheduled.
Feb  8 08:40:39 (none) NetworkManager: <information>	Activation (eth1) Stage 5 (IP Configure Commit) complete.
Feb  8 08:40:39 (none) NetworkManager: <information>	Activation (eth1) successful, device activated.
Feb  8 08:41:39 (none) NetworkManager: <information>	Updating allowed wireless network lists.
Feb  8 08:41:39 (none) NetworkManager: <information>	Updating VPN Connections...
Feb  8 08:42:17 (none) NetworkManager: <information>	Will activate VPN connection 'Cambridge', service 'org.freedesktop.NetworkManager.vpnc', user_name 'michael', vpn_data 'IPSec gateway / 130.57.170.98 / IPSec ID / vpn_users / Xauth username / mmeeks'.
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 1 (Connection Prepare) scheduled...
Feb  8 08:42:17 (none) NetworkManager: <information>	nm_vpn_service_stage1_daemon_exec(org.freedesktop.NetworkManager.vpnc): execed the VPN service, PID is 3979.
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 2 (Connection Prepare Wait) scheduled...
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN service 'org.freedesktop.NetworkManager.vpnc' signaled new state 6, old state 1.
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 3 (Connect) scheduled...
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 3 (Connect) reply expected soon...
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN service 'org.freedesktop.NetworkManager.vpnc' signaled new state 3, old state 6.
Feb  8 08:42:17 (none) NetworkManager: <WARNING>	 nm_vpn_service_process_signal (): VPN failed for service 'org.freedesktop.NetworkManager.vpnc', signal 'LaunchFailed', with message 'The VPN login failed because the VPN program could not be started.'.
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN service 'org.freedesktop.NetworkManager.vpnc' signaled new state 6, old state 3.
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 3 (Connect) reply received.
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 4 (IP Config Get) timeout scheduled...
Feb  8 08:42:17 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 4 (IP Config Get) reply expected soon...
Feb  8 08:42:17 (none) NetworkManager: <information>	nm_vpn_service_start_connection(org.freedesktop.NetworkManager.vpnc): could not stop connection 'Cambridge' because service was not STARTED.
Feb  8 08:42:17 (none) NetworkManager: <debug info>	[1139388137.925736] nm_dbus_signal_filter (): NetworkManagerInfo triggered update of VPN connection 'Cambridge'
Feb  8 08:45:14 (none) NetworkManager: <information>	Will activate VPN connection 'Cambridge', service 'org.freedesktop.NetworkManager.vpnc', user_name 'michael', vpn_data 'IPSec gateway / 130.57.170.98 / IPSec ID / vpn_users / Xauth username / mmeeks'.
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 1 (Connection Prepare) scheduled...
Feb  8 08:45:14 (none) NetworkManager: <information>	nm_vpn_service_stage1_daemon_exec(org.freedesktop.NetworkManager.vpnc): execed the VPN service, PID is 4126.
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 2 (Connection Prepare Wait) scheduled...
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN service 'org.freedesktop.NetworkManager.vpnc' signaled new state 6, old state 1.
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 3 (Connect) scheduled...
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 3 (Connect) reply expected soon...
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN service 'org.freedesktop.NetworkManager.vpnc' signaled new state 3, old state 6.
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 3 (Connect) reply received.
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 4 (IP Config Get) timeout scheduled...
Feb  8 08:45:14 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 4 (IP Config Get) reply expected soon...
Feb  8 08:45:18 (none) NetworkManager: <information>	VPN Activation (Cambridge) Stage 4 (IP Config Get) reply received.
Feb  8 08:45:19 (none) NetworkManager: <information>	VPN Activation (Cambridge) successful.
Feb  8 08:45:19 (none) NetworkManager: <information>	VPN service 'org.freedesktop.NetworkManager.vpnc' signaled new state 4, old state 3.
Feb  8 08:45:19 (none) NetworkManager: <debug info>	[1139388319.564104] nm_dbus_signal_filter (): NetworkManagerInfo triggered update of VPN connection 'Cambridge'
Comment 2 Robert Love 2006-02-08 15:41:58 UTC
Is this consistently reproducible?
Comment 3 Michael Meeks 2006-02-08 16:02:36 UTC
Well - I keep seeing it yes :-) and the above was from a clean boot - so I hope so  - can I get some more output for you ? strace it or something ?
Comment 4 Robert Love 2006-02-08 16:10:06 UTC
strace would be lovely -- what I want to see is why vpnc (the client NM works with) is failing.  I don't think the problem is NM so much as vpnc dying.  Although NetworkManager-vpnc could also be the problem.

But the strace I want is of vpnc, not NM, and that would be nontrivial ... I suppose 'strace -f' on NM would yield the intended results, but it might be ungainly.
Comment 5 Michael Meeks 2006-02-08 17:35:48 UTC
So - I generated the straces & it works, reboot & re-try no joy - seems to have evaporated; scary. Hope it doesn't come back ;-)