[Openswan Users] IPSEC SA only being installed on one side

Mon Jan 5 11:02:26 EST 2009

2.6.20rc1 has been running for three days and is much better.

I would say it is perfect for phase 2 rekeying but there are two incidents 
I am still investigating.

My monitoring is still picking up quite a few incidents where I have no
phase 1 SA but this could be because I only have a 60 second rekeying 
margin (to mitigate the effects of the rekeying problems). I will push out 
new configs with a higher rekeying margin and see what happens.

Thanks
Tim

On Thu, 1 Jan 2009, Paul Wouters wrote:

> On Tue, 30 Dec 2008, openswan at thefeds.net wrote:
>
> There have been some fixes to rekeying lately. Please try the latest
> test release (2.6.20rc1). Though this bug might still exist.
>
> Paul
>
>> Date: Tue, 30 Dec 2008 18:35:42 +0000 (GMT)
>> From:  <openswan at thefeds.net>
>> To:  <users at openswan.org>
>> Subject: [Openswan Users] IPSEC SA only being installed on one side
>>
>> I am trying to track down a problem I am having quite frequently where my
>> phase 1 SA is fine (and thus DPD doesn't see any problems) but my phase 2
>> SAs aren't in step and thus traffic can't get through.
>>
>> The problem appears to be that sometimes when a new phase 2 SA is
>> negotiated one side is happy and installs the SA, but the other side
>> (never the initiator) doesn't install the SA. The side with the newer SA
>> then sends packets encrypted with the new SPI which the other side cannot
>> understand.
>>
>> I have the following extracts from /var/log/secure:
>>
>> The initiator:
>> Dec 30 12:40:04 vpn01d pluto[4943]: "tun02a01d" #442: STATE_MAIN_I4:
>> ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_256
>> prf=oakley_sha group=modp1536}
>> Dec 30 12:40:04 vpn01d pluto[4943]: "tun02a01d" #442: Dead Peer Detection
>> (RFC 3706): enabled
>> Dec 30 14:32:40 vpn01d pluto[4943]: "tun02a01d" #455: initiating Quick
>> Mode PSK+ENCRYPT+PFS+UP+IKEv2ALLOW to replace #428 {using isakmp#442
>> msgid:1ff67d30 proposal=AES(12)_256-SHA1(2)_160
>> pfsgroup=OAKLEY_GROUP_MODP1536}
>> Dec 30 14:32:40 vpn01d pluto[4943]: "tun02a01d" #455: Dead Peer Detection
>> (RFC 3706): enabled
>> Dec 30 14:32:40 vpn01d pluto[4943]: "tun02a01d" #455: transition from
>> state STATE_QUICK_I1 to state STATE_QUICK_I2
>> Dec 30 14:32:40 vpn01d pluto[4943]: "tun02a01d" #455: STATE_QUICK_I2: sent
>> QI2, IPsec SA established transport mode {ESP=>0x0f2d2e3a <0x36134870
>> xfrm=AES_256-HMAC_SHA1 NATOA=none NATD=none DPD=enabled}
>> Dec 30 14:32:50 vpn01d pluto[4943]: "tun02a01d" #455: message ignored
>> because it contains an unexpected payload type (ISAKMP_NEXT_HASH)
>> Dec 30 14:32:50 vpn01d pluto[4943]: "tun02a01d" #455: sending encrypted
>> notification INVALID_PAYLOAD_TYPE to <vpn02a ip>:500
>>
>> The reciever:
>> Dec 30 12:40:04 vpn02a pluto[547]: "tun02a01d" #480: STATE_MAIN_R3: sent
>> MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=aes_256
>> prf=oakley_sha group=modp1536}
>> Dec 30 12:40:04 vpn02a pluto[547]: "tun02a01d" #480: Dead Peer Detection
>> (RFC 3706): enabled
>> Dec 30 14:32:40 vpn02a pluto[547]: "tun02a01d" #480: the peer proposed:
>> <vpn02a ip>/32:0/0 -> <vpn02d ip>/32:0/0
>> Dec 30 14:32:40 vpn02a pluto[547]: "tun02a01d" #515: responding to Quick
>> Mode proposal {msgid:1ff67d30}
>> Dec 30 14:32:40 vpn02a pluto[547]: "tun02a01d" #515:     us:
>> <vpn02a ip><<vpn02a ip>>[+S=C]---<vpn02a nh>
>> Dec 30 14:32:40 vpn02a pluto[547]: "tun02a01d" #515:   them:
>> <vpn01d nh>---<vpn01d ip><<vpn01d ip>>[+S=C]
>> Dec 30 14:32:40 vpn02a pluto[547]: "tun02a01d" #515: keeping
>> refhim=4294901761 during rekey
>> Dec 30 14:32:40 vpn02a pluto[547]: "tun02a01d" #515: transition from state
>> STATE_QUICK_R0 to state STATE_QUICK_R1
>> Dec 30 14:32:40 vpn02a pluto[547]: "tun02a01d" #515: STATE_QUICK_R1: sent
>> QR1, inbound IPsec SA installed, expecting QI2
>> Dec 30 14:32:40 vpn02a pluto[547]: packet from <vpn01d ip>:500:
>> Informational Exchange is for an unknown (expired?) SA
>> Dec 30 14:32:50 vpn02a pluto[547]: "tun02a01d" #480: ignoring
>> informational payload, type INVALID_PAYLOAD_TYPE msgid=00000000
>> Dec 30 14:32:50 vpn02a pluto[547]: "tun02a01d" #480: received and ignored
>> informational message
>>
>> I then end up with the following SAs on vpn02a:
>> 000 #523: "tun02a01d":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established);
>> EVENT_SA_REPLACE in 9590s; newest ISAKMP; lastdpd=2s(seq in:24780 out:0);
>> idle; import:not set
>> 000 #480: "tun02a01d":500 STATE_MAIN_R3 (sent MR3, ISAKMP SA established);
>> EVENT_SA_REPLACE in 2449s; lastdpd=1210s(seq in:7855 out:0); idle;
>> import:not set
>> 000 #470: "tun02a01d":500 STATE_QUICK_R2 (IPsec SA established);
>> EVENT_SA_REPLACE in 2026s; newest IPSEC; eroute owner; isakmp#454; idle;
>> import:not set
>> 000 #470: "tun02a01d" esp.f2d777e3@<vpn01d ip> esp.8ca1e089@<vpn02a ip>
>> ref=0 refhim=4294901761
>>
>> and vpn01d:
>> 000 #466: "tun02a01d":500 STATE_MAIN_I4 (ISAKMP SA established);
>> EVENT_SA_REPLACE in 5934s; newest ISAKMP; lastdpd=1s(seq in:3752 out:0);
>> idle; import:admin initiate
>> 000 #455: "tun02a01d":500 STATE_QUICK_I2 (sent QI2, IPsec SA established);
>> EVENT_SA_REPLACE in 5593s; newest IPSEC; eroute owner; isakmp#442; idle;
>> import:admin initiate
>> 000 #455: "tun02a01d" esp.f2d2e3a@<vpn02a ip> esp.36134870@<vpn01d ip>
>> ref=0 refhim=4294901761
>> 000 #442: "tun02a01d":500 STATE_MAIN_I4 (ISAKMP SA established);
>> EVENT_SA_EXPIRE in 6050s; lastdpd=1209s(seq in:17036 out:0); idle;
>> import:admin initiate
>> 000 #428: "tun02a01d":500 STATE_QUICK_I2 (sent QI2, IPsec SA established);
>> EVENT_SA_EXPIRE in 5627s; isakmp#411; idle; import:admin initiate
>> 000 #428: "tun02a01d" esp.8ca1e089@<vpn02a ip> esp.f2d777e3@<vpn01d ip>
>> ref=0 refhim=4294901761
>>
>> So you can see that vpn02a does have esp.36134870@<vpn01d ip>
>> esp.f2d2e3a@<vpn02a ip> installed and as that is newest on vpn01d that is
>> what it is using for all traffic to vpn02a.
>>
>> I am guessing that the log entry of:
>> Dec 30 14:32:40 vpn02a pluto[547]: packet from <vpn01d ip>:500:
>> Informational Exchange is for an unknown (expired?) SA
>> May be the QI2 packet from vpn01d that vpn01d doesn't understand? I
>> thought at one time that the phase 1 SA may be expiring at this point, but
>> I am seeing this happen far too often for that. Plus as the logs show the
>> phase 1 SA was renegotiated 112 minutes and 48 seconds earlier and I have
>> a key life of 240 minutes with a rekeying margin of 120 minutes and a
>> rekeying fuzz of 1% so the next phase 1 rekeying isn't due for another 6
>> minutes to 7 minutes 12 seconds. I do see the phase 1 rekey happen in the
>> logs 6 minutes and 25 seconds later.
>>
>> Does anyone have any idea how I can go about finding out why the recieving
>> end sometimes doesn't install the new phase 2 SA?
>>
>> Thanks in advance for any help
>> Tim
>> _______________________________________________
>> Users at openswan.org
>> http://lists.openswan.org/mailman/listinfo/users
>> Building and Integrating Virtual Private Networks with Openswan:
>> http://www.amazon.com/gp/product/1904811256/104-3099591-2946327?n=283155
>>
>