[Openswan dev] [Openswan Users] Troubleshooting pluto crash - NSS related (fwd)
Paul Wouters
paul at xelerance.com
Thu Jul 21 19:54:08 EDT 2011
Is there a good reason for asserting on obtaining an NSS free slot?
It seems this is should just be a "not available try again later" error?
Though to properly do that, calc_ke() would need a non-void return and
its return value should be checked.
Paul
---------- Forwarded message ----------
Date: Thu, 21 Jul 2011 12:39:27 -0700
From: Kevin Keane <subscription at kkeane.com>
Cc: "users at openswan.org" <users at openswan.org>
Subject: Re: [Openswan Users] Troubleshooting pluto crash - NSS related
Here it is. Note: remoteip and localip are actual IP addresses mangled for confidentiality. localFQDN and remoteFQDN are actual valid FQDNs.
(I hope this wraps correctly)
Jul 21 19:08:17 mymachine pluto[31333]: |
Jul 21 19:08:17 mymachine pluto[31333]: | *received 481 bytes from remoteip:500 on eth0 (port=500)
Jul 21 19:08:17 mymachine pluto[31333]: | c4 ff e2 bc 42 ac a8 b5 00 00 00 00 00 00 00 00
... 29 lines deleted
Jul 21 19:08:17 mymachine pluto[31333]: | 12
Jul 21 19:08:17 mymachine pluto[31333]: | **parse ISAKMP Message:
Jul 21 19:08:17 mymachine pluto[31333]: | initiator cookie:
Jul 21 19:08:17 mymachine pluto[31333]: | c4 ff e2 bc 42 ac a8 b5
Jul 21 19:08:17 mymachine pluto[31333]: | responder cookie:
Jul 21 19:08:17 mymachine pluto[31333]: | 00 00 00 00 00 00 00 00
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_SA
Jul 21 19:08:17 mymachine pluto[31333]: | ISAKMP version: ISAKMP Version 1.0 (rfc2407)
Jul 21 19:08:17 mymachine pluto[31333]: | exchange type: ISAKMP_XCHG_AGGR
Jul 21 19:08:17 mymachine pluto[31333]: | flags: none
Jul 21 19:08:17 mymachine pluto[31333]: | message ID: 00 00 00 00
Jul 21 19:08:17 mymachine pluto[31333]: | length: 481
Jul 21 19:08:17 mymachine pluto[31333]: | processing version=1.0 packet with exchange type=ISAKMP_XCHG_AGGR (4)
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2(ISAKMP_NEXT_SA) needed: 0x432 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Security Association Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_KE
Jul 21 19:08:17 mymachine pluto[31333]: | length: 52
Jul 21 19:08:17 mymachine pluto[31333]: | DOI: ISAKMP_DOI_IPSEC
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x10(ISAKMP_NEXT_KE) needed: 0x430 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Key Exchange Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_NONCE
Jul 21 19:08:17 mymachine pluto[31333]: | length: 196
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x400(ISAKMP_NEXT_NONCE) needed: 0x420 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Nonce Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_ID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 24
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x20(ISAKMP_NEXT_ID) needed: 0x20 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Identification Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 33
Jul 21 19:08:17 mymachine pluto[31333]: | ID type: ID_FQDN
Jul 21 19:08:17 mymachine pluto[31333]: | DOI specific A: 0
Jul 21 19:08:17 mymachine pluto[31333]: | DOI specific B: 0
Jul 21 19:08:17 mymachine pluto[31333]: | obj: 69 6e 74 72 61 6e 65 74 2e 6e 63 74 65 63 68 63
Jul 21 19:08:17 mymachine pluto[31333]: | obj: 65 6e 74 65 72 2e 63 6f 6d 0d 00 00 0c 40 4b f4
Jul 21 19:08:17 mymachine pluto[31333]: | obj: 39
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 12
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 12
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 20
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 20
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 20
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 20
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 12
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_VID
Jul 21 19:08:17 mymachine pluto[31333]: | length: 20
Jul 21 19:08:17 mymachine pluto[31333]: | got payload 0x2000(ISAKMP_NEXT_VID) needed: 0x0 opt: 0x102000
Jul 21 19:08:17 mymachine pluto[31333]: | ***parse ISAKMP Vendor ID Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_NONE
Jul 21 19:08:17 mymachine pluto[31333]: | length: 12
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: ignoring Vendor ID payload [Sonicwall 1 (TZ 170 Standard?)]
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: ignoring unknown Vendor ID payload [<S/N>]
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: received Vendor ID payload [RFC 3947] meth=109, but port floating is off
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] meth=108, but port floating is off
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but port floating is off
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: ignoring Vendor ID payload [Sonicwall 2 (3.1.0.12-86s?)]
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: received Vendor ID payload [Dead Peer Detection]
Jul 21 19:08:17 mymachine pluto[31333]: packet from remoteip:500: received Vendor ID payload [XAUTH]
Jul 21 19:08:17 mymachine pluto[31333]: | find_host_connection2 called from aggr_inI1_outR1_common, me=localip:500 him=remoteip:500 policy=none
Jul 21 19:08:17 mymachine pluto[31333]: | find_host_pair: comparing to localip:500 remoteip:500
Jul 21 19:08:17 mymachine pluto[31333]: | find_host_pair_conn (find_host_connection2): localip:500 remoteip:500 -> hp:homeoffice
Jul 21 19:08:17 mymachine pluto[31333]: | find_host_connection returns homeoffice
Jul 21 19:08:17 mymachine pluto[31333]: | creating state object #1 at 0x7f182c384080
Jul 21 19:08:17 mymachine pluto[31333]: "homeoffice" #1: Aggressive mode peer ID is ID_FQDN: '@remoteFQDN'
Jul 21 19:08:17 mymachine pluto[31333]: | refine_connection: starting with homeoffice
Jul 21 19:08:17 mymachine pluto[31333]: | started looking for secret for @localFQDN->@remoteFQDN of kind PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | actually looking for secret for @localFQDN->@remoteFQDN of kind PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | line 1: key type PPK_PSK(@localFQDN) to type PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | 1: compared key @remoteFQDN to @localFQDN / @remoteFQDN -> 4
Jul 21 19:08:17 mymachine pluto[31333]: | 2: compared key @localFQDN to @localFQDN / @remoteFQDN -> 12
Jul 21 19:08:17 mymachine pluto[31333]: | line 1: match=12
Jul 21 19:08:17 mymachine pluto[31333]: | best_match 0>12 best=0x7f182c374630 (line=1)
Jul 21 19:08:17 mymachine pluto[31333]: | concluding with best_match=12 best=0x7f182c374630 (lineno=1)
Jul 21 19:08:17 mymachine pluto[31333]: | match_id a=@remoteFQDN
Jul 21 19:08:17 mymachine pluto[31333]: | b=@remoteFQDN
Jul 21 19:08:17 mymachine pluto[31333]: | results matched
Jul 21 19:08:17 mymachine pluto[31333]: | trusted_ca called with a=(empty) b=(empty)
Jul 21 19:08:17 mymachine pluto[31333]: | refine_connection: checking homeoffice against homeoffice, best=(none) with match=1(id=1/ca=1/reqca=1)
Jul 21 19:08:17 mymachine pluto[31333]: | refine_connection: checked homeoffice against homeoffice, now for see if best
Jul 21 19:08:17 mymachine pluto[31333]: | started looking for secret for @localFQDN->@remoteFQDN of kind PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | actually looking for secret for @localFQDN->@remoteFQDN of kind PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | line 1: key type PPK_PSK(@localFQDN) to type PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | 1: compared key @remoteFQDN to @localFQDN / @remoteFQDN -> 4
Jul 21 19:08:17 mymachine pluto[31333]: | 2: compared key @localFQDN to @localFQDN / @remoteFQDN -> 12
Jul 21 19:08:17 mymachine pluto[31333]: | line 1: match=12
Jul 21 19:08:17 mymachine pluto[31333]: | best_match 0>12 best=0x7f182c374630 (line=1)
Jul 21 19:08:17 mymachine pluto[31333]: | concluding with best_match=12 best=0x7f182c374630 (lineno=1)
Jul 21 19:08:17 mymachine pluto[31333]: | offered CA: '%none'
Jul 21 19:08:17 mymachine pluto[31333]: | processing connection homeoffice
Jul 21 19:08:17 mymachine pluto[31333]: | NSS: sha1 init start
Jul 21 19:08:17 mymachine pluto[31333]: | NSS: sha1 final end
Jul 21 19:08:17 mymachine pluto[31333]: | ICOOKIE: c4 ff e2 bc 42 ac a8 b5
Jul 21 19:08:17 mymachine pluto[31333]: | RCOOKIE: 82 aa 0a d4 90 41 d9 40
Jul 21 19:08:17 mymachine pluto[31333]: | state hash entry 14
Jul 21 19:08:17 mymachine pluto[31333]: | inserting state object #1 on chain 14
Jul 21 19:08:17 mymachine pluto[31333]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #1
Jul 21 19:08:17 mymachine pluto[31333]: | event added at head of queue
Jul 21 19:08:17 mymachine pluto[31333]: "homeoffice" #1: responding to Aggressive Mode, state #1, connection "homeoffice" from remoteip
Jul 21 19:08:17 mymachine pluto[31333]: | ****parse IPsec DOI SIT:
Jul 21 19:08:17 mymachine pluto[31333]: | IPsec DOI SIT: SIT_IDENTITY_ONLY
Jul 21 19:08:17 mymachine pluto[31333]: | ****parse ISAKMP Proposal Payload:
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_NONE
Jul 21 19:08:17 mymachine pluto[31333]: | length: 40
Jul 21 19:08:17 mymachine pluto[31333]: | proposal number: 1
Jul 21 19:08:17 mymachine pluto[31333]: | protocol ID: PROTO_ISAKMP
Jul 21 19:08:17 mymachine pluto[31333]: | SPI size: 0
Jul 21 19:08:17 mymachine pluto[31333]: | number of transforms: 1
Jul 21 19:08:17 mymachine pluto[31333]: | *****parse ISAKMP Transform Payload (ISAKMP):
Jul 21 19:08:17 mymachine pluto[31333]: | next payload type: ISAKMP_NEXT_NONE
Jul 21 19:08:17 mymachine pluto[31333]: | length: 32
Jul 21 19:08:17 mymachine pluto[31333]: | transform number: 1
Jul 21 19:08:17 mymachine pluto[31333]: | transform ID: KEY_IKE
Jul 21 19:08:17 mymachine pluto[31333]: | ******parse ISAKMP Oakley attribute:
Jul 21 19:08:17 mymachine pluto[31333]: | af+type: OAKLEY_ENCRYPTION_ALGORITHM
Jul 21 19:08:17 mymachine pluto[31333]: | length/value: 5
Jul 21 19:08:17 mymachine pluto[31333]: | [5 is OAKLEY_3DES_CBC]
Jul 21 19:08:17 mymachine pluto[31333]: | ike_alg_enc_ok(ealg=5,key_len=0): blocksize=8, keyminlen=192, keydeflen=192, keymaxlen=192, ret=1
Jul 21 19:08:17 mymachine pluto[31333]: | ******parse ISAKMP Oakley attribute:
Jul 21 19:08:17 mymachine pluto[31333]: | af+type: OAKLEY_HASH_ALGORITHM
Jul 21 19:08:17 mymachine pluto[31333]: | length/value: 2
Jul 21 19:08:17 mymachine pluto[31333]: | [2 is OAKLEY_SHA1]
Jul 21 19:08:17 mymachine pluto[31333]: | ******parse ISAKMP Oakley attribute:
Jul 21 19:08:17 mymachine pluto[31333]: | af+type: OAKLEY_GROUP_DESCRIPTION
Jul 21 19:08:17 mymachine pluto[31333]: | length/value: 5
Jul 21 19:08:17 mymachine pluto[31333]: | [5 is OAKLEY_GROUP_MODP1536]
Jul 21 19:08:17 mymachine pluto[31333]: | ******parse ISAKMP Oakley attribute:
Jul 21 19:08:17 mymachine pluto[31333]: | af+type: OAKLEY_AUTHENTICATION_METHOD
Jul 21 19:08:17 mymachine pluto[31333]: | length/value: 1
Jul 21 19:08:17 mymachine pluto[31333]: | [1 is OAKLEY_PRESHARED_KEY]
Jul 21 19:08:17 mymachine pluto[31333]: | started looking for secret for @localFQDN->@remoteFQDN of kind PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | actually looking for secret for @localFQDN->@remoteFQDN of kind PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | line 1: key type PPK_PSK(@localFQDN) to type PPK_PSK
Jul 21 19:08:17 mymachine pluto[31333]: | 1: compared key @remoteFQDN to @localFQDN / @remoteFQDN -> 4
Jul 21 19:08:17 mymachine pluto[31333]: | 2: compared key @localFQDN to @localFQDN / @remoteFQDN -> 12
Jul 21 19:08:17 mymachine pluto[31333]: | line 1: match=12
Jul 21 19:08:17 mymachine pluto[31333]: | best_match 0>12 best=0x7f182c374630 (line=1)
Jul 21 19:08:17 mymachine pluto[31333]: | concluding with best_match=12 best=0x7f182c374630 (lineno=1)
Jul 21 19:08:17 mymachine pluto[31333]: | ******parse ISAKMP Oakley attribute:
Jul 21 19:08:17 mymachine pluto[31333]: | af+type: OAKLEY_LIFE_TYPE
Jul 21 19:08:17 mymachine pluto[31333]: | length/value: 1
Jul 21 19:08:17 mymachine pluto[31333]: | [1 is OAKLEY_LIFE_SECONDS]
Jul 21 19:08:17 mymachine pluto[31333]: | ******parse ISAKMP Oakley attribute:
Jul 21 19:08:17 mymachine pluto[31333]: | af+type: OAKLEY_LIFE_DURATION
Jul 21 19:08:17 mymachine pluto[31333]: | length/value: 28800
Jul 21 19:08:17 mymachine pluto[31333]: | Oakley Transform 1 accepted
Jul 21 19:08:17 mymachine pluto[31333]: | DH public value received:
Jul 21 19:08:17 mymachine pluto[31333]: | ca 68 f8 08 85 9a ca 02 b0 c5 92 48 70 07 5e c8
Jul 21 19:08:17 mymachine pluto[31333]: | 17 5f 73 3d 88 78 d1 b4 83 ad db 68 c8 3f e4 ea
Jul 21 19:08:17 mymachine pluto[31333]: | ee e6 09 1a 1c 42 ca 0e fd 4d 05 19 c5 31 9e db
Jul 21 19:08:17 mymachine pluto[31333]: | a9 b4 07 39 18 ec c2 63 19 d8 a5 1f ef ef b5 01
Jul 21 19:08:17 mymachine pluto[31333]: | f5 fe ba a7 50 ae 8d 13 44 aa bb 07 68 de ff c1
Jul 21 19:08:17 mymachine pluto[31333]: | e6 fe af c3 c4 48 16 1e da d5 33 d2 0a 9c a6 d9
Jul 21 19:08:17 mymachine pluto[31333]: | 63 08 e4 7f 68 fe ea da 8a 71 71 a4 69 6a cb 17
Jul 21 19:08:17 mymachine pluto[31333]: | 1f d9 4f e7 c3 bd 13 f8 43 a1 cd 8e 32 46 28 f4
Jul 21 19:08:17 mymachine pluto[31333]: | 47 a8 0d d7 92 50 64 cd f5 b7 05 3a f3 b7 56 23
Jul 21 19:08:17 mymachine pluto[31333]: | 03 a0 00 62 34 a3 fd 70 6d 6f 6a 40 c9 b2 da 9f
Jul 21 19:08:17 mymachine pluto[31333]: | b4 82 d4 2d ee 38 97 6e 75 ea 65 95 3a 44 b6 d3
Jul 21 19:08:17 mymachine pluto[31333]: | 80 d6 7c 65 d7 c5 c3 c1 ee c8 e9 81 f3 fc dd 55
Jul 21 19:08:17 mymachine pluto[31333]: | helper -1 doing build_kenonce op id: 0
Jul 21 19:08:18 mymachine pluto[31333]: packet from remoteip:500: NSS: slot for DH key gen is NULL
Jul 21 19:08:29 mymachine ipsec__plutorun: Restarting Pluto subsystem...
Kevin Keane
The NetTech
http://www.4nettech.com
-----Original Message-----
From: Paul Wouters [mailto:paul at xelerance.com]
Sent: Thursday, July 21, 2011 6:58 AM
To: Kevin Keane
Cc: users at openswan.org
Subject: Re: [Openswan Users] Troubleshooting pluto crash - NSS related
On Thu, 21 Jul 2011, Kevin Keane wrote:
> I'm trying to get openswan to establish an IPSec connection to my Sonicwall firewall. It works fine with a shared secret, but I can't get openswan to work with certificates. I'm using CentOS 5.6, with openswan 2.6.21-5.el5_6.4
>
> This version of Openswan uses NSS for certificate management. Unfortunately, as soon as I add my client certificate to the NSS database, pluto crashes with an error "NSS: slot for DH key gen is NULL" when the peer first tries to connect.
>
> This seems to be strictly related to the certificate database, not to the actual connection configuration. It happens even if I leave my tunnel configured for shared secret. I can resolve the problem simply by deleting the three certificate DB files and restarting openswan; a new, empty, certificate database does not trigger this problem.
>
> Any ideas how to solve this would be appreciated!
Can you do this with plutodebug=all and post it to the list?
Paul
_______________________________________________
Users at openswan.org
http://lists.openswan.org/mailman/listinfo/users
Micropayments: https://flattr.com/thing/38387/IPsec-for-Linux-made-easy
Building and Integrating Virtual Private Networks with Openswan:
http://www.amazon.com/gp/product/1904811256/104-3099591-2946327?n=283155
More information about the Dev
mailing list