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

Wed Dec 17 16:57:03 CET 2014

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
>