[Swan] dpd question

Sat Feb 2 08:33:17 UTC 2019

On Sat, Feb 2, 2019, at 1:54 AM, Paul Wouters wrote:
> On Sat, 2 Feb 2019, Kostya Vasilyev wrote:
> 
>[...]
> > #23 showed up in ipsec status like this:
> >
> > 000 #23: "mytunnel":4500 STATE_V2_REKEY_IKE_I0 (STATE_V2_REKEY_IKE_I0); EVENT_SA_REPLACE in 82s; lastlive=0s; crypto/dns-lookup;
> >
> > And after those 82 seconds expired:
> >
> > pluto[8407]: "mytunnel" #23: deleting state (STATE_V2_REKEY_IKE_I0) and NOT sending notification
> >
> > and #23 is not listed anymore in ipsec status.
> 
> Seems it tried to rekey and fail. I wonder what will happen near the end
> of your ikelifetime. It better be able to rekey :P
> 
> Paul

Looks like it may be reconnecting instead of rekeying? #69 at 10:50 and 10:55?

10:43:54 pluto[8407]: "mytunnel" #72: negotiated new IPsec SA [139.0.0.1-139.0.0.1:0-65535 47] -> [89.0.0.1-89.2
10:43:54 pluto[8407]: "mytunnel" #72: negotiated connection [139.0.0.1-139.0.0.1:0-65535 47] -> [89.0.0.1-89.208
10:43:54 pluto[8407]: "mytunnel" #72: STATE_V2_IPSEC_R: IPsec SA established transport mode {ESP=>0x0df90787 <0x33b24e47 xfrm=A
10:43:56 pluto[8407]: "mytunnel" #69: received Delete SA payload: delete IPSEC State #71 now
10:43:56 pluto[8407]: "mytunnel" #71: deleting other state #71 (STATE_V2_IPSEC_R) and NOT sending notification
10:43:56 pluto[8407]: "mytunnel" #71: ESP traffic information: in=0B out=0B
10:50:49 pluto[8407]: "mytunnel" #69: initiate rekey of IKEv2 CREATE_CHILD_SA IKE Rekey
10:50:49 pluto[8407]: "mytunnel" #73: message id deadlock? wait sending, add to send next list using parent #69 unacknowledged 
10:54:09 pluto[8407]: "mytunnel" #73: deleting state (STATE_V2_REKEY_IKE_I0) and NOT sending notification
10:55:19 pluto[8407]: "mytunnel" #69: ISAKMP SA expired (LATEST!)
10:55:19 pluto[8407]: "mytunnel" #72: deleting other state #72 (STATE_V2_IPSEC_R) and sending notification
10:55:19 pluto[8407]: "mytunnel" #72: ESP traffic information: in=0B out=0B
10:55:19 pluto[8407]: "mytunnel" #69: deleting state (STATE_PARENT_R2) and sending notification
10:55:19 pluto[8407]: packet from 89.0.0.1:4500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
10:55:19 pluto[8407]: packet from 89.0.0.1:4500: CREATE_CHILD_SA message request has no corresponding IKE SA
10:55:19 pluto[8407]: packet from 89.0.0.1:4500: ISAKMP_v2_INFORMATIONAL message response has no matching IKE SA
10:55:24 pluto[8407]: packet from 89.0.0.1:4500: CREATE_CHILD_SA message request has no corresponding IKE SA
10:55:29 pluto[8407]: packet from 89.0.0.1:4500: CREATE_CHILD_SA message request has no corresponding IKE SA
10:55:34 pluto[8407]: packet from 89.0.0.1:4500: CREATE_CHILD_SA message request has no corresponding IKE SA
10:55:39 pluto[8407]: packet from 89.0.0.1:4500: CREATE_CHILD_SA message request has no corresponding IKE SA
10:55:44 pluto[8407]: packet from 89.0.0.1:4500: INFORMATIONAL message request has no corresponding IKE SA
10:55:48 pluto[8407]: packet from 89.0.0.1:4500: proposal 1:IKE:ENCR=AES_CBC_128;PRF=HMAC_SHA2_256;INTEG=HMAC_SHA2_256_128
10:55:48 pluto[8407]: "mytunnel" #74: STATE_PARENT_R1: received v2I1, sent v2R1 {auth=IKEv2 cipher=AES_CBC_128 integ=HMAC_SHA2_
10:55:49 pluto[8407]: "mytunnel" #74: certificate verified OK: OU=ac2,O=NewTunnel,L=Moscow,C=RU
10:55:49 pluto[8407]: "mytunnel" #74: IKEv2 mode peer ID is ID_DER_ASN1_DN: 'C=RU, L=Moscow, O=NewTunnel, OU=ac2'
10:55:49 pluto[8407]: "mytunnel" #74: Authenticated using RSA
10:55:49 pluto[8407]: "mytunnel" #74: constructed local ESP/AH proposals for mytunnel (IKE SA responder matching remote ESP/AH 
10:55:49 pluto[8407]: "mytunnel" #74: proposal 1:ESP:SPI=03c98495;ENCR=AES_CBC_128;INTEG=HMAC_SHA2_256_128;ESN=DISABLED chosen 
10:55:49 pluto[8407]: "mytunnel" #75: negotiated connection [139.0.0.1-139.0.0.1:0-65535 47] -> [89.0.0.1-89.0...
10:55:49 pluto[8407]: "mytunnel" #75: STATE_V2_IPSEC_R: IPsec SA established transport mode {ESP=>0x03c98495 <0x6a8a557b xfrm=A
11:19:50 pluto[8407]: "mytunnel" #74: constructed local ESP/AH proposals for mytunnel (ESP/AH responder matching remote proposa
11:19:50 pluto[8407]: "mytunnel" #74: proposal 1:ESP:SPI=00770875;ENCR=AES_CBC_128;INTEG=HMAC_SHA2_256_128;DH=MODP2048;ESN=DISA
11:19:50 pluto[8407]: "mytunnel" #76: negotiated new IPsec SA [139.0.0.1-139.0.0.1:0-65535 47] -> [89.0.0.1-89.0...
11:19:50 pluto[8407]: "mytunnel" #76: negotiated connection [139.0.0.1-139.0.0.1:0-65535 47] -> [89.0.0.1-89.0...
11:19:50 pluto[8407]: "mytunnel" #76: STATE_V2_IPSEC_R: IPsec SA established transport mode {ESP=>0x00770875 <0xb70c92c2 xfrm=A
11:19:59 pluto[8407]: "mytunnel" #74: received Delete SA payload: delete IPSEC State #75 now
11:19:59 pluto[8407]: "mytunnel" #75: deleting other state #75 (STATE_V2_IPSEC_R) and NOT sending notification
11:19:59 pluto[8407]: "mytunnel" #75: ESP traffic information: in=1MB out=122MB

ipsec status at this time:

000 #74: "mytunnel":4500 STATE_PARENT_R2 (received v2I2, PARENT SA established); EVENT_SA_REPLACE in 1453s; newest ISAKMP; idle;
000 #76: "mytunnel":4500 STATE_V2_IPSEC_R (IPsec SA established); EVENT_SA_REPLACE in 28094s; newest IPSEC; eroute owner; isakmp#74; idle;
000 #76: "mytunnel" esp.770875 at 89.208.22.144 esp.b70c92c2 at 139.162.238.65 ref=0 refhim=0 Traffic: ESPin=8KB ESPout=62KB! ESPmax=0B 

-- K