[Swan] Duplicate ip xfrm state entries, unconfigured ip xfrm state entries

Craig Marker cmarker at inspeednetworks.com
Mon Sep 10 17:53:16 UTC 2018


 I use auto=ignore since I have other processes that manage the tunnel connection and ensure it sets up correctly (client initiating with server rather than leaving that up to chance).. I believe something went wrong during post-reboot initiation, which is contained in the first two log snippets. Multiples IPsec SAs are installed and I can’t explain why.

The last two log snippets capture ipsec auto —delete conn37 followed by ipsec auto —replace conn37 and ipsec auto —route conn37. It appears like something went amiss when the client receives the —delete conn37 notification, as the quick mode initiation in #64 gets deleted, and thus the client machine appears to forget about conn1. I believe the root problem is the initial initiation of multiple SAs, though I could be wrong.

Post-reboot initiation from server...

Sep  7 03:23:16 cq-use1f-1 pluto[2446]: "conn37": prepare-client output: net.ipv4.conf.conn37.disable_policy = 1
Sep  7 03:23:16 cq-use1f-1 pluto[2446]: "conn37": prepare-client output: net.ipv4.conf.conn37.rp_filter = 0
Sep  7 03:23:16 cq-use1f-1 pluto[2446]: "conn37": prepare-client output: net.ipv4.conf.conn37.forwarding = 1
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: packet from 199.32.40.51:500: initial Main Mode message received on 51.179.82.210:500 but no connection has been authorized with policy RSASIG+IKEV1_ALLOW
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: "conn37" #1: responding to Main Mode
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: "conn37" #1: STATE_MAIN_R1: sent MR1, expecting MI2
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: packet from 100.9.123.24:500: initial Main Mode message received on 51.179.82.210:500 but no connection has been authorized with policy RSASIG+IKEV1_ALLOW
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: "conn37" #1: STATE_MAIN_R2: sent MR2, expecting MI3
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: "conn37" #1: Peer ID is ID_FQDN: '@left-70.240.163.43'
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: "conn37" #1: certificate verified OK: CN=ABC123,OU=Engineering,O="Craig Inc.",L=Seattle,ST=Washington,C=US
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: "conn37" #1: I am sending my cert
Sep  7 03:23:17 cq-use1f-1 pluto[2446]: "conn37" #1: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=RSA_SIG cipher=aes_256 integ=sha2_256 group=MODP2048}
Sep  7 03:23:18 cq-use1f-1 pluto[2446]: "conn37" #1: retransmitting in response to duplicate packet; already STATE_MAIN_R3
Sep  7 03:23:18 cq-use1f-1 pluto[2446]: "conn37" #1: the peer proposed: 0.0.0.0/0:0/0 -> 0.0.0.0/0:0/0
Sep  7 03:23:18 cq-use1f-1 pluto[2446]: "conn37" #2: responding to Quick Mode proposal {msgid:6e65d8fb}
Sep  7 03:23:18 cq-use1f-1 pluto[2446]: "conn37" #2:     us: 0.0.0.0/0===51.179.82.210<51.179.82.210>[C=US, ST=Washington, L=Seattle, O=Craig Inc., OU=Engineering, CN=cq-use1f-1]
Sep  7 03:23:18 cq-use1f-1 pluto[2446]: "conn37" #2:   them: 70.240.163.43<70.240.163.43>[@left-70.240.163.43]===0.0.0.0/0
Sep  7 03:23:18 cq-use1f-1 pluto[2446]: "conn37" #2: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2 tunnel mode {ESP/NAT=>0x5e5bf357 <0xa767280b xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=70.240.163.43:4500 DPD=passive}
Sep  7 03:23:18 cq-use1f-1 pluto[2446]: "conn37" #2: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP/NAT=>0x5e5bf357 <0xa767280b xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=70.240.163.43:4500 DPD=passive}

… information unrelated to conn37 removed ...

Sep  7 03:23:20 cq-use1f-1 pluto[2446]: assign_holdpass() delete_bare_shunt() failed
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: initiate_ondemand_body() failed to install negotiation_shunt,
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: initiate on demand from 172.16.0.2:8 to 172.16.0.3:0 proto=1 because: acquire
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: "conn37" #5: initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#1 msgid:da2d1713 proposal=AES_CBC_256-HMAC_SHA2_256_128 pfsgroup=MODP2048}
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: assign_holdpass() delete_bare_shunt() failed
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: initiate_ondemand_body() failed to install negotiation_shunt,
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: initiate on demand from 172.16.2.2:8 to 172.16.2.3:0 proto=1 because: acquire
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: "conn37" #5: initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#1 msgid:da2d1713 proposal=AES_CBC_256-HMAC_SHA2_256_128 pfsgroup=MODP2048}
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: "conn37" #6: initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#1 msgid:4f41317c proposal=AES_CBC_256-HMAC_SHA2_256_128 pfsgroup=MODP2048}
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: "conn37" #5: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP/NAT=>0xc981ba01 <0xefe112e2 xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=70.240.163.43:4500 DPD=passive}
Sep  7 03:23:20 cq-use1f-1 pluto[2446]: "conn37" #6: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP/NAT=>0x863a2b6b <0xcbfb1484 xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=70.240.163.43:4500 DPD=passive}

Post-reboot initiation from client...

Sep  7 03:23:14 fmn-767 pluto[2190]: "conn1" #47: STATE_MAIN_I1: retransmission; will wait 0.5 seconds for response
Sep  7 03:23:14 fmn-767 pluto[2190]: "conn1" #47: STATE_MAIN_I1: retransmission; will wait 1 seconds for response
Sep  7 03:23:15 fmn-767 pluto[2190]: "conn1" #47: STATE_MAIN_I1: retransmission; will wait 2 seconds for response
Sep  7 03:23:17 fmn-767 pluto[2190]: "conn1" #47: STATE_MAIN_I1: retransmission; will wait 4 seconds for response
Sep  7 03:23:17 fmn-767 pluto[2190]: "conn1" #47: STATE_MAIN_I2: sent MI2, expecting MR2
Sep  7 03:23:17 fmn-767 pluto[2190]: "conn1" #47: I am sending my cert
Sep  7 03:23:17 fmn-767 pluto[2190]: "conn1" #47: I am sending a certificate request
Sep  7 03:23:17 fmn-767 pluto[2190]: "conn1" #47: STATE_MAIN_I3: sent MI3, expecting MR3
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #47: STATE_MAIN_I3: retransmission; will wait 0.5 seconds for response
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #47: Peer ID is ID_DER_ASN1_DN: 'C=US, ST=Washington, L=Seattle, O=Craig Inc., OU=Engineering, CN=cq-use1f-1'
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #47: certificate verified OK: CN=cq-use1f-1,OU=Engineering,O="Craig Inc.",L=Seattle,ST=Washington,C=US
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #47: STATE_MAIN_I4: ISAKMP SA established {auth=RSA_SIG cipher=aes_256 integ=sha2_256 group=MODP2048}
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #48: initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO {using isakmp#47 msgid:6e65d8fb proposal=AES_CBC_256-HMAC_SHA2_256_128 pfsgroup=MODP2048}
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #48: up-client output: vti interface "conn1" already exists with conflicting setting
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #48: up-client output: existing: conn1: ip/ip remote any local 70.240.163.43 ttl inherit key 16777216
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #48: up-client output: wanted  : conn1: ip/ip  remote any  local 70.240.163.43  ttl inherit  key 16777216
Sep  7 03:23:18 fmn-767 pluto[2190]: "conn1" #48: STATE_QUICK_I2: sent QI2, IPsec SA established tunnel mode {ESP/NAT=>0xa767280b <0x5e5bf357 xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=51.179.82.210:4500 DPD=active}
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #47: the peer proposed: 0.0.0.0/0:0/0 -> 0.0.0.0/0:0/0
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #49: responding to Quick Mode proposal {msgid:da2d1713}
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #49:     us: 0.0.0.0/0===70.240.163.43<70.240.163.43>[@left-70.240.163.43]
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #49:   them: 51.179.82.210<51.179.82.210>[C=US, ST=Washington, L=Seattle, O=Craig Inc., OU=Engineering, CN=cq-use1f-1]===0.0.0.0/0
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #49: keeping refhim=0 during rekey
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #49: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2 tunnel mode {ESP/NAT=>0xefe112e2 <0xc981ba01 xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=51.179.82.210:4500 DPD=active}
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #47: the peer proposed: 0.0.0.0/0:0/0 -> 0.0.0.0/0:0/0
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #50: responding to Quick Mode proposal {msgid:4f41317c}
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #50:     us: 0.0.0.0/0===70.240.163.43<70.240.163.43>[@left-70.240.163.43]
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #50:   them: 51.179.82.210<51.179.82.210>[C=US, ST=Washington, L=Seattle, O=Craig Inc., OU=Engineering, CN=cq-use1f-1]===0.0.0.0/0
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #50: keeping refhim=0 during rekey
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #50: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2 tunnel mode {ESP/NAT=>0xcbfb1484 <0x863a2b6b xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=51.179.82.210:4500 DPD=active}
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #49: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP/NAT=>0xefe112e2 <0xc981ba01 xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=51.179.82.210:4500 DPD=active}
Sep  7 03:23:20 fmn-767 pluto[2190]: "conn1" #50: STATE_QUICK_R2: IPsec SA established tunnel mode {ESP/NAT=>0xcbfb1484 <0x863a2b6b xfrm=AES_CBC_256-HMAC_SHA2_256_128 NATOA=none NATD=51.179.82.210:4500 DPD=active}

Server invokes ipsec auto —delete conn37 and later ipsec auto —replace conn37 and ipsec auto —route conn37...

Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37": deleting non-instance connection
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37" #6: deleting state (STATE_QUICK_I2) and sending notification
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37" #6: ESP traffic information: in=280B out=2MB
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37" #5: deleting state (STATE_QUICK_I2) and sending notification
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37" #5: ESP traffic information: in=3MB out=0B
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37" #2: deleting state (STATE_QUICK_R2) and sending notification
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37" #2: ESP traffic information: in=28B out=28B
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37" #49: deleting state (STATE_MAIN_R3) and sending notification
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37" #41: deleting state (STATE_MAIN_R3) and sending notification
Sep  7 08:09:39 cq-use1f-1 pluto[2446]: "conn37": ERROR: netlink XFRM_MSG_DELPOLICY response for flow eroute_connection delete included errno 2: No such file or directory

...

Sep  7 08:09:48 cq-use1f-1 pluto[8504]: added connection description “conn37"
Sep  7 08:09:49 cq-use1f-1 pluto[8504]: "conn37": prepare-client output: net.ipv4.conf. conn37.disable_policy = 1
Sep  7 08:09:49 cq-use1f-1 pluto[8504]: "conn37": prepare-client output: net.ipv4.conf. conn37.rp_filter = 0
Sep  7 08:09:49 cq-use1f-1 pluto[8504]: "conn37": prepare-client output: net.ipv4.conf. conn37.forwarding = 1

Client receives --delete notification from server...

Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #63: received Delete SA payload: replace IPSEC State #50 now
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #63: received and ignored empty informational notification payload
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #64: initiating Quick Mode RSASIG+ENCRYPT+TUNNEL+PFS+UP+IKEV1_ALLOW+IKEV2_ALLOW+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO to replace #50 {using isakmp#63 msgid:7973fff2 proposal=AES_CBC_256-HMAC_SHA2_256_128 pfsgroup=MODP2048}
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #50: deleting state (STATE_QUICK_R2) and sending notification
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #50: ESP traffic information: in=2MB out=280B
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #63: received Delete SA(0xefe112e2) payload: deleting IPSEC State #49
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #49: deleting other state #49 (STATE_QUICK_R2) and sending notification
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #49: ESP traffic information: in=0B out=3MB
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #64: deleting state (STATE_QUICK_I1)
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #48: deleting state (STATE_QUICK_I2) and sending notification
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #48: ESP traffic information: in=28B out=28B
Sep  7 08:09:39 fmn-767 pluto[2190]: "conn1" #63: deleting state (STATE_MAIN_I4) and sending notification

…no further conn1 messages in client logs.

Here is the conn1.conf file. The conn37.conf file is contained in my original message.

conn conn1
left=70.240.163.43
leftid="@left-70.240.163.43"
leftsubnet=0.0.0.0/0
leftcert=client
left=70.240.163.43
leftcert=client
right=51.179.82.210
rightid="%fromcert"
rightsubnet=0.0.0.0/0
right=51.179.82.210
authby=rsasig
vti-routing=no
vti-shared=yes
encapsulation=yes
keyingtries=0
dpddelay=30
dpdtimeout=120
dpdaction=restart
mark=0x1000000/0xff000000
vti-interface=conn1
phase2alg=aes256-sha2_256
auto=ignore
type=tunnel
compress=no
pfs=yes
ikepad=yes
authby=rsasig
phase2=esp
ikev2=permit
ppk=no
esn=no

--
cm

On Sep 9, 2018, at 2:51 PM, Paul Wouters <paul at nohats.ca<mailto:paul at nohats.ca>> wrote:

On Fri, 7 Sep 2018, Craig Marker wrote:

I’m debugging an issue where my server rebooted and the tunnel didn’t reestablish correctly, and
I noticed strange entries in the server’s ip xfrm state table. Namely, a ton of duplicates for
established connections. Is this something I should be worried about or something that has been
seen before?

Usually that means the two endpoints keep renegotiating for some reason,
and libreswan is keeping the old ones for a bit before cleaning them up.

I also noticed this strange entry that doesn’t correspond to any .conf file, except it has the
src/dst mapping to the VTI Ip address for conn37. Though there is no configuration anywhere that
connects conn37.conf and the VTI IP address endpoints (they are applied with ip addr after the
connection has been established).
src 172.16.0.4 dst 172.16.0.5
proto esp spi 0x00000000 reqid 0 mode transport
replay-window 0
mark 0x25000000/0xff000000
anti-replay context: seq 0x0, oseq 0x0, bitmap 0x00000000
sel src 172.16.0.4/32 dst 172.16.0.5/32 proto icmp type 8 code 0 dev conn37

This is an ACQUIRE in larval state. It happens during on-demand tunnels.
It means the kernel send the ACQUIRE to the IKE daemon, and now the IKE
daemon is expected to replace this with a tunnel IPsec SA. I think this
is just a side effect of the many re-establishing you are seeing.

Sep  7 08:10:10 cq-use1f-1 pluto[8504]: initiate on demand from 172.16.0.4:8 to 172.16.0.5:0
proto=1 because: acquire

Yeah that is the ACQUIRE.

Here’s the associated conn37.conf, if that’s helpful.
conn conn37
left=70.240.163.43
leftid=“@left-70.240.163.43"
leftsubnet=0.0.0.0/0
left=70.240.163.43
right=51.179.82.210
rightid="%fromcert"
rightsubnet=0.0.0.0/0
rightcert=server
right=51.179.82.210
rightupdown=/usr/libexec/ipsec/inspeed_updown
rightcert=server
authby=rsasig
vti-routing=no
encapsulation=yes
keyingtries=0
mark=0x25000000/0xff000000
vti-interface=conn37
phase2alg=aes256-sha2_256
auto=ignore

If you want this to go up at boot, you should put in auto=start

type=tunnel
compress=no
pfs=yes
ikepad=yes
authby=rsasig
phase2=esp
ikev2=permit
ppk=no
esn=no


I guess the reason for why it keeps restarting the tunnel should be in
the logs on one of the endpoints?

Paul

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20180910/a949b3ac/attachment-0001.html>


More information about the Swan mailing list