Bug 1266440

Summary: VPN fails when a static route is defined
Product: [Fedora] Fedora Reporter: Daniele Viganò <dennyvatwork>
Component: NetworkManagerAssignee: Lubomir Rintel <lkundrak>
Status: CLOSED EOL QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: unspecified    
Version: 22CC: altarasyuk, bugzilla.redhat, dcbw, jonas, lkundrak, mails.bugzilla.redhat.com, mj.wilson.uk, psimerda, robert.willert
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: 2016-07-19 19:19:04 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Daniele Viganò 2015-09-25 09:55:23 UTC 
Description of problem:

After upgrading NetworkManager to 1.0.6 from 1.0.2 (on Fedora 22) VPN connections (tested with PPTP) that have static routes defined do not work anymore. Removing the static routes make the connections working again (but it is not a real fix).

The error from the journal is:

platform-linux: do-add-ip4-route: failure adding ip4-route '18: 172.16.9.0/24 50': Unspecific failure (1)

Version-Release number of selected component (if applicable):

NetworkManager.x86_64                   1:1.0.6-5.fc22
NetworkManager-adsl.x86_64              1:1.0.6-5.fc22
NetworkManager-bluetooth.x86_64         1:1.0.6-5.fc22
NetworkManager-config-connectivity-fedora.x86_64
NetworkManager-glib.x86_64              1:1.0.6-5.fc22
NetworkManager-libnm.x86_64             1:1.0.6-5.fc22
NetworkManager-openconnect.x86_64       1.0.2-1.fc22
NetworkManager-openvpn.x86_64           1:1.0.2-2.fc22
NetworkManager-openvpn-gnome.x86_64     1:1.0.2-2.fc22
NetworkManager-pptp.x86_64              1:1.1.0-1.20150428git695d4f2.fc22
NetworkManager-pptp-gnome.x86_64        1:1.1.0-1.20150428git695d4f2.fc22
NetworkManager-team.x86_64              1:1.0.6-5.fc22
NetworkManager-vpnc.x86_64              1:1.0.2-1.fc22
NetworkManager-vpnc-gnome.x86_64        1:1.0.2-1.fc22
NetworkManager-wifi.x86_64              1:1.0.6-5.fc22
NetworkManager-wwan.x86_64              1:1.0.6-5.fc22

with NetworkManager 1:1.0.2-1.fc22 everything is working as expected.


How reproducible:

Always with VPN connections and NM 1.0.6-5

Steps to Reproduce:
1. Upgrade to NetworkManager-1:1.0.6-5
2. Create a VPN connection with a static route
3. Connect to the VPN

Actual results:

Connection to the VPN fails. In the journal this error is printed:

platform-linux: do-add-ip4-route: failure adding ip4-route '25: 172.16.9.0/24 1300': Unspecific failure (1)

Expected results:

A working connection as it was in NetworkManager 1.0.2


Additional info:

See also:
https://bugs.archlinux.org/task/45716?dev=179
https://bugzilla.novell.com/show_bug.cgi?id=943326

A workaround is to downgrade NetworkManager:
sudo dnf downgrade NetworkManager --allowerasing

NetworkManager           1:1.0.2-1.fc22
NetworkManager-adsl      1:1.0.2-1.fc22
NetworkManager-bluetooth 1:1.0.2-1.fc22
NetworkManager-libnm     1:1.0.2-1.fc22
NetworkManager-team      1:1.0.2-1.fc22
NetworkManager-wifi      1:1.0.2-1.fc22
NetworkManager-wwan      1:1.0.2-1.fc22
Comment 1 Daniele Viganò 2015-09-25 09:56:15 UTC 
I've also tested it with a different MTU metric with no success.
Comment 2 Daniele Viganò 2015-09-25 10:27:26 UTC 
I've been finally able to fix the issue changing the gateway in the router from the VPN gateway local IP to 0.0.0.0 has suggested here: https://bugzilla.gnome.org/show_bug.cgi?id=733296

