[Openswan Users] Problem with userland 2.4.12/2.4.13 : NO_PROPOSAL_CHOSEN
Paul Wouters
paul at xelerance.com
Wed Sep 24 11:15:31 EDT 2008
On Wed, 24 Sep 2008, Jean-Michel Bonnefond wrote:
> I face a bug where some of my tunnels which used to correctly negociate
> phase one and two with v2.4.9 can't reach to negociate phase two with newer
> versions. It seems that klips is not responsible for that as the tunnels
> works on version :
> 2.4.9, U2.4.9/K2.4.12, U2.4.10/K2.4.9, U2.4.10/K2.4.12, U2.4.11/K2.4.9,
> U2.4.11/K2.4.12
>
> The problem seems to have been introduced into openswan version 2.4.12 as
> these tested version present the problem :
> U2.4.12/K2.4.9, 2.4.12, U2.4.13/K2.4.9, U2.4.13/K2.4.12
Thanks for doing the extensive testing to assist us in locating the bug.
> -All working tunnels are with other openswan remote gateways, those which
> doesn't work are with cisco or racoon.
> -All working tunnels are configured with esp=3des-sha1, non-working ones
> uses esp=3des-md5
> -All working tunnels have only one ipsec SA defined, non-working ones have 2
> to 5 ipsec SA
This could be because a default value in the list of proposals changed,
and the remote is rejecting us based on the first now non-matching proposal.
You can test this using the following setups:
ike=3des-md5,3des-sha1
vs
ike=3des-sha1,3des-md5
In these cases Openswan still sends the same propals, and if the other
end rejects one of these, then their implementation of IKE is wrong. I
believe some Cisco's might fall in this category, but please let me know
the results of your tests.
> Sep 24 08:18:29 tamerlane pluto[2739]: "cortez_primary" #1: STATE_MAIN_I4:
> ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192
> prf=oakley_md5 group=modp1024}
> Sep 24 08:16:08 tamerlane pluto[31064]: "cortez_primary" #1: STATE_MAIN_I4:
> ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192
Though it seems your phase 1 is matching.... So perhaps this is an esp=
issue instead. So try the above but for esp= instead of ike=
If these meassures do not solve is, please send me offlist the output
of these plutodebug logs of two entire exchanges. One working and one
not, where you are sure the remote end started from scratch without a
previous state.
Paul
> Linux Openswan U2.4.11/K2.4.12 (klips)
> See `ipsec --copyright' for copyright information.
> Sep 24 08:34:24 tamerlane pluto[13782]: "sfr_primary" #1: ignoring
> informational payload, type IPSEC_RESPONDER_LIFETIME
> Sep 24 08:34:24 tamerlane pluto[13782]: "sfr_primary" #1: received and
> ignored informational message
> Sep 24 08:34:24 tamerlane pluto[13782]: | processing connection sfr_primary
> Sep 24 08:34:24 tamerlane pluto[13782]: "sfr_primary" #2: Dead Peer
> Detection (RFC 3706): enabled
> Sep 24 08:34:24 tamerlane pluto[13782]: | state: 2 requesting event none to
> be deleted by dpd.c:160
> Sep 24 08:34:24 tamerlane pluto[13782]: | state: 1 requesting event
> EVENT_DPD to be deleted by dpd.c:172
> Sep 24 08:34:24 tamerlane pluto[13782]: "sfr_primary" #2: transition from
> state STATE_QUICK_I1 to state STATE_QUICK_I2
> Sep 24 08:34:24 tamerlane pluto[13782]: "sfr_primary" #2: STATE_QUICK_I2:
> sent QI2, IPsec SA established {ESP=>0xd0f8aeb7 <0x00bd73ac
> xfrm=3DES_0-HMAC_MD5 NATD=none DPD=enabled}
I don't see a phase 1 message here, just a phase 2. Are you sure your
machines actually restarted from fresh without a phase 1 being already up?
> When it works (U2.4.11/K2.4.12):
>
> 1095 : | ******emit ISAKMP IPsec DOI attribute:
> 1096 : | af+type: AUTH_ALGORITHM
> 1097 : | length/value: 1
> 1098 : | [1 is AUTH_ALGORITHM_HMAC_MD5]
> 1099 : | emitting length of ISAKMP Transform Payload (ESP): 28
> 1100 : | emitting length of ISAKMP Proposal Payload: 40
> 1101 : | emitting length of ISAKMP Security Association Payload: 52
> 1102 : | ***emit ISAKMP Nonce Payload:
> 1103 : | next payload type: ISAKMP_NEXT_KE
> 1104 : | emitting 16 raw bytes of Ni into ISAKMP Nonce Payload
> 1105 : | Ni 5a 2e 92 2a db 97 5e f8 40 0e 7f 6c c6 9f ec 80
> 1106 : | emitting length of ISAKMP Nonce Payload: 20
> [...]
> 1158 : | IV:
> 1159 : | 6d 8d 61 0a b9 1d 33 71 58 57 c9 a3 9c 79 f1 79
> 1160 : | encrypting using OAKLEY_3DES_CBC
> 1161 : | next IV: a3 df ac 13 c6 16 f3 60
> 1162 : | emitting length of ISAKMP Message: 276
> 1163 : | sending 276 bytes for quick_outI1 through eth0:1:500 to
> xxx.xxx.252.134:500:
> [...]
> 1244 : | *received 284 bytes from xxx.xxx.252.134:500 on eth0:1
> (port=500)
> [...]
> 1263 : | **parse ISAKMP Message:
> 1264 : | initiator cookie:
> 1265 : | c4 5e 7d 41 6a 26 f2 ad
> 1266 : | responder cookie:
> 1267 : | 18 a2 e8 86 e1 5d a1 0e
> 1268 : | next payload type: ISAKMP_NEXT_HASH
> 1269 : | ISAKMP version: ISAKMP Version 1.0
> 1270 : | exchange type: ISAKMP_XCHG_QUICK
> 1271 : | flags: ISAKMP_FLAG_ENCRYPTION
> 1272 : | message ID: e6 e3 2d d9
> 1273 : | length: 284
> 1274 : | processing packet with exchange type=ISAKMP_XCHG_QUICK (32)
> 1275 : | ICOOKIE: c4 5e 7d 41 6a 26 f2 ad
> 1276 : | RCOOKIE: 18 a2 e8 86 e1 5d a1 0e
> 1277 : | peer: 5b 44 fc 86
> 1278 : | state hash entry 19
> 1279 : | peer and cookies match on #2, provided msgid e6e32dd9 vs
> e6e32dd9
> 1280 : | state object #2 found, in STATE_QUICK_I1
> 1281 : | processing connection sfr_primary
> 1282 : | received encrypted packet from xxx.xxx.252.134:500
> 1283 : | decrypting 256 bytes using algorithm OAKLEY_3DES_CBC
> 1284 : | decrypted:
> [...]
> 1301 : | next IV: 42 33 bf ce 6c 17 b2 b9
> 1302 : | np=8 and sd=0x80e11f0
> 1303 : | ***parse ISAKMP Hash Payload:
> 1304 : | next payload type: ISAKMP_NEXT_SA
> 1305 : | length: 20
> 1306 : | np=1 and sd=0x80e1160
> 1307 : | ***parse ISAKMP Security Association Payload:
> 1308 : | next payload type: ISAKMP_NEXT_NONCE
> 1309 : | length: 52
> 1310 : | DOI: ISAKMP_DOI_IPSEC
> 1311 : | np=10 and sd=0x80e1208
> 1312 : | ***parse ISAKMP Nonce Payload:
> 1313 : | next payload type: ISAKMP_NEXT_KE
> 1314 : | length: 24
> 1315 : | np=4 and sd=0x80e11b4
> 1316 : | ***parse ISAKMP Key Exchange Payload:
> 1317 : | next payload type: ISAKMP_NEXT_ID
> 1318 : | length: 132
> 1319 : | np=5 and sd=(nil)
> 1320 : | ***parse ISAKMP Identification Payload (IPsec DOI):
> 1321 : | next payload type: ISAKMP_NEXT_ID
> 1322 : | length: 12
> 1323 : | ID type: ID_IPV4_ADDR
> 1324 : | Protocol ID: 0
> 1325 : | port: 0
>
>
>
> When it doesn't work (2.4.12):
>
> 1095 : | ******emit ISAKMP IPsec DOI attribute:
> 1096 : | af+type: AUTH_ALGORITHM
> 1097 : | length/value: 1
> 1098 : | [1 is AUTH_ALGORITHM_HMAC_MD5]
> 1099 : | emitting length of ISAKMP Transform Payload (ESP): 28
> 1100 : | emitting length of ISAKMP Proposal Payload: 40
> 1101 : | out_sa pcn: 0 pn: 1<2 valid_count: 1
> 1102 : | ****emit ISAKMP Proposal Payload:
> 1103 : | next payload type: ISAKMP_NEXT_NONE
> 1104 : | proposal number: 0
> 1105 : | protocol ID: PROTO_IPCOMP
> 1106 : | SPI size: 2
> 1107 : | number of transforms: 1
> 1108 : | emitting 2 raw bytes of CPI into ISAKMP Proposal Payload
> 1109 : | CPI b9 f4
> 1110 : | *****emit ISAKMP Transform Payload (COMP):
> 1111 : | next payload type: ISAKMP_NEXT_NONE
> 1112 : | transform number: 0
> 1113 : | transform ID: IPCOMP_DEFLAT
> 1114 : | ******emit ISAKMP IPsec DOI attribute:
> 1115 : | af+type: ENCAPSULATION_MODE
> 1116 : | length/value: 1
> 1117 : | [1 is ENCAPSULATION_MODE_TUNNEL]
> 1118 : | ******emit ISAKMP IPsec DOI attribute:
> 1119 : | af+type: SA_LIFE_TYPE
> 1120 : | length/value: 1
> 1121 : | [1 is SA_LIFE_TYPE_SECONDS]
> 1122 : | ******emit ISAKMP IPsec DOI attribute:
> 1123 : | af+type: SA_LIFE_DURATION
> 1124 : | length/value: 3600
> 1125 : | emitting length of ISAKMP Transform Payload (COMP): 20
> 1126 : | emitting length of ISAKMP Proposal Payload: 30
> 1127 : | emitting length of ISAKMP Security Association Payload: 82
> 1128 : | ***emit ISAKMP Nonce Payload:
> 1129 : | next payload type: ISAKMP_NEXT_KE
> 1130 : | emitting 16 raw bytes of Ni into ISAKMP Nonce Payload
> 1131 : | Ni 19 07 c2 30 63 91 f3 cd 69 30 91 71 ed 96 8e 4d
> 1132 : | emitting length of ISAKMP Nonce Payload: 20
> [...]
> 1186 : | IV:
> 1187 : | d3 dc 05 fb b0 1a ac 23 1a 2b 10 6d a8 81 f6 c3
> 1188 : | emitting 2 zero bytes of encryption padding into ISAKMP Message
> 1189 : | encrypting using OAKLEY_3DES_CBC
> 1190 : | next IV: 00 09 0f dc 66 4a d7 c5
> 1191 : | emitting length of ISAKMP Message: 308
> 1192 : | sending 308 bytes for quick_outI1 through eth0:1:500 to
> xxx.xxx.252.134:500
> [...]
> 1271 : "sfr_primary" #1: received and ignored informational message
> 1272 : | complete state transition with STF_IGNORE
> 1273 : | next event EVENT_RETRANSMIT in 10 seconds for #2
> 1274 : |
> 1275 : | *received 84 bytes from xxx.xxx.252.134:500 on eth0:1 (port=500)
> [...]
> 1282 : | **parse ISAKMP Message:
> 1283 : | initiator cookie:
> 1284 : | 79 bd de c4 39 d7 41 1d
> 1285 : | responder cookie:
> 1286 : | ce df ba 7e 71 c3 1d 16
> 1287 : | next payload type: ISAKMP_NEXT_HASH
> 1288 : | ISAKMP version: ISAKMP Version 1.0
> 1289 : | exchange type: ISAKMP_XCHG_INFO
> 1290 : | flags: ISAKMP_FLAG_ENCRYPTION
> 1291 : | message ID: 47 5a cf ab
> 1292 : | length: 84
> 1293 : | processing packet with exchange type=ISAKMP_XCHG_INFO (5)
> 1294 : | ICOOKIE: 79 bd de c4 39 d7 41 1d
> 1295 : | RCOOKIE: ce df ba 7e 71 c3 1d 16
> 1296 : | peer: 5b 44 fc 86
> 1297 : | state hash entry 1
> 1298 : | peer and cookies match on #2, provided msgid 00000000 vs
> 5c551e99/00000000
> 1299 : | peer and cookies match on #1, provided msgid 00000000 vs
> 00000000/00000000
> 1300 : | p15 state object #1 found, in STATE_MAIN_I4
> 1301 : | processing connection sfr_primary
> 1302 : | last Phase 1 IV: ff 75 1f 04 07 7c 55 b0
> 1303 : | current Phase 1 IV: ff 75 1f 04 07 7c 55 b0
> 1304 : | computed Phase 2 IV:
> 1305 : | ca ab a2 d7 a5 c9 da dc 11 2d d8 3d 8d 61 c0 06
> 1306 : | received encrypted packet from xxx.xxx.252.134:500
> 1307 : | decrypting 56 bytes using algorithm OAKLEY_3DES_CBC
> 1308 : | decrypted:
> [...]
> 1313 : | next IV: a5 3a 8d 32 4a 05 c6 76
> 1314 : | np=8 and sd=0x80e1430
> 1315 : | ***parse ISAKMP Hash Payload:
> 1316 : | next payload type: ISAKMP_NEXT_N
> 1317 : | length: 20
> 1318 : | np=11 and sd=0x80e1454
> 1319 : | ***parse ISAKMP Notification Payload:
> 1320 : | next payload type: ISAKMP_NEXT_NONE
> 1321 : | length: 32
> 1322 : | DOI: ISAKMP_DOI_IPSEC
> 1323 : | protocol ID: 3
> 1324 : | SPI size: 16
> 1325 : | Notify Message Type: NO_PROPOSAL_CHOSEN
>
>
>
> Also I've noticed a strange error messages somewhere in the logs (but it's
> relative to another not-working tunnel) :
>
> Sep 23 15:40:37 tamerlane pluto[9424]: | payload malformed after IV
> Sep 23 15:40:37 tamerlane pluto[9424]: |
> Sep 23 15:40:37 tamerlane pluto[9424]: packet from xxx.xxx.174.200:500:
> sending notification PAYLOAD_MALFORMED to xxx.xxx.174.200:500
> Sep 23 15:40:38 tamerlane pluto[9424]: packet from xxx.xxx.174.200:500: not
> enough room in input packet for ISAKMP Message (remain=0, sd->size=28)
>
> This tunnel is against a Cisco-unity pix and the message does'nt appear with
> Linux Openswan U2.4.11/K2.4.12 (klips).
> Funny, while googling this last error message, to find myself sending a
> message to the list in 2006 with an equivalent problem on an older versions
> :-D ...
>
> Any idea?
> Jean-Michel.
>
More information about the Users
mailing list