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
<[email protected]<mailto:[email protected]>> 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
_______________________________________________
Swan mailing list
[email protected]
https://lists.libreswan.org/mailman/listinfo/swan
