[Openswan Users] Problem with Openswan 2.4.6 and WinXP roadwarrior PAYLOAD_MALFORMED

Thu Jun 26 10:01:40 EDT 2008

Hi,

I've recently had a problem with one of our roadwarriors. We use Openswan Version 2.4.6 as server, and Windows XP SP2 as clients. We use X.509 certificates to authenticate cleints, and we have NAT-traversal activated. Until now we had no problems with both NATed and non-NATed clients.

Openswan Version 2.4.6 X.509-1.5.4 LDAP_V3 PLUTO_SENDS_VENDORID PLUTO_USES_KEYRR; Vendor ID OElLO]RdWNRD

I attach 2 logs, one working and another with the failure:

* Roadwarrior connecting correctly (public IP xx.xx.xx.xx):

Jun 24 12:53:40 vpnserver pluto[5586]: packet from xx.xx.xx.xx:500: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000004]
Jun 24 12:53:40 vpnserver pluto[5586]: packet from xx.xx.xx.xx:500: ignoring Vendor ID payload [FRAGMENTATION]
Jun 24 12:53:40 vpnserver pluto[5586]: packet from xx.xx.xx.xx:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] method set to=106
Jun 24 12:53:40 vpnserver pluto[5586]: packet from xx.xx.xx.xx:500: ignoring Vendor ID payload [Vid-Initial-Contact]
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: responding to Main Mode from unknown peer xx.xx.xx.xx
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: STATE_MAIN_R1: sent MR1, expecting MI2
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike-02/03: peer is NATed
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: STATE_MAIN_R2: sent MR2, expecting MI3
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: Main mode peer ID is ID_DER_ASN1_DN: 'CN=LAPxxxx'
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: crl update for "DC=foo, DC=bar, CN=rootca.foo.bar" is overdue since Jun 20 07:27:34 UTC 2008
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[1] xx.xx.xx.xx #9: switched from "roadwarrior-cert-net" to "roadwarrior-cert-net"
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[2] xx.xx.xx.xx #9: deleting connection "roadwarrior-cert-net" instance with peer xx.xx.xx.xx {isakmp=#0/ipsec=#0}
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[2] xx.xx.xx.xx #9: I am sending my cert
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[2] xx.xx.xx.xx #9: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Jun 24 12:53:40 vpnserver pluto[5586]: | NAT-T: new mapping xx.xx.xx.xx:500/4500)
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-net"[2] xx.xx.xx.xx #9: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp2048}
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-l2tp"[1] xx.xx.xx.xx #10: responding to Quick Mode {msgid:1bebf327}
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-l2tp"[1] xx.xx.xx.xx #10: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Jun 24 12:53:40 vpnserver pluto[5586]: "roadwarrior-cert-l2tp"[1] xx.xx.xx.xx #10: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Jun 24 12:53:41 vpnserver pluto[5586]: "roadwarrior-cert-l2tp"[1] xx.xx.xx.xx #10: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Jun 24 12:53:41 vpnserver pluto[5586]: "roadwarrior-cert-l2tp"[1] xx.xx.xx.xx #10: STATE_QUICK_R2: IPsec SA established {ESP=>0x258614cc <0xecff6039 xfrm=3DES_0-HMAC_MD5 NATD=xx.xx.xx.xx:4500 DPD=none}
Jun 24 12:53:45 vpnserver pluto[5586]: "roadwarrior-cert-net"[2] xx.xx.xx.xx #9: received Delete SA(0x258614cc) payload: deleting IPSEC State #10
Jun 24 12:53:45 vpnserver pluto[5586]: "roadwarrior-cert-net"[2] xx.xx.xx.xx #9: deleting connection "roadwarrior-cert-l2tp" instance with peer xx.xx.xx.xx {isakmp=#0/ipsec=#0}
Jun 24 12:53:45 vpnserver pluto[5586]: "roadwarrior-cert-net"[2] xx.xx.xx.xx #9: received and ignored informational message
Jun 24 12:53:45 vpnserver pluto[5586]: packet from xx.xx.xx.xx:4500: received and ignored informational message

* Unable to connect (public IP yy.yy.yy.yy):

Jun 25 10:37:14 vpnserver pluto[5586]: packet from yy.yy.yy.yy:173: ignoring Vendor ID payload [MS NT5 ISAKMPOAKLEY 00000004]
Jun 25 10:37:14 vpnserver pluto[5586]: packet from yy.yy.yy.yy:173: ignoring Vendor ID payload [FRAGMENTATION]
Jun 25 10:37:14 vpnserver pluto[5586]: packet from yy.yy.yy.yy:173: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] method set to=106
Jun 25 10:37:14 vpnserver pluto[5586]: packet from yy.yy.yy.yy:173: ignoring Vendor ID payload [Vid-Initial-Contact]
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: responding to Main Mode from unknown peer yy.yy.yy.yy
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: STATE_MAIN_R1: sent MR1, expecting MI2
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: NAT-Traversal: Result using draft-ietf-ipsec-nat-t-ike-02/03: peer is NATed
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: STATE_MAIN_R2: sent MR2, expecting MI3
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: Main mode peer ID is ID_DER_ASN1_DN: 'CN=LAPyyyy'
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: crl update for "DC=foo, DC=bar, CN=rootca.foo.bar" is overdue since Jun 20 07:27:34 UTC 2008
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: I am sending my cert
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Jun 25 10:37:14 vpnserver pluto[5586]: | NAT-T: new mapping yy.yy.yy.yy:173/61374)
Jun 25 10:37:14 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp2048}
Jun 25 10:37:16 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: retransmitting in response to duplicate packet; already STATE_MAIN_R3
Jun 25 10:37:18 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: retransmitting in response to duplicate packet; already STATE_MAIN_R3
Jun 25 10:37:22 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: discarding duplicate packet -- exhausted retransmission; already STATE_MAIN_R3
Jun 25 10:37:30 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: discarding duplicate packet -- exhausted retransmission; already STATE_MAIN_R3
Jun 25 10:37:30 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: next payload type of ISAKMP Hash Payload has an unknown value: 88
Jun 25 10:37:30 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: malformed payload in packet
Jun 25 10:37:30 vpnserver pluto[5586]: "roadwarrior-cert-net"[56] yy.yy.yy.yy #102: sending notification PAYLOAD_MALFORMED to yy.yy.yy.yy:61374

I see that on the failing case ports are not 500 and 4500. Can that be the cause? Same laptop can connect from other networks, so I think is something on the firewall/router of the other network-end. Any ideas?

Thanks!!! :)

Regards,

--
Xesc Arbona