[Openswan dev] interop failture openswan-2.0.0 klips with freebsd 4.8 racoon

Mon Mar 8 13:12:19 CET 2004

Interop between freebsd-4.8 with racoon and openswan-2.0.0 cvs with klips using
PSK is failing. IP compression was not compiled into klips.

The odd thing is, we both seem to have an IPsec SA that the other side doesn't
recognise. This might be due to the negotiation. When openswan initiates, it
triggers initiation on the other end. It seems racoon doesn't have a udp 500
"hole" to prevent this. So freebsd/racoon is always the initiator and we end
up initiating two connections concurrently.

Full barfs, including pluto klips full debug is available at:

http://www.xtdnet.nl/paul/freebsd-4.8-openswan-2.0.0-klips-1.barf.txt
http://www.xtdnet.nl/paul/freebsd-4.8-openswan-2.0.0-klips-2.barf.txt

I think part of the problem might also be visible here:

Mar  1 13:09:25 bofh kernel: klips_debug:pfkey_msg_parse: parsing message ver=2, type=15(x-delflow(eroute)), errno=0, satype=0(UNKNOWN), len=5, res=0, seq=1, pid=4738.

This might be the incompatible IPCOMP transform, but I'm no klips expert.

 ipsec auto --up fedoratest
104 "fedoratest" #1: STATE_MAIN_I1: initiate
003 "fedoratest" #1: ignoring Vendor ID payload [KAME/racoon]
106 "fedoratest" #1: STATE_MAIN_I2: sent MI2, expecting MR2
Mar  1 13:09:34 bofh pluto[4775]: "fedoratest" #1: initiating Main Mode
Mar  1 13:09:34 bofh pluto[4775]: "fedoratest" #1: ignoring Vendor ID payload [KAME/racoon]
Mar  1 13:09:34 bofh pluto[4775]: "fedoratest" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
003 "fedoratest" #1: ignoring Vendor ID payload [KAME/racoon]
108 "fedoratest" #1: STATE_MAIN_I3: sent MI3, expecting MR3
004 "fedoratest" #1: STATE_MAIN_I4: ISAKMP SA established
112 "fedoratest" #2: STATE_QUICK_I1: initiate
Mar  1 13:09:34 bofh pluto[4775]: "fedoratest" #1: ignoring Vendor ID payload [KAME/racoon]
Mar  1 13:09:34 bofh pluto[4775]: "fedoratest" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
Mar  1 13:09:35 bofh pluto[4775]: "fedoratest" #1: Peer ID is ID_IPV4_ADDR: '62.16.0.39'
Mar  1 13:09:35 bofh pluto[4775]: "fedoratest" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
Mar  1 13:09:35 bofh pluto[4775]: "fedoratest" #1: ISAKMP SA established
Mar  1 13:09:35 bofh pluto[4775]: "fedoratest" #2: initiating Quick Mode PSK+ENCRYPT+TUNNEL+PFS+UP {using isakmp#1}
Mar  1 13:09:35 bofh pluto[4775]: "fedoratest" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Mar  1 13:09:35 bofh pluto[4775]: "fedoratest" #3: responding to Quick Mode
Mar  1 13:09:35 bofh pluto[4775]: "fedoratest" #3: transition from state (null) to state STATE_QUICK_R1
Mar  1 13:09:36 bofh pluto[4775]: "fedoratest" #3: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Mar  1 13:09:36 bofh pluto[4775]: "fedoratest" #3: IPsec SA established {ESP=>0x09a85c7f <0xe96e67e0 AH=>0x08a80d14 <0xe96e67df}
010 "fedoratest" #2: STATE_QUICK_I1: retransmission; will wait 20s for response
Mar  1 13:09:45 bofh pluto[4775]: "fedoratest" #4: responding to Main Mode
Mar  1 13:09:45 bofh pluto[4775]: "fedoratest" #4: transition from state (null) to state STATE_MAIN_R1
Mar  1 13:09:45 bofh pluto[4775]: "fedoratest" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Mar  1 13:10:04 bofh pluto[4775]: "fedoratest" #5: responding to Main Mode
Mar  1 13:10:04 bofh pluto[4775]: "fedoratest" #5: transition from state (null) to state STATE_MAIN_R1
010 "fedoratest" #2: STATE_QUICK_I1: retransmission; will wait 40s for response
Mar  1 13:10:05 bofh pluto[4775]: "fedoratest" #5: ignoring Vendor ID payload [KAME/racoon]
Mar  1 13:10:05 bofh pluto[4775]: "fedoratest" #5: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Mar  1 13:10:05 bofh pluto[4775]: "fedoratest" #5: Peer ID is ID_IPV4_ADDR: '62.16.0.39'
Mar  1 13:10:05 bofh pluto[4775]: "fedoratest" #5: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Mar  1 13:10:05 bofh pluto[4775]: "fedoratest" #5: sent MR3, ISAKMP SA established
Mar  1 13:10:05 bofh pluto[4775]: "fedoratest" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN

freebsd says:

Mar  1 14:10:35 ar racoon: INFO: pfkey.c:1110:pk_recvupdate(): IPsec-SA established: AH/Transport 193.110.157.17->62.16.0.39 spi=145231124(0x8a80d14)
Mar  1 14:10:35 ar racoon: INFO: pfkey.c:1110:pk_recvupdate(): IPsec-SA established: ESP/Transport 193.110.157.17->62.16.0.39 spi=162028671(0x9a85c7f)
Mar  1 14:10:35 ar racoon: INFO: pfkey.c:1322:pk_recvadd(): IPsec-SA established: AH/Transport 62.16.0.39->193.110.157.17 spi=3916326879(0xe96e67df)
Mar  1 14:10:35 ar racoon: INFO: pfkey.c:1322:pk_recvadd(): IPsec-SA established: ESP/Transport 62.16.0.39->193.110.157.17 spi=3916326880(0xe96e67e0) 
Mar  1 14:13:25 ar racoon: INFO: isakmp.c:1049:isakmp_ph2begin_r(): respond new phase 2 negotiation: 62.16.0.39[0]<=>193.110.157.17[0]
Mar  1 14:13:25 ar racoon: ERROR: ipsec_doi.c:1001:get_ph2approvalx(): not matched
Mar  1 14:13:25 ar racoon: ERROR: ipsec_doi.c:966:get_ph2approval(): no suitable policy found.
Mar  1 14:13:25 ar racoon: ERROR: isakmp.c:1063:isakmp_ph2begin_r(): failed to pre-process packet.

tcpdump -i eth0 -n host 62.16.0.39
tcpdump: listening on eth0
13:14:10.092781 193.110.157.17.isakmp > 62.16.0.39.isakmp: isakmp: phase 1 I ident (DF)
13:14:10.239723 62.16.0.39.isakmp > 193.110.157.17.isakmp: isakmp: phase 1 R ident
13:14:10.246139 193.110.157.17.isakmp > 62.16.0.39.isakmp: isakmp: phase 1 I ident (DF)
13:14:20.240688 193.110.157.17.isakmp > 62.16.0.39.isakmp: isakmp: phase 1 I ident (DF)
13:14:20.385494 62.16.0.39.isakmp > 193.110.157.17.isakmp: isakmp: phase 1 R ident
13:14:20.391251 193.110.157.17.isakmp > 62.16.0.39.isakmp: isakmp: phase 1 I ident[E] (DF)
13:14:20.503153 62.16.0.39.isakmp > 193.110.157.17.isakmp: isakmp: phase 1 R ident[E]
13:14:20.510740 193.110.157.17.isakmp > 62.16.0.39.isakmp: isakmp: phase 2/others I oakley-quick[E] (DF)
13:14:20.647676 62.16.0.39.isakmp > 193.110.157.17.isakmp: isakmp: phase 2/others R inf[E]
13:14:21.725275 62.16.0.39.isakmp > 193.110.157.17.isakmp: isakmp: phase 2/others R oakley-quick[E]
13:14:21.745767 193.110.157.17.isakmp > 62.16.0.39.isakmp: isakmp: phase 2/others I oakley-quick[E] (DF)
13:14:21.965791 62.16.0.39.isakmp > 193.110.157.17.isakmp: isakmp: phase 2/others R oakley-quick[E]
13:14:30.160224 193.110.157.17.isakmp > 62.16.0.39.isakmp: isakmp: phase 2/others I oakley-quick[E] (DF)
13:14:30.386228 62.16.0.39 > 193.110.157.17: AH(spi=0x168e3d46,seq=0x1): ESP(spi=0x168e3d47,seq=0x1)
13:14:35.006651 193.110.157.17 > 62.16.0.39: AH(spi=0x0131a0e5,seq=0x1): ESP(spi=0x09cb68fb,seq=0x1) (DF)
13:14:35.212889 62.16.0.39 > 193.110.157.17: AH(spi=0x168e3d46,seq=0x3): ESP(spi=0x168e3d47,seq=0x3) (DF)
13:14:36.020385 193.110.157.17 > 62.16.0.39: AH(spi=0x0131a0e5,seq=0x2): ESP(spi=0x09cb68fb,seq=0x2) (DF)
13:14:37.020916 193.110.157.17 > 62.16.0.39: AH(spi=0x0131a0e5,seq=0x3): ESP(spi=0x09cb68fb,seq=0x3) (DF)
13:14:37.309252 62.16.0.39 > 193.110.157.17: AH(spi=0x168e3d46,seq=0x5): ESP(spi=0x168e3d47,seq=0x5) (DF)
13:14:38.021006 193.110.157.17 > 62.16.0.39: AH(spi=0x0131a0e5,seq=0x4): ESP(spi=0x09cb68fb,seq=0x4) (DF)
13:14:38.572505 62.16.0.39 > 193.110.157.17: AH(spi=0x168e3d46,seq=0x7): ESP(spi=0x168e3d47,seq=0x7) (DF)
13:14:39.020918 193.110.157.17 > 62.16.0.39: AH(spi=0x0131a0e5,seq=0x5): ESP(spi=0x09cb68fb,seq=0x5) (DF)
13:14:39.346234 62.16.0.39 > 193.110.157.17: AH(spi=0x168e3d46,seq=0x9): ESP(spi=0x168e3d47,seq=0x9) (DF)
13:14:45.328160 62.16.0.39 > 193.110.157.17: AH(spi=0x168e3d46,seq=0xa): ESP(spi=0x168e3d47,seq=0xa)

However, all packets are dropped.

Paul