I don't know if this could be considered a bug and the solution is just a workaround or if NetworkManager was doint it in the wrong way before.
Comment 3 W. Andrew Denton 2015-09-30 03:41:37 UTC 
I just hit this on F22 as well. The solution of changing the gateway IP to 0.0.0.0 fixed it.
I feel this is more of a Gnome UI bug than anything... For point-to-point interfaces like VPNs it would make more sense to have just a list of "use this connection to reach these additional networks" rather than explicit ip / netmask / gateway.
Comment 4 Oleksandr Tarasiuk 2015-10-19 16:25:03 UTC 
Have the same issue:
pptp-1.8.0-6.fc22.x86_64
ppp-2.4.7-7.fc22.x86_64
NetworkManager-pptp-1.1.0-1.20150428git695d4f2.fc22.x86_64
NetworkManager-adsl-1.0.6-6.fc22.x86_64
NetworkManager-l2tp-0.9.8.7-3.fc22.x86_64
NetworkManager-team-1.0.6-6.fc22.x86_64
NetworkManager-1.0.6-6.fc22.x86_64
NetworkManager-vpnc-1.0.6-3.fc22.x86_64
NetworkManager-config-connectivity-fedora-1.0.6-6.fc22.x86_64
NetworkManager-bluetooth-1.0.6-6.fc22.x86_64
NetworkManager-wwan-1.0.6-6.fc22.x86_64
NetworkManager-openvpn-1.0.6-3.fc22.x86_64
NetworkManager-glib-1.0.6-6.fc22.x86_64
NetworkManager-wifi-1.0.6-6.fc22.x86_64
NetworkManager-libnm-1.0.6-6.fc22.x86_64
NetworkManager-openconnect-1.0.2-1.fc22.x86_64
NetworkManager-openswan-1.0.6-2.fc22.x86_64
NetworkManager-pptp-1.1.0-1.20150428git695d4f2.fc22.x86_64

/var/log/messages (real IP addresses masked as ***.***.***.**1, ***.***.***.**2):
Oct 19 18:14:55 localhost NetworkManager[869]: <info>  Starting VPN service 'pptp'...
Oct 19 18:14:55 localhost NetworkManager[869]: <info>  VPN service 'pptp' started (org.freedesktop.NetworkManager.pptp), PID 12141
Oct 19 18:14:55 localhost NetworkManager[869]: <info>  VPN service 'pptp' appeared; activating connections
Oct 19 18:14:55 localhost NetworkManager: (nm-pptp-service:12141): GLib-GObject-WARNING **: value "81" of type 'guint' is invalid or out of range for property 'gateway-ping-timeout' of type 'guint'
Oct 19 18:14:55 localhost NetworkManager: (nm-pptp-service:12141): GLib-GObject-WARNING **: value "81" of type 'guint' is invalid or out of range for property 'gateway-ping-timeout' of type 'guint'
Oct 19 18:14:55 localhost NetworkManager: (nm-pptp-service:12141): GLib-GObject-WARNING **: value "81" of type 'guint' is invalid or out of range for property 'gateway-ping-timeout' of type 'guint'
Oct 19 18:14:55 localhost NetworkManager[869]: <info>  VPN plugin state changed: starting (3)
Oct 19 18:14:55 localhost NetworkManager: ** Message: pppd started with pid 12145
Oct 19 18:14:55 localhost NetworkManager[869]: <info>  VPN connection 'New vpn connection' (Connect) reply received.
Oct 19 18:14:55 localhost pppd[12145]: Plugin /usr/lib64/pppd/2.4.7/nm-pptp-pppd-plugin.so loaded.
Oct 19 18:14:55 localhost NetworkManager: Plugin /usr/lib64/pppd/2.4.7/nm-pptp-pppd-plugin.so loaded.
Oct 19 18:14:55 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (plugin_init): initializing
Oct 19 18:14:55 localhost pppd[12145]: pppd 2.4.7 started by root, uid 0
Oct 19 18:14:55 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Oct 19 18:14:55 localhost pppd[12145]: Using interface ppp0
Oct 19 18:14:55 localhost pppd[12145]: Connect: ppp0 <--> /dev/pts/8
Oct 19 18:14:55 localhost NetworkManager: Using interface ppp0
Oct 19 18:14:55 localhost NetworkManager: Connect: ppp0 <--> /dev/pts/8
Oct 19 18:14:55 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Oct 19 18:14:55 localhost NetworkManager[869]: <info>  (ppp0): new Generic device (carrier: UNKNOWN, driver: 'unknown', ifindex: 18)
Oct 19 18:14:55 localhost pptp[12147]: nm-pptp-service-12141 log[main:pptp.c:333]: The synchronous pptp option is NOT activated
Oct 19 18:14:55 localhost pptp[12157]: nm-pptp-service-12141 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 1 'Start-Control-Connection-Request'
Oct 19 18:14:55 localhost pptp[12157]: nm-pptp-service-12141 log[ctrlp_disp:pptp_ctrl.c:758]: Received Start Control Connection Reply
Oct 19 18:14:55 localhost pptp[12157]: nm-pptp-service-12141 log[ctrlp_disp:pptp_ctrl.c:792]: Client connection established.
Oct 19 18:14:56 localhost pptp[12157]: nm-pptp-service-12141 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 7 'Outgoing-Call-Request'
Oct 19 18:14:56 localhost pptp[12157]: nm-pptp-service-12141 log[ctrlp_disp:pptp_ctrl.c:877]: Received Outgoing Call Reply.
Oct 19 18:14:56 localhost pptp[12157]: nm-pptp-service-12141 log[ctrlp_disp:pptp_ctrl.c:916]: Outgoing call established (call ID 0, peer's call ID 7552).
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (get_credentials): passwd-hook, requesting credentials...
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (get_credentials): got credentials from NetworkManager-pptp
Oct 19 18:14:56 localhost pppd[12145]: CHAP authentication succeeded
Oct 19 18:14:56 localhost NetworkManager: CHAP authentication succeeded
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Oct 19 18:14:56 localhost pppd[12145]: Deflate (15) compression enabled
Oct 19 18:14:56 localhost NetworkManager: Deflate (15) compression enabled
Oct 19 18:14:56 localhost pppd[12145]: local  IP address 192.168.254.100
Oct 19 18:14:56 localhost pppd[12145]: remote IP address 192.168.254.1
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  keyfile: add connection in-memory (4ba8435c-dbdc-47b3-b143-f92784478547,"ppp0")
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
Oct 19 18:14:56 localhost NetworkManager: local  IP address 192.168.254.100
Oct 19 18:14:56 localhost NetworkManager: remote IP address 192.168.254.1
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 9 / phase 'running'
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_ip_up): ip-up event
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_ip_up): sending Ip4Config to NetworkManager-pptp...
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): Activation: starting connection 'ppp0' (4ba8435c-dbdc-47b3-b143-f92784478547)
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  VPN connection 'New vpn connection' (IP4 Config Get) reply received from old-style plugin.
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  VPN Gateway: ***.***.***.**1
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  Tunnel Device: ppp0
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  IPv4 configuration:
Oct 19 18:14:56 localhost NetworkManager[869]: <info>    Internal Address: 192.168.254.100
Oct 19 18:14:56 localhost NetworkManager[869]: <info>    Internal Prefix: 32
Oct 19 18:14:56 localhost NetworkManager[869]: <info>    Internal Point-to-Point Address: 192.168.254.1
Oct 19 18:14:56 localhost NetworkManager[869]: <info>    Maximum Segment Size (MSS): 0
Oct 19 18:14:56 localhost NetworkManager[869]: <info>    Static Route: ***.***.***.***/32   Next Hop: 192.168.254.1
Oct 19 18:14:56 localhost NetworkManager[869]: <info>    Forbid Default Route: no
Oct 19 18:14:56 localhost NetworkManager[869]: <info>    DNS Domain: '(none)'
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  No IPv6 configuration
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  VPN plugin state changed: started (4)
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: prepare -> config (reason 'none') [40 50 0]
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: config -> ip-config (reason 'none') [50 70 0]
Oct 19 18:14:56 localhost NetworkManager: ** Message: PPTP service (IP Config Get) reply received.
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: ip-config -> ip-check (reason 'none') [70 80 0]
Oct 19 18:14:56 localhost dbus[770]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=2 entries=92
Oct 19 18:14:56 localhost systemd: Starting Network Manager Script Dispatcher Service...
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=10 entries=83
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=2 entries=93
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=10 entries=84
Oct 19 18:14:56 localhost dbus[770]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Oct 19 18:14:56 localhost nm-dispatcher: Dispatching action 'pre-up' for ppp0
Oct 19 18:14:56 localhost systemd: Started Network Manager Script Dispatcher Service.
Oct 19 18:14:56 localhost audit: <audit-1130> pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=2 entries=94
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: ip-check -> secondaries (reason 'none') [80 90 0]
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: secondaries -> activated (reason 'none') [90 100 0]
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=10 entries=85
Oct 19 18:14:56 localhost audit: <audit-1325> table=mangle family=2 entries=41
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): Activation: successful, device activated.
Oct 19 18:14:56 localhost nm-dispatcher: Dispatching action 'up' for ppp0
Oct 19 18:14:56 localhost audit: <audit-1325> table=mangle family=10 entries=40
Oct 19 18:14:56 localhost audit: <audit-1325> table=nat family=2 entries=57
Oct 19 18:14:56 localhost audit: <audit-1325> table=nat family=10 entries=52
Oct 19 18:14:56 localhost audit: <audit-1325> table=nat family=2 entries=58
Oct 19 18:14:56 localhost audit: <audit-1325> table=nat family=10 entries=53
Oct 19 18:14:56 localhost NetworkManager[869]: <warn>  platform-linux: do-add-ip4-route: failure adding ip4-route '18: ***.***.***.**2/32 50': Unspecific failure (1)
Oct 19 18:14:56 localhost NetworkManager[869]: <warn>  VPN connection 'New vpn connection' did not receive valid IP config information.
Oct 19 18:14:56 localhost NetworkManager: ** Message: Terminated ppp daemon with PID 12145.
Oct 19 18:14:56 localhost pptp[12157]: nm-pptp-service-12141 log[callmgr_main:pptp_callmgr.c:245]: Closing connection (unhandled)
Oct 19 18:14:56 localhost pptp[12157]: nm-pptp-service-12141 log[ctrlp_rep:pptp_ctrl.c:258]: Sent control packet type is 12 'Call-Clear-Request'
Oct 19 18:14:56 localhost pptp[12157]: nm-pptp-service-12141 log[call_callback:pptp_callmgr.c:84]: Closing connection (call state)
Oct 19 18:14:56 localhost pppd[12145]: Terminating on signal 15
Oct 19 18:14:56 localhost NetworkManager: Terminating on signal 15
Oct 19 18:14:56 localhost pppd[12145]: Modem hangup
Oct 19 18:14:56 localhost NetworkManager: Modem hangup
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Oct 19 18:14:56 localhost pppd[12145]: Connect time 0.0 minutes.
Oct 19 18:14:56 localhost pppd[12145]: Sent 0 bytes, received 0 bytes.
Oct 19 18:14:56 localhost dbus[770]: [system] Rejected send message, 10 matched rules; type="error", sender=":1.91" (uid=0 pid=12141 comm="/usr/libexec/nm-pptp-service ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.92" (uid=0 pid=12145 comm="/sbin/pppd pty /sbin/pptp ***.***.***.**1 --nolaunchp")
Oct 19 18:14:56 localhost NetworkManager: Connect time 0.0 minutes.
Oct 19 18:14:56 localhost NetworkManager: Sent 0 bytes, received 0 bytes.
Oct 19 18:14:56 localhost pppd[12145]: Connection terminated.
Oct 19 18:14:56 localhost dbus[770]: [system] Rejected send message, 10 matched rules; type="error", sender=":1.91" (uid=0 pid=12141 comm="/usr/libexec/nm-pptp-service ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.92" (uid=0 pid=12145 comm="/sbin/pppd pty /sbin/pptp ***.***.***.**1 --nolaunchp")
Oct 19 18:14:56 localhost dbus[770]: [system] Rejected send message, 10 matched rules; type="error", sender=":1.91" (uid=0 pid=12141 comm="/usr/libexec/nm-pptp-service ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.92" (uid=0 pid=12145 comm="/sbin/pppd pty /sbin/pptp ***.***.***.**1 --nolaunchp")
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 11 / phase 'disconnect'
Oct 19 18:14:56 localhost NetworkManager: Connection terminated.
Oct 19 18:14:56 localhost systemd: Unit iscsi.service cannot be reloaded because it is inactive.
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=2 entries=95
Oct 19 18:14:56 localhost NetworkManager[869]: <info>  (ppp0): device state change: activated -> unmanaged (reason 'removed') [100 10 36]
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=10 entries=86
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=2 entries=94
Oct 19 18:14:56 localhost NetworkManager[869]: <warn>  (ppp0): failed to disable userspace IPv6LL address handling
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=10 entries=85
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=2 entries=93
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
Oct 19 18:14:56 localhost dbus[770]: [system] Rejected send message, 10 matched rules; type="error", sender=":1.91" (uid=0 pid=12141 comm="/usr/libexec/nm-pptp-service ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.92" (uid=0 pid=12145 comm="/sbin/pppd pty /sbin/pptp ***.***.***.**1 --nolaunchp")
Oct 19 18:14:56 localhost audit: <audit-1325> table=filter family=10 entries=84
Oct 19 18:14:56 localhost audit: <audit-1325> table=mangle family=2 entries=42
Oct 19 18:14:56 localhost audit: <audit-1325> table=mangle family=10 entries=41
Oct 19 18:14:56 localhost audit: <audit-1325> table=nat family=2 entries=59
Oct 19 18:14:56 localhost nm-dispatcher: Cannot find device "ppp0"
Oct 19 18:14:56 localhost NetworkManager: ** Message: nm-pptp-ppp-plugin: (nm_exit_notify): cleaning up
Oct 19 18:14:56 localhost pppd[12145]: Exit.
Oct 19 18:14:56 localhost audit: <audit-1325> table=nat family=10 entries=54
Oct 19 18:14:56 localhost NetworkManager: ** (nm-pptp-service:12141): WARNING **: pppd exited with error code 16
Oct 19 18:14:56 localhost audit: <audit-1325> table=nat family=2 entries=58
Oct 19 18:14:56 localhost nm-dispatcher: Dispatching action 'down' for ppp0
Oct 19 18:14:56 localhost audit: <audit-1325> table=nat family=10 entries=53
Comment 5 Fedora End Of Life 2016-07-19 19:19:04 UTC 
Fedora 22 changed to end-of-life (EOL) status on 2016-07-19. Fedora 22 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. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

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