[Pkg-utopia-maintainers] Bug#799784: network-manager: VPN connect timer kills reconnect after password fail
Matthew Gabeler-Lee
cheetah at fastcat.org
Tue Sep 22 14:13:00 UTC 2015
Package: network-manager
Version: 1.0.6-1
Severity: normal
I'm experiencing this with network-manager-openvpn, but a quick grep through
the source suggests it is a bug in the core network-manager vpn support and
not in the openvpn plugin itself.
Scenario:
* Start a VPN connection that requires entering secrets (e.g. openvpn with
the PAM plugin on the server)
* Accidentally fat-finger the password
* Reconnect immediately and type the password correctly this time
* Wait a minute and watch NM kill the successfully started VPN
Syslog:
Starting the connection and fat fingering the password:
Sep 22 09:50:23 xyzzy NetworkManager[848]: (nm-openvpn-service:20864): nm-openvpn-WARNING **: (nm-openvpn-service.c:1269):nm_openvpn_start_openvpn_binary: runtime check failed: (priv->mgt_path == NULL)
Sep 22 09:50:23 xyzzy NetworkManager[848]: <info> VPN plugin state changed: starting (3)
Sep 22 09:50:23 xyzzy NetworkManager[848]: nm-openvpn-Message: openvpn started with pid 22961
Sep 22 09:50:23 xyzzy NetworkManager[848]: <info> VPN connection 'xyzzy' (Connect) reply received.
Sep 22 09:50:23 xyzzy nm-openvpn[22961]: OpenVPN 2.3.7 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Sep 8 2015
Sep 22 09:50:23 xyzzy nm-openvpn[22961]: library versions: OpenSSL 1.0.2d 9 Jul 2015, LZO 2.08
Sep 22 09:50:23 xyzzy nm-openvpn[22961]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sep 22 09:50:23 xyzzy nm-openvpn[22961]: NOTE: chroot will be delayed because of --client, --pull, or --up-delay
Sep 22 09:50:23 xyzzy nm-openvpn[22961]: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay
Sep 22 09:50:23 xyzzy nm-openvpn[22961]: UDPv4 link local: [undef]
Sep 22 09:50:23 xyzzy nm-openvpn[22961]: UDPv4 link remote: [AF_INET]xyzzyip:xyzzyport
Sep 22 09:50:25 xyzzy nm-openvpn[22961]: [server] Peer Connection Initiated with [AF_INET]xyzzyip:xyzzyport
Sep 22 09:50:27 xyzzy nm-openvpn[22961]: AUTH: Received control message: AUTH_FAILED
Sep 22 09:50:27 xyzzy nm-openvpn[22961]: SIGUSR1[soft,auth-failure] received, process restarting
Sep 22 09:50:27 xyzzy NetworkManager[848]: <warn> VPN plugin failed: login-failed (0)
Sep 22 09:50:27 xyzzy NetworkManager[848]: <info> VPN plugin state changed: stopped (6)
Sep 22 09:50:27 xyzzy NetworkManager[848]: <info> VPN plugin state change reason: login-failed (10)
Sep 22 09:50:27 xyzzy NetworkManager[848]: (nm-openvpn-service:20864): nm-openvpn-WARNING **: Password verification failed
Sep 22 09:50:27 xyzzy NetworkManager[848]: <warn> error disconnecting VPN: Could not process the request because no VPN connection was active.
Oops, reconnect!
Sep 22 09:50:31 xyzzy NetworkManager[848]: (nm-openvpn-service:20864): nm-openvpn-WARNING **: (nm-openvpn-service.c:1269):nm_openvpn_start_openvpn_binary: runtime check failed: (priv->mgt_path == NULL)
Sep 22 09:50:31 xyzzy NetworkManager[848]: nm-openvpn-Message: openvpn started with pid 23033
Sep 22 09:50:31 xyzzy NetworkManager[848]: <info> VPN plugin state changed: starting (3)
Sep 22 09:50:31 xyzzy NetworkManager[848]: <info> VPN connection 'xyzzy' (Connect) reply received.
Sep 22 09:50:31 xyzzy nm-openvpn[23033]: OpenVPN 2.3.7 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on Sep 8 2015
Sep 22 09:50:31 xyzzy nm-openvpn[23033]: library versions: OpenSSL 1.0.2d 9 Jul 2015, LZO 2.08
Sep 22 09:50:32 xyzzy nm-openvpn[23033]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sep 22 09:50:32 xyzzy nm-openvpn[23033]: NOTE: chroot will be delayed because of --client, --pull, or --up-delay
Sep 22 09:50:32 xyzzy nm-openvpn[23033]: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay
Sep 22 09:50:32 xyzzy nm-openvpn[23033]: UDPv4 link local: [undef]
Sep 22 09:50:32 xyzzy nm-openvpn[23033]: UDPv4 link remote: [AF_INET]xyzzyip:xyzzyport
Sep 22 09:50:33 xyzzy nm-openvpn[23033]: [server] Peer Connection Initiated with [AF_INET]xyzzyip:xyzzyport
Sep 22 09:50:35 xyzzy nm-openvpn[23033]: TUN/TAP device tap0 opened
Sep 22 09:50:35 xyzzy nm-openvpn[23033]: /usr/lib/NetworkManager/nm-openvpn-service-openvpn-helper --tap -- tap0 1500 1574 xyzzy 255.255.255.0 init
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): new Tun device (carrier: OFF, driver: 'tun', ifindex: 6)
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> devices added (path: /sys/devices/virtual/net/tap0, iface: tap0)
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> device added (path: /sys/devices/virtual/net/tap0, iface: tap0): no ifupdown configuration found.
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> VPN connection 'xyzzy' (IP Config Get) reply received.
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> VPN connection 'xyzzy' (IP4 Config Get) reply received.
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> VPN plugin state changed: started (4)
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> VPN connection 'xyzzy' (IP6 Config Get) reply received.
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> VPN Gateway: xyzzyip
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> Tunnel Device: tap0
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> IPv4 configuration:
blahblahblah
Sep 22 09:50:35 xyzzy nm-openvpn[23033]: chroot to '/var/lib/openvpn/chroot' and cd to '/' succeeded
Sep 22 09:50:35 xyzzy nm-openvpn[23033]: GID set to nm-openvpn
Sep 22 09:50:35 xyzzy nm-openvpn[23033]: UID set to nm-openvpn
Sep 22 09:50:35 xyzzy nm-openvpn[23033]: Initialization Sequence Completed
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> IPv6 configuration:
blahblahblah
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> VPN connection 'xyzzy' (IP Config Get) complete.
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): link connected
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> keyfile: add connection in-memory (25d87337-a0de-4b1f-bd2e-1fa21d08ef81,"tap0")
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): device state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): Activation: starting connection 'tap0' (25d87337-a0de-4b1f-bd2e-1fa21d08ef81)
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): device state change: prepare -> config (reason 'none') [40 50 0]
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): device state change: config -> ip-config (reason 'none') [50 70 0]
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): device state change: secondaries -> activated (reason 'none') [90 100 0]
Sep 22 09:50:35 xyzzy dbus[880]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> Policy set 'tap0' (tap0) as default for IPv4 routing and DNS.
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> Policy set 'tap0' (tap0) as default for IPv6 routing and DNS.
Sep 22 09:50:35 xyzzy NetworkManager[848]: <info> (tap0): Activation: successful, device activated.
Sep 22 09:50:35 xyzzy dbus[880]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Sep 22 09:50:35 xyzzy nm-dispatcher: Dispatching action 'vpn-up' for tap0
Sep 22 09:50:37 xyzzy nm-dispatcher: Dispatching action 'up' for tap0
And then, the bug: the connect timer from the first failed attempt fires,
and kills the second sucessful attempt :(
Sep 22 09:51:23 xyzzy NetworkManager[848]: libnm-glib-Message: Connect timer expired, disconnecting.
Sep 22 09:51:23 xyzzy NetworkManager[848]: nm-openvpn-Message: Terminated openvpn daemon with PID 23033.
-- System Information:
Debian Release: stretch/sid
APT prefers testing
APT policy: (990, 'testing'), (500, 'unstable'), (1, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386
Kernel: Linux 4.1.0-2-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
Versions of packages network-manager depends on:
ii adduser 3.113+nmu3
ii dbus 1.10.0-3
ii init-system-helpers 1.23
ii isc-dhcp-client 4.3.3-3
ii libbluetooth3 5.33-1
ii libc6 2.19-20
ii libdbus-1-3 1.10.0-3
ii libdbus-glib-1-2 0.102-1
ii libglib2.0-0 2.44.1-1.1
ii libgnutls-deb0-28 3.3.17-1
ii libgudev-1.0-0 230-2
ii libmm-glib0 1.4.10-1
ii libndp0 1.4-2
ii libnewt0.52 0.52.18-1
ii libnl-3-200 3.2.26-1
ii libnl-genl-3-200 3.2.26-1
ii libnl-route-3-200 3.2.26-1
ii libnm0 1.0.6-1
ii libpam-systemd 225-1
ii libpolkit-agent-1-0 0.105-12
ii libpolkit-gobject-1-0 0.105-12
ii libreadline6 6.3-8+b3
ii libsoup2.4-1 2.50.0-2
ii libsystemd0 225-1
ii libteamdctl0 1.18-1
ii libuuid1 2.26.2-9
ii lsb-base 9.20150826
ii policykit-1 0.105-12
ii udev 225-1
ii wpasupplicant 2.3-2.1
Versions of packages network-manager recommends:
ii crda 3.13-1
ii dnsmasq-base 2.75-1
ii iptables 1.4.21-2+b1
ii iputils-arping 3:20121221-5+b2
pn modemmanager <none>
pn ppp <none>
Versions of packages network-manager suggests:
ii avahi-autoipd 0.6.31-5
pn libteam-utils <none>
-- Configuration Files:
/etc/NetworkManager/NetworkManager.conf changed:
[main]
plugins=ifupdown,keyfile
no-auto-default=
[ifupdown]
managed=false
-- no debconf information
More information about the Pkg-utopia-maintainers
mailing list