<div dir="ltr">Hi Paul,<div><br></div><div>Do you have any idea about what is wrong with the phase2 according to the logs?  </div><div><br></div><div>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.</div><div><br></div><div>Thanks,</div><div>Toby</div><div><br></div><div><br></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Jun 14, 2016 at 8:51 PM, Ge Xu <span dir="ltr"><<a href="mailto:tobyfan1980@gmail.com" target="_blank">tobyfan1980@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Attached are the log files on both peers.  I took a look, and found following lines, but not sure.<div><br></div><div><div>Jun 15 03:34:13: | pfkey_lib_debug:pfkey_extensions_free:Free extension 24 (24)</div><div>Jun 15 03:34:13: | raw_eroute result=success</div><div>Jun 15 03:34:13: | command executing up-client</div><div>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='<a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a>' 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='<a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a>' 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</div><div>Jun 15 03:34:13: | popen cmd is 883 chars long</div><div>Jun 15 03:34:13: | cmd(   0):2>&1 PLUTO_VERB='up-client' PLUTO_VERSION='2.0' PLUTO_CONNECTION='vpn-0' PLUTO_I:</div><div>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=:</div><div>Jun 15 03:34:13: | cmd( 160):'10.2.128.241' PLUTO_MY_CLIENT='<a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a>' PLUTO_MY_CLIENT_NET='0.0.0.0' PLUTO_M:</div><div>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=':</div><div>Jun 15 03:34:13: | cmd( 320):16388' PLUTO_SA_TYPE='ESP' PLUTO_PEER='10.2.128.240' PLUTO_PEER_ID='<a href="http://10.2.128.240" target="_blank">10.2.128.240</a>:</div><div>Jun 15 03:34:13: | cmd( 400):' PLUTO_PEER_CLIENT='<a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a>' PLUTO_PEER_CLIENT_NET='0.0.0.0' PLUTO_PEER_CLIEN:</div><div>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:</div><div>Jun 15 03:34:13: | cmd( 560):UTO_STACK='klips' PLUTO_ADDTIME='0' PLUTO_CONN_POLICY='PSK+ENCRYPT+TUNNEL+PFS+UP:</div><div>Jun 15 03:34:13: | cmd( 640):+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO' PLUTO_CONN_ADDRFAMIL:</div><div>Jun 15 03:34:13: | cmd( 720):Y='ipv4' XAUTH_FAILED=0 PLUTO_IS_PEER_CISCO='0' PLUTO_PEER_DNS_INFO='' PLUTO_PEE:</div><div>Jun 15 03:34:13: | cmd( 800):R_DOMAIN_INFO='' PLUTO_PEER_BANNER='' PLUTO_NM_CONFIGURED='0' /var/run/updown.kl:</div><div>Jun 15 03:34:13: | cmd( 880):ips:</div><div><span style="background-color:rgb(255,255,0)">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</span></div><div><span style="background-color:rgb(255,255,0)">Jun 15 03:34:13: "vpn-0" #2: up-client command exited with status 127</span></div><div><span style="background-color:rgb(255,255,0)">Jun 15 03:34:13: | route_and_eroute: firewall_notified: false</span></div><div><span style="background-color:rgb(255,255,0)">Jun 15 03:34:13: "vpn-0" #2: ASSERTION FAILED at /home/htsai/src/libreswan/programs/pluto/kernel.c:3038: esr != NULL</span></div><div><span style="background-color:rgb(255,255,0)">Jun 15 03:34:13: "vpn-0" #2: ABORT at /home/htsai/src/libreswan/programs/pluto/kernel.c:3038</span></div><div><span style="background-color:rgb(255,255,0)">"vpn-0" #2: ABORT at /home/htsai/src/libreswan/programs/pluto/kernel.c:3038</span></div><div><span style="background-color:rgb(255,255,0)">Jun 15 03:34:13: NSS DB directory: sql:/etc/ipsec.d</span></div><div><span style="background-color:rgb(255,255,0)">Jun 15 03:34:14: NSS initialized</span></div><div><span style="background-color:rgb(255,255,0)">Jun 15 03:34:14: libcap-ng support [disabled]</span></div></div><div><span style="background-color:rgb(255,255,0)"><br></span></div><div><span style="background-color:rgb(255,255,0)"><br></span></div><div><span style="background-color:rgb(255,255,255)">Thanks,</span></div><div><span style="background-color:rgb(255,255,255)">Toby</span></div></div><div class="gmail_extra"><div><div class="h5"><br><div class="gmail_quote">On Tue, Jun 14, 2016 at 4:24 PM, Paul Wouters <span dir="ltr"><<a href="mailto:paul@nohats.ca" target="_blank">paul@nohats.ca</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">On Tue, 14 Jun 2016, Ge Xu wrote:<br>
<br>
Sorry but you will have to find the real logs. If you do not know where<br>
those are, you can always enable logging to a file in ipsec.conf by<br>
adding:<br>
<br>
        logfile=/tmp/pluto.log<br>
<br>
to the "config setup" section in /etc/ipsec.conf<br>
<br>
It looks to me perhaps one kernel does not support whatever ESP<br>
algorithm you picked, but I can only tell for sure with the logs.<br>
<br>
Paul<br>
<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Date: Tue, 14 Jun 2016 19:03:27<br>
From: Ge Xu <<a href="mailto:tobyfan1980@gmail.com" target="_blank">tobyfan1980@gmail.com</a>><br>
Cc: <a href="mailto:swan@lists.libreswan.org" target="_blank">swan@lists.libreswan.org</a><br>
To: Paul Wouters <<a href="mailto:paul@nohats.ca" target="_blank">paul@nohats.ca</a>><br>
Subject: Re: [Swan] libreswan 3.17 NAT-T fails in phase2<div><div><br>
<br>
Paul,<br>
<br>
First of all, thanks for your reply and suggestion.<br>
<br>
<br>
I cannot find anything related about IPSec SA in syslog even though I set klipsdebug=all and plutodebug=all in ipsec.conf.<br>
After restart ipsec, I found that in the remote peer, it seems succeeds according to the ipsec status as bellow.<br>
<br>
000 vpn-0: "vpn-0-ipsectunnel-0":   newest ISAKMP SA: #8; newest IPsec SA: #18;<br>
000 vpn-0: "vpn-0-ipsectunnel-0":   IKE algorithms wanted: 3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2)<br>
000 vpn-0: "vpn-0-ipsectunnel-0":   IKE algorithms found:  3DES_CBC(5)_192-SHA1(2)_160-MODP1024(2)<br>
000 vpn-0: "vpn-0-ipsectunnel-0":   IKE algorithm newest: 3DES_CBC_192-SHA1-MODP1024<br>
000 vpn-0: "vpn-0-ipsectunnel-0":   ESP algorithms wanted: 3DES(3)_000-SHA1(2)_000; pfsgroup=MODP1024(2)<br>
000 vpn-0: "vpn-0-ipsectunnel-0":   ESP algorithms loaded: 3DES(3)_000-SHA1(2)_000<br>
000 vpn-0: "vpn-0-ipsectunnel-0":   ESP algorithm newest: 3DES_000-HMAC_SHA1; pfsgroup=MODP1024<br>
000 vpn-0:<br>
000 vpn-0: Total IPsec connections: loaded 1, active 1<br>
000 vpn-0:<br>
000 vpn-0: State Information: DDoS cookies not required, Accepting new IKE connections<br>
000 vpn-0: IKE SAs: total(1), half-open(0), open(0), authenticated(1), anonymous(0)<br>
000 vpn-0: IPsec SAs: total(1), authenticated(1), anonymous(0)<br>
000 vpn-0:<br>
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<br>
000 vpn-0: #18: "vpn-0-ipsectunnel-0" used 26s ago; <a href="mailto:esp.57df2ed4@10.2.128.241" target="_blank">esp.57df2ed4@10.2.128.241</a> <a href="mailto:esp.e688baf6@10.2.128.240" target="_blank">esp.e688baf6@10.2.128.240</a> <a href="mailto:tun.1018@10.2.128.241" target="_blank">tun.1018@10.2.128.241</a> <a href="mailto:tun.1019@10.2.128.240" target="_blank">tun.1019@10.2.128.240</a> ref=0 refhim=4294901761 Traffic:!<br>
ESPmax=4194303B<br>
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<br>
000 vpn-0:<br>
000 vpn-0: Bare Shunt list:<br>
000 vpn-0:<br>
<br>
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<br>
through.  <br>
<br>
000 "vpn-0": <a href="http://0.0.0.0/0===10.0.0.1" rel="noreferrer" target="_blank">0.0.0.0/0===10.0.0.1</a><10.0.0.1>[10.2.128.241]...10.2.128.240<10.2.128.240>===<a href="http://0.0.0.0/0" rel="noreferrer" target="_blank">0.0.0.0/0</a>; unrouted; eroute owner: #0<br>
000 "vpn-0":     oriented; my_ip=unset; their_ip=unset; myup=/var/run/updown.klips<br>
000 "vpn-0":   xauth us:none, xauth them:none,  my_username=[any]; their_username=[any]<br>
000 "vpn-0":   modecfg info: us:none, them:none, modecfg policy:push, dns1:unset, dns2:unset, domain:unset, banner:unset;<br>
000 "vpn-0":   labeled_ipsec:no;<br>
000 "vpn-0":   policy_label:unset;<br>
000 "vpn-0":   ike_life: 28800s; ipsec_life: 3600s; replay_window: 32; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0;<br>
000 "vpn-0":   retransmit-interval: 500ms; retransmit-timeout: 60s;<br>
000 "vpn-0":   sha2_truncbug:no; initial_contact:no; cisco_unity:no; fake_strongswan:no; send_vendorid:no;<br>
000 "vpn-0":   policy: PSK+ENCRYPT+TUNNEL+PFS+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO;<br>
000 "vpn-0":   conn_prio: 0,0; interface: eth0; metric: 0; mtu: unset; sa_prio:auto; nflog-group: unset; mark: unset;<br>
000 "vpn-0":   dpd: action:hold; delay:15; timeout:75; nat-t: force_encaps:no; nat_keepalive:yes; ikev1_natt:both<br>
000 "vpn-0":   newest ISAKMP SA: #5; newest IPsec SA: #0;<br>
000 "vpn-0":   IKE algorithms wanted: 3DES_CBC(5)_000-SHA1(2)_000-MODP1024(2)<br>
000 "vpn-0":   IKE algorithms found:  3DES_CBC(5)_192-SHA1(2)_160-MODP1024(2)<br>
000 "vpn-0":   IKE algorithm newest: 3DES_CBC_192-SHA1-MODP1024<br>
000 "vpn-0":   ESP algorithms wanted: 3DES(3)_000-SHA1(2)_000; pfsgroup=MODP1024(2)<br>
000 "vpn-0":   ESP algorithms loaded: 3DES(3)_000-SHA1(2)_000<br>
000<br>
000 Total IPsec connections: loaded 1, active 0<br>
000<br>
000 State Information: DDoS cookies not required, Accepting new IKE connections<br>
000 IKE SAs: total(1), half-open(0), open(0), authenticated(1), anonymous(0)<br>
000 IPsec SAs: total(1), authenticated(1), anonymous(0)<br>
000<br>
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<br>
000 #15: "vpn-0" <a href="mailto:esp.e688baf6@10.2.128.240" target="_blank">esp.e688baf6@10.2.128.240</a> <a href="mailto:esp.57df2ed4@10.0.0.1" target="_blank">esp.57df2ed4@10.0.0.1</a> <a href="mailto:tun.1016@10.2.128.240" target="_blank">tun.1016@10.2.128.240</a> <a href="mailto:tun.1017@10.0.0.1" target="_blank">tun.1017@10.0.0.1</a> ref=0 refhim=4294901761 Traffic:! ESPmax=4194303B<br>
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<br>
000<br>
000 Bare Shunt list:<br>
<br>
Looks like in phase 2, something wrong in the 2nd/3rd packet. <br>
<br>
I tcpdump the packets on local side and see <br>
<br>
23:00:08.195272 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap: isakmp: phase 1 ? ident[E]<br>
23:00:08.215129 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 1 ? ident[E]<br>
23:00:08.238236 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:08.339546 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:08.477468 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:08.791668 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:08.819497 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:09.292133 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:09.304959 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:10.294561 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:12.294304 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:16.296868 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:23.201352 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? inf[E]<br>
23:00:23.212712 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap: isakmp: phase 2/others ? inf[E]<br>
23:00:24.297207 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
23:00:28.135880 IP 10.0.0.1.4500 > 10.2.128.240.4500: isakmp-nat-keep-alive<br>
23:00:38.370317 IP 10.2.128.240.4500 > 10.0.0.1.4500: NONESP-encap: isakmp: phase 2/others ? inf[E]<br>
23:00:38.378497 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? inf[E]<br>
23:00:40.298093 IP 10.0.0.1.4500 > 10.2.128.240.4500: NONESP-encap: isakmp: phase 2/others ? oakley-quick[E]<br>
<br>
<br>
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?<br>
<br>
Thanks,<br>
Toby<br>
<br>
<br>
Thanks,<br>
Toby<br>
<br>
On Tue, Jun 14, 2016 at 10:45 AM, Paul Wouters <<a href="mailto:paul@nohats.ca" target="_blank">paul@nohats.ca</a>> wrote:<br>
      On Mon, 13 Jun 2016, Ge Xu wrote:<br>
<br>
            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<br>
            fails. <br>
<br>
<br>
      I am not aware of anything specific causing that.<br>
<br>
            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;<br>
            import:admin initiate<br>
            000 #1: "vpn-0":4500 STATE_MAIN_I4 (ISAKMP SA established); EVENT_SA_REPLACE in 27801s; newest ISAKMP; lastdpd=-1s(seq in:0<br>
            out:0); idle; import:admin initiate<br>
<br>
<br>
      It looks like the IPsec SA did not fully establish. Either your logs or<br>
      the remote endpoint's log should have an entry saying what went wrong.<br>
<br>
      Paul<br>
<br>
<br>
<br>
<br>
--<br>
Ge (Toby) Xu<br>
<br>
<br>
</div></div></blockquote>
</blockquote></div><br><br clear="all"><div><br></div></div></div><span class="HOEnZb"><font color="#888888">-- <br><div data-smartmail="gmail_signature">Ge (Toby) Xu<br></div>
</font></span></div>
</blockquote></div><br><br clear="all"><div><br></div>-- <br><div class="gmail_signature" data-smartmail="gmail_signature">Ge (Toby) Xu<br></div>
</div>