[Openswan Users] Problem with userland 2.4.12/2.4.13 : NO_PROPOSAL_CHOSEN
Jean-Michel Bonnefond
pompon2 at gmail.com
Wed Sep 24 07:10:56 EDT 2008
Hello folks,
First sorry if this email is a bit long, but I tried to analyse my problemas
deeper as I can.
I'm still in the process of validating some new version of openswan/klips to
upgrade my current version 2.4.9. The kernel is a 2.6.18 with latest debian
patches and without netkey. I don't use certs but only pre-shared keys.
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
(I've not tested with klips 2.4.13 as I've fired out this version wich as a
fatal bug for us while unloading the ipsec device)
I'm searching for differencies between tunnels that work and those that
doesn't work :
-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
I've modified one working tunnel to set up esp=3des-md5 but it still works.
I've added a secondary ipsec SA to a working tunnel but it still works.
All tunnels that have a problem have the same error message :
NO_PROPOSAL_CHOSEN (instead of the DPD message)
Here is an example with a tunnel to a racoon server :
tamerlane:~# ipsec --version
Linux Openswan U2.4.11/K2.4.12 (klips)
See `ipsec --copyright' for copyright information.
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:18:29 tamerlane pluto[2739]: "cortez_primary" #1: Dead Peer
Detection (RFC 3706): not enabled because peer did not advertise it
Sep 24 08:18:29 tamerlane pluto[2739]: | unpending state #1
Sep 24 08:18:29 tamerlane pluto[2739]: | processing connection
cortez_primary
Sep 24 08:18:29 tamerlane pluto[2739]: "cortez_primary" #2: initiating Quick
Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS+UP {using isakmp#1}
Sep 24 08:18:29 tamerlane pluto[2739]: | processing connection
cortez_primary
Sep 24 08:18:29 tamerlane pluto[2739]: | removing pending policy for "none"
{0x80febc8}
Sep 24 08:18:29 tamerlane pluto[2739]: | processing connection
cortez_primary
Sep 24 08:18:29 tamerlane pluto[2739]: "cortez_primary" #2: Dead Peer
Detection (RFC 3706): not enabled because peer did not advertise it
Sep 24 08:18:29 tamerlane pluto[2739]: "cortez_primary" #2: transition from
state STATE_QUICK_I1 to state STATE_QUICK_I2
Sep 24 08:18:29 tamerlane pluto[2739]: "cortez_primary" #2: STATE_QUICK_I2:
sent QI2, IPsec SA established {ESP=>0x0d5285bb <0x02ce27da
xfrm=3DES_0-HMAC_MD5 NATD=none DPD=none}
tamerlane:ipsec.d# ipsec --version
Linux Openswan 2.4.12 (klips)
See `ipsec --copyright' for copyright information.
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
prf=oakley_md5 group=modp1024}
Sep 24 08:16:08 tamerlane pluto[31064]: "cortez_primary" #1: Dead Peer
Detection (RFC 3706): not enabled because peer did not advertise it
Sep 24 08:16:08 tamerlane pluto[31064]: | unpending state #1
Sep 24 08:16:08 tamerlane pluto[31064]: | processing connection
cortez_primary
Sep 24 08:16:08 tamerlane pluto[31064]: "cortez_primary" #2: initiating
Quick Mode PSK+ENCRYPT+COMPRESS+TUNNEL+PFS+UP {using isakmp#1}
Sep 24 08:16:08 tamerlane pluto[31064]: | processing connection
cortez_primary
Sep 24 08:16:08 tamerlane pluto[31064]: | removing pending policy for "none"
{0x80fc218}
Sep 24 08:16:08 tamerlane pluto[31064]: | processing connection
cortez_primary
Sep 24 08:16:08 tamerlane pluto[31064]: "cortez_primary" #1: ignoring
informational payload, type NO_PROPOSAL_CHOSEN
Sep 24 08:16:08 tamerlane pluto[31064]: "cortez_primary" #1: received and
ignored informational message
And another example with Cisco :
tamerlane:~# ipsec --version
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}
tamerlane:ipsec.d# ipsec --version
Linux Openswan 2.4.12 (klips)
See `ipsec --copyright' for copyright information.
Sep 24 08:33:18 tamerlane pluto[9672]: "sfr_primary" #1: ignoring
informational payload, type IPSEC_RESPONDER_LIFETIME
Sep 24 08:33:18 tamerlane pluto[9672]: "sfr_primary" #1: received and
ignored informational message
Sep 24 08:33:18 tamerlane pluto[9672]: | processing connection sfr_primary
Sep 24 08:33:18 tamerlane pluto[9672]: "sfr_primary" #1: ignoring
informational payload, type NO_PROPOSAL_CHOSEN
Sep 24 08:33:18 tamerlane pluto[9672]: "sfr_primary" #1: received and
ignored informational message
I tried the full debug mode and noticed some differencies in the logs :
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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.openswan.org/pipermail/users/attachments/20080924/6f459e5e/attachment-0001.html
More information about the Users
mailing list