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

[openswan at thefeds.net]

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