[Swan] libreswan 3.17 NAT-T fails in phase2
Ge Xu
tobyfan1980 at gmail.com
Thu Jun 23 19:33:27 UTC 2016
Hi Paul,
Do you have any idea about what is wrong with the phase2 according to the
logs?
The machines at both sides have the same kernel I don't understand why the
status on one side is active, but on the NAT side is not.
Thanks,
Toby
On Tue, Jun 14, 2016 at 8:51 PM, Ge Xu <tobyfan1980 at gmail.com> wrote:
> Attached are the log files on both peers. I took a look, and found
> following lines, but not sure.
>
> Jun 15 03:34:13: | pfkey_lib_debug:pfkey_extensions_free:Free extension 24
> (24)
> Jun 15 03:34:13: | raw_eroute result=success
> Jun 15 03:34:13: | command executing up-client
> Jun 15 03:34:13: | executing up-client: 2>&1 PLUTO_VERB='up-client'
> PLUTO_VERSION='2.0' PLUTO_CONNECTION='vpn-0' PLUTO_INTERFACE='ipsec0'
> PLUTO_NEXT_HOP='10.2.128.240' PLUTO_ME='10.0.0.1'
> PLUTO_MY_ID='10.2.128.241' PLUTO_MY_CLIENT='0.0.0.0/0'
> PLUTO_MY_CLIENT_NET='0.0.0.0' PLUTO_MY_CLIENT_MASK='0.0.0.0'
> PLUTO_MY_PORT='0' PLUTO_MY_PROTOCOL='0' PLUTO_SA_REQID='16388'
> PLUTO_SA_TYPE='ESP' PLUTO_PEER='10.2.128.240' PLUTO_PEER_ID='10.2.128.240'
> PLUTO_PEER_CLIENT='0.0.0.0/0' PLUTO_PEER_CLIENT_NET='0.0.0.0'
> PLUTO_PEER_CLIENT_MASK='0.0.0.0' PLUTO_PEER_PORT='0'
> PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PLUTO_STACK='klips'
> PLUTO_ADDTIME='0'
> PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO'
> PLUTO_CONN_ADDRFAMILY='ipv4' XAUTH_FAILED=0 PLUTO_IS_PEER_CISCO='0'
> PLUTO_PEER_DNS_INFO='' PLUTO_PEER_DOMAIN_INFO='' PLUTO_PEER_BANNER=''
> PLUTO_NM_CONFIGURED='0' /var/run/updown.klips
> Jun 15 03:34:13: | popen cmd is 883 chars long
> Jun 15 03:34:13: | cmd( 0):2>&1 PLUTO_VERB='up-client'
> PLUTO_VERSION='2.0' PLUTO_CONNECTION='vpn-0' PLUTO_I:
> Jun 15 03:34:13: | cmd( 80):NTERFACE='ipsec0'
> PLUTO_NEXT_HOP='10.2.128.240' PLUTO_ME='10.0.0.1' PLUTO_MY_ID=:
> Jun 15 03:34:13: | cmd( 160):'10.2.128.241' PLUTO_MY_CLIENT='0.0.0.0/0'
> PLUTO_MY_CLIENT_NET='0.0.0.0' PLUTO_M:
> Jun 15 03:34:13: | cmd( 240):Y_CLIENT_MASK='0.0.0.0' PLUTO_MY_PORT='0'
> PLUTO_MY_PROTOCOL='0' PLUTO_SA_REQID=':
> Jun 15 03:34:13: | cmd( 320):16388' PLUTO_SA_TYPE='ESP'
> PLUTO_PEER='10.2.128.240' PLUTO_PEER_ID='10.2.128.240:
> Jun 15 03:34:13: | cmd( 400):' PLUTO_PEER_CLIENT='0.0.0.0/0'
> PLUTO_PEER_CLIENT_NET='0.0.0.0' PLUTO_PEER_CLIEN:
> Jun 15 03:34:13: | cmd( 480):T_MASK='0.0.0.0' PLUTO_PEER_PORT='0'
> PLUTO_PEER_PROTOCOL='0' PLUTO_PEER_CA='' PL:
> Jun 15 03:34:13: | cmd( 560):UTO_STACK='klips' PLUTO_ADDTIME='0'
> PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+PFS+UP:
> Jun 15 03:34:13: | cmd(
> 640):+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO'
> PLUTO_CONN_ADDRFAMIL:
> Jun 15 03:34:13: | cmd( 720):Y='ipv4' XAUTH_FAILED=0
> PLUTO_IS_PEER_CISCO='0' PLUTO_PEER_DNS_INFO='' PLUTO_PEE:
> Jun 15 03:34:13: | cmd( 800):R_DOMAIN_INFO='' PLUTO_PEER_BANNER=''
> PLUTO_NM_CONFIGURED='0' /var/run/updown.kl:
> Jun 15 03:34:13: | cmd( 880):ips:
> Jun 15 03:34:13: "vpn-0" #2: up-client output: /var/run/updown.klips: 12:
> exec: /usr/local/libexec/ipsec/_updown.klips: not found
> Jun 15 03:34:13: "vpn-0" #2: up-client command exited with status 127
> Jun 15 03:34:13: | route_and_eroute: firewall_notified: false
> Jun 15 03:34:13: "vpn-0" #2: ASSERTION FAILED at
> /home/htsai/src/libreswan/programs/pluto/kernel.c:3038: esr != NULL
> Jun 15 03:34:13: "vpn-0" #2: ABORT at
> /home/htsai/src/libreswan/programs/pluto/kernel.c:3038
> "vpn-0" #2: ABORT at /home/htsai/src/libreswan/programs/pluto/kernel.c:3038
> Jun 15 03:34:13: NSS DB directory: sql:/etc/ipsec.d
> Jun 15 03:34:14: NSS initialized
> Jun 15 03:34:14: libcap-ng support [disabled]
>
>
> Thanks,
> Toby
>
> On Tue, Jun 14, 2016 at 4:24 PM, Paul Wouters <paul at nohats.ca> wrote:
>
>> On Tue, 14 Jun 2016, Ge Xu wrote:
>>
>> Sorry but you will have to find the real logs. If you do not know where
>> those are, you can always enable logging to a file in ipsec.conf by
>> adding:
>>
>> logfile=/tmp/pluto.log
>>
>> to the "config setup" section in /etc/ipsec.conf
>>
>> It looks to me perhaps one kernel does not support whatever ESP
>> algorithm you picked, but I can only tell for sure with the logs.
>>
>> Paul
>>
>> Date: Tue, 14 Jun 2016 19:03:27
>>> From: Ge Xu <tobyfan1980 at gmail.com>
>>> Cc: swan at lists.libreswan.org
>>> To: Paul Wouters <paul at nohats.ca>
>>> Subject: Re: [Swan] libreswan 3.17 NAT-T fails in phase2
>>>
>>>
>>> Paul,
>>>
>>> First of all, thanks for your reply and suggestion.
>>>
>>>
>>> I cannot find anything related about IPSec SA in syslog even though I
>>> set klipsdebug=all and plutodebug=all in ipsec.conf.
>>> After restart ipsec, I found that in the remote peer, it seems succeeds
>>> according to the ipsec status as bellow.
>>>
>>> 000 vpn-0: "vpn-0-ipsectunnel-0": newest ISAKMP SA: #8; newest IPsec
>>> SA: #18;
>>> 000 vpn-0: "vpn-0-ipsectunnel-0": IKE algorithms wanted:
>>> 3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2)
>>> 000 vpn-0: "vpn-0-ipsectunnel-0": IKE algorithms found:
>>> 3DES_CBC(5)_192-SHA1(2)_160-MODP1024(2)
>>> 000 vpn-0: "vpn-0-ipsectunnel-0": IKE algorithm newest:
>>> 3DES_CBC_192-SHA1-MODP1024
>>> 000 vpn-0: "vpn-0-ipsectunnel-0": ESP algorithms wanted:
>>> 3DES(3)_000-SHA1(2)_000; pfsgroup=MODP1024(2)
>>> 000 vpn-0: "vpn-0-ipsectunnel-0": ESP algorithms loaded:
>>> 3DES(3)_000-SHA1(2)_000
>>> 000 vpn-0: "vpn-0-ipsectunnel-0": ESP algorithm newest:
>>> 3DES_000-HMAC_SHA1; pfsgroup=MODP1024
>>> 000 vpn-0:
>>> 000 vpn-0: Total IPsec connections: loaded 1, active 1
>>> 000 vpn-0:
>>> 000 vpn-0: State Information: DDoS cookies not required, Accepting new
>>> IKE connections
>>> 000 vpn-0: IKE SAs: total(1), half-open(0), open(0), authenticated(1),
>>> anonymous(0)
>>> 000 vpn-0: IPsec SAs: total(1), authenticated(1), anonymous(0)
>>> 000 vpn-0:
>>> 000 vpn-0: #18: "vpn-0-ipsectunnel-0":4500 STATE_QUICK_I2 (sent QI2,
>>> IPsec SA established); EVENT_SA_REPLACE in 38s; newest IPSEC; eroute owner;
>>> isakmp#8; idle; import:local rekey
>>> 000 vpn-0: #18: "vpn-0-ipsectunnel-0" used 26s ago;
>>> esp.57df2ed4 at 10.2.128.241 esp.e688baf6 at 10.2.128.240
>>> tun.1018 at 10.2.128.241 tun.1019 at 10.2.128.240 ref=0 refhim=4294901761
>>> Traffic:!
>>> ESPmax=4194303B
>>> 000 vpn-0: #8: "vpn-0-ipsectunnel-0":4500 STATE_MAIN_I4 (ISAKMP SA
>>> established); EVENT_SA_REPLACE in 26635s; newest ISAKMP; lastdpd=11s(seq
>>> in:5909 out:0); idle; import:local rekey
>>> 000 vpn-0:
>>> 000 vpn-0: Bare Shunt list:
>>> 000 vpn-0:
>>>
>>> But on the local peer behind NAT gateway, it looks weird. The message
>>> shows IPsec SA installed but no established. IPsec connections active 0,
>>> and my end to end traffic still cannot go
>>> through.
>>>
>>> 000 "vpn-0": 0.0.0.0/0===10.0.0.1
>>> <10.0.0.1>[10.2.128.241]...10.2.128.240<10.2.128.240>===0.0.0.0/0;
>>> unrouted; eroute owner: #0
>>> 000 "vpn-0": oriented; my_ip=unset; their_ip=unset;
>>> myup=/var/run/updown.klips
>>> 000 "vpn-0": xauth us:none, xauth them:none, my_username=[any];
>>> their_username=[any]
>>> 000 "vpn-0": modecfg info: us:none, them:none, modecfg policy:push,
>>> dns1:unset, dns2:unset, domain:unset, banner:unset;
>>> 000 "vpn-0": labeled_ipsec:no;
>>> 000 "vpn-0": policy_label:unset;
>>> 000 "vpn-0": ike_life: 28800s; ipsec_life: 3600s; replay_window: 32;
>>> rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0;
>>> 000 "vpn-0": retransmit-interval: 500ms; retransmit-timeout: 60s;
>>> 000 "vpn-0": sha2_truncbug:no; initial_contact:no; cisco_unity:no;
>>> fake_strongswan:no; send_vendorid:no;
>>> 000 "vpn-0": policy:
>>> PSK+ENCRYPT+TUNNEL+PFS+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO;
>>> 000 "vpn-0": conn_prio: 0,0; interface: eth0; metric: 0; mtu: unset;
>>> sa_prio:auto; nflog-group: unset; mark: unset;
>>> 000 "vpn-0": dpd: action:hold; delay:15; timeout:75; nat-t:
>>> force_encaps:no; nat_keepalive:yes; ikev1_natt:both
>>> 000 "vpn-0": newest ISAKMP SA: #5; newest IPsec SA: #0;
>>> 000 "vpn-0": IKE algorithms wanted:
>>> 3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2)
>>> 000 "vpn-0": IKE algorithms found:
>>> 3DES_CBC(5)_192-SHA1(2)_160-MODP1024(2)
>>> 000 "vpn-0": IKE algorithm newest: 3DES_CBC_192-SHA1-MODP1024
>>> 000 "vpn-0": ESP algorithms wanted: 3DES(3)_000-SHA1(2)_000;
>>> pfsgroup=MODP1024(2)
>>> 000 "vpn-0": ESP algorithms loaded: 3DES(3)_000-SHA1(2)_000
>>> 000
>>> 000 Total IPsec connections: loaded 1, active 0
>>> 000
>>> 000 State Information: DDoS cookies not required, Accepting new IKE
>>> connections
>>> 000 IKE SAs: total(1), half-open(0), open(0), authenticated(1),
>>> anonymous(0)
>>> 000 IPsec SAs: total(1), authenticated(1), anonymous(0)
>>> 000
>>> 000 #15: "vpn-0":4500 STATE_QUICK_R1 (sent QR1, inbound IPsec SA
>>> installed, expecting QI2); EVENT_v1_RETRANSMIT in 2s; isakmp#5; idle;
>>> import:not set
>>> 000 #15: "vpn-0" esp.e688baf6 at 10.2.128.240 esp.57df2ed4 at 10.0.0.1
>>> tun.1016 at 10.2.128.240 tun.1017 at 10.0.0.1 ref=0 refhim=4294901761
>>> Traffic:! ESPmax=4194303B
>>> 000 #5: "vpn-0":4500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established);
>>> EVENT_SA_REPLACE in 27399s; newest ISAKMP; lastdpd=18s(seq in:1072 out:0);
>>> idle; import:not set
>>> 000
>>> 000 Bare Shunt list:
>>>
>>> Looks like in phase 2, something wrong in the 2nd/3rd packet.
>>>
>>> I tcpdump the packets on local side and see
>>>
>>> 23:00:08.195272 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap:
>>> isakmp: phase 1 ? ident[E]
>>> 23:00:08.215129 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 1 ? ident[E]
>>> 23:00:08.238236 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:08.339546 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:08.477468 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:08.791668 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:08.819497 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:09.292133 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:09.304959 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:10.294561 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:12.294304 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:16.296868 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:23.201352 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? inf[E]
>>> 23:00:23.212712 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap:
>>> isakmp: phase 2/others ? inf[E]
>>> 23:00:24.297207 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>> 23:00:28.135880 IP 10.0.0.1.4500 > 10.2.128.240.4500:
>>> isakmp-nat-keep-alive
>>> 23:00:38.370317 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap:
>>> isakmp: phase 2/others ? inf[E]
>>> 23:00:38.378497 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? inf[E]
>>> 23:00:40.298093 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap:
>>> isakmp: phase 2/others ? oakley-quick[E]
>>>
>>>
>>> Just from this dump, it is difficult to find anything useful. Is there
>>> a way to see more detailed things about what happened in phase 2?
>>>
>>> Thanks,
>>> Toby
>>>
>>>
>>> Thanks,
>>> Toby
>>>
>>> On Tue, Jun 14, 2016 at 10:45 AM, Paul Wouters <paul at nohats.ca> wrote:
>>> On Mon, 13 Jun 2016, Ge Xu wrote:
>>>
>>> I am testing a VPN behind of a NAT gateway. I tried
>>> libreswan 3.15 and 3.17 with same configuration. 3.15 succeeds, but 3.17
>>> fails.
>>>
>>>
>>> I am not aware of anything specific causing that.
>>>
>>> 000 #2: "vpn-0":4500 STATE_QUICK_I1 (sent QI1, expecting
>>> QR1); EVENT_CRYPTO_FAILED in 54s; lastdpd=-1s(seq in:0 out:0); idle;
>>> import:admin initiate
>>> 000 #1: "vpn-0":4500 STATE_MAIN_I4 (ISAKMP SA established);
>>> EVENT_SA_REPLACE in 27801s; newest ISAKMP; lastdpd=-1s(seq in:0
>>> out:0); idle; import:admin initiate
>>>
>>>
>>> It looks like the IPsec SA did not fully establish. Either your
>>> logs or
>>> the remote endpoint's log should have an entry saying what went
>>> wrong.
>>>
>>> Paul
>>>
>>>
>>>
>>>
>>> --
>>> Ge (Toby) Xu
>>>
>>>
>>>
>
>
> --
> Ge (Toby) Xu
>
--
Ge (Toby) Xu
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20160623/8394e2e3/attachment-0001.html>
More information about the Swan
mailing list