[Openswan Users] Roadwarrior L2TP connection drops after 2 hours, openswan <=> XPSP2

[Ronald Moesbergen]

Hi,

I'm using openswan 2.3.0, kernel 2.6.10 with NETKEY for our company to
support roadwarriors with XP SP2 machines calling into our network with
L2TP using certificates (rp-lt2pd). Everything works great, connection
is ok, but after 2 hours of use the connection is suddenly lost. I heard
there were some problems with 2.3.0, but we have a customer with a cisco
3000 that only accepts XAUTH, so I must use version 2.3.0. The following
is shown in the logfiles when the roadwarrior problem appears:

The client connects with NAT-T (this is a user with a dsl modem doing
NAT for a private LAN):
 
Jan 26 19:26:20  "dialup"[7] x.x.x.x:4500 #31: IPsec SA established
{ESP/NAT=>0x2ba87e1d <0x50beaab9 NATOA=192.168.1.102}

All is well, everything works, after 1 hour the key is successfully
renewed:

Jan 26 20:25:40  "dialup"[7] x.x.x.x:4500 #36: IPsec SA established
{ESP/NAT=>0x88931c12 <0x27b6a7ba NATOA=192.168.1.102}
Jan 26 20:25:40  "dialup"[7] x.x.x.x:4500 #30: received Delete
SA(0x2ba87e1d) payload: deleting IPSEC State #31

after 2 hours the following happens, probably because the key needs to
be renewed again:

Jan 26 21:21:10  "dialup"[7] x.x.x.x:4500 #40: initiating Main Mode
Jan 26 21:21:10  | no IKE algorithms for this connection 
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: NAT-Traversal: Only 0
NAT-D - Aborting NAT-Traversal negociation
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: I am sending my cert
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: I am sending a
certificate request
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: transition from state
STATE_MAIN_I2 to state STATE_MAIN_I3
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: Main mode peer ID is
ID_DER_ASN1_DN: 'C=NL, ST=Utrecht, L=Maarn, O=BK Vision International
B.V., OU=Systeembeheer, CN=EJ1, E=***'
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: transition from state
STATE_MAIN_I3 to state STATE_MAIN_I4
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: ISAKMP SA established
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #41: initiating Quick Mode
RSASIG+ENCRYPT+TUNNEL {using isakmp#40}
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: discarding duplicate
packet; already STATE_MAIN_I4
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: ignoring informational
payload, type INVALID_ID_INFORMATION
Jan 26 21:21:11  "dialup"[7] x.x.x.x:4500 #40: received and ignored
informational message
Jan 26 21:22:21  "dialup"[7] x.x.x.x:4500 #41: max number of
retransmissions (2) reached STATE_QUICK_I1
Jan 26 21:24:28  "dialup"[8] x.x.x.x:4500 #43: responding to Quick Mode
Jan 26 21:24:28  "dialup"[8] x.x.x.x:4500 #43: transition from state
STATE_QUICK_R0 to state STATE_QUICK_R1
Jan 26 21:24:28  "dialup"[8] x.x.x.x:4500 #43: transition from state
STATE_QUICK_R1 to state STATE_QUICK_R2
Jan 26 21:24:28  "dialup"[8] x.x.x.x:4500 #43: IPsec SA established
{ESP/NAT=>0xb8d16981 <0x85a4f4ea}
Jan 26 21:24:28  "dialup"[7] x.x.x.x:4500 #36: next payload type of
ISAKMP Hash Payload has an unknown value: 108
Jan 26 21:24:28  "dialup"[7] x.x.x.x:4500 #36: malformed payload in
packet
Jan 26 21:24:28  "dialup"[7] x.x.x.x:4500 #36: sending notification
PAYLOAD_MALFORMED to x.x.x.x:4500
Jan 26 21:24:29  "dialup"[8] x.x.x.x:4500 #44: responding to Quick Mode
Jan 26 21:24:29  "dialup"[8] x.x.x.x:4500 #44: transition from state
STATE_QUICK_R0 to state STATE_QUICK_R1
Jan 26 21:24:29  "dialup"[8] x.x.x.x:4500 #44: transition from state
STATE_QUICK_R1 to state STATE_QUICK_R2
Jan 26 21:24:29  "dialup"[8] x.x.x.x:4500 #44: IPsec SA established
{ESP/NAT=>0x5f9b1bdc <0x4b328591}

... The last 3 lines then repeat 100's of times until it starts to drop
all the SA's it just made:

Jan 26 21:27:46  "dialup"[7] x.x.x.x:4500 #40: received Delete
SA(0xdcc88ea2) payload: deleting IPSEC State #1418
Jan 26 21:27:46  "dialup"[7] x.x.x.x:4500 #40: received and ignored
informational message
Jan 26 21:27:46  "dialup"[7] x.x.x.x:4500 #40: received Delete
SA(0x36e63c6a) payload: deleting IPSEC State #1417
Jan 26 21:27:46  "dialup"[7] x.x.x.x:4500 #40: received and ignored
informational message
Jan 26 21:27:46  "dialup"[7] x.x.x.x:4500 #40: received Delete
SA(0xce2c5381) payload: deleting IPSEC State #1416
Jan 26 21:27:46  "dialup"[7] x.x.x.x:4500 #40: received and ignored
informational message

... Also 100's of times. During all this, the ppp connection is dropped
and the user is logged out.

After that, the user tried to reestablish the connection:

Jan 26 21:42:59  "dialup"[11] x.x.x.x #1424: responding to Main Mode
from unknown peer x.x.x.x
Jan 26 21:42:59  "dialup"[11] x.x.x.x #1424: transition from state
STATE_MAIN_R0 to state STATE_MAIN_R1
Jan 26 21:42:59  "dialup"[11] x.x.x.x #1424: NAT-Traversal: Result using
draft-ietf-ipsec-nat-t-ike-02/03: peer is NATed
Jan 26 21:43:00  "dialup"[11] x.x.x.x #1424: transition from state
STATE_MAIN_R1 to state STATE_MAIN_R2
Jan 26 21:43:00  "dialup"[11] x.x.x.x #1424: Main mode peer ID is
ID_DER_ASN1_DN: 'C=NL, ST=Utrecht, L=Maarn, O=BK Vision International
B.V., OU=Systeembeheer, CN=EJ1, E=***'
Jan 26 21:43:00  "dialup"[12] x.x.x.x #1424: deleting connection
"dialup" instance with peer x.x.x.x {isakmp=#0/ipsec=#0}
Jan 26 21:43:00  "dialup"[12] x.x.x.x #1424: I am sending my cert
Jan 26 21:43:00  "dialup"[12] x.x.x.x #1424: deleting connection
"dialup" instance with peer x.x.x.x {isakmp=#0/ipsec=#0}
Jan 26 21:43:00  "dialup" #1060: deleting state (STATE_QUICK_R2)
Jan 26 21:43:00  "dialup" #1059: deleting state (STATE_QUICK_R2)
Jan 26 21:43:00  "dialup" #1058: deleting state (STATE_QUICK_R2)

(the last 3 lines again repeat 100's of times)
The new connection then fails: 

Jan 26 21:43:25  "dialup"[12] x.x.x.x #1424: deleting connection
"dialup" instance with peer x.x.x.x {isakmp=#40/ipsec=#0}
Jan 26 21:43:25  "dialup" #40: deleting state (STATE_MAIN_I4)
Jan 26 21:43:25  "dialup"[12] x.x.x.x #1424: transition from state
STATE_MAIN_R2 to state STATE_MAIN_R3
Jan 26 21:43:25  | NAT-T: new mapping x.x.x.x:500/4500)
Jan 26 21:43:25  "dialup"[12] x.x.x.x:4500 #1424: sent MR3, ISAKMP SA
established
Jan 26 21:43:25  "dialup"[12] x.x.x.x:4500 #1424: retransmitting in
response to duplicate packet; already STATE_MAIN_R3
Jan 26 21:43:25  "dialup"[12] x.x.x.x:4500 #1424: retransmitting in
response to duplicate packet; already STATE_MAIN_R3
Jan 26 21:43:25  "dialup"[12] x.x.x.x:4500 #1424: discarding duplicate
packet -- exhausted retransmission; already STATE_MAIN_R3
Jan 26 21:43:25  "dialup"[12] x.x.x.x:4500 #1424: discarding duplicate
packet -- exhausted retransmission; already STATE_MAIN_R3
Jan 26 21:43:25  "dialup"[12] x.x.x.x:4500 #1424: next payload type of
ISAKMP Hash Payload has an unknown value: 236
Jan 26 21:43:25  "dialup"[12] x.x.x.x:4500 #1424: malformed payload in
packet
Jan 26 21:43:25  "dialup"[12] x.x.x.x:4500 #1424: sending notification
PAYLOAD_MALFORMED to x.x.x.x:4500

Any clue what happened here? Is it a bug, and if so is there a
workaround or fix? It looks like the renegotiation of the key after 2
hours is failing and something goes into a frenzy retrying. More info is
available, just ask. Thanks in advance for any help.

Regards,
Ronald.