[Swan] private key for cert Thor not found in local cache; loading from NSS DB
rayv33n
rayv33n at gmail.com
Mon Oct 8 18:19:59 UTC 2018
Thanks Nick! I was following a sub Reddit that suggested this can't be
done. I think the problem is always going to be the IGW and NAT aware stuff
we have no control over. But I'm looking into it.
This thread started out in confusion about Thor's private key which I've no
solved by completely wiping and redoing the ipsec NSS DB. I have no idea
why it broke but here's what I can now thankfully. Unfortunately now
ipsechost1 says " private key for cert ipsechost1 not found in local cache;
loading from NSS DB" which of course I know is got to be miss leading since
ipsechost1 has active SA's created with the other host in my lab. I think
this statement is miss leading and maybe it could be clarified later on so
noobs like me don't gravitate towards it.
Is there anything you guys would recommend I do to debug or troubleshoot
this or is this as simple as mismatching info due to NAT?
----------------- Logs from Thor(AWS instance) Receiving end---------------
Oct 8 18:04:00.985391: XAUTH PAM support [enabled]
Oct 8 18:04:00.985798: | encryption algorithm NULL_AUTH_AES_GMAC, IKEv1
OAKLEY id: -1, IKEv1 ESP_INFO id: 23, IKEv2 id: 21
Oct 8 18:04:00.985803: | IKEv1 ESP ID id: 23 enum name: NULL_AUTH_AES_GMAC
Oct 8 18:04:00.985806: | IKEv2 ID id: 21 enum name: NULL_AUTH_AES_GMAC
Oct 8 18:04:00.985899: NULL_AUTH_AES_GMAC IKEv1: ESP
IKEv2: ESP {256,192,*128} aes_gmac
Oct 8 18:04:01.010590: | extracting the RSA private key for Thor
Oct 8 18:04:01.026495: | DH ike_alg_lookup_by_id id: MODP2048=14, found
MODP2048
Oct 8 18:04:05.039048: | DH ike_alg_lookup_by_id id: MODP2048=14, found
MODP2048
Oct 8 18:04:08.147322: | encryption ike_alg_lookup_by_id id: AES_CBC=12,
found AES_CBC
Oct 8 18:04:08.147330: | PRF ike_alg_lookup_by_id id: HMAC_SHA1=2, found
HMAC_SHA1
Oct 8 18:04:08.147335: | integrity ike_alg_lookup_by_id id:
HMAC_SHA1_96=2, found HMAC_SHA1_96
Oct 8 18:04:08.147339: | DH ike_alg_lookup_by_id id: MODP2048=14, found
MODP2048
Oct 8 18:04:08.184824: "private#0.0.0.0/0"[1] ...76.102.236.205 #3:
Authenticated using RSA
Oct 8 18:04:08.185023: | extracting the RSA private key for Thor
Oct 8 18:04:08.185502: | RSA key AwEAAeaaN found
Oct 8 18:04:08.185674: | NSS: Authentication to NSS successful
Oct 8 18:04:08.189602: "private#0.0.0.0/0"[1] ...XX.XXX.XXX.205 #3:
responding to AUTH message (ID 1) from XX.XXX.XXX.205:22311 with encrypted
notification AUTHENTICATION_FAILED
Oct 8 18:04:09.045268: | DH ike_alg_lookup_by_id id: MODP2048=14, found
MODP2048
Oct 8 18:04:09.066730: | encryption ike_alg_lookup_by_id id: AES_CBC=12,
found AES_CBC
Oct 8 18:04:09.066735: | PRF ike_alg_lookup_by_id id: HMAC_SHA1=2, found
HMAC_SHA1
Oct 8 18:04:09.066739: | integrity ike_alg_lookup_by_id id:
HMAC_SHA1_96=2, found HMAC_SHA1_96
Oct 8 18:04:09.066743: | DH ike_alg_lookup_by_id id: MODP2048=14, found
MODP2048
Oct 8 18:04:09.068964: | RSA key AwEAAeaaN found
Oct 8 18:04:09.069137: | NSS: Authentication to NSS successful
Oct 8 18:04:13.079020: "private#0.0.0.0/0"[1] ...XX.XXX.XXX.205 #5:
STATE_PARENT_I2: 3 second timeout exceeded after 3 retransmits. Possible
authentication failure: no acceptable response to our first encrypted
message
---------------- Logs from ipsechost1(Behind home office NAT/FW) initiating
connection
Oct 8 11:04:06.912445: | cmd( 640):TIME='0'
PLUTO_CONN_POLICY='AUTH_NEVER+GROUPINSTANCE+PASS+NEVER_NEGOTIATE' PLUTO:
Oct 8 11:04:06.912449: | cmd( 720):_CONN_KIND='CK_INSTANCE'
PLUTO_CONN_ADDRFAMILY='ipv4' XAUTH_FAILED=0 PLUTO_IS_PE:
Oct 8 11:04:08.108299: | established-authenticated-ike states: 0
Oct 8 11:04:08.108304: | authenticated-ipsec states: 0
Oct 8 11:04:08.110246: | IKEv2 transform ID: AUTH_HMAC_SHA2_512_256
(0xe)
Oct 8 11:04:08.110266: | IKEv2 transform ID: AUTH_HMAC_SHA2_256_128
(0xc)
Oct 8 11:04:08.110286: | IKEv2 transform ID: AUTH_HMAC_SHA1_96 (0x2)
Oct 8 11:04:08.110517: | IKEv2 transform ID: AUTH_HMAC_SHA2_512_256
(0xe)
Oct 8 11:04:08.110537: | IKEv2 transform ID: AUTH_HMAC_SHA2_256_128
(0xc)
Oct 8 11:04:08.110557: | IKEv2 transform ID: AUTH_HMAC_SHA1_96 (0x2)
Oct 8 11:04:08.110976: | established-authenticated-ike states: 0
Oct 8 11:04:08.110981: | authenticated-ipsec states: 0
Oct 8 11:04:08.125827: | v2 state object #1 found, in STATE_PARENT_I1
Oct 8 11:04:08.125839: | found state #1
Oct 8 11:04:08.126016: | selected state microcode Initiator: process
IKE_SA_INIT reply, initiate IKE_AUTH
Oct 8 11:04:08.126021: | calling processor Initiator: process IKE_SA_INIT
reply, initiate IKE_AUTH
Oct 8 11:04:08.126398: | IKEv2 transform ID: AUTH_HMAC_SHA1_96 (0x2)
Oct 8 11:04:08.128316: | established-authenticated-ike states: 0
Oct 8 11:04:08.128321: | authenticated-ipsec states: 0
Oct 8 11:04:08.128356: | exchange type: ISAKMP_v2_AUTH (0x23)
Oct 8 11:04:08.128686: | next payload type: setting 'IKEv2 Certificate
Request Payload'.'next payload type' to IKEv2 Authentication Payload
(39:ISAKMP_NEXT_v2AUTH)
Oct 8 11:04:08.128688: | *****emit IKEv2 Authentication Payload:
Oct 8 11:04:08.128694: | auth method: IKEv2_AUTH_RSA (0x1)
Oct 8 11:04:08.128697: | next payload type: saving payload location 'IKEv2
Authentication Payload'.'next payload type'
Oct 8 11:04:08.128818: | private key for cert ipsechost1 not found in
local cache; loading from NSS DB
Oct 8 11:04:08.132511: | emitting 256 raw bytes of rsa signature into
IKEv2 Authentication Payload
Oct 8 11:04:08.132565: | emitting length of IKEv2 Authentication Payload:
264
Oct 8 11:04:08.132619: | next payload type: previous 'IKEv2 Authentication
Payload'.'next payload type' matches 'IKEv2 Security Association Payload'
(33:ISAKMP_NEXT_v2SA)
Oct 8 11:04:08.132835: | IKEv2 transform ID: AUTH_HMAC_SHA2_512_256
(0xe)
Oct 8 11:04:08.132852: | IKEv2 transform ID: AUTH_HMAC_SHA2_256_128
(0xc)
Oct 8 11:04:08.132980: | IKEv2 transform ID: AUTH_HMAC_SHA2_512_256
(0xe)
Oct 8 11:04:08.132997: | IKEv2 transform ID: AUTH_HMAC_SHA2_256_128
(0xc)
Oct 8 11:04:08.133097: | IKEv2 transform ID: AUTH_HMAC_SHA1_96 (0x2)
Oct 8 11:04:08.133277: | exchange type: ISAKMP_v2_AUTH (0x23)
Oct 8 11:04:08.133515: | out calculated auth:
Oct 8 11:04:08.133542: | exchange type: ISAKMP_v2_AUTH (0x23)
Oct 8 11:04:08.133773: | out calculated auth:
Oct 8 11:04:08.133800: | exchange type: ISAKMP_v2_AUTH (0x23)
Oct 8 11:04:08.134027: | out calculated auth:
Oct 8 11:04:08.134054: | exchange type: ISAKMP_v2_AUTH (0x23)
Oct 8 11:04:08.134226: | out calculated auth:
Oct 8 11:04:08.134267: | established-authenticated-ike states: 0
Oct 8 11:04:08.134272: | authenticated-ipsec states: 0
Oct 8 11:04:08.166428: | exchange type: ISAKMP_v2_AUTH (0x23)
Oct 8 11:04:08.166439: | processing version=2.0 packet with exchange
type=ISAKMP_v2_AUTH (35)
Oct 8 11:04:08.166441: | I am receiving an IKEv2 Response ISAKMP_v2_AUTH
Oct 8 11:04:08.166456: | v2 state object #2 found, in STATE_PARENT_I2
Oct 8 11:04:08.166459: | found state #2
Oct 8 11:04:08.166489: | Unpacking clear payload for svm: Initiator:
process INVALID_SYNTAX AUTH notification
Oct 8 11:04:08.166654: | calculated auth: 4a b3 f9 8a 22 3d 39 7d c6 16
5c 1a
Oct 8 11:04:08.166656: | provided auth: 4a b3 f9 8a 22 3d 39 7d c6 16
5c 1a
Oct 8 11:04:08.166659: | authenticator matched
Oct 8 11:04:08.166671: | #2 ikev2 ISAKMP_v2_AUTH decrypt success
Oct 8 11:04:08.166691: | Notify Message Type: v2N_AUTHENTICATION_FAILED
(0x18)
Oct 8 11:04:08.166696: | selected state microcode Initiator: process
AUTHENTICATION_FAILED AUTH notification
Oct 8 11:04:08.166701: | calling processor Initiator: process
AUTHENTICATION_FAILED AUTH notification
Oct 8 11:04:08.166706: "private#0.0.0.0/0"[1] ...13.57.200.87 #2: IKE SA
authentication request rejected: AUTHENTICATION_FAILED
Oct 8 11:04:08.166830: | v2 state object #1 found, in STATE_PARENT_I2
Oct 8 11:04:08.166836: | found state #1
Oct 8 11:04:08.166854: | no useful state microcode entry found
Oct 8 11:04:08.166976: | out calculated auth:
Oct 8 11:04:09.025208: | parent_init v2 state object not found
Oct 8 11:04:09.025506: | found policy =
RSASIG+ENCRYPT+TUNNEL+PFS+FAIL1+OPPORTUNISTIC+GROUPINSTANCE+IKEV2_ALLOW+IKEV2_PROPOSE+SAREF_TRACK+IKE_FRAG_ALLOW+ESN_NO
(private#0.0.0.0/0)
On Mon, Oct 8, 2018 at 12:10 AM Nick Howitt <nick at howitts.co.uk> wrote:
> A bit of a sideways jump, but have you done the AWS set up for elastic
> IP's -
> https://libreswan.org/wiki/Interoperability#The_elastic_IP_and_the_RFC1918_native_IP_address
>
> Nick
>
> On 08/10/2018 01:12, rayv33n wrote:
>
>
> Yes, sir. That actually helps me understand and confirm a few things. My
> lab setup has two hosts. Each host is in a different network routed through
> a firewall with no NAT. They work perfectly creating SA and having no
> problems. But when ipsechost01 tries to talk to the AWS instances check out
> ipsechost01 to Thor(AWS). Which is AWS NAT with ipsechost behind a
> firewall, also NAT.
>
> Feel free to give me example configs or anything else you want me to try
> this is all lab stuff and I have time so I can be your lab monkey.
>
> * This is ipsechost01 and ejbca working in OE action*
> 000 #1: "private#0.0.0.0/0"[1] ...192.168.57.3:500 STATE_PARENT_R2
> (received v2I2, PARENT SA established); EVENT_v2_SA_REPLACE_IF_USED_IKE in
> 3328s; newest ISAKMP; idle;
> 000 #2: "private#0.0.0.0/0"[1] ...192.168.57.3:500 STATE_V2_IPSEC_R
> (IPsec SA established); EVENT_v2_SA_REPLACE_IF_USED in 28528s; newest
> IPSEC; eroute owner; isakmp#1; idle;
> 000 #2: "private#0.0.0.0/0"[1] ...192.168.57.3 esp.84f01efa at 192.168.57.3
> esp.67e30a4c at 192.168.56.109 tun.0 at 192.168.57.3 tun.0 at 192.168.56.109 ref=0
> refhim=0 Traffic: ESPin=84B ESPout=84B! ESPmax=0B
> 000
> logs from ejbca with ipsechost01 as source of connection
> Oct 7 17:02:27.658858: | returning since no better match then original
> best_found
> Oct 7 17:02:27.658864: | Peer ID matches and no better connection found -
> continuing with existing connection
> Oct 7 17:02:27.658902: | checking keyid 'C=US, ST=CA, L=Palo Alto,
> O=mycompany, OU=Level5, CN=ipsechost1, E=admin at mycompany.com' for match
> with 'C=US, ST=CA, L=Palo Alto, O=mycompany, OU=Level5, CN=ipsechost1, E=
> admin at mycompany.com'
> Oct 7 17:02:27.658972: "private#0.0.0.0/0"[2] ...192.168.57.3 #3:
> Authenticated using RSA
> Oct 7 17:02:27.659070: | private key for cert ejbca not found in local
> cache; loading from NSS DB
> Oct 7 17:02:27.662565: | tsi[0] 0-65535: exact port match with 0.
> fitness 65536
> Oct 7 17:02:27.662568: | tsr[0] 0-65535: exact port match with 0.
> fitness 65536
> Oct 7 17:02:27.662571: | best ports fit so far: tsi[0] fitrange_i
> 65536, tsr[0] fitrange_r 65536, matchiness 131072
> Oct 7 17:02:27.662575: | protocol 0 and tsi[0].ipprotoid 0: exact match
> Oct 7 17:02:27.662578: | protocol 0 and tsr[0].ipprotoid 0: exact match
> Oct 7 17:02:27.662580: | best protocol fit so far: tsi[0] fitrange_i
> 255, tsr[0] fitrange_r 255, matchiness 510
> Oct 7 17:02:27.662608: | selecting default construvted local ESP/AH
> proposals for private#0.0.0.0/0 (IKE SA responder matching remote ESP/AH
> proposals)
> Oct 7 17:02:27.662620: "private#0.0.0.0/0"[2] ...192.168.57.3 #3:
> constructed local ESP/AH proposals for private#0.0.0.0/0 (IKE SA
> responder matching remote ESP/AH proposals):
> 1:ESP:ENCR=AES_GCM_C_256;INTEG=NONE;ESN=DISABLED
> 2:ESP:ENCR=AES_GCM_C_128;INTEG=NONE;ESN=DISABLED
> 3:ESP:ENCR=AES_CBC_256;INTEG=HMAC_SHA2_512_256,HMAC_SHA2_256_128;ESN=DISABLED
> 4:ESP:ENCR=AES_CBC_128;INTEG=HMAC_SHA2_512_256,HMAC_SHA2_256_128;ESN=DISABLED
> 5:ESP:ENCR=AES_CBC_128;INTEG=HMAC_SHA1_96;ESN=DISABLED (default)
> Oct 7 17:02:27.662624: | Comparing remote proposals against IKE SA
> responder matching remote ESP/AH proposals 5 local proposals
> Oct 7 17:02:27.662632: | remote proposal 1 matches local proposal 1
> Oct 7 17:02:27.662639: | remote proposal 2 does not match; unmatched
> remote transforms: ENCR+ESN
> Oct 7 17:02:27.662645: | remote proposal 3 does not match; unmatched
> remote transforms: ENCR+INTEG+ESN
> Oct 7 17:02:27.662651: | remote proposal 4 does not match; unmatched
> remote transforms: ENCR+INTEG+ESN
> Oct 7 17:02:27.662657: | remote proposal 5 does not match; unmatched
> remote transforms: ENCR+INTEG+ESN
>
>
> ---------------------------------------------------------------------------------------------------------
> *Here's ipsechost01 tries to talk to Thor(AWS instance) *
>
> Oct 7 16:42:43.277322: | v2 state object #3 found, in STATE_PARENT_I1
> Oct 7 16:42:43.277332: | found state #3
> Oct 7 16:42:43.279975: | next payload type: setting 'IKEv2 Certificate
> Request Payload'.'next payload type' to IKEv2 Authentication Payload
> (39:ISAKMP_NEXT_v2AUTH)
> Oct 7 16:42:43.279978: | *****emit IKEv2 Authentication Payload:
> Oct 7 16:42:43.279988: | next payload type: saving payload location
> 'IKEv2 Authentication Payload'.'next payload type'
> Oct 7 16:42:43.283436: | emitting 256 raw bytes of rsa signature into
> IKEv2 Authentication Payload
> Oct 7 16:42:43.283492: | emitting length of IKEv2 Authentication Payload:
> 264
> Oct 7 16:42:43.283543: | next payload type: previous 'IKEv2
> Authentication Payload'.'next payload type' matches 'IKEv2 Security
> Association Payload' (33:ISAKMP_NEXT_v2SA)
> Oct 7 16:42:43.309983: | v2 state object #4 found, in STATE_PARENT_I2
> Oct 7 16:42:43.309985: | found state #4
> Oct 7 16:42:43.310116: | Notify Message Type:
> v2N_AUTHENTICATION_FAILED (0x18)
> Oct 7 16:42:43.310121: | selected state microcode Initiator: process
> AUTHENTICATION_FAILED AUTH notification
> Oct 7 16:42:43.310125: | calling processor Initiator: process
> AUTHENTICATION_FAILED AUTH notification
> Oct 7 16:42:43.310129: "private#0.0.0.0/0"[2] ...13.57.200.87 #4: IKE SA
> authentication request rejected: AUTHENTICATION_FAILED
> Oct 7 16:42:43.310241: | v2 state object #3 found, in STATE_PARENT_I2
> Oct 7 16:42:43.310249: | found state #3
> Oct 7 16:42:43.310266: | no useful state microcode entry found
> Oct 7 16:42:46.289302: "private#0.0.0.0/0"[2] ...13.57.200.87 #4:
> STATE_PARENT_I2: 3 second timeout exceeded after 0 retransmits. Possible
> authentication failure: no acceptable response to our first encrypted
> message
> Oct 7 16:42:46.289344: | OE: delete_state orphaning hold with
> failureshunt drop (negotiation shunt would have been trap)
> Oct 7 16:42:46.289346: | failureshunt == negotiationshunt, no replace
> needed
> Oct 7 16:42:46.289363: | add bare shunt 0x55f75a704a58 172.16.1.61/32:0
> --0--> 13.57.200.87/32:0 => %drop 0 oe-failing
> Oct 7 16:42:46.289378: | No need to replace negotiation_shunt with
> failure_shunt - they are the same
> Oct 7 16:42:48.526882: | keeping recent bare shunt 0x55f75a704a58
> 172.16.1.61/32:0 --0--> 13.57.200.87/32:0 => %drop 0 oe-failing
>
> On Sun, Oct 7, 2018 at 2:50 PM Paul Wouters <paul at nohats.ca> wrote:
>
>> On Sun, 7 Oct 2018, rayv33n wrote:
>>
>> > Followed all your suggestions and the connection information shows the
>> that the oppo sees that IP addresses across
>> > the connection down to the %fromcert. What's different this time is the
>> +MS+S=C which I have no idea what that is.
>> > I blew away the /etc/ipsec.d/*.db and when back to the instruction on
>> how to create it.
>>
>> That string is a clumpsy way to show identifications used, ignore it.
>>
>> > Oct 7 18:54:28.198237: | private key for cert Thor not found in local
>> cache; loading from NSS DB
>>
>> I am still very confused about this. It is abnormal and other people
>> don't run into this issue at all. So I am really trying to see what
>> is different in your setup. Can you configure a static ip to ip
>> connection with the same certificates? Does that work?
>>
>> Maybe try adding leftsendca=all ? Although the intermediary should
>> not be needed since it appears in your NSS and is marked as trusted
>> already. Perhaps you are missing some expected flags in the EKU or KU
>> for NSS?
>>
>> > The regular config I have work if there is not NAT involved.
>>
>> So whether or not there is NAT should not affect the authentication at
>> all?
>>
>> Paul
>>
>
>
> --
> You are FREE to become a slave
>
> Key ID: 9A452ABAA4593489
> Finger Print: 7A8A 5849 ED44 52B1 0D8A EDAC 9A45 2ABA A459 3489
> *Pub Key: *
> http://pgp.mit.edu:11371/pks/lookup?search=rayv33n%40gmail.com&op=index
>
>
> _______________________________________________
> Swan mailing listSwan at lists.libreswan.orghttps://lists.libreswan.org/mailman/listinfo/swan
>
>
> _______________________________________________
> Swan mailing list
> Swan at lists.libreswan.org
> https://lists.libreswan.org/mailman/listinfo/swan
>
--
You are FREE to become a slave
Key ID: 9A452ABAA4593489
Finger Print: 7A8A 5849 ED44 52B1 0D8A EDAC 9A45 2ABA A459 3489
*Pub Key: *
http://pgp.mit.edu:11371/pks/lookup?search=rayv33n%40gmail.com&op=index
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan/attachments/20181008/7cfa3513/attachment-0001.html>
More information about the Swan
mailing list