Re: [Swan] private key for cert Thor not found in local cache; loading from NSS DB

Mon, 08 Oct 2018 14:07:43 -0700

I can't help much more as I don't use nss/RSA/XAUTH/AWS. It is just that I'd bumped into the AWS issue before and I was wondering if it was giving you a wrong IP in the negotiation. I'd seen you move from a lab set up to AWS but didn't see any changes for being on AWS.

Nick

On 08/10/2018 19:19, rayv33n wrote:
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 <[email protected]> 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 [email protected] [email protected] [email protected] [email protected] 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=[email protected]' for match with 'C=US, ST=CA, L=Palo Alto, O=mycompany, OU=Level5, CN=ipsechost1, E=[email protected]'
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 <[email protected]> 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


_______________________________________________
Swan mailing list
[email protected]
https://lists.libreswan.org/mailman/listinfo/swan

_______________________________________________
Swan mailing list
[email protected]
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



_______________________________________________
Swan mailing list
[email protected]
https://lists.libreswan.org/mailman/listinfo/swan

Reply via email to