[strongSwan] questions on syslog output; linux server/mac client RSA certificate auth

[Cindy Moore]

Hm, can this portion be explained in a bit more detail?

Dec 17 07:33:46 vpn charon: 15[ENC] parsed QUICK_MODE request
4114711345 [ HASH SA No ID ID NAT-OA NAT-OA ]
Dec 17 07:33:46 vpn charon: 15[IKE] changing received traffic
selectors 10.0.1.32/32[udp/62338]=== vpn_ip/32[udp/l2f] due to NAT
Dec 17 07:33:46 vpn charon: 15[CFG] looking for a child config for
vpn_ip/32[udp/l2f] === client_ip/32[udp/62338]
Dec 17 07:33:46 vpn charon: 15[CFG] proposing traffic selectors for us:
Dec 17 07:33:46 vpn charon: 15[CFG]  0.0.0.0/0
Dec 17 07:33:46 vpn charon: 15[CFG] proposing traffic selectors for other:
Dec 17 07:33:46 vpn charon: 15[CFG]  dynamic
Dec 17 07:33:46 vpn charon: 15[IKE] no matching CHILD_SA config found

Looks for a child config, doesn't find one, what's going on here?

On Wed, Dec 17, 2014 at 7:57 AM, Cindy Moore <ctmoore at cs.ucsd.edu> wrote:
> Maybe I'm just being dense, but what is "Main Mode"?
>
> OK, the reason I have xauth-noauth is that I was under the impression
> mac os X *required* xauth because of ikev1. So removing this, I get
>
> Maybe I'm just being dense, but what is "Main Mode"?
>
> OK, the reason I had xauth-noauth is that I was under the impression
> mac os X *required* xauth because of ikev1. So removing that line from
> the conn, I get this.  It looks more successful on the server side
> (I'm not seeing the messages I was asking about last time), and the
> same on the client side.  At this point, it looks like they connect up
> but then don't "hear" each other.  Any thoughts?
>
> (on linux server, /var/log/syslog)
> Dec 17 07:33:45 vpn charon: 12[NET] received packet: from
> client_ip[500] to vpn_ip[500] (300 bytes)
> Dec 17 07:33:45 vpn charon: 12[ENC] parsed ID_PROT request 0 [ SA V V
> V V V V V V V V V ]
> Dec 17 07:33:45 vpn charon: 12[CFG] looking for an ike config for
> vpn_ip...client_ip
> Dec 17 07:33:45 vpn charon: 12[CFG]   candidate: vpn_ip...%any, prio 1052
> Dec 17 07:33:45 vpn charon: 12[CFG]   candidate: vpn_ip...%any, prio 1052
> Dec 17 07:33:45 vpn charon: 12[CFG] found matching ike config:
> vpn_ip...%any with prio 1052
> Dec 17 07:33:45 vpn charon: 12[IKE] received NAT-T (RFC 3947) vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike-08 vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike-07 vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike-06 vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike-05 vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike-04 vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike-03 vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike-02 vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received
> draft-ietf-ipsec-nat-t-ike-02\n vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] received DPD vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] client_ip is initiating a Main Mode IKE_SA
> Dec 17 07:33:45 vpn charon: 12[IKE] IKE_SA (unnamed)[1] state change:
> CREATED => CONNECTING
> Dec 17 07:33:45 vpn charon: 12[CFG] selecting proposal:
> Dec 17 07:33:45 vpn charon: 12[CFG]   no acceptable ENCRYPTION_ALGORITHM found
> Dec 17 07:33:45 vpn charon: 12[CFG] selecting proposal:
> Dec 17 07:33:45 vpn charon: 12[CFG]   no acceptable DIFFIE_HELLMAN_GROUP found
> Dec 17 07:33:45 vpn charon: 12[CFG] selecting proposal:
> Dec 17 07:33:45 vpn charon: 12[CFG]   proposal matches
> Dec 17 07:33:45 vpn charon: 12[CFG] received proposals:
> IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
> Dec 17 07:33:45 vpn charon: 12[CFG] configured proposals:
> IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_2048,
> IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536,
> IKE:AES_CBC_128/AES_CBC_192/AES_CBC_256/3DES_CBC/AES_XCBC_96/AES_CMAC_96/HMAC_SHA1_96/HMAC_MD5_96/HMAC_SHA2_256_128/HMAC_SHA2_384_192/HMAC_SHA2_512_256/PRF_AES128_XCBC/PRF_AES128_CMAC/PRF_HMAC_SHA1/PRF_HMAC_MD5/PRF_HMAC_SHA2_256/PRF_HMAC_SHA2_384/PRF_HMAC_SHA2_512/MODP_2048/MODP_2048_224/MODP_2048_256/MODP_1536/MODP_3072/MODP_4096/MODP_8192/MODP_1024/MODP_1024_160
> Dec 17 07:33:45 vpn charon: 12[CFG] selected proposal:
> IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
> Dec 17 07:33:45 vpn charon: 12[IKE] sending XAuth vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] sending DPD vendor ID
> Dec 17 07:33:45 vpn charon: 12[IKE] sending NAT-T (RFC 3947) vendor ID
> Dec 17 07:33:45 vpn charon: 12[ENC] generating ID_PROT response 0 [ SA V V V ]
> Dec 17 07:33:45 vpn charon: 12[NET] sending packet: from vpn_ip[500]
> to client_ip[500] (132 bytes)
> Dec 17 07:33:45 vpn charon: 03[NET] sending packet: from vpn_ip[500]
> to client_ip[500]
> Dec 17 07:33:45 vpn charon: 01[NET] received packet: from
> client_ip[500] to vpn_ip[500]
> Dec 17 07:33:45 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:33:45 vpn charon: 04[NET] received packet: from
> client_ip[500] to vpn_ip[500] (228 bytes)
> Dec 17 07:33:45 vpn charon: 04[ENC] parsed ID_PROT request 0 [ KE No
> NAT-D NAT-D ]
> Dec 17 07:33:45 vpn charon: 04[IKE] remote host is behind NAT
> Dec 17 07:33:45 vpn charon: 04[IKE] sending cert request for "C=US,
> O=ThatsUs, CN=strongSwan Root CA"
> Dec 17 07:33:45 vpn charon: 04[ENC] generating ID_PROT response 0 [ KE
> No CERTREQ NAT-D NAT-D ]
> Dec 17 07:33:45 vpn charon: 04[NET] sending packet: from vpn_ip[500]
> to client_ip[500] (310 bytes)
> Dec 17 07:33:45 vpn charon: 03[NET] sending packet: from vpn_ip[500]
> to client_ip[500]
> Dec 17 07:33:45 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:33:45 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:33:45 vpn charon: 13[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (1492 bytes)
> Dec 17 07:33:45 vpn charon: 13[ENC] parsed ID_PROT request 0 [ ID CERT
> SIG CERTREQ N(INITIAL_CONTACT) ]
> Dec 17 07:33:45 vpn charon: 13[IKE] ignoring certificate request without data
> Dec 17 07:33:45 vpn charon: 13[IKE] received end entity cert "C=US,
> O=ThatsUs, CN=cindy at example.com"
> Dec 17 07:33:45 vpn charon: 13[CFG] looking for RSA signature peer
> configs matching vpn_ip...client_ip[C=US, O=ThatsUs,
> CN=cindy at example.com]
> Dec 17 07:33:45 vpn charon: 13[CFG]   candidate "roadwarrior-ikev1",
> match: 1/1/1052 (me/other/ike)
> Dec 17 07:33:45 vpn charon: 13[CFG]   candidate "rw-ctmoore", match:
> 1/20/1052 (me/other/ike)
> Dec 17 07:33:45 vpn charon: 13[CFG] selected peer config "roadwarrior-ikev1"
> Dec 17 07:33:45 vpn charon: 13[CFG]   using certificate "C=US,
> O=ThatsUs, CN=cindy at example.com"
> Dec 17 07:33:45 vpn charon: 13[CFG]   certificate "C=US, O=ThatsUs,
> CN=cindy at example.com" key: 2048 bit RSA
> Dec 17 07:33:45 vpn charon: 13[CFG]   using trusted ca certificate
> "C=US, O=ThatsUs, CN=strongSwan Root CA"
> Dec 17 07:33:45 vpn charon: 13[CFG] checking certificate status of
> "C=US, O=ThatsUs, CN=cindy at example.com"
> Dec 17 07:33:45 vpn charon: 13[CFG] ocsp check skipped, no ocsp found
> Dec 17 07:33:45 vpn charon: 13[CFG] certificate status is not available
> Dec 17 07:33:45 vpn charon: 13[CFG]   certificate "C=US, O=ThatsUs,
> CN=strongSwan Root CA" key: 4096 bit RSA
> Dec 17 07:33:45 vpn charon: 13[CFG]   reached self-signed root ca with
> a path length of 0
> Dec 17 07:33:45 vpn charon: 13[IKE] authentication of 'C=US,
> O=ThatsUs, CN=cindy at example.com' with RSA successful
> Dec 17 07:33:45 vpn charon: 13[IKE] authentication of 'C=US,
> O=ThatsUs, CN=vpn.example.com' (myself) successful
> Dec 17 07:33:45 vpn charon: 13[IKE] IKE_SA roadwarrior-ikev1[1]
> established between vpn_ip[C=US, O=ThatsUs,
> CN=vpn.example.com]...client_ip[C=US, O=ThatsUs, CN=cindy at example.com]
> Dec 17 07:33:45 vpn charon: 13[IKE] IKE_SA roadwarrior-ikev1[1] state
> change: CONNECTING => ESTABLISHED
> Dec 17 07:33:45 vpn charon: 13[IKE] scheduling reauthentication in 3293s
> Dec 17 07:33:45 vpn charon: 13[IKE] maximum IKE_SA lifetime 3473s
> Dec 17 07:33:45 vpn charon: 13[IKE] sending end entity cert "C=US,
> O=ThatsUs, CN=vpn.example.com"
> Dec 17 07:33:45 vpn charon: 13[ENC] generating ID_PROT response 0 [ ID
> CERT SIG ]
> Dec 17 07:33:45 vpn charon: 13[NET] sending packet: from vpn_ip[4500]
> to client_ip[38391] (1484 bytes)
> Dec 17 07:33:45 vpn charon: 03[NET] sending packet: from vpn_ip[4500]
> to client_ip[38391]
> Dec 17 07:33:46 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:33:46 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:33:46 vpn charon: 15[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:33:46 vpn charon: 15[ENC] parsed QUICK_MODE request
> 4114711345 [ HASH SA No ID ID NAT-OA NAT-OA ]
> Dec 17 07:33:46 vpn charon: 15[IKE] changing received traffic
> selectors 10.0.1.32/32[udp/62338]=== vpn_ip/32[udp/l2f] due to NAT
> Dec 17 07:33:46 vpn charon: 15[CFG] looking for a child config for
> vpn_ip/32[udp/l2f] === client_ip/32[udp/62338]
> Dec 17 07:33:46 vpn charon: 15[CFG] proposing traffic selectors for us:
> Dec 17 07:33:46 vpn charon: 15[CFG]  0.0.0.0/0
> Dec 17 07:33:46 vpn charon: 15[CFG] proposing traffic selectors for other:
> Dec 17 07:33:46 vpn charon: 15[CFG]  dynamic
> Dec 17 07:33:46 vpn charon: 15[IKE] no matching CHILD_SA config found
> Dec 17 07:33:46 vpn charon: 15[IKE] queueing INFORMATIONAL task
> Dec 17 07:33:46 vpn charon: 15[IKE] activating new tasks
> Dec 17 07:33:46 vpn charon: 15[IKE]   activating INFORMATIONAL task
> Dec 17 07:33:46 vpn charon: 15[ENC] generating INFORMATIONAL_V1
> request 2161614569 [ HASH N(INVAL_ID) ]
> Dec 17 07:33:46 vpn charon: 15[NET] sending packet: from vpn_ip[4500]
> to client_ip[38391] (76 bytes)
> Dec 17 07:33:46 vpn charon: 15[IKE] activating new tasks
> Dec 17 07:33:46 vpn charon: 15[IKE] nothing to initiate
> Dec 17 07:33:46 vpn charon: 03[NET] sending packet: from vpn_ip[4500]
> to client_ip[38391]
> Dec 17 07:33:49 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:33:49 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:33:49 vpn charon: 05[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:33:49 vpn charon: 05[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:33:52 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:33:52 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:33:52 vpn charon: 06[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:33:52 vpn charon: 06[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:33:55 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:33:55 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:33:55 vpn charon: 07[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:33:55 vpn charon: 07[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:33:58 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:33:58 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:33:58 vpn charon: 08[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:33:58 vpn charon: 08[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:34:01 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:34:01 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:34:01 vpn charon: 09[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:34:01 vpn charon: 09[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:34:04 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:34:04 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:34:04 vpn charon: 10[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:34:04 vpn charon: 10[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:34:07 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:34:07 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:34:07 vpn charon: 11[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:34:07 vpn charon: 11[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:34:10 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:34:10 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:34:10 vpn charon: 12[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:34:10 vpn charon: 12[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:34:13 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:34:13 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:34:13 vpn charon: 04[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (252 bytes)
> Dec 17 07:34:13 vpn charon: 04[IKE] received retransmit of request
> with ID 4114711345, but no response to retransmit
> Dec 17 07:34:16 vpn charon: 01[NET] received packet: from
> client_ip[38391] to vpn_ip[4500]
> Dec 17 07:34:16 vpn charon: 01[NET] waiting for data on sockets
> Dec 17 07:34:16 vpn charon: 14[NET] received packet: from
> client_ip[38391] to vpn_ip[4500] (84 bytes)
> Dec 17 07:34:16 vpn charon: 14[ENC] parsed INFORMATIONAL_V1 request
> 2185990223 [ HASH D ]
> Dec 17 07:34:16 vpn charon: 14[IKE] received DELETE for IKE_SA
> roadwarrior-ikev1[1]
> Dec 17 07:34:16 vpn charon: 14[IKE] deleting IKE_SA
> roadwarrior-ikev1[1] between vpn_ip[C=US, O=ThatsUs,
> CN=vpn.example.com]...client_ip[C=US, O=ThatsUs, CN=cindy at example.com]
> Dec 17 07:34:16 vpn charon: 14[IKE] IKE_SA roadwarrior-ikev1[1] state
> change: ESTABLISHED => DELETING
> Dec 17 07:34:16 vpn charon: 14[IKE] IKE_SA roadwarrior-ikev1[1] state
> change: DELETING => DELETING
> Dec 17 07:34:16 vpn charon: 14[IKE] IKE_SA roadwarrior-ikev1[1] state
> change: DELETING => DESTROYING
>
>
> (on mac client, /var/log/system.log)
> Dec 17 07:33:44 macbook pro pppd[4619]: pppd 2.4.2 (Apple version
> 412.5.70) started by mac_owner, uid 501
> Dec 17 07:33:44 macbook pro pppd[4619]: L2TP connecting to server
> 'vpn.example.com' (vpn_ip)...
> Dec 17 07:33:44 macbook pro pppd[4619]: IPSec connection started
> Dec 17 07:33:45 macbook pro racoon[4620]: Connecting.
> Dec 17 07:33:45 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Initiator, Main-Mode message 1).
> Dec 17 07:33:45 macbook pro racoon[4620]: IKE Packet: receive success.
> (Initiator, Main-Mode message 2).
> Dec 17 07:33:45 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Initiator, Main-Mode message 3).
> Dec 17 07:33:45 macbook pro racoon[4620]: IKE Packet: receive success.
> (Initiator, Main-Mode message 4).
> Dec 17 07:33:45 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Initiator, Main-Mode message 5).
> Dec 17 07:33:45 macbook pro racoon[4620]: IKEv1 Phase1 AUTH: success.
> (Initiator, Main-Mode Message 6).
> Dec 17 07:33:45 macbook pro racoon[4620]: IKE Packet: receive success.
> (Initiator, Main-Mode message 6).
> Dec 17 07:33:45 macbook pro racoon[4620]: IKEv1 Phase1 Initiator:
> success. (Initiator, Main-Mode).
> Dec 17 07:33:46 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Initiator, Quick-Mode message 1).
> Dec 17 07:33:46 macbook pro racoon[4620]: IKE Packet: receive success.
> (Information message).
> Dec 17 07:33:49 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Phase2 Retransmit).
> Dec 17 07:33:55 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Phase2 Retransmit).
> Dec 17 07:34:04 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Phase2 Retransmit).
> Dec 17 07:34:13 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Phase2 Retransmit).
> Dec 17 07:34:16 macbook pro pppd[4619]: IPSec connection failed
> Dec 17 07:34:16 macbook pro racoon[4620]: IKE Packet: transmit
> success. (Information message).
> Dec 17 07:34:16 macbook pro racoon[4620]: IKEv1 Information-Notice:
> transmit success. (Delete ISAKMP-SA).
> Dec 17 07:34:16 macbook pro racoon[4620]: Disconnecting. (Connection
> tried to negotiate for, 31.608495 seconds).
>
>
>
> On Wed, Dec 17, 2014 at 1:08 AM, Martin Willi <martin at strongswan.org> wrote:
>> Cindy,
>>
>>> 14[CFG] looking for RSA signature peer configs matching vpn_ip...client_ip[C=US, O=ThatsUs, CN=myemailaddr]
>>>
>>> Would this be as expected?  I can't figure out why it isn't trying to
>>> match to the vpn host certificate.
>>
>> Before looking for certificates, strongSwan looks for a configuration
>> that matches the proposed identities and authentication method.
>>
>>> 14[IKE] found 1 matching config, but none allows RSA signature authentication using Main Mode
>>>
>>> Can anyone tell me what this means?
>>
>> It means that the daemon couldn't find a configuration for that client
>> that uses RSA authentication with Main Mode.
>>
>>> 07[CFG]   rightauth=pubkey
>>> 07[CFG]   rightauth2=xauth-noauth
>>
>> Your config uses XAuth, that is RSA followed by username/password
>> authentication. This is not the same as the client expects, try to
>> remove the rightauth2 line to use RSA authentication only.
>>
>> Regards
>> Martin
>>