xl2tp shows disconnected even though successful

Bug #1359195 reported by freecode
12
This bug affects 1 person
Affects Status Importance Assigned to Milestone
xl2tpd (Ubuntu)
New
Undecided
Unassigned

Bug Description

Using xl2tp on 14.04.1 Trusty, connection information shows that the connection is up, but it does not advance to "connected" as it used to do. I am successfully into my VPN:

Aug 20 06:44:10.408 ipsec_setup: Starting Openswan IPsec U2.6.38/K3.13.0-32-generic...
Aug 20 06:44:10.683 ipsec__plutorun: Starting Pluto subsystem...
Aug 20 06:44:10.818 ipsec__plutorun: adjusting ipsec.d to /etc/ipsec.d
Aug 20 06:44:10.833 recvref[30]: Protocol not available
Aug 20 06:44:10.833 xl2tpd[11497]: This binary does not support kernel L2TP.
Aug 20 06:44:10.833 xl2tpd[11499]: xl2tpd version xl2tpd-1.3.6 started on iamcereal2 PID:11499
Aug 20 06:44:10.833 xl2tpd[11499]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
Aug 20 06:44:10.833 xl2tpd[11499]: Forked by Scott Balmos and David Stipp, (C) 2001
Aug 20 06:44:10.834 xl2tpd[11499]: Inherited by Jeff McAdams, (C) 2002
Aug 20 06:44:10.834 xl2tpd[11499]: Forked again by Xelerance (www.xelerance.com) (C) 2006
Aug 20 06:44:10.834 xl2tpd[11499]: Listening on IP address 0.0.0.0, port 1701
Aug 20 06:44:10.834 Starting xl2tpd: xl2tpd.
Aug 20 06:44:10.954 ipsec__plutorun: 002 added connection description "L2TP-PSK"
Aug 20 06:44:11.559 104 "L2TP-PSK" #1: STATE_MAIN_I1: initiate
Aug 20 06:44:11.560 003 "L2TP-PSK" #1: ignoring unknown Vendor ID payload [882fe56d6fd20dbc2251613b2ebe5beb]
Aug 20 06:44:11.560 003 "L2TP-PSK" #1: received Vendor ID payload [Cisco-Unity]
Aug 20 06:44:11.560 003 "L2TP-PSK" #1: received Vendor ID payload [XAUTH]
Aug 20 06:44:11.560 003 "L2TP-PSK" #1: received Vendor ID payload [Dead Peer Detection]
Aug 20 06:44:11.561 003 "L2TP-PSK" #1: received Vendor ID payload [RFC 3947] method set to=115
Aug 20 06:44:11.561 106 "L2TP-PSK" #1: STATE_MAIN_I2: sent MI2, expecting MR2
Aug 20 06:44:11.561 003 "L2TP-PSK" #1: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike (MacOS X): i am NATed
Aug 20 06:44:11.561 108 "L2TP-PSK" #1: STATE_MAIN_I3: sent MI3, expecting MR3
Aug 20 06:44:11.561 004 "L2TP-PSK" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128 prf=oakley_sha group=modp2048}
Aug 20 06:44:11.562 117 "L2TP-PSK" #2: STATE_QUICK_I1: initiate
Aug 20 06:44:11.562 004 "L2TP-PSK" #2: STATE_QUICK_I2: sent QI2, IPsec SA established transport mode {ESP=>0xc1ccdd3a <0x69b800a2 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=none}
Aug 20 06:44:12.563 xl2tpd[11499]: Connecting to host x.x.x.x, port 1701
Aug 20 06:44:13.231 xl2tpd[11499]: Connection established to x.x.x.x 1701. Local: 53917, Remote: 48147 (ref=0/0).
Aug 20 06:44:13.231 xl2tpd[11499]: Calling on tunnel 53917
Aug 20 06:44:13.287 xl2tpd[11499]: Call established with x.x.x.x, Local: 8268, Remote: 47497, Serial: 1 (ref=0/0)
Aug 20 06:44:13.288 xl2tpd[11499]: start_pppd: I'm running:
Aug 20 06:44:13.289 xl2tpd[11499]: "/usr/sbin/pppd"
Aug 20 06:44:13.289 xl2tpd[11499]: "passive"
Aug 20 06:44:13.290 xl2tpd[11499]: "nodetach"
Aug 20 06:44:13.290 xl2tpd[11499]: ":"
Aug 20 06:44:13.290 xl2tpd[11499]: "file"
Aug 20 06:44:13.291 xl2tpd[11499]: "/etc/ppp/L2TP-PSK.options.xl2tpd"
Aug 20 06:44:13.291 xl2tpd[11499]: "/dev/pts/0"
Aug 20 06:44:13.395 pppd[11559]: Plugin passprompt.so loaded.
Aug 20 06:44:13.395 pppd[11559]: pppd 2.4.5 started by root, uid 0
Aug 20 06:44:13.395 pppd[11559]: using channel 2
Aug 20 06:44:13.396 pppd[11559]: Using interface ppp0
Aug 20 06:44:13.396 pppd[11559]: Connect: ppp0 <--> /dev/pts/0
Aug 20 06:44:13.396 pppd[11559]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <magic 0x4369adde> <pcomp> <accomp>]
Aug 20 06:44:14.010 pppd[11559]: rcvd [LCP ConfReq id=0x1 <mru 1380> <asyncmap 0x0> <auth chap MS-v2> <magic 0xd43b9d80>]
Aug 20 06:44:14.011 pppd[11559]: sent [LCP ConfAck id=0x1 <mru 1380> <asyncmap 0x0> <auth chap MS-v2> <magic 0xd43b9d80>]
Aug 20 06:44:16.398 pppd[11559]: sent [LCP ConfReq id=0x1 <mru 1410> <asyncmap 0x0> <magic 0x4369adde> <pcomp> <accomp>]
Aug 20 06:44:16.410 pppd[11559]: rcvd [LCP ConfAck id=0x1 <mru 1410> <asyncmap 0x0> <magic 0x4369adde> <pcomp> <accomp>]
Aug 20 06:44:16.411 pppd[11559]: sent [LCP EchoReq id=0x0 magic=0x4369adde]
Aug 20 06:44:16.412 pppd[11559]: rcvd [CHAP Challenge id=0x67 <cd1de4c9c932323b66d1c366280f638a>, name = "firewall.sailpoint.com"]
Aug 20 06:44:16.412 pppd[11559]: sent [CHAP Response id=0x67 <ba6f06df46d6ace24e26f19c118e68a40000000000000000fecd9fee8b432b15bff34ec72a84066f7494d85c798115ef00>, name = "<email address hidden>"]
Aug 20 06:44:16.420 pppd[11559]: rcvd [LCP EchoRep id=0x0 magic=0xd43b9d80]
Aug 20 06:44:18.060 pppd[11559]: rcvd [CHAP Success id=0x67 "S=BA1467DC27DB8FA1512C84125D66447C7A7E2582"]
Aug 20 06:44:18.060 pppd[11559]: CHAP authentication succeeded
Aug 20 06:44:18.061 pppd[11559]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Aug 20 06:44:18.252 pppd[11559]: rcvd [IPCP ConfReq id=0x1 <addr 172.16.10.1>]
Aug 20 06:44:18.252 pppd[11559]: sent [IPCP ConfAck id=0x1 <addr 172.16.10.1>]
Aug 20 06:44:18.253 pppd[11559]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>]
Aug 20 06:44:18.253 pppd[11559]: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Aug 20 06:44:18.261 pppd[11559]: rcvd [IPCP ConfNak id=0x2 <addr 172.16.10.2> <ms-dns1 172.16.1.10> <ms-dns2 172.16.1.7>]
Aug 20 06:44:18.262 pppd[11559]: sent [IPCP ConfReq id=0x3 <addr 172.16.10.2> <ms-dns1 172.16.1.10> <ms-dns2 172.16.1.7>]
Aug 20 06:44:18.280 pppd[11559]: rcvd [IPCP ConfAck id=0x3 <addr 172.16.10.2> <ms-dns1 172.16.1.10> <ms-dns2 172.16.1.7>]
Aug 20 06:44:18.280 pppd[11559]: not replacing existing default route via 192.168.0.1
Aug 20 06:44:18.280 pppd[11559]: local IP address 172.16.10.2
Aug 20 06:44:18.281 pppd[11559]: remote IP address 172.16.10.1
Aug 20 06:44:18.281 pppd[11559]: primary DNS address 172.16.1.10
Aug 20 06:44:18.282 pppd[11559]: secondary DNS address 172.16.1.7
Aug 20 06:44:18.282 pppd[11559]: Script /etc/ppp/ip-up started (pid 11571)
Aug 20 06:44:20.751 pppd[11559]: Script /etc/ppp/ip-up finished (pid 11571), status = 0x0

from /var/auth.log:

Aug 20 06:44:10 iamcereal2 ipsec__plutorun: Starting Pluto subsystem...
Aug 20 06:44:10 iamcereal2 pluto[11489]: Starting Pluto (Openswan Version 2.6.38; Vendor ID OEvy\134kgzWq\134s) pid:11489
Aug 20 06:44:10 iamcereal2 pluto[11489]: LEAK_DETECTIVE support [disabled]
Aug 20 06:44:10 iamcereal2 pluto[11489]: OCF support for IKE [disabled]
Aug 20 06:44:10 iamcereal2 pluto[11489]: SAref support [disabled]: Protocol not available
Aug 20 06:44:10 iamcereal2 pluto[11489]: SAbind support [disabled]: Protocol not available
Aug 20 06:44:10 iamcereal2 pluto[11489]: NSS support [disabled]
Aug 20 06:44:10 iamcereal2 pluto[11489]: HAVE_STATSD notification support not compiled in
Aug 20 06:44:10 iamcereal2 pluto[11489]: Setting NAT-Traversal port-4500 floating to on
Aug 20 06:44:10 iamcereal2 pluto[11489]: port floating activation criteria nat_t=1/port_float=1
Aug 20 06:44:10 iamcereal2 pluto[11489]: NAT-Traversal support [enabled]
Aug 20 06:44:10 iamcereal2 pluto[11489]: using /dev/urandom as source of random entropy
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_enc(): Activating OAKLEY_AES_CBC: Ok (ret=0)
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_hash(): Activating OAKLEY_SHA2_512: Ok (ret=0)
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_hash(): Activating OAKLEY_SHA2_256: Ok (ret=0)
Aug 20 06:44:10 iamcereal2 pluto[11489]: starting up 3 cryptographic helpers
Aug 20 06:44:10 iamcereal2 pluto[11489]: started helper pid=11500 (fd:6)
Aug 20 06:44:10 iamcereal2 pluto[11489]: started helper pid=11501 (fd:7)
Aug 20 06:44:10 iamcereal2 pluto[11489]: started helper pid=11502 (fd:8)
Aug 20 06:44:10 iamcereal2 pluto[11489]: Using Linux 2.6 IPsec interface code on 3.13.0-32-generic (experimental code)
Aug 20 06:44:10 iamcereal2 pluto[11500]: using /dev/urandom as source of random entropy
Aug 20 06:44:10 iamcereal2 pluto[11501]: using /dev/urandom as source of random entropy
Aug 20 06:44:10 iamcereal2 pluto[11502]: using /dev/urandom as source of random entropy
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_enc(): Activating aes_ccm_8: Ok (ret=0)
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_add(): ERROR: algo_type '0', algo_id '0', Algorithm type already exists
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_enc(): Activating aes_ccm_12: FAILED (ret=-17)
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_add(): ERROR: algo_type '0', algo_id '0', Algorithm type already exists
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_enc(): Activating aes_ccm_16: FAILED (ret=-17)
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_add(): ERROR: algo_type '0', algo_id '0', Algorithm type already exists
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_enc(): Activating aes_gcm_8: FAILED (ret=-17)
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_add(): ERROR: algo_type '0', algo_id '0', Algorithm type already exists
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_enc(): Activating aes_gcm_12: FAILED (ret=-17)
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_add(): ERROR: algo_type '0', algo_id '0', Algorithm type already exists
Aug 20 06:44:10 iamcereal2 pluto[11489]: ike_alg_register_enc(): Activating aes_gcm_16: FAILED (ret=-17)
Aug 20 06:44:10 iamcereal2 pluto[11489]: added connection description "L2TP-PSK"
Aug 20 06:44:10 iamcereal2 pluto[11489]: listening for IKE messages
Aug 20 06:44:10 iamcereal2 pluto[11489]: adding interface eth0/eth0 192.168.0.6:500
Aug 20 06:44:10 iamcereal2 pluto[11489]: adding interface eth0/eth0 192.168.0.6:4500
Aug 20 06:44:10 iamcereal2 pluto[11489]: adding interface lo/lo 127.0.0.1:500
Aug 20 06:44:10 iamcereal2 pluto[11489]: adding interface lo/lo 127.0.0.1:4500
Aug 20 06:44:10 iamcereal2 pluto[11489]: adding interface lo/lo ::1:500
Aug 20 06:44:10 iamcereal2 pluto[11489]: loading secrets from "/etc/ipsec.secrets"
Aug 20 06:44:10 iamcereal2 pluto[11489]: listening for IKE messages
Aug 20 06:44:10 iamcereal2 pluto[11489]: forgetting secrets
Aug 20 06:44:10 iamcereal2 pluto[11489]: loading secrets from "/etc/ipsec.secrets"
Aug 20 06:44:10 iamcereal2 pluto[11489]: "L2TP-PSK" #1: initiating Main Mode
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: ignoring unknown Vendor ID payload [882fe56d6fd20dbc2251613b2ebe5beb]
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: received Vendor ID payload [Cisco-Unity]
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: received Vendor ID payload [XAUTH]
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: received Vendor ID payload [Dead Peer Detection]
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: received Vendor ID payload [RFC 3947] method set to=115
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: enabling possible NAT-traversal with method RFC 3947 (NAT-Traversal)
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: STATE_MAIN_I2: sent MI2, expecting MR2
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike (MacOS X): i am NATed
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: STATE_MAIN_I3: sent MI3, expecting MR3
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: Main mode peer ID is ID_IPV4_ADDR: 'x.x.x.x'
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_128 prf=oakley_sha group=modp2048}
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #2: initiating Quick Mode PSK+ENCRYPT+UP+IKEv2ALLOW+SAREFTRACK {using isakmp#1 msgid:6b6ec1df proposal=defaults pfsgroup=no-pfs}
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #2: transition from state STATE_QUICK_I1 to state STATE_QUICK_I2
Aug 20 06:44:11 iamcereal2 pluto[11489]: "L2TP-PSK" #2: STATE_QUICK_I2: sent QI2, IPsec SA established transport mode {ESP=>0xc1ccdd3a <0x69b800a2 xfrm=AES_128-HMAC_SHA1 NATOA=none NATD=none DPD=none}

Then I receive a message from inotify that I am "disconnected" though that is not true as all VPN connections are available. Seems like an inconvenience only though, as it makes it a little more tedious to disconnect from VPN, does not hamper VPN operations. Not sure why, searching through logs, let me know if a different one might be needed. GUI icon also says "disconnected" though I clearly am connected and can reach VPN resources.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.