<html>
<head>
<style><!--
.hmmessage P
{
margin:0px;
padding:0px
}
body.hmmessage
{
font-size: 10pt;
font-family:Tahoma
}
--></style>
</head>
<body class='hmmessage'>
<div><div>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?</div><div><br></div><div>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. :(</div><div><br></div><div>======== /var/log/debug</div><div>-------- The log starts with the following:</div><div>network_thread: recv packet from 208.54.14.115, size = 107, tunnel = 0, call = 0 ref=0 refhim=0</div><div>get_call: allocating new tunnel for host 208.54.14.115, port 38626.</div><div>handle_avps: handling avp's for tunnel 47709, call 34297</div><div>message_type_avp: message type 1 (Start-Control-Connection-Request)</div><div>protocol_version_avp: peer is using version 1, revision 0.</div><div>hostname_avp: peer reports hostname 'anonymous'</div><div>framing_caps_avp: supported peer frames: async sync</div><div>assigned_tunnel_avp: using peer's tunnel 14256</div><div>receive_window_size_avp: peer wants RWS of 1. Will use flow control.</div><div>challenge_avp: challenge avp found</div><div>control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 14256, call is 0.</div><div>control_finish: sending SCCRP</div><div>build_fdset: closing down tunnel 18281</div><div>-------- Then the following block repeats 12 times:</div><div>network_thread: recv packet from 208.54.14.115, size = 107, tunnel = 0, call = 0 ref=0 refhim=0</div><div>get_call: allocating new tunnel for host 208.54.14.115, port 38626.</div><div>handle_avps: handling avp's for tunnel 64383, call 26519</div><div>message_type_avp: message type 1 (Start-Control-Connection-Request)</div><div>protocol_version_avp: peer is using version 1, revision 0.</div><div>hostname_avp: peer reports hostname 'anonymous'</div><div>framing_caps_avp: supported peer frames: async sync</div><div>assigned_tunnel_avp: using peer's tunnel 14256</div><div>receive_window_size_avp: peer wants RWS of 1. Will use flow control.</div><div>challenge_avp: challenge avp found</div><div>control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 14256, call is 0.</div><div>control_finish: Peer requested tunnel 14256 twice, ignoring second one.</div><div>build_fdset: closing down tunnel 64383</div><div>network_thread: select timeout</div><div>-------- The log wraps up with the following block:</div><div>network_thread: recv packet from 208.54.14.115, size = 36, tunnel = 0, call = 0 ref=0 refhim=0</div><div>get_call: allocating new tunnel for host 208.54.14.115, port 38626.</div><div>check_control: Received out of order control packet on tunnel -1 (got 1, expected 0)</div><div>handle_packet: bad control packet!</div><div>network_thread: bad packet</div><div>build_fdset: closing down tunnel 30254</div><div>network_thread: select timeout</div></div><div><br></div><div>======= Here's what the conversation looks like, according to tcpdump; what should I be looking for, here?</div><div><div>17:17:27.786160 IP 208.54.14.115.15236 > 71.231.87.222.500: isakmp: phase 1 I ident</div><div>17:17:27.786779 IP 71.231.87.222.500 > 208.54.14.115.15236: isakmp: phase 1 R ident</div><div>17:17:29.505126 IP 208.54.14.115.15236 > 71.231.87.222.500: isakmp: phase 1 I ident</div><div>17:17:29.516977 IP 71.231.87.222.500 > 208.54.14.115.15236: isakmp: phase 1 R ident</div><div>17:17:30.123990 IP 208.54.14.115.15345 > 71.231.87.222.4500: NONESP-encap: isakmp: phase 1 I ident[E]</div><div>17:17:30.125979 IP 71.231.87.222.4500 > 208.54.14.115.15345: NONESP-encap: isakmp: phase 1 R ident[E]</div><div>17:17:30.664761 IP 208.54.14.115.15345 > 71.231.87.222.4500: NONESP-encap: isakmp: phase 2/others I inf[E]</div><div>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]</div><div>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]</div><div>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]</div><div>17:17:34.184843 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x1), length 148</div><div>17:17:34.244410 IP 208.54.14.115.15345 > 71.231.87.222.4500: isakmp-nat-keep-alive</div><div>17:17:36.085581 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x2), length 148</div><div>17: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)</div><div>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)</div><div>17:17:36.189092 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17: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)</div><div>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)</div><div>17:17:38.064661 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x3), length 148</div><div>17:17:38.065827 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17: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)</div><div>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)</div><div>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)</div><div>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)</div><div>17:17:40.145423 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x4), length 148</div><div>17:17:40.147630 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17: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)</div><div>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)</div><div>17:17:42.245444 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x5), length 148</div><div>17:17:42.246617 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17: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)</div><div>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)</div><div>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)</div><div>17:17:45.206186 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x6), length 148</div><div>17:17:45.207306 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17: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)</div><div>17:17:45.906060 IP 71.231.87.222.4500 > 208.54.3.1.4500: UDP-encap: ESP(spi=0x000415f4,seq=0x110a6), length 84</div><div>17:17:45.985803 IP 208.54.3.1.4500 > 71.231.87.222.4500: UDP-encap: ESP(spi=0x40a0ca07,seq=0x121ca), length 84</div><div>17:17:46.137118 IP 71.231.87.222.4500 > 208.54.3.1.4500: NONESP-encap: isakmp: child_sa inf2[I]</div><div>17:17:46.172593 IP 208.54.3.1.4500 > 71.231.87.222.4500: NONESP-encap: isakmp: child_sa inf2[R]</div><div>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)</div><div>17:17:46.706352 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x7), length 148</div><div>17:17:46.707411 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17:17:48.945072 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x8), length 148</div><div>17:17:48.946168 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17:17:50.685077 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0x9), length 148</div><div>17:17:52.208277 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0xa), length 148</div></div><div><div>17: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)</div><div>17:17:52.688881 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17: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)</div><div>17:17:54.245187 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0xb), length 148</div><div>17:17:54.246291 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17:17:54.268723 IP 208.54.14.115.15345 > 71.231.87.222.4500: isakmp-nat-keep-alive</div><div>17: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)</div><div>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)</div><div>17:17:56.144442 IP 208.54.14.115.15345 > 71.231.87.222.4500: UDP-encap: ESP(spi=0xb7c48a9f,seq=0xc), length 148</div><div>17:17:56.145615 IP 71.231.87.222.1701 > 208.54.14.115.38626: l2tp:[TLS](14256/0)Ns=0,Nr=1 ZLB</div><div>17: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)</div></div><div><div><br></div></div><div>Here's the IPSec conversation, just for completeness.</div><div><div style="text-indent: 0px !important; ">======== /var/log/auth.log</div><div style="text-indent: 0px !important; "><div style="text-indent: 0px !important; ">packet from 208.54.14.115:15236: received Vendor ID payload [RFC 3947] method set to=109</div><div style="text-indent: 0px !important; ">packet from 208.54.14.115:15236: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02] meth=107, but already using method 109</div><div style="text-indent: 0px !important; ">packet from 208.54.14.115:15236: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 109</div><div style="text-indent: 0px !important; ">packet from 208.54.14.115:15236: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]</div><div style="text-indent: 0px !important; ">packet from 208.54.14.115:15236: ignoring Vendor ID payload [FRAGMENTATION 80000000]</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: responding to Main Mode from unknown peer 208.54.14.115</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: STATE_MAIN_R1: sent MR1, expecting MI2</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: NAT-Traversal: Result using RFC 3947 (NAT-Traversal): peer is NATed</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: STATE_MAIN_R2: sent MR2, expecting MI3</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: Main mode peer ID is ID_IPV4_ADDR: '25.131.144.251'</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3</div><div style="text-indent: 0px !important; ">"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</div><div style="text-indent: 0px !important; ">"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}</div></div><div style="text-indent: 0px !important; "><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: ignoring informational payload, type IPSEC_INITIAL_CONTACT msgid=00000000</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #3: received and ignored informational message</div><div style="text-indent: 0px !important; ">"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</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #4: responding to Quick Mode proposal {msgid:5147a7c5}</div><div style="text-indent: 0px !important; ">"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</div><div style="text-indent: 0px !important; ">"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</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #4: keeping refhim=4294901761 during rekey</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #4: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #4: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2</div><div style="text-indent: 0px !important; ">"L2TP-PSK-NAT"[2] 208.54.14.115 #4: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2</div><div style="text-indent: 0px !important; ">"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}</div><div><br></div></div></div><div>======== Versions</div><div><div style="text-indent: 0px !important; "><div style="text-indent: 0px !important; ">Package: openswan</div><div style="text-indent: 0px !important; ">State: installed</div><div style="text-indent: 0px !important; ">Automatically installed: no</div><div style="text-indent: 0px !important; ">Version: 1:2.6.26+dfsg-1</div></div><div style="text-indent: 0px !important; "><br style="text-indent: 0px !important; "></div><div style="text-indent: 0px !important; "><div style="text-indent: 0px !important; ">Package: xl2tpd</div><div style="text-indent: 0px !important; ">State: installed</div><div style="text-indent: 0px !important; ">Automatically installed: no</div><div style="text-indent: 0px !important; ">Version: 1.2.6+dfsg-1</div></div></div> </body>
</html>