Discussion:
[Swan] libreswan 3.17 NAT-T fails in phase2
Ge Xu
2016-06-14 06:16:57 UTC
Permalink
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.

Here is ipsec.conf of the VPN endpoint behind NAT

config setup
protostack=klips
interfaces="ipsec0=eth0"
conn vpn-0
authby=secret
auto=start
left=<local ip>
leftid=<vpn peer ip public>
right=<vpn remote peer ip>
leftsubnet=0.0.0.0/0
rightsubnet=0.0.0.0/0
ike=3des-sha1;modp1024
phase2alg=3des-sha1;modp1024
ikelifetime=28800s
salifetime=3600s
leftupdown=/var/run/updown.klips
dpddelay=15
dpdtimeout=25
dpdaction=hold

Then I run ipsec verify, and get
Version check and ipsec on-path [OK]
Libreswan 3.17 (klips) on 3.13.0-79-generic
Checking for IPsec support in kernel [OK]
KLIPS: checking for NAT Traversal support [OK]
KLIPS: checking for OCF crypto offload support [N/A]
KLIPS: IPsec SAref kernel support [N/A]
KLIPS: IPsec SAref Bind kernel support [N/A]
Pluto ipsec.conf syntax [OK]
Hardware random device [N/A]
Two or more interfaces found, checking IP forwarding [OK]
Checking rp_filter [OK]
Checking that pluto is running [OK]
Pluto listening for IKE on udp 500 [OK]
Pluto listening for IKE/NAT-T on udp 4500 [OK]
Pluto ipsec.secret syntax [OK]
Checking 'ip' command [OK]
Checking 'iptables' command [OK]
Checking 'prelink' command does not interfere with FIPSChecking for
obsolete ipsec.conf options [OK]
Opportunistic Encryption [DISABLED]

Looks OK. Then I ran ipsec status, I got

000 algorithm IKE dh group: id=2, name=OAKLEY_GROUP_MODP1024, bits=1024
000 algorithm IKE dh group: id=5, name=OAKLEY_GROUP_MODP1536, bits=1536
000 algorithm IKE dh group: id=14, name=OAKLEY_GROUP_MODP2048, bits=2048
000 algorithm IKE dh group: id=15, name=OAKLEY_GROUP_MODP3072, bits=3072
000 algorithm IKE dh group: id=16, name=OAKLEY_GROUP_MODP4096, bits=4096
000 algorithm IKE dh group: id=17, name=OAKLEY_GROUP_MODP6144, bits=6144
000 algorithm IKE dh group: id=18, name=OAKLEY_GROUP_MODP8192, bits=8192
000 algorithm IKE dh group: id=22, name=OAKLEY_GROUP_DH22, bits=1024
000 algorithm IKE dh group: id=23, name=OAKLEY_GROUP_DH23, bits=2048
000 algorithm IKE dh group: id=24, name=OAKLEY_GROUP_DH24, bits=2048
000
000 stats db_ops: {curr_cnt, total_cnt, maxsz} :context={0,2,64}
trans={0,2,2112} attrs={0,2,1408}
000
000 Connection list:
000
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+UP+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: #1; 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 #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
000
000 Bare Shunt list:
000


When I generate some traffic from remote peer, tcpdump shows the
encapsulated packet goes to the ipsec0 interface, but not decapped.

I was wondering if there is any change from 3.15 to 3.17 which makes my
ipsec.conf not working anymore.

Thanks for any suggestions and helps.

Toby
--
Ge (Toby) Xu
Paul Wouters
2016-06-14 17:45:19 UTC
Permalink
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 Xu
2016-06-14 23:03:27 UTC
Permalink
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;
***@10.2.128.241 ***@10.2.128.240 ***@10.2.128.241
***@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" ***@10.2.128.240 ***@10.0.0.1
***@10.2.128.240 ***@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
Post by Ge Xu
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
Paul Wouters
2016-06-14 23:24:13 UTC
Permalink
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
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: Total IPsec connections: loaded 1, active 1
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: #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
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
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 #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
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
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 Xu
2016-06-23 19:33:27 UTC
Permalink
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
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'
Jun 15 03:34:13: | cmd( 80):NTERFACE='ipsec0'
Jun 15 03:34:13: | cmd( 160):'10.2.128.241' PLUTO_MY_CLIENT='0.0.0.0/0'
Jun 15 03:34:13: | cmd( 240):Y_CLIENT_MASK='0.0.0.0' PLUTO_MY_PORT='0'
Jun 15 03:34:13: | cmd( 320):16388' PLUTO_SA_TYPE='ESP'
Jun 15 03:34:13: | cmd( 400):' PLUTO_PEER_CLIENT='0.0.0.0/0'
Jun 15 03:34:13: | cmd( 480):T_MASK='0.0.0.0' PLUTO_PEER_PORT='0'
Jun 15 03:34:13: | cmd( 560):UTO_STACK='klips' PLUTO_ADDTIME='0'
Jun 15 03:34:13: | cmd(
640):+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO'
Jun 15 03:34:13: | cmd( 720):Y='ipv4' XAUTH_FAILED=0
Jun 15 03:34:13: | cmd( 800):R_DOMAIN_INFO='' PLUTO_PEER_BANNER=''
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
Post by Paul Wouters
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
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
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;
3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2)
3DES_CBC(5)_192-SHA1(2)_160-MODP1024(2)
3DES_CBC_192-SHA1-MODP1024
3DES(3)_000-SHA1(2)_000; pfsgroup=MODP1024(2)
3DES(3)_000-SHA1(2)_000
3DES_000-HMAC_SHA1; pfsgroup=MODP1024
000 vpn-0: Total IPsec connections: loaded 1, active 1
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: #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;
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
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;
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;
force_encaps:no; nat_keepalive:yes; ikev1_natt:both
000 "vpn-0": newest ISAKMP SA: #5; newest IPsec SA: #0;
3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2)
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
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
Looks like in phase 2, something wrong in the 2nd/3rd packet.
I tcpdump the packets on local side and see
isakmp: phase 1 ? ident[E]
isakmp: phase 1 ? ident[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp: phase 2/others ? inf[E]
isakmp: phase 2/others ? inf[E]
isakmp: phase 2/others ? oakley-quick[E]
isakmp-nat-keep-alive
isakmp: phase 2/others ? inf[E]
isakmp: phase 2/others ? inf[E]
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
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
Paul Wouters
2016-07-02 12:19:37 UTC
Permalink
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.
It looks like you configured leftupdown=/var/run/updown.klips which
tries to run /usr/local/libexec/ipsec/_updown.klips which does not
exist? I think that failure is causing the passert() crash later on?
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]
Paul

Loading...