[Openswan Users] IPSec up, L2TP down
Cim Ryan
cimryan at hotmail.com
Sat Mar 5 21:14:36 EST 2011
Hi folks! I'm having trouble understanding the debug output from xl2tpd. Will one of you fluent in this mysterious tongue please help me understand what it's trying so hard to tell me?
For background, I'm trying to connect from my phone (Android on T-Mobile) to my router/firewall (Ubuntu server 10.10). The phone tries to connect for around 15 seconds and then tells me it couldn't. While the IPSec connection seems to get established successfully (yay!), the l2tp connection seems to... not. :(
======== /var/log/debug-------- The log starts with the following:network_thread: recv packet from 208.54.14.115, size = 107, tunnel = 0, call = 0 ref=0 refhim=0get_call: allocating new tunnel for host 208.54.14.115, port 38626.handle_avps: handling avp's for tunnel 47709, call 34297message_type_avp: message type 1 (Start-Control-Connection-Request)protocol_version_avp: peer is using version 1, revision 0.hostname_avp: peer reports hostname 'anonymous'framing_caps_avp: supported peer frames: async syncassigned_tunnel_avp: using peer's tunnel 14256receive_window_size_avp: peer wants RWS of 1. Will use flow control.challenge_avp: challenge avp foundcontrol_finish: message type is Start-Control-Connection-Request(1). Tunnel is 14256, call is 0.control_finish: sending SCCRPbuild_fdset: closing down tunnel 18281-------- Then the following block repeats 12 times:network_thread: recv packet from 208.54.14.115, size = 107, tunnel = 0, call = 0 ref=0 refhim=0get_call: allocating new tunnel for host 208.54.14.115, port 38626.handle_avps: handling avp's for tunnel 64383, call 26519message_type_avp: message type 1 (Start-Control-Connection-Request)protocol_version_avp: peer is using version 1, revision 0.hostname_avp: peer reports hostname 'anonymous'framing_caps_avp: supported peer frames: async syncassigned_tunnel_avp: using peer's tunnel 14256receive_window_size_avp: peer wants RWS of 1. Will use flow control.challenge_avp: challenge avp foundcontrol_finish: message type is Start-Control-Connection-Request(1). Tunnel is 14256, call is 0.control_finish: Peer requested tunnel 14256 twice, ignoring second one.build_fdset: closing down tunnel 64383network_thread: select timeout-------- The log wraps up with the following block:network_thread: recv packet from 208.54.14.115, size = 36, tunnel = 0, call = 0 ref=0 refhim=0get_call: allocating new tunnel for host 208.54.14.115, port 38626.check_control: Received out of order control packet on tunnel -1 (got 1, expected 0)handle_packet: bad control packet!network_thread: bad packetbuild_fdset: closing down tunnel 30254network_thread: select timeout
======= Here's what the conversation looks like, according to tcpdump; what should I be looking for, here?17:17:27.786160 IP 208.54.14.115.15236 > 71.231.87.222.500: isakmp: phase 1 I ident17:17:27.786779 IP 71.231.87.222.500 > 208.54.14.115.15236: isakmp: phase 1 R ident17:17:29.505126 IP 208.54.14.115.15236 > 71.231.87.222.500: isakmp: phase 1 I ident17:17:29.516977 IP 71.231.87.222.500 > 208.54.14.115.15236: isakmp: phase 1 R ident17:17:30.123990 IP 208.54.14.115.15345 > 71.231.87.222.4500: NONESP-encap: isakmp: phase 1 I ident[E]17:17:30.125979 IP 71.231.87.222.4500 > 208.54.14.115.15345: NONESP-encap: isakmp: phase 1 R ident[E]17:17:30.664761 IP 208.54.14.115.15345 > 71.231.87.222.4500: NONESP-encap: isakmp: phase 2/others I inf[E]17:17:31.664716 IP 208.54.14.115.15345 > 71.231.87.222.4500: NONESP-encap: isakmp: phase 2/others I oakley-quick[E]17:17:31.668162 IP 71.231.87.222.4500 > 208.54.14.115.15345: NONESP-encap: isakmp: phase 2/others R oakley-quick[E]17:17:32.084793 IP 208.54.14.115.15345 > 71.231.87.222.4500: NONESP-encap: isakmp: phase 2/others I oakley-quick[E]17:17:34.184843 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x1), length 14817:17:34.244410 IP 208.54.14.115.15345 > 71.231.87.222.4500: isakmp-nat-keep-alive17:17:36.085581 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x2), length 14817:17:36.187915 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(47709) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:36.188080 IP 71.231.87.222.1701 > 208.54.14.115.39743: l2tp:[TLS](40147/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(18281) *RESULT_CODE(1/0 Timeout)17:17:36.189092 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:37.189031 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(47709) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:37.189067 IP 71.231.87.222.1701 > 208.54.14.115.39743: l2tp:[TLS](40147/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(18281) *RESULT_CODE(1/0 Timeout)17:17:38.064661 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x3), length 14817:17:38.065827 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:38.189262 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(47709) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:38.189297 IP 71.231.87.222.1701 > 208.54.14.115.39743: l2tp:[TLS](40147/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(18281) *RESULT_CODE(1/0 Timeout)17:17:39.190372 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(47709) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:39.190405 IP 71.231.87.222.1701 > 208.54.14.115.39743: l2tp:[TLS](40147/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(18281) *RESULT_CODE(1/0 Timeout)17:17:40.145423 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x4), length 14817:17:40.147630 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:40.190533 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(47709) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:40.190574 IP 71.231.87.222.1701 > 208.54.14.115.39743: l2tp:[TLS](40147/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(18281) *RESULT_CODE(1/0 Timeout)17:17:42.245444 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x5), length 14817:17:42.246617 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:42.246762 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(47709) *RESULT_CODE(1/0 Timeout)17:17:43.247903 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(47709) *RESULT_CODE(1/0 Timeout)17:17:44.249009 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(47709) *RESULT_CODE(1/0 Timeout)17:17:45.206186 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x6), length 14817:17:45.207306 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:45.249199 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(47709) *RESULT_CODE(1/0 Timeout)17:17:45.906060 IP 71.231.87.222.4500 > 208.54.3.1.4500: UDP-encap: ESP(spi=0x000415f4,seq=0x110a6), length 8417:17:45.985803 IP 208.54.3.1.4500 > 71.231.87.222.4500: UDP-encap: ESP(spi=0x40a0ca07,seq=0x121ca), length 8417:17:46.137118 IP 71.231.87.222.4500 > 208.54.3.1.4500: NONESP-encap: isakmp: child_sa inf2[I]17:17:46.172593 IP 208.54.3.1.4500 > 71.231.87.222.4500: NONESP-encap: isakmp: child_sa inf2[R]17:17:46.250312 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=1,Nr=1 *MSGTYPE(StopCCN) *ASSND_TUN_ID(47709) *RESULT_CODE(1/0 Timeout)17:17:46.706352 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x7), length 14817:17:46.707411 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:48.945072 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x8), length 14817:17:48.946168 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:50.685077 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x9), length 14817:17:52.208277 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0xa), length 14817:17:52.686689 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(49990) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:52.688881 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:53.687802 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(49990) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:54.245187 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0xb), length 14817:17:54.246291 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:54.268723 IP 208.54.14.115.15345 > 71.231.87.222.4500: isakmp-nat-keep-alive17:17:54.688356 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(49990) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:55.689475 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(49990) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)17:17:56.144442 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0xc), length 14817:17:56.145615 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB17:17:56.690128 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 *MSGTYPE(SCCRP) *PROTO_VER(1.0) *FRAMING_CAP(AS) *BEARER_CAP() *FIRM_VER(1680) *HOST_NAME(melange) *VENDOR_NAME(xelerance.com) *ASSND_TUN_ID(49990) *RECV_WIN_SIZE(4) *CHALLENGE_RESP(2e3c5f3d5661e05e82b51078ec6ae7b0)
Here's the IPSec conversation, just for completeness.======== /var/log/auth.logpacket from 208.54.14.115:15236: received Vendor ID payload [RFC 3947] method set to=109packet from 208.54.14.115:15236: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but already using method 109packet from 208.54.14.115:15236: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 109packet from 208.54.14.115:15236: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]packet from 208.54.14.115:15236: ignoring Vendor ID payload [FRAGMENTATION 80000000]"L2TP-PSK-NAT"[2] 208.54.14.115 #3: responding to Main Mode from unknown peer 208.54.14.115"L2TP-PSK-NAT"[2] 208.54.14.115 #3: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1"L2TP-PSK-NAT"[2] 208.54.14.115 #3: STATE_MAIN_R1: sent MR1, expecting MI2"L2TP-PSK-NAT"[2] 208.54.14.115 #3: NAT-Traversal: Result using RFC 3947 (NAT-Traversal): peer is NATed"L2TP-PSK-NAT"[2] 208.54.14.115 #3: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2"L2TP-PSK-NAT"[2] 208.54.14.115 #3: STATE_MAIN_R2: sent MR2, expecting MI3"L2TP-PSK-NAT"[2] 208.54.14.115 #3: Main mode peer ID is ID_IPV4_ADDR: '25.131.144.251'"L2TP-PSK-NAT"[2] 208.54.14.115 #3: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3"L2TP-PSK-NAT"[2] 208.54.14.115 #3: new NAT mapping for #3, was 208.54.14.115:15236, now 208.54.14.115:15345"L2TP-PSK-NAT"[2] 208.54.14.115 #3: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1024}"L2TP-PSK-NAT"[2] 208.54.14.115 #3: ignoring informational payload, type IPSEC_INITIAL_CONTACT msgid=00000000"L2TP-PSK-NAT"[2] 208.54.14.115 #3: received and ignored informational message"L2TP-PSK-NAT"[2] 208.54.14.115 #3: the peer proposed: 71.231.87.222/32:17/1701 -> 25.131.144.251/32:17/0"L2TP-PSK-NAT"[2] 208.54.14.115 #4: responding to Quick Mode proposal {msgid:5147a7c5}"L2TP-PSK-NAT"[2] 208.54.14.115 #4: us: 71.231.87.222<71.231.87.222>[+S=C]:17/1701---71.231.87.1"L2TP-PSK-NAT"[2] 208.54.14.115 #4: them: 208.54.14.115[25.131.144.251,+S=C]:17/0===25.131.144.251/32"L2TP-PSK-NAT"[2] 208.54.14.115 #4: keeping refhim=4294901761 during rekey"L2TP-PSK-NAT"[2] 208.54.14.115 #4: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1"L2TP-PSK-NAT"[2] 208.54.14.115 #4: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2"L2TP-PSK-NAT"[2] 208.54.14.115 #4: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2"L2TP-PSK-NAT"[2] 208.54.14.115 #4: STATE_QUICK_R2: IPsec SA established transport mode {ESP=>0x093b628a <0xb7c48a9f xfrm=3DES_0-HMAC_SHA1 NATOA=none NATD=208.54.14.115:15345 DPD=none}
======== VersionsPackage: openswanState: installedAutomatically installed: noVersion: 1:2.6.26+dfsg-1Package: xl2tpdState: installedAutomatically installed: noVersion: 1.2.6+dfsg-1
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.openswan.org/pipermail/users/attachments/20110305/c4e10174/attachment-0001.html
More information about the Users
mailing list