search

nm-l2tp / NetworkManager-l2tp

L2TP and L2TP/IPsec support for NetworkManager
GNU General Public License v2.0
489 stars 84 forks source link

Archlinux NetworkManager Maximum retries exceeded for tunnel XXX and lost connection around every 1.5 minutes #140

Closed urack closed 4 years ago

urack commented 4 years ago

I am running the latest version of networkmanager-l2tp 1.8.2-1 on Archlinux Download from here.

https://aur.archlinux.org/packages/networkmanager-git

The server works fine with no issues . I am using L2TP with Ipsec pre-sharekey.

Windows and Mac os /IOS /Android phones works fine with the server and no issues. Seems keep alive no response. I have closed all possible FW between the client and server. But the error still exists.

And i get those running conifgs from /var/run/nm-xxx/ folder.

Any comments or suggestions here?

Only Archlinux lost connection every 1.5 minutes. And report following error nm.error.tar.gz . 

May 05 21:57:49 arch charon[1816]: 00[NET] sending packet: from 172.31.88.222[6520] to 192.168.1.32[4500] (92 bytes)
May 05 21:57:49 arch charon[1816]: 00[ENC] generating INFORMATIONAL_V1 request 2046398011 [ HASH D ]
May 05 21:57:49 arch charon[1816]: 00[IKE] sending DELETE for IKE_SA 34bc7ff6-ed7a-4d05-b934-42ec61b48242[1]
May 05 21:57:49 arch charon[1816]: 00[IKE] deleting IKE_SA 34bc7ff6-ed7a-4d05-b934-42ec61b48242[1] between 172.31.88.222[172.31.88.222]...192.168.1.32[192.168.1.32]
May 05 21:57:49 arch charon[1816]: 00[IKE] deleting IKE_SA 34bc7ff6-ed7a-4d05-b934-42ec61b48242[1] between 172.31.88.222[172.31.88.222]...192.168.1.32[192.168.1.32]
May 05 21:57:49 arch charon[1816]: 00[NET] sending packet: from 172.31.88.222[6520] to 192.168.1.32[4500] (76 bytes)
May 05 21:57:49 arch charon[1816]: 00[ENC] generating INFORMATIONAL_V1 request 3873912413 [ HASH D ]
May 05 21:57:49 arch charon[1816]: 00[IKE] sending DELETE for ESP CHILD_SA with SPI cf38dae2
May 05 21:57:49 arch charon[1816]: 00[IKE] closing CHILD_SA 34bc7ff6-ed7a-4d05-b934-42ec61b48242{1} with SPIs cf38dae2_i (22750 bytes) c0d103c4_o (11909 bytes) and TS 172.3>
May 05 21:57:49 arch charon[1816]: 00[IKE] closing CHILD_SA 34bc7ff6-ed7a-4d05-b934-42ec61b48242{1} with SPIs cf38dae2_i (22750 bytes) c0d103c4_o (11909 bytes) and TS 172.3>
May 05 21:57:49 arch charon[1816]: 00[DMN] signal of type SIGINT received. Shutting down
May 05 21:57:49 arch NetworkManager[2089]: Stopping strongSwan IPsec...
May 05 21:57:49 arch pppd[1908]: Exit.
May 05 21:57:49 arch NetworkManager[429]: <info>  [1588687069.3252] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: VPN plugin: state c>
May 05 21:57:49 arch NetworkManager[1904]: xl2tpd[1904]: death_handler: Fatal signal 15 received
May 05 21:57:49 arch charon[1816]: 14[KNL] interface ppp0 deleted
May 05 21:57:49 arch pppd[1908]: Connection terminated.
May 05 21:57:49 arch charon[1816]: 10[CFG] joining forecast multicast groups: 224.0.0.1,224.0.0.22,224.0.0.251,224.0.0.252,239.255.255.250
May 05 21:57:49 arch charon[1816]: 13[IKE] uninstalling bypass policy for 192.168.110.1/32
May 05 21:57:49 arch charon[1816]: 10[NET] using forecast interface wlp2s0
May 05 21:57:49 arch NetworkManager[429]: <info>  [1588687069.0013] device (ppp0): state change: disconnected -> unmanaged (reason 'connection-assumed', sys-iface-state: 'e>
May 05 21:57:48 arch pppd[1908]: Overriding mru 1500 to mtu value 1400
May 05 21:57:48 arch pppd[1908]: Overriding mtu 1500 to 1400
May 05 21:57:48 arch charon[1816]: 07[KNL] 192.168.110.240 disappeared from ppp0
May 05 21:57:48 arch charon[1816]: 06[KNL] interface ppp0 deactivated
May 05 21:57:48 arch pppd[1908]: Sent 9054 bytes, received 20767 bytes.
May 05 21:57:48 arch pppd[1908]: Connect time 1.5 minutes.
May 05 21:57:48 arch pppd[1908]: Terminating on signal 15
May 05 21:57:48 arch NetworkManager[1904]: xl2tpd[1904]: Connection 50911 closed to 192.168.1.32, port 1701 (Timeout)
May 05 21:57:48 arch NetworkManager[1904]: xl2tpd[1904]: Terminating pppd: sending TERM signal to pid 1908
May 05 21:57:48 arch NetworkManager[1904]: xl2tpd[1904]: Maximum retries exceeded for tunnel 39938.  Closing.
May 05 21:57:41 arch charon[1816]: 15[IKE] sending keep alive to 192.168.1.32[4500]
May 05 21:56:21 arch charon[1816]: 09[IKE] installed bypass policy for 192.168.110.1/32
May 05 21:56:21 arch charon[1816]: 09[IKE] installed bypass policy for 172.31.88.1/32
May 05 21:56:21 arch charon[1816]: 12[CFG] joining forecast multicast groups: 224.0.0.1,224.0.0.22,224.0.0.251,224.0.0.252,239.255.255.250
May 05 21:56:21 arch charon[1816]: 12[NET] using forecast interface wlp2s0
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0440] policy: set 'home' (ppp0) as default for IPv4 routing and DNS
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0293] device (ppp0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'external')
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0286] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: VPN connection: (IP>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0258] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: VPN plugin: state c>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0257] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data: No IPv6 confi>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0255] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data:   DNS Domain:>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0254] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data:   Internal DN>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0253] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data:   Static Rout>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0252] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data:   Static Rout>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0251] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data:   Internal Po>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0250] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data:   Internal Pr>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0249] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data:   Internal Ad>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0248] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data: IPv4 configur>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0246] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data: Tunnel Device>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0245] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",4:(ppp0)]: Data: VPN Gateway: >
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0236] vpn-connection[0x564f1813e0a0,34bc7ff6-ed7a-4d05-b934-42ec61b48242,"home",0]: VPN connection: (IP4 Confi>
May 05 21:56:21 arch NetworkManager[429]: <info>  [1588686981.0202] device (ppp0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'ex>
May 05 21:56:21 arch charon[1816]: 07[KNL] interface ppp0 activated
May 05 21:56:21 arch charon[1816]: 06[KNL] 192.168.110.240 appeared on ppp0
May 05 21:56:21 arch charon[1816]: 15[KNL] 192.168.110.240 disappeared from ppp0
May 05 21:56:21 arch pppd[1908]: secondary DNS address 192.168.110.1
May 05 21:56:21 arch pppd[1908]: primary   DNS address 192.168.110.1
May 05 21:56:21 arch pppd[1908]: remote IP address 192.168.110.1
May 05 21:56:21 arch pppd[1908]: local  IP address 192.168.110.240
==========/nm-l2tp-34bc7ff6-ed7a-4d05-b934-42ec61b48242/ipsec.conf=================
conn 34bc7ff6-ed7a-4d05-b934-42ec61b48242
  auto=add
  type=transport
  authby=secret
  left=%defaultroute
  leftprotoport=udp/l2tp
  rightprotoport=udp/l2tp
  right=192.168.1.32
  rightid=%any
  keyingtries=%forever
  ike=aes256-sha2_256-modp2048,aes256-sha2_256-modp1536,aes256-sha2_256-modp1024,aes256-sha1-modp2048,aes256-sha1-modp1536,aes256-sha1-modp1024,aes256-sha1-ecp384,aes128-sha1-modp1024,aes128-sha1-ecp256,3des-sha1-modp2048,3des-sha1-modp1024!
  esp=aes256-sha1,aes128-sha1,3des-sha1!
  ikelifetime=10800
  lifetime=10800
  keyexchange=ikev1
==========/nm-l2tp-34bc7ff6-ed7a-4d05-b934-42ec61b48242/xl2tpd.conf=================
[global]
access control = yes
port = 1701
[lac l2tp]
lns = 192.168.1.32
pppoptfile = /var/run/nm-l2tp-34bc7ff6-ed7a-4d05-b934-42ec61b48242/ppp-options
autodial = yes
tunnel rws = 8
tx bps = 100000000
rx bps = 100000000
==========/nm-l2tp-34bc7ff6-ed7a-4d05-b934-42ec61b48242/ppp-options================
ipparam nm-l2tp-service-34bc7ff6-ed7a-4d05-b934-42ec61b48242
nodetach
usepeerdns
noipdefault
nodefaultroute
noauth
noccp
refuse-eap
lcp-echo-failure 5
lcp-echo-interval 30
plugin /usr/lib/pppd/2.4.7/nm-l2tp-pppd-plugin.so
mru 1400
mtu 1400
dkosovic commented 4 years ago

I've seen various reports of Cisco VPN servers disconnecting the connection after 1.5 minutes.

This might be a routing issue, see issue #132. After VPN connection has been established, try route del \<gateway IP address>, which I think in your case would be :

route del 192.168.1.32
urack commented 4 years ago

Thanks Guy. I think i have already found the root cause now.

I got 2 ip address through DHCP from my wifi router (linksys WRT1900ACS). Not sure why this happened till now. I plug a ethernet cable to the laptop lan port. Now i have 4 IPs totally. 2 from wifi interface, 2 from ethernet interface. All was set DHCP from router.

Here is the command output of the lan port

2: eno1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000 link/ether f0:1f:af:60:9f:b9 brd ff:ff:ff:ff:ff:ff altname enp0s25 inet 172.31.88.203/24 brd 172.31.88.255 scope global noprefixroute eno1 valid_lft forever preferred_lft forever inet 172.31.88.204/24 brd 172.31.88.255 scope global secondary dynamic noprefixroute eno1 valid_lft 86383sec preferred_lft 75583sec inet6 2409:8a00:6047:1570:4f5c:e4ab:beb8:bc22/64 scope global dynamic mngtmpaddr noprefixroute valid_lft 192506sec preferred_lft 106106sec inet6 2409:8a00:6047:1570:ae81:d0b3:1581:272d/64 scope global dynamic noprefixroute valid_lft 192506sec preferred_lft 106106sec inet6 fe80::308e:1e64:699e:7615/64 scope link noprefixroute valid_lft forever preferred_lft forever inet6 fe80::84fa:deec:8934:c712/64 scope link noprefixroute valid_lft forever preferred_lft forever 3: wlp2s0: <BROADCAST,MULTICAST> mtu 1500 qdisc noop state DOWN group default qlen 1000 link/ether 3a:ea:fe:10:6e:19 brd ff:ff:ff:ff:ff:ff permaddr 0c:8b:fd:e9:43:d7

But i am still not sure where the secondary ip come from. I finally found a workaround. Using following command and then wait few seconds you will only have 1 ip instead of 2.

ip addr flush dev eno1

here is the output after the operation: 2: eno1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000 link/ether f0:1f:af:60:9f:b9 brd ff:ff:ff:ff:ff:ff altname enp0s25 inet 172.31.88.204/24 brd 172.31.88.255 scope global dynamic noprefixroute eno1 valid_lft 86316sec preferred_lft 75516sec inet6 2409:8a00:6047:1570:4f5c:e4ab:beb8:bc22/64 scope global dynamic mngtmpaddr noprefixroute valid_lft 192384sec preferred_lft 105984sec inet6 2409:8a00:6047:1570:ae81:d0b3:1581:272d/64 scope global dynamic noprefixroute valid_lft 192384sec preferred_lft 105984sec inet6 fe80::f7f7:4534:3fc8:43c2/64 scope link noprefixroute valid_lft forever preferred_lft forever Then you can dial to l2tp server with no issues. I did wait for a long time and send some big files (around 5GB data )to internal sftp server. All successfully sent with no lost connection.

The root cause should because of asymmetric routes cause the keep alive packet lost while come back. From initiate state it send out packet using the bigger IP here in my case is 172.31.88.204.But while come back it will try to reach to 172.31.88.203. Cause the keepalive packet lost. And after 1.5 minutes it will terminate the connection.

I do remember this happened while we deploy zoom video conference Onprem service for customer . 2 same segment ip on same machine will cause the data lost while come back. Finally we use 2 different machines with 1 ip each server. This consume more machines while do the deployment.

May 06 18:44:01 arch charon[4690]: 11[NET] sending packet: from 172.31.88.204[6520] to 192.168.1.32[4500] (60 bytes) May 06 18:44:01 arch NetworkManager[4719]: sending packet: from 172.31.88.204[6520] to 192.168.1.32[4500] (252 bytes) May 06 18:44:01 arch NetworkManager[4719]: sending packet: from 172.31.88.204[6520] to 192.168.1.32[4500] (76 bytes) May 06 18:44:01 arch NetworkManager[4719]: local host is behind NAT, sending keep alives We may need to fix why get secondary ip through NetworkManager under one NIC. Once i found the answer i will update here.

urack commented 4 years ago

Here is the final solution here.

Because the dhcpcd service is running in your linux . Please disable it . And then you will find you will have only 1 IP assigned.

: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000 link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host valid_lft forever preferred_lft forever 2: eno1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000 link/ether f0:1f:af:60:9f:b9 brd ff:ff:ff:ff:ff:ff altname enp0s25 inet 172.31.88.203/24 brd 172.31.88.255 scope global noprefixroute eno1 valid_lft forever preferred_lft forever inet 172.31.88.204/24 brd 172.31.88.255 scope global secondary dynamic noprefixroute eno1 valid_lft 86327sec preferred_lft 75527sec inet6 2409:8a00:6047:1570:4f5c:e4ab:beb8:bc22/64 scope global dynamic mngtmpaddr noprefixroute valid_lft 231825sec preferred_lft 145425sec inet6 2409:8a00:6047:1570:ae81:d0b3:1581:272d/64 scope global dynamic noprefixroute valid_lft 231824sec preferred_lft 145424sec inet6 fe80::84fa:deec:8934:c712/64 scope link noprefixroute valid_lft forever preferred_lft forever 3: wlp2s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000 link/ether 0c:8b:fd:e9:43:d7 brd ff:ff:ff:ff:ff:ff inet 172.31.88.197/24 brd 172.31.88.255 scope global dynamic noprefixroute wlp2s0 valid_lft 85797sec preferred_lft 85797sec inet 172.31.88.222/24 brd 172.31.88.255 scope global secondary dynamic noprefixroute wlp2s0 valid_lft 86329sec preferred_lft 75529sec inet6 fe80::f618:f3e5:f37e:9cd7/64 scope link noprefixroute valid_lft forever preferred_lft forever

systemctl stop dhcpcd systemctl disable dhcpcd after those please unplug and plug the cable. or turn off wifi and turn it on again will fix this.

1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000 link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00 inet 127.0.0.1/8 scope host lo valid_lft forever preferred_lft forever inet6 ::1/128 scope host valid_lft forever preferred_lft forever 2: eno1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000 link/ether f0:1f:af:60:9f:b9 brd ff:ff:ff:ff:ff:ff altname enp0s25 inet 172.31.88.203/24 brd 172.31.88.255 scope global noprefixroute eno1 valid_lft forever preferred_lft forever inet6 2409:8a00:6047:1570:ae81:d0b3:1581:272d/64 scope global dynamic noprefixroute valid_lft 231789sec preferred_lft 145389sec inet6 fe80::84fa:deec:8934:c712/64 scope link noprefixroute valid_lft forever preferred_lft forever 3: wlp2s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000 link/ether 0c:8b:fd:e9:43:d7 brd ff:ff:ff:ff:ff:ff inet 172.31.88.197/24 brd 172.31.88.255 scope global dynamic noprefixroute wlp2s0 valid_lft 86400sec preferred_lft 86400sec inet6 fe80::f618:f3e5:f37e:9cd7/64 scope link tentative noprefixroute valid_lft forever preferred_lft forever `

dkosovic commented 4 years ago

Glad to hear you solved the issue.

The asymmetric routes and keep alive packet loss diagnosis which causes the connection to fail after 1.5 minutes was very useful to know.