IKEv2 EAP-RADIUS w/ FreeRADIUS (EAP-TLS) won't authenticate with separate certificates
-
Hey guys,
I have difficulties setting up IKEv2 EAP-RADIUS with FreeRADIUS (EAP-TLS).
I created three different certificates. One for strongswan, one for the freeradius server and one for the client.
As long strongswan and radius use different certificates the client is totaly unable to authenticate against strongswan. Even when I try to trust my the radius certificate my OSX Client quits connection with "authentication failed".
As soon I tell freeradius to use same certificate as strongswan, everything runs great!
Does anybody have an idea about what I'm doing wrong?
Background
I'll try to keep things short...
Fist I've setup IKEv2 with EAP-TLS, which worked great...
[https://github.com/pfsense/docs/blob/master/source/vpn/ipsec/ikev2-with-eap-tls.rst](link url)Then I moved on to make IKEv2 run against my central RADIUS, which didn't work...
[https://github.com/mikael-andre/pfSense/wiki/HOWTO-pfSense-IPsec-VPN-RADIUS-TLS](link url)RADIUS LOGS
Jul 19 20:34:47 radiusd 73890 (23) Login incorrect (Failed retrieving values required to evaluate condition): [c4-b3-01-d9-4e-6b.v2@rocky***.de] (from client firewall01 port 14 cli 10.00.2.2[4500]) Jul 19 20:34:28 radiusd 73890 (15) Login incorrect (Failed retrieving values required to evaluate condition): [c4-b3-01-d9-4e-6b.v2@rocky***.de] (from client firewall01 port 13 cli 10.00.2.2[4500]) Jul 19 20:34:23 radiusd 73890 (7) Login incorrect (Failed retrieving values required to evaluate condition): [c4-b3-01-d9-4e-6b.v2@rocky***.de] (from client firewall01 port 12 cli 10.00.2.2[4500])
STRONGSWAN LOGS
Jul 19 20:34:48 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (80 bytes) Jul 19 20:34:48 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 9 [ EAP/FAIL ] Jul 19 20:34:48 charon 12[IKE] <con-mobile|14> EAP method EAP_TLS failed for peer c4-b3-01-d9-4e-6b.v2@rocky***.de Jul 19 20:34:48 charon 12[IKE] <con-mobile|14> RADIUS authentication of 'c4-b3-01-d9-4e-6b.v2@rocky***.de' failed Jul 19 20:34:48 charon 12[CFG] <con-mobile|14> received RADIUS Access-Reject from server 'radius01' Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> parsed IKE_AUTH request 9 [ EAP/RES/TLS ] Jul 19 20:34:47 charon 12[NET] <con-mobile|14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (96 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (528 bytes) Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 8 [ EAP/REQ/TLS ] Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> parsed IKE_AUTH request 8 [ EAP/RES/TLS ] Jul 19 20:34:47 charon 12[NET] <con-mobile|14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 7 [ EAP/REQ/TLS ] Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> parsed IKE_AUTH request 7 [ EAP/RES/TLS ] Jul 19 20:34:47 charon 12[NET] <con-mobile|14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 6 [ EAP/REQ/TLS ] Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> parsed IKE_AUTH request 6 [ EAP/RES/TLS ] Jul 19 20:34:47 charon 12[NET] <con-mobile|14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 5 [ EAP/REQ/TLS ] Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> parsed IKE_AUTH request 5 [ EAP/RES/TLS ] Jul 19 20:34:47 charon 12[NET] <con-mobile|14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 4 [ EAP/REQ/TLS ] Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> parsed IKE_AUTH request 4 [ EAP/RES/TLS ] Jul 19 20:34:47 charon 12[NET] <con-mobile|14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (240 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (80 bytes) Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 3 [ EAP/REQ/TLS ] Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> parsed IKE_AUTH request 3 [ EAP/RES/NAK ] Jul 19 20:34:47 charon 12[NET] <con-mobile|14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (96 bytes) Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 2 [ EAP/REQ/MD5 ] Jul 19 20:34:47 charon 12[IKE] <con-mobile|14> initiating EAP_MD5 method (id 0x01) Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:47 charon 12[CFG] <con-mobile|14> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:47 charon 12[IKE] <con-mobile|14> received EAP identity 'c4-b3-01-d9-4e-6b.v2@rocky***.de' Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> parsed IKE_AUTH request 2 [ EAP/RES/ID ] Jul 19 20:34:47 charon 12[NET] <con-mobile|14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (128 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (996 bytes) Jul 19 20:34:47 charon 12[NET] <con-mobile|14> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1236 bytes) Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 1 [ EF(2/2) ] Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 1 [ EF(1/2) ] Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> splitting IKE message (2160 bytes) into 2 fragments Jul 19 20:34:47 charon 12[ENC] <con-mobile|14> generating IKE_AUTH response 1 [ IDr CERT AUTH EAP/REQ/ID ] Jul 19 20:34:47 charon 12[IKE] <con-mobile|14> sending end entity cert "C=DE, ST=Region, O=rocky***, CN=vpn.*.de" Jul 19 20:34:47 charon 12[IKE] <con-mobile|14> authentication of 'vpn.*.de' (myself) with RSA signature successful Jul 19 20:34:46 charon 12[IKE] <con-mobile|14> peer supports MOBIKE Jul 19 20:34:46 charon 12[IKE] <con-mobile|14> received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding Jul 19 20:34:46 charon 12[IKE] <con-mobile|14> initiating EAP_IDENTITY method (id 0x00) Jul 19 20:34:46 charon 12[CFG] <con-mobile|14> selected peer config 'con-mobile' Jul 19 20:34:46 charon 12[CFG] <14> looking for peer configs matching 10.00.1.22[vpn.*.de]...10.00.2.2[c4-b3-01-d9-4e-6b.v2@rocky***.de] Jul 19 20:34:46 charon 12[ENC] <14> parsed IKE_AUTH request 1 [ IDi N(INIT_CONTACT) N(MOBIKE_SUP) IDr CPRQ(ADDR DHCP DNS MASK ADDR6 DHCP6 DNS6 (25)) N(ESP_TFC_PAD_N) N(NON_FIRST_FRAG) SA TSi TSr ] Jul 19 20:34:46 charon 12[ENC] <14> unknown attribute type (25) Jul 19 20:34:46 charon 12[NET] <14> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (544 bytes) Jul 19 20:34:46 charon 13[NET] <14> sending packet: from 10.00.1.22[500] to 10.00.2.2[500] (473 bytes) Jul 19 20:34:46 charon 13[ENC] <14> generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(FRAG_SUP) N(MULT_AUTH) ] Jul 19 20:34:46 charon 13[IKE] <14> sending cert request for "C=DE, ST=Region, L=City, O=rocky***, E=admin@example.org, CN=rocky*** Certificate Authority" Jul 19 20:34:46 charon 13[CFG] <14> selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048 Jul 19 20:34:46 charon 13[IKE] <14> 10.00.2.2 is initiating an IKE_SA Jul 19 20:34:46 charon 13[ENC] <14> parsed IKE_SA_INIT request 0 [ SA KE No N(REDIR_SUP) N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) ] Jul 19 20:34:46 charon 13[NET] <14> received packet: from 10.00.2.2[500] to 10.00.1.22[500] (604 bytes) Jul 19 20:34:29 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (80 bytes) Jul 19 20:34:29 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 9 [ EAP/FAIL ] Jul 19 20:34:29 charon 13[IKE] <con-mobile|13> EAP method EAP_TLS failed for peer c4-b3-01-d9-4e-6b.v2@rocky***.de Jul 19 20:34:29 charon 13[IKE] <con-mobile|13> RADIUS authentication of 'c4-b3-01-d9-4e-6b.v2@rocky***.de' failed Jul 19 20:34:29 charon 13[CFG] <con-mobile|13> received RADIUS Access-Reject from server 'radius01' Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> parsed IKE_AUTH request 9 [ EAP/RES/TLS ] Jul 19 20:34:28 charon 13[NET] <con-mobile|13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (96 bytes) Jul 19 20:34:28 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (528 bytes) Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 8 [ EAP/REQ/TLS ] Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> parsed IKE_AUTH request 8 [ EAP/RES/TLS ] Jul 19 20:34:28 charon 13[NET] <con-mobile|13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:28 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 7 [ EAP/REQ/TLS ] Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> parsed IKE_AUTH request 7 [ EAP/RES/TLS ] Jul 19 20:34:28 charon 13[NET] <con-mobile|13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:28 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 6 [ EAP/REQ/TLS ] Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> parsed IKE_AUTH request 6 [ EAP/RES/TLS ] Jul 19 20:34:28 charon 13[NET] <con-mobile|13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:28 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 5 [ EAP/REQ/TLS ] Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> parsed IKE_AUTH request 5 [ EAP/RES/TLS ] Jul 19 20:34:28 charon 13[NET] <con-mobile|13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:28 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 4 [ EAP/REQ/TLS ] Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> parsed IKE_AUTH request 4 [ EAP/RES/TLS ] Jul 19 20:34:28 charon 13[NET] <con-mobile|13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (240 bytes) Jul 19 20:34:28 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (80 bytes) Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 3 [ EAP/REQ/TLS ] Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> parsed IKE_AUTH request 3 [ EAP/RES/NAK ] Jul 19 20:34:28 charon 13[NET] <con-mobile|13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:28 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (96 bytes) Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 2 [ EAP/REQ/MD5 ] Jul 19 20:34:28 charon 13[IKE] <con-mobile|13> initiating EAP_MD5 method (id 0x01) Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:28 charon 13[CFG] <con-mobile|13> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:28 charon 13[IKE] <con-mobile|13> received EAP identity 'c4-b3-01-d9-4e-6b.v2@rocky***.de' Jul 19 20:34:28 charon 13[ENC] <con-mobile|13> parsed IKE_AUTH request 2 [ EAP/RES/ID ] Jul 19 20:34:28 charon 13[NET] <con-mobile|13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (128 bytes) Jul 19 20:34:27 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (996 bytes) Jul 19 20:34:27 charon 13[NET] <con-mobile|13> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1236 bytes) Jul 19 20:34:27 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 1 [ EF(2/2) ] Jul 19 20:34:27 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 1 [ EF(1/2) ] Jul 19 20:34:27 charon 13[ENC] <con-mobile|13> splitting IKE message (2160 bytes) into 2 fragments Jul 19 20:34:27 charon 13[ENC] <con-mobile|13> generating IKE_AUTH response 1 [ IDr CERT AUTH EAP/REQ/ID ] Jul 19 20:34:27 charon 13[IKE] <con-mobile|13> sending end entity cert "C=DE, ST=Region, O=rocky***, CN=vpn.*.de" Jul 19 20:34:27 charon 13[IKE] <con-mobile|13> authentication of 'vpn.*.de' (myself) with RSA signature successful Jul 19 20:34:27 charon 13[IKE] <con-mobile|13> peer supports MOBIKE Jul 19 20:34:27 charon 13[IKE] <con-mobile|13> received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding Jul 19 20:34:27 charon 13[IKE] <con-mobile|13> initiating EAP_IDENTITY method (id 0x00) Jul 19 20:34:27 charon 13[CFG] <con-mobile|13> selected peer config 'con-mobile' Jul 19 20:34:27 charon 13[CFG] <13> looking for peer configs matching 10.00.1.22[vpn.*.de]...10.00.2.2[c4-b3-01-d9-4e-6b.v2@rocky***.de] Jul 19 20:34:27 charon 13[ENC] <13> parsed IKE_AUTH request 1 [ IDi N(INIT_CONTACT) N(MOBIKE_SUP) IDr CPRQ(ADDR DHCP DNS MASK ADDR6 DHCP6 DNS6 (25)) N(ESP_TFC_PAD_N) N(NON_FIRST_FRAG) SA TSi TSr ] Jul 19 20:34:27 charon 13[ENC] <13> unknown attribute type (25) Jul 19 20:34:27 charon 13[NET] <13> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (544 bytes) Jul 19 20:34:27 charon 13[NET] <13> sending packet: from 10.00.1.22[500] to 10.00.2.2[500] (473 bytes) Jul 19 20:34:27 charon 13[ENC] <13> generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(FRAG_SUP) N(MULT_AUTH) ] Jul 19 20:34:27 charon 13[IKE] <13> sending cert request for "C=DE, ST=Region, L=City, O=rocky***, E=admin@example.org, CN=rocky*** Certificate Authority" Jul 19 20:34:27 charon 13[CFG] <13> selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048 Jul 19 20:34:27 charon 13[IKE] <13> 10.00.2.2 is initiating an IKE_SA Jul 19 20:34:27 charon 13[ENC] <13> parsed IKE_SA_INIT request 0 [ SA KE No N(REDIR_SUP) N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) ] Jul 19 20:34:27 charon 13[NET] <13> received packet: from 10.00.2.2[500] to 10.00.1.22[500] (604 bytes) Jul 19 20:34:24 charon 13[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (80 bytes) Jul 19 20:34:24 charon 13[ENC] <con-mobile|12> generating IKE_AUTH response 9 [ EAP/FAIL ] Jul 19 20:34:24 charon 13[IKE] <con-mobile|12> EAP method EAP_TLS failed for peer c4-b3-01-d9-4e-6b.v2@rocky***.de Jul 19 20:34:24 charon 13[IKE] <con-mobile|12> RADIUS authentication of 'c4-b3-01-d9-4e-6b.v2@rocky***.de' failed Jul 19 20:34:24 charon 13[CFG] <con-mobile|12> received RADIUS Access-Reject from server 'radius01' Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> parsed IKE_AUTH request 9 [ EAP/RES/TLS ] Jul 19 20:34:23 charon 13[NET] <con-mobile|12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (96 bytes) Jul 19 20:34:23 charon 13[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (528 bytes) Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> generating IKE_AUTH response 8 [ EAP/REQ/TLS ] Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> parsed IKE_AUTH request 8 [ EAP/RES/TLS ] Jul 19 20:34:23 charon 13[NET] <con-mobile|12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:23 charon 13[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> generating IKE_AUTH response 7 [ EAP/REQ/TLS ] Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> parsed IKE_AUTH request 7 [ EAP/RES/TLS ] Jul 19 20:34:23 charon 13[NET] <con-mobile|12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:23 charon 13[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> generating IKE_AUTH response 6 [ EAP/REQ/TLS ] Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> parsed IKE_AUTH request 6 [ EAP/RES/TLS ] Jul 19 20:34:23 charon 13[NET] <con-mobile|12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:23 charon 13[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> generating IKE_AUTH response 5 [ EAP/REQ/TLS ] Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:23 charon 13[CFG] <con-mobile|12> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:23 charon 13[ENC] <con-mobile|12> parsed IKE_AUTH request 5 [ EAP/RES/TLS ] Jul 19 20:34:23 charon 13[NET] <con-mobile|12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:23 charon 14[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1088 bytes) Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> generating IKE_AUTH response 4 [ EAP/REQ/TLS ] Jul 19 20:34:23 charon 14[CFG] <con-mobile|12> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:23 charon 14[CFG] <con-mobile|12> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> parsed IKE_AUTH request 4 [ EAP/RES/TLS ] Jul 19 20:34:23 charon 14[NET] <con-mobile|12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (240 bytes) Jul 19 20:34:23 charon 14[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (80 bytes) Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> generating IKE_AUTH response 3 [ EAP/REQ/TLS ] Jul 19 20:34:23 charon 14[CFG] <con-mobile|12> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:23 charon 14[CFG] <con-mobile|12> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> parsed IKE_AUTH request 3 [ EAP/RES/NAK ] Jul 19 20:34:23 charon 14[NET] <con-mobile|12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (80 bytes) Jul 19 20:34:23 charon 14[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (96 bytes) Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> generating IKE_AUTH response 2 [ EAP/REQ/MD5 ] Jul 19 20:34:23 charon 14[IKE] <con-mobile|12> initiating EAP_MD5 method (id 0x01) Jul 19 20:34:23 charon 14[CFG] <con-mobile|12> received RADIUS Access-Challenge from server 'radius01' Jul 19 20:34:23 charon 14[CFG] <con-mobile|12> sending RADIUS Access-Request to server 'radius01' Jul 19 20:34:23 charon 14[IKE] <con-mobile|12> received EAP identity 'c4-b3-01-d9-4e-6b.v2@rocky***.de' Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> parsed IKE_AUTH request 2 [ EAP/RES/ID ] Jul 19 20:34:23 charon 14[NET] <con-mobile|12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (128 bytes) Jul 19 20:34:23 charon 14[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (996 bytes) Jul 19 20:34:23 charon 14[NET] <con-mobile|12> sending packet: from 10.00.1.22[4500] to 10.00.2.2[4500] (1236 bytes) Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> generating IKE_AUTH response 1 [ EF(2/2) ] Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> generating IKE_AUTH response 1 [ EF(1/2) ] Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> splitting IKE message (2160 bytes) into 2 fragments Jul 19 20:34:23 charon 14[ENC] <con-mobile|12> generating IKE_AUTH response 1 [ IDr CERT AUTH EAP/REQ/ID ] Jul 19 20:34:23 charon 14[IKE] <con-mobile|12> sending end entity cert "C=DE, ST=Region, O=rocky***, CN=vpn.*.de" Jul 19 20:34:23 charon 14[IKE] <con-mobile|12> authentication of 'vpn.*.de' (myself) with RSA signature successful Jul 19 20:34:23 charon 14[IKE] <con-mobile|12> peer supports MOBIKE Jul 19 20:34:23 charon 14[IKE] <con-mobile|12> received ESP_TFC_PADDING_NOT_SUPPORTED, not using ESPv3 TFC padding Jul 19 20:34:23 charon 14[IKE] <con-mobile|12> initiating EAP_IDENTITY method (id 0x00) Jul 19 20:34:23 charon 14[CFG] <con-mobile|12> selected peer config 'con-mobile' Jul 19 20:34:23 charon 14[CFG] <12> looking for peer configs matching 10.00.1.22[vpn.*.de]...10.00.2.2[c4-b3-01-d9-4e-6b.v2@rocky***.de] Jul 19 20:34:23 charon 14[ENC] <12> parsed IKE_AUTH request 1 [ IDi N(INIT_CONTACT) N(MOBIKE_SUP) IDr CPRQ(ADDR DHCP DNS MASK ADDR6 DHCP6 DNS6 (25)) N(ESP_TFC_PAD_N) N(NON_FIRST_FRAG) SA TSi TSr ] Jul 19 20:34:23 charon 14[ENC] <12> unknown attribute type (25) Jul 19 20:34:23 charon 14[NET] <12> received packet: from 10.00.2.2[4500] to 10.00.1.22[4500] (544 bytes) Jul 19 20:34:23 charon 14[NET] <12> sending packet: from 10.00.1.22[500] to 10.00.2.2[500] (473 bytes) Jul 19 20:34:23 charon 14[ENC] <12> generating IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) CERTREQ N(FRAG_SUP) N(MULT_AUTH) ] Jul 19 20:34:23 charon 14[IKE] <12> sending cert request for "C=DE, ST=Region, L=City, O=rocky***, E=admin@example.org, CN=rocky*** Certificate Authority" Jul 19 20:34:23 charon 14[CFG] <12> selected proposal: IKE:AES_CBC_256/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_2048 Jul 19 20:34:23 charon 14[IKE] <12> 10.00.2.2 is initiating an IKE_SA Jul 19 20:34:23 charon 14[ENC] <12> parsed IKE_SA_INIT request 0 [ SA KE No N(REDIR_SUP) N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) ] Jul 19 20:34:23 charon 14[NET] <12> received packet: from 10.00.2.2[500] to 10.00.1.22[500] (604 bytes)
I'd appreciate any help.
Marti
-
My external Radius Server has been a bit more informational...
EXTERNAL RADIUS LOGS (Part 1)
Fri Jul 19 18:02:48 2019 : Debug: (0) Received Access-Request Id 15 from 10.0.3.1:56782 to 10.0.3.11:1812 length 216 Fri Jul 19 18:02:48 2019 : Debug: (0) User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (0) NAS-Port-Type = Virtual Fri Jul 19 18:02:48 2019 : Debug: (0) Service-Type = Framed-User Fri Jul 19 18:02:48 2019 : Debug: (0) NAS-Port = 4 Fri Jul 19 18:02:48 2019 : Debug: (0) NAS-Port-Id = "con-mobile" Fri Jul 19 18:02:48 2019 : Debug: (0) NAS-IP-Address = 10.0.1.22 Fri Jul 19 18:02:48 2019 : Debug: (0) Called-Station-Id = "10.0.1.22[4500]" Fri Jul 19 18:02:48 2019 : Debug: (0) Calling-Station-Id = "10.0.2.117[4500]" Fri Jul 19 18:02:48 2019 : Debug: (0) EAP-Message = 0x0200002b0163342d62332d30312d64392d34652d36622e763240726f636b796d6f756e7461696e732e6465 Fri Jul 19 18:02:48 2019 : Debug: (0) NAS-Identifier = "strongSwan" Fri Jul 19 18:02:48 2019 : Debug: (0) Message-Authenticator = 0x90640d19a7edc6f6746b746e4eb738fd Fri Jul 19 18:02:48 2019 : Debug: (0) session-state: No State attribute Fri Jul 19 18:02:48 2019 : Debug: (0) # Executing section authorize from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (0) authorize { Fri Jul 19 18:02:48 2019 : Debug: (0) policy filter_username { Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name) -> TRUE Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ / /) { Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ / /) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ /@[^@]*@/ ) { Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ /\.\./ ) { Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ /\.\./ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Fri Jul 19 18:02:48 2019 : Debug: (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ /\.$/) { Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ /\.$/) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ /@\./) { Fri Jul 19 18:02:48 2019 : Debug: (0) if (&User-Name =~ /@\./) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (0) } # if (&User-Name) = notfound Fri Jul 19 18:02:48 2019 : Debug: (0) } # policy filter_username = notfound Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (0) [preprocess] = ok Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authorize]: calling digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authorize]: returned from digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (0) [digest] = noop Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authorize]: calling suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (0) suffix: Checking for suffix after "@" Fri Jul 19 18:02:48 2019 : Debug: (0) suffix: Looking up realm "rocky*.de" for User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (0) suffix: No such realm "rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authorize]: returned from suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (0) [suffix] = noop Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (0) eap: Peer sent EAP Response (code 2) ID 0 length 43 Fri Jul 19 18:02:48 2019 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (0) [eap] = ok Fri Jul 19 18:02:48 2019 : Debug: (0) } # authorize = ok Fri Jul 19 18:02:48 2019 : Debug: (0) Found Auth-Type = eap Fri Jul 19 18:02:48 2019 : Debug: (0) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (0) authenticate { Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authenticate]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (0) eap: Peer sent packet with method EAP Identity (1) Fri Jul 19 18:02:48 2019 : Debug: (0) eap: Calling submodule eap_tls to process data Fri Jul 19 18:02:48 2019 : Debug: (0) eap_tls: Initiating new TLS session Fri Jul 19 18:02:48 2019 : Debug: (0) eap_tls: Flushing SSL sessions (of #0) Fri Jul 19 18:02:48 2019 : Debug: (0) eap_tls: Setting verify mode to require certificate from client Fri Jul 19 18:02:48 2019 : Debug: (0) eap_tls: [eaptls start] = request Fri Jul 19 18:02:48 2019 : Debug: (0) eap: Sending EAP Request (code 1) ID 1 length 6 Fri Jul 19 18:02:48 2019 : Debug: (0) eap: EAP session adding &reply:State = 0x18f137d118f03a02 Fri Jul 19 18:02:48 2019 : Debug: (0) modsingle[authenticate]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (0) [eap] = handled Fri Jul 19 18:02:48 2019 : Debug: (0) } # authenticate = handled Fri Jul 19 18:02:48 2019 : Debug: (0) Using Post-Auth-Type Challenge Fri Jul 19 18:02:48 2019 : Debug: (0) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (0) Challenge { ... } # empty sub-section is ignored Fri Jul 19 18:02:48 2019 : Debug: (0) session-state: Nothing to cache Fri Jul 19 18:02:48 2019 : Debug: (0) Sent Access-Challenge Id 15 from 10.0.3.11:1812 to 10.0.3.1:56782 length 0 Fri Jul 19 18:02:48 2019 : Debug: (0) EAP-Message = 0x010100060d20 Fri Jul 19 18:02:48 2019 : Debug: (0) Message-Authenticator = 0x00000000000000000000000000000000 Fri Jul 19 18:02:48 2019 : Debug: (0) State = 0x18f137d118f03a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (0) Finished request Fri Jul 19 18:02:48 2019 : Debug: Waking up in 4.9 seconds. Fri Jul 19 18:02:48 2019 : Debug: (1) Received Access-Request Id 16 from 10.0.3.1:56782 to 10.0.3.11:1812 length 352 Fri Jul 19 18:02:48 2019 : Debug: (1) User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (1) NAS-Port-Type = Virtual Fri Jul 19 18:02:48 2019 : Debug: (1) Service-Type = Framed-User Fri Jul 19 18:02:48 2019 : Debug: (1) NAS-Port = 4 Fri Jul 19 18:02:48 2019 : Debug: (1) NAS-Port-Id = "con-mobile" Fri Jul 19 18:02:48 2019 : Debug: (1) NAS-IP-Address = 10.0.1.22 Fri Jul 19 18:02:48 2019 : Debug: (1) Called-Station-Id = "10.0.1.22[4500]" Fri Jul 19 18:02:48 2019 : Debug: (1) Calling-Station-Id = "10.0.2.117[4500]" Fri Jul 19 18:02:48 2019 : Debug: (1) EAP-Message = 0x020100a10d800000009716030100920100008e03035d3205c83dd932b6458dff6b342b0125ec15ebb38a7b1188a2088f775825e84700002c00ffc02cc02bc024c023c00ac009c008c030c02fc028c027c014c013c012009d009c003d003c0035002f000a01000039000a00080006001700180019000b00020100000d00120010040102010501060104030203050306030005000501000000000012000000170000 Fri Jul 19 18:02:48 2019 : Debug: (1) NAS-Identifier = "strongSwan" Fri Jul 19 18:02:48 2019 : Debug: (1) State = 0x18f137d118f03a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (1) Message-Authenticator = 0x3d1ff22f3419c3d8e48a58f806ad5fd2 Fri Jul 19 18:02:48 2019 : Debug: (1) session-state: No cached attributes Fri Jul 19 18:02:48 2019 : Debug: (1) # Executing section authorize from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (1) authorize { Fri Jul 19 18:02:48 2019 : Debug: (1) policy filter_username { Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name) -> TRUE Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ / /) { Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ / /) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ /@[^@]*@/ ) { Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ /\.\./ ) { Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ /\.\./ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Fri Jul 19 18:02:48 2019 : Debug: (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ /\.$/) { Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ /\.$/) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ /@\./) { Fri Jul 19 18:02:48 2019 : Debug: (1) if (&User-Name =~ /@\./) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (1) } # if (&User-Name) = notfound Fri Jul 19 18:02:48 2019 : Debug: (1) } # policy filter_username = notfound Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: calling preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: returned from preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (1) [preprocess] = ok Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: calling digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: returned from digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (1) [digest] = noop Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: calling suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (1) suffix: Checking for suffix after "@" Fri Jul 19 18:02:48 2019 : Debug: (1) suffix: Looking up realm "rocky*.de" for User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (1) suffix: No such realm "rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: returned from suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (1) [suffix] = noop Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (1) eap: Peer sent EAP Response (code 2) ID 1 length 161 Fri Jul 19 18:02:48 2019 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (1) [eap] = updated Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: calling files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: returned from files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (1) [files] = noop Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: calling expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: returned from expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (1) [expiration] = noop Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: calling logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authorize]: returned from logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (1) [logintime] = noop Fri Jul 19 18:02:48 2019 : Debug: (1) } # authorize = updated Fri Jul 19 18:02:48 2019 : Debug: (1) Found Auth-Type = eap Fri Jul 19 18:02:48 2019 : Debug: (1) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (1) authenticate { Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (1) eap: Expiring EAP session with state 0x18f137d118f03a02 Fri Jul 19 18:02:48 2019 : Debug: (1) eap: Finished EAP session with state 0x18f137d118f03a02 Fri Jul 19 18:02:48 2019 : Debug: (1) eap: Previous EAP request found for state 0x18f137d118f03a02, released from the list Fri Jul 19 18:02:48 2019 : Debug: (1) eap: Peer sent packet with method EAP TLS (13) Fri Jul 19 18:02:48 2019 : Debug: (1) eap: Calling submodule eap_tls to process data Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: Continuing EAP-TLS Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: Peer sent flags --L Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: Peer indicated complete TLS record size will be 151 bytes Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: Got complete TLS record (151 bytes) Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: [eaptls verify] = length included Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: (other): before SSL initialization Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: before SSL initialization Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: before SSL initialization Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: <<< recv TLS 1.3 [length 0092] Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS read client hello Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 005d] Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write server hello Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 0da3] Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write certificate Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 0291] Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write key exchange Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 00ed] Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write certificate request Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: >>> send TLS 1.2 [length 0004] Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: SSLv3/TLS write server done Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS_accept: Need to read more data: SSLv3/TLS write server done Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS - In Handshake Phase Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: TLS - got 4507 bytes of data Fri Jul 19 18:02:48 2019 : Debug: (1) eap_tls: [eaptls process] = handled Fri Jul 19 18:02:48 2019 : Debug: (1) eap: Sending EAP Request (code 1) ID 2 length 1004 Fri Jul 19 18:02:48 2019 : Debug: (1) eap: EAP session adding &reply:State = 0x18f137d119f33a02 Fri Jul 19 18:02:48 2019 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (1) [eap] = handled Fri Jul 19 18:02:48 2019 : Debug: (1) } # authenticate = handled Fri Jul 19 18:02:48 2019 : Debug: (1) Using Post-Auth-Type Challenge Fri Jul 19 18:02:48 2019 : Debug: (1) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (1) Challenge { ... } # empty sub-section is ignored Fri Jul 19 18:02:48 2019 : Debug: (1) session-state: Nothing to cache Fri Jul 19 18:02:48 2019 : Debug: (1) Sent Access-Challenge Id 16 from 10.0.3.11:1812 to 10.0.3.1:56782 length 0 Fri Jul 19 18:02:48 2019 : Debug: (1) EAP-Message = 0x010203ec0dc00000119b160303005d020000590303f485950c61865a1bfb00f232e8fda3561e7775df201310f44b5a519ce62250d8207269671d2024f798db208987e944259582f95ddad1fd079609b4e93543d536bac030000011ff01000100000b000403000102001700001603030da30b000d9f000d9c000647308206433082042ba003020102020117300d06092a864886f70d01010b05003081ae310b3009060355040613024445311f301d06035504080c164e6f727468205268696e652d576573747068616c69613114301206035504070c0b4475657373656c646f726631173015060355040a0c0e526f636b794d6f756e7461696e733120301e06092a864886f70d010901161161646d696e406578616d706c652e6f7267312d302b06035504030c24526f636b794d6f756e7461696e7320436572746966696361746520417574686f72697479301e170d3139303533313230303034315a170d3339303532363230303034315a305e310b3009060355040613 Fri Jul 19 18:02:48 2019 : Debug: (1) Message-Authenticator = 0x00000000000000000000000000000000 Fri Jul 19 18:02:48 2019 : Debug: (1) State = 0x18f137d119f33a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (1) Finished request Fri Jul 19 18:02:48 2019 : Debug: Waking up in 4.9 seconds.
-
My external Radius Server has been a bit more informational...
EXTERNAL RADIUS LOGS (Part 2)
Fri Jul 19 18:02:48 2019 : Debug: (2) Received Access-Request Id 17 from 10.0.3.1:56782 to 10.0.3.11:1812 length 197 Fri Jul 19 18:02:48 2019 : Debug: (2) User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (2) NAS-Port-Type = Virtual Fri Jul 19 18:02:48 2019 : Debug: (2) Service-Type = Framed-User Fri Jul 19 18:02:48 2019 : Debug: (2) NAS-Port = 4 Fri Jul 19 18:02:48 2019 : Debug: (2) NAS-Port-Id = "con-mobile" Fri Jul 19 18:02:48 2019 : Debug: (2) NAS-IP-Address = 10.0.1.22 Fri Jul 19 18:02:48 2019 : Debug: (2) Called-Station-Id = "10.0.1.22[4500]" Fri Jul 19 18:02:48 2019 : Debug: (2) Calling-Station-Id = "10.0.2.117[4500]" Fri Jul 19 18:02:48 2019 : Debug: (2) EAP-Message = 0x020200060d00 Fri Jul 19 18:02:48 2019 : Debug: (2) NAS-Identifier = "strongSwan" Fri Jul 19 18:02:48 2019 : Debug: (2) State = 0x18f137d119f33a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (2) Message-Authenticator = 0xbb1948964f6c463a58f7a46c638945a1 Fri Jul 19 18:02:48 2019 : Debug: (2) session-state: No cached attributes Fri Jul 19 18:02:48 2019 : Debug: (2) # Executing section authorize from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (2) authorize { Fri Jul 19 18:02:48 2019 : Debug: (2) policy filter_username { Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name) -> TRUE Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ / /) { Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ / /) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ /@[^@]*@/ ) { Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ /\.\./ ) { Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ /\.\./ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Fri Jul 19 18:02:48 2019 : Debug: (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ /\.$/) { Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ /\.$/) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ /@\./) { Fri Jul 19 18:02:48 2019 : Debug: (2) if (&User-Name =~ /@\./) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (2) } # if (&User-Name) = notfound Fri Jul 19 18:02:48 2019 : Debug: (2) } # policy filter_username = notfound Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: calling preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: returned from preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (2) [preprocess] = ok Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: calling digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: returned from digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (2) [digest] = noop Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: calling suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (2) suffix: Checking for suffix after "@" Fri Jul 19 18:02:48 2019 : Debug: (2) suffix: Looking up realm "rocky*.de" for User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (2) suffix: No such realm "rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: returned from suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (2) [suffix] = noop Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (2) eap: Peer sent EAP Response (code 2) ID 2 length 6 Fri Jul 19 18:02:48 2019 : Debug: (2) eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (2) [eap] = updated Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: calling files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: returned from files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (2) [files] = noop Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: calling expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: returned from expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (2) [expiration] = noop Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: calling logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authorize]: returned from logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (2) [logintime] = noop Fri Jul 19 18:02:48 2019 : Debug: (2) } # authorize = updated Fri Jul 19 18:02:48 2019 : Debug: (2) Found Auth-Type = eap Fri Jul 19 18:02:48 2019 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (2) authenticate { Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authenticate]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (2) eap: Expiring EAP session with state 0x18f137d119f33a02 Fri Jul 19 18:02:48 2019 : Debug: (2) eap: Finished EAP session with state 0x18f137d119f33a02 Fri Jul 19 18:02:48 2019 : Debug: (2) eap: Previous EAP request found for state 0x18f137d119f33a02, released from the list Fri Jul 19 18:02:48 2019 : Debug: (2) eap: Peer sent packet with method EAP TLS (13) Fri Jul 19 18:02:48 2019 : Debug: (2) eap: Calling submodule eap_tls to process data Fri Jul 19 18:02:48 2019 : Debug: (2) eap_tls: Continuing EAP-TLS Fri Jul 19 18:02:48 2019 : Debug: (2) eap_tls: Peer sent flags --- Fri Jul 19 18:02:48 2019 : Debug: (2) eap_tls: Peer ACKed our handshake fragment Fri Jul 19 18:02:48 2019 : Debug: (2) eap_tls: [eaptls verify] = request Fri Jul 19 18:02:48 2019 : Debug: (2) eap_tls: [eaptls process] = handled Fri Jul 19 18:02:48 2019 : Debug: (2) eap: Sending EAP Request (code 1) ID 3 length 1004 Fri Jul 19 18:02:48 2019 : Debug: (2) eap: EAP session adding &reply:State = 0x18f137d11af23a02 Fri Jul 19 18:02:48 2019 : Debug: (2) modsingle[authenticate]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (2) [eap] = handled Fri Jul 19 18:02:48 2019 : Debug: (2) } # authenticate = handled Fri Jul 19 18:02:48 2019 : Debug: (2) Using Post-Auth-Type Challenge Fri Jul 19 18:02:48 2019 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (2) Challenge { ... } # empty sub-section is ignored Fri Jul 19 18:02:48 2019 : Debug: (2) session-state: Nothing to cache Fri Jul 19 18:02:48 2019 : Debug: (2) Sent Access-Challenge Id 17 from 10.0.3.11:1812 to 10.0.3.1:56782 length 0 Fri Jul 19 18:02:48 2019 : Debug: (2) EAP-Message = 0x010303ec0dc00000119b0203010001a381ba3081b730090603551d1304023000300b0603551d0f0404030205e030130603551d25040c300a06082b0601050507030130360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c303706082b06010505070101042b3029302706082b06010505073001861b687474703a2f2f7777772e6578616d706c652e6f72672f6f63737030170603551d110410300e820c647372767261646975733031300d06092a864886f70d01010b05000382020100cd9caca8a6ce540031502d4e0b92bf62492c314fa812a135c21f3bbd1dfda7e173d50b225d647afc280bcb8d597208caebd68a79a4502f586cf3532557423b8af2d056f0f562168f5a9cc86e5a606e1d7e3a0f425df45cc333c3eedeccd0c239e34cd75d4241594441d02846afde19d2fa94c85be8f6f0f4fc8aefac0760b683531d034a17c980ce7e1e4171bff7689b8740a24e1237ed Fri Jul 19 18:02:48 2019 : Debug: (2) Message-Authenticator = 0x00000000000000000000000000000000 Fri Jul 19 18:02:48 2019 : Debug: (2) State = 0x18f137d11af23a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (2) Finished request Fri Jul 19 18:02:48 2019 : Debug: Waking up in 4.8 seconds. Fri Jul 19 18:02:48 2019 : Debug: (3) Received Access-Request Id 18 from 10.0.3.1:56782 to 10.0.3.11:1812 length 197 Fri Jul 19 18:02:48 2019 : Debug: (3) User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (3) NAS-Port-Type = Virtual Fri Jul 19 18:02:48 2019 : Debug: (3) Service-Type = Framed-User Fri Jul 19 18:02:48 2019 : Debug: (3) NAS-Port = 4 Fri Jul 19 18:02:48 2019 : Debug: (3) NAS-Port-Id = "con-mobile" Fri Jul 19 18:02:48 2019 : Debug: (3) NAS-IP-Address = 10.0.1.22 Fri Jul 19 18:02:48 2019 : Debug: (3) Called-Station-Id = "10.0.1.22[4500]" Fri Jul 19 18:02:48 2019 : Debug: (3) Calling-Station-Id = "10.0.2.117[4500]" Fri Jul 19 18:02:48 2019 : Debug: (3) EAP-Message = 0x020300060d00 Fri Jul 19 18:02:48 2019 : Debug: (3) NAS-Identifier = "strongSwan" Fri Jul 19 18:02:48 2019 : Debug: (3) State = 0x18f137d11af23a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (3) Message-Authenticator = 0xe540f22d1a623645e8fdbf2b45636359 Fri Jul 19 18:02:48 2019 : Debug: (3) session-state: No cached attributes Fri Jul 19 18:02:48 2019 : Debug: (3) # Executing section authorize from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (3) authorize { Fri Jul 19 18:02:48 2019 : Debug: (3) policy filter_username { Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name) -> TRUE Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ / /) { Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ / /) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ /@[^@]*@/ ) { Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ /\.\./ ) { Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ /\.\./ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Fri Jul 19 18:02:48 2019 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ /\.$/) { Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ /\.$/) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ /@\./) { Fri Jul 19 18:02:48 2019 : Debug: (3) if (&User-Name =~ /@\./) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (3) } # if (&User-Name) = notfound Fri Jul 19 18:02:48 2019 : Debug: (3) } # policy filter_username = notfound Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: calling preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: returned from preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (3) [preprocess] = ok Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: calling digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: returned from digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (3) [digest] = noop Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: calling suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (3) suffix: Checking for suffix after "@" Fri Jul 19 18:02:48 2019 : Debug: (3) suffix: Looking up realm "rocky*.de" for User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (3) suffix: No such realm "rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: returned from suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (3) [suffix] = noop Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (3) eap: Peer sent EAP Response (code 2) ID 3 length 6 Fri Jul 19 18:02:48 2019 : Debug: (3) eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (3) [eap] = updated Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: calling files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: returned from files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (3) [files] = noop Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: calling expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: returned from expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (3) [expiration] = noop Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: calling logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authorize]: returned from logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (3) [logintime] = noop Fri Jul 19 18:02:48 2019 : Debug: (3) } # authorize = updated Fri Jul 19 18:02:48 2019 : Debug: (3) Found Auth-Type = eap Fri Jul 19 18:02:48 2019 : Debug: (3) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (3) authenticate { Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authenticate]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (3) eap: Expiring EAP session with state 0x18f137d11af23a02 Fri Jul 19 18:02:48 2019 : Debug: (3) eap: Finished EAP session with state 0x18f137d11af23a02 Fri Jul 19 18:02:48 2019 : Debug: (3) eap: Previous EAP request found for state 0x18f137d11af23a02, released from the list Fri Jul 19 18:02:48 2019 : Debug: (3) eap: Peer sent packet with method EAP TLS (13) Fri Jul 19 18:02:48 2019 : Debug: (3) eap: Calling submodule eap_tls to process data Fri Jul 19 18:02:48 2019 : Debug: (3) eap_tls: Continuing EAP-TLS Fri Jul 19 18:02:48 2019 : Debug: (3) eap_tls: Peer sent flags --- Fri Jul 19 18:02:48 2019 : Debug: (3) eap_tls: Peer ACKed our handshake fragment Fri Jul 19 18:02:48 2019 : Debug: (3) eap_tls: [eaptls verify] = request Fri Jul 19 18:02:48 2019 : Debug: (3) eap_tls: [eaptls process] = handled Fri Jul 19 18:02:48 2019 : Debug: (3) eap: Sending EAP Request (code 1) ID 4 length 1004 Fri Jul 19 18:02:48 2019 : Debug: (3) eap: EAP session adding &reply:State = 0x18f137d11bf53a02 Fri Jul 19 18:02:48 2019 : Debug: (3) modsingle[authenticate]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (3) [eap] = handled Fri Jul 19 18:02:48 2019 : Debug: (3) } # authenticate = handled Fri Jul 19 18:02:48 2019 : Debug: (3) Using Post-Auth-Type Challenge Fri Jul 19 18:02:48 2019 : Debug: (3) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (3) Challenge { ... } # empty sub-section is ignored Fri Jul 19 18:02:48 2019 : Debug: (3) session-state: Nothing to cache Fri Jul 19 18:02:48 2019 : Debug: (3) Sent Access-Challenge Id 18 from 10.0.3.11:1812 to 10.0.3.1:56782 length 0 Fri Jul 19 18:02:48 2019 : Debug: (3) EAP-Message = 0x010403ec0dc00000119b09060355040613024445311f301d06035504080c164e6f727468205268696e652d576573747068616c69613114301206035504070c0b4475657373656c646f726631173015060355040a0c0e526f636b794d6f756e7461696e733120301e06092a864886f70d010901161161646d696e406578616d706c652e6f7267312d302b06035504030c24526f636b794d6f756e7461696e7320436572746966696361746520417574686f7269747930820222300d06092a864886f70d01010105000382020f003082020a0282020100d370e4a0088a010629b885cbf21e70d0a5180df63e7898785598ff0bb4878ad839131f93cfec4d42a77ffbeae4a7a76419a13a9888db494f18c3a89bdddef5f5ec4acfde2a81144fc88098403d5807976c6c275a41b66f87efd20b1c141a8a82cb55b8aea53c165cd02eb23e7f6b69c123ac5e39343b89d2039c6a0f16cb6b723906a9bdd2430c1c1654a7f229816d28f8db857700da3f189b239b6f4514b98b41 Fri Jul 19 18:02:48 2019 : Debug: (3) Message-Authenticator = 0x00000000000000000000000000000000 Fri Jul 19 18:02:48 2019 : Debug: (3) State = 0x18f137d11bf53a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (3) Finished request Fri Jul 19 18:02:48 2019 : Debug: Waking up in 4.8 seconds. Fri Jul 19 18:02:48 2019 : Debug: (4) Received Access-Request Id 19 from 10.0.3.1:56782 to 10.0.3.11:1812 length 197 Fri Jul 19 18:02:48 2019 : Debug: (4) User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (4) NAS-Port-Type = Virtual Fri Jul 19 18:02:48 2019 : Debug: (4) Service-Type = Framed-User Fri Jul 19 18:02:48 2019 : Debug: (4) NAS-Port = 4 Fri Jul 19 18:02:48 2019 : Debug: (4) NAS-Port-Id = "con-mobile" Fri Jul 19 18:02:48 2019 : Debug: (4) NAS-IP-Address = 10.0.1.22 Fri Jul 19 18:02:48 2019 : Debug: (4) Called-Station-Id = "10.0.1.22[4500]" Fri Jul 19 18:02:48 2019 : Debug: (4) Calling-Station-Id = "10.0.2.117[4500]" Fri Jul 19 18:02:48 2019 : Debug: (4) EAP-Message = 0x020400060d00 Fri Jul 19 18:02:48 2019 : Debug: (4) NAS-Identifier = "strongSwan" Fri Jul 19 18:02:48 2019 : Debug: (4) State = 0x18f137d11bf53a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (4) Message-Authenticator = 0xf38adee88adf30c1b7bdc4668d9ee580 Fri Jul 19 18:02:48 2019 : Debug: (4) session-state: No cached attributes Fri Jul 19 18:02:48 2019 : Debug: (4) # Executing section authorize from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (4) authorize { Fri Jul 19 18:02:48 2019 : Debug: (4) policy filter_username { Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name) -> TRUE Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ / /) { Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ / /) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ /@[^@]*@/ ) { Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ /\.\./ ) { Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ /\.\./ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Fri Jul 19 18:02:48 2019 : Debug: (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ /\.$/) { Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ /\.$/) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ /@\./) { Fri Jul 19 18:02:48 2019 : Debug: (4) if (&User-Name =~ /@\./) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (4) } # if (&User-Name) = notfound Fri Jul 19 18:02:48 2019 : Debug: (4) } # policy filter_username = notfound Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: calling preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: returned from preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (4) [preprocess] = ok Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: calling digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: returned from digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (4) [digest] = noop Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: calling suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (4) suffix: Checking for suffix after "@" Fri Jul 19 18:02:48 2019 : Debug: (4) suffix: Looking up realm "rocky*.de" for User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (4) suffix: No such realm "rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: returned from suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (4) [suffix] = noop Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (4) eap: Peer sent EAP Response (code 2) ID 4 length 6 Fri Jul 19 18:02:48 2019 : Debug: (4) eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (4) [eap] = updated Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: calling files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: returned from files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (4) [files] = noop Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: calling expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: returned from expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (4) [expiration] = noop Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: calling logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authorize]: returned from logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (4) [logintime] = noop Fri Jul 19 18:02:48 2019 : Debug: (4) } # authorize = updated Fri Jul 19 18:02:48 2019 : Debug: (4) Found Auth-Type = eap Fri Jul 19 18:02:48 2019 : Debug: (4) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (4) authenticate { Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authenticate]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (4) eap: Expiring EAP session with state 0x18f137d11bf53a02 Fri Jul 19 18:02:48 2019 : Debug: (4) eap: Finished EAP session with state 0x18f137d11bf53a02 Fri Jul 19 18:02:48 2019 : Debug: (4) eap: Previous EAP request found for state 0x18f137d11bf53a02, released from the list Fri Jul 19 18:02:48 2019 : Debug: (4) eap: Peer sent packet with method EAP TLS (13) Fri Jul 19 18:02:48 2019 : Debug: (4) eap: Calling submodule eap_tls to process data Fri Jul 19 18:02:48 2019 : Debug: (4) eap_tls: Continuing EAP-TLS Fri Jul 19 18:02:48 2019 : Debug: (4) eap_tls: Peer sent flags --- Fri Jul 19 18:02:48 2019 : Debug: (4) eap_tls: Peer ACKed our handshake fragment Fri Jul 19 18:02:48 2019 : Debug: (4) eap_tls: [eaptls verify] = request Fri Jul 19 18:02:48 2019 : Debug: (4) eap_tls: [eaptls process] = handled Fri Jul 19 18:02:48 2019 : Debug: (4) eap: Sending EAP Request (code 1) ID 5 length 1004 Fri Jul 19 18:02:48 2019 : Debug: (4) eap: EAP session adding &reply:State = 0x18f137d11cf43a02 Fri Jul 19 18:02:48 2019 : Debug: (4) modsingle[authenticate]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (4) [eap] = handled Fri Jul 19 18:02:48 2019 : Debug: (4) } # authenticate = handled Fri Jul 19 18:02:48 2019 : Debug: (4) Using Post-Auth-Type Challenge Fri Jul 19 18:02:48 2019 : Debug: (4) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (4) Challenge { ... } # empty sub-section is ignored Fri Jul 19 18:02:48 2019 : Debug: (4) session-state: Nothing to cache Fri Jul 19 18:02:48 2019 : Debug: (4) Sent Access-Challenge Id 19 from 10.0.3.11:1812 to 10.0.3.1:56782 length 0 Fri Jul 19 18:02:48 2019 : Debug: (4) EAP-Message = 0x010503ec0dc00000119b2f8fdc91b3006b300f0603551d130101ff040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e6f72672f6578616d706c655f63612e63726c300d06092a864886f70d01010b050003820201004d16e5940c9dadc1ff51f433f49ac669b7fda840ec7cc76fd160fddf8ee93da413d9b60d0a7d717ff1d650f830a3b007b43f0074b35f2e0519509030b8a1701082c6062aa79dd06b5929832183bff431a03f54d314f564ad4bcd601f690305dbabcdaf574c6cc1afc9c115ef1a8dc8775f210fa0022399862a93efd15f534937a9ef10a2fefcbccfbeffb4731b06498f7ee74204d012d0ec90c20fae0c8eacdc53889832ec4acdd65bdaa017c2b4883a619119ba24580b6340cf3767a2a0156061d897322f6f223867ef80b8ad5f6adfa008f3bf1335c86e8266e9c506505085920681fdf7375e7f33ca19867c1789a4d2fb9b837e70bb2bdb66dd40953319b9b96a80e833a080fef9 Fri Jul 19 18:02:48 2019 : Debug: (4) Message-Authenticator = 0x00000000000000000000000000000000 Fri Jul 19 18:02:48 2019 : Debug: (4) State = 0x18f137d11cf43a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (4) Finished request Fri Jul 19 18:02:48 2019 : Debug: Waking up in 4.8 seconds. Fri Jul 19 18:02:48 2019 : Debug: (5) Received Access-Request Id 20 from 10.0.3.1:56782 to 10.0.3.11:1812 length 197 Fri Jul 19 18:02:48 2019 : Debug: (5) User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (5) NAS-Port-Type = Virtual Fri Jul 19 18:02:48 2019 : Debug: (5) Service-Type = Framed-User Fri Jul 19 18:02:48 2019 : Debug: (5) NAS-Port = 4 Fri Jul 19 18:02:48 2019 : Debug: (5) NAS-Port-Id = "con-mobile" Fri Jul 19 18:02:48 2019 : Debug: (5) NAS-IP-Address = 10.0.1.22 Fri Jul 19 18:02:48 2019 : Debug: (5) Called-Station-Id = "10.0.1.22[4500]" Fri Jul 19 18:02:48 2019 : Debug: (5) Calling-Station-Id = "10.0.2.117[4500]" Fri Jul 19 18:02:48 2019 : Debug: (5) EAP-Message = 0x020500060d00 Fri Jul 19 18:02:48 2019 : Debug: (5) NAS-Identifier = "strongSwan" Fri Jul 19 18:02:48 2019 : Debug: (5) State = 0x18f137d11cf43a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (5) Message-Authenticator = 0x7198bf195f7c30cb97652dd482735e88 Fri Jul 19 18:02:48 2019 : Debug: (5) session-state: No cached attributes Fri Jul 19 18:02:48 2019 : Debug: (5) # Executing section authorize from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (5) authorize { Fri Jul 19 18:02:48 2019 : Debug: (5) policy filter_username { Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name) -> TRUE Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ / /) { Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ / /) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ /@[^@]*@/ ) { Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ /\.\./ ) { Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ /\.\./ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Fri Jul 19 18:02:48 2019 : Debug: (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ /\.$/) { Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ /\.$/) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ /@\./) { Fri Jul 19 18:02:48 2019 : Debug: (5) if (&User-Name =~ /@\./) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (5) } # if (&User-Name) = notfound Fri Jul 19 18:02:48 2019 : Debug: (5) } # policy filter_username = notfound Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: calling preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: returned from preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (5) [preprocess] = ok Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: calling digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: returned from digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (5) [digest] = noop Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: calling suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (5) suffix: Checking for suffix after "@" Fri Jul 19 18:02:48 2019 : Debug: (5) suffix: Looking up realm "rocky*.de" for User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (5) suffix: No such realm "rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: returned from suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (5) [suffix] = noop Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (5) eap: Peer sent EAP Response (code 2) ID 5 length 6 Fri Jul 19 18:02:48 2019 : Debug: (5) eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (5) [eap] = updated Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: calling files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: returned from files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (5) [files] = noop Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: calling expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: returned from expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (5) [expiration] = noop Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: calling logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authorize]: returned from logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (5) [logintime] = noop Fri Jul 19 18:02:48 2019 : Debug: (5) } # authorize = updated Fri Jul 19 18:02:48 2019 : Debug: (5) Found Auth-Type = eap Fri Jul 19 18:02:48 2019 : Debug: (5) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (5) authenticate { Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authenticate]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (5) eap: Expiring EAP session with state 0x18f137d11cf43a02 Fri Jul 19 18:02:48 2019 : Debug: (5) eap: Finished EAP session with state 0x18f137d11cf43a02 Fri Jul 19 18:02:48 2019 : Debug: (5) eap: Previous EAP request found for state 0x18f137d11cf43a02, released from the list Fri Jul 19 18:02:48 2019 : Debug: (5) eap: Peer sent packet with method EAP TLS (13) Fri Jul 19 18:02:48 2019 : Debug: (5) eap: Calling submodule eap_tls to process data Fri Jul 19 18:02:48 2019 : Debug: (5) eap_tls: Continuing EAP-TLS Fri Jul 19 18:02:48 2019 : Debug: (5) eap_tls: Peer sent flags --- Fri Jul 19 18:02:48 2019 : Debug: (5) eap_tls: Peer ACKed our handshake fragment Fri Jul 19 18:02:48 2019 : Debug: (5) eap_tls: [eaptls verify] = request Fri Jul 19 18:02:48 2019 : Debug: (5) eap_tls: [eaptls process] = handled Fri Jul 19 18:02:48 2019 : Debug: (5) eap: Sending EAP Request (code 1) ID 6 length 541 Fri Jul 19 18:02:48 2019 : Debug: (5) eap: EAP session adding &reply:State = 0x18f137d11df73a02 Fri Jul 19 18:02:48 2019 : Debug: (5) modsingle[authenticate]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (5) [eap] = handled Fri Jul 19 18:02:48 2019 : Debug: (5) } # authenticate = handled Fri Jul 19 18:02:48 2019 : Debug: (5) Using Post-Auth-Type Challenge Fri Jul 19 18:02:48 2019 : Debug: (5) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (5) Challenge { ... } # empty sub-section is ignored Fri Jul 19 18:02:48 2019 : Debug: (5) session-state: Nothing to cache Fri Jul 19 18:02:48 2019 : Debug: (5) Sent Access-Challenge Id 20 from 10.0.3.11:1812 to 10.0.3.1:56782 length 0 Fri Jul 19 18:02:48 2019 : Debug: (5) EAP-Message = 0x0106021d0d800000119b9adba496734e849d9863d26a28d2027ae01475530c24624a15dd68389e6e9f7a02acc3260888db223770594391fd128de23f6bb86177f66a885dea6287d4701aba0da103bb78e0e04b278520053288f4e746011741f4c9e06db726b7ac422226fe94679eccf1c28a094707bfc2882c7f42f4c8e0bc4c1d45d0a8e26dc5fdf67e0460c59d3de5de18c35e8888fe345ad4afcce58eca91df63e4fff6f711577d29aeb210a9e695917839e23645c8aa7cb75322ca3e12e9af64b49fc4faabe273f31307b2ef5709f776d213da595728113dc22d5c01eb9b80265f55fbab4ee7025e61c8e52f6945d3b2ff18e2fab149e70dba051745b1c41d35c4a431b97c6d259887f164b5f4403d6e556e5c04f1c901d077b841432e8a16cd16030300ed0d0000e903010240002e040305030603080708080809080a080b08040805080604010501060103030203030102010302020204020502060200b300b13081ae310b3009060355040613024445311f301d Fri Jul 19 18:02:48 2019 : Debug: (5) Message-Authenticator = 0x00000000000000000000000000000000 Fri Jul 19 18:02:48 2019 : Debug: (5) State = 0x18f137d11df73a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (5) Finished request Fri Jul 19 18:02:48 2019 : Debug: Waking up in 4.8 seconds.
-
My external Radius Server has been a bit more informational...
EXTERNAL RADIUS LOGS (Part 3/last)
Fri Jul 19 18:02:48 2019 : Debug: (6) Received Access-Request Id 21 from 10.0.3.1:56782 to 10.0.3.11:1812 length 208 Fri Jul 19 18:02:48 2019 : Debug: (6) User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (6) NAS-Port-Type = Virtual Fri Jul 19 18:02:48 2019 : Debug: (6) Service-Type = Framed-User Fri Jul 19 18:02:48 2019 : Debug: (6) NAS-Port = 4 Fri Jul 19 18:02:48 2019 : Debug: (6) NAS-Port-Id = "con-mobile" Fri Jul 19 18:02:48 2019 : Debug: (6) NAS-IP-Address = 10.0.1.22 Fri Jul 19 18:02:48 2019 : Debug: (6) Called-Station-Id = "10.0.1.22[4500]" Fri Jul 19 18:02:48 2019 : Debug: (6) Calling-Station-Id = "10.0.2.117[4500]" Fri Jul 19 18:02:48 2019 : Debug: (6) EAP-Message = 0x020600110d800000000715030300020100 Fri Jul 19 18:02:48 2019 : Debug: (6) NAS-Identifier = "strongSwan" Fri Jul 19 18:02:48 2019 : Debug: (6) State = 0x18f137d11df73a027808058e4222834c Fri Jul 19 18:02:48 2019 : Debug: (6) Message-Authenticator = 0x29344c814a088797548f4f9e2bdafebf Fri Jul 19 18:02:48 2019 : Debug: (6) session-state: No cached attributes Fri Jul 19 18:02:48 2019 : Debug: (6) # Executing section authorize from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (6) authorize { Fri Jul 19 18:02:48 2019 : Debug: (6) policy filter_username { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name) -> TRUE Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name) { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ / /) { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ / /) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ /@[^@]*@/ ) { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ /\.\./ ) { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ /\.\./ ) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Fri Jul 19 18:02:48 2019 : Debug: (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ /\.$/) { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ /\.$/) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ /@\./) { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&User-Name =~ /@\./) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (6) } # if (&User-Name) = notfound Fri Jul 19 18:02:48 2019 : Debug: (6) } # policy filter_username = notfound Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: calling preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: returned from preprocess (rlm_preprocess) Fri Jul 19 18:02:48 2019 : Debug: (6) [preprocess] = ok Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: calling digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: returned from digest (rlm_digest) Fri Jul 19 18:02:48 2019 : Debug: (6) [digest] = noop Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: calling suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (6) suffix: Checking for suffix after "@" Fri Jul 19 18:02:48 2019 : Debug: (6) suffix: Looking up realm "rocky*.de" for User-Name = "c4-b3-01-d9-4e-6b.v2@rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (6) suffix: No such realm "rocky*.de" Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: returned from suffix (rlm_realm) Fri Jul 19 18:02:48 2019 : Debug: (6) [suffix] = noop Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Peer sent EAP Response (code 2) ID 6 length 17 Fri Jul 19 18:02:48 2019 : Debug: (6) eap: No EAP Start, assuming it's an on-going EAP conversation Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (6) [eap] = updated Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: calling files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: returned from files (rlm_files) Fri Jul 19 18:02:48 2019 : Debug: (6) [files] = noop Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: calling expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: returned from expiration (rlm_expiration) Fri Jul 19 18:02:48 2019 : Debug: (6) [expiration] = noop Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: calling logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authorize]: returned from logintime (rlm_logintime) Fri Jul 19 18:02:48 2019 : Debug: (6) [logintime] = noop Fri Jul 19 18:02:48 2019 : Debug: (6) } # authorize = updated Fri Jul 19 18:02:48 2019 : Debug: (6) Found Auth-Type = eap Fri Jul 19 18:02:48 2019 : Debug: (6) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (6) authenticate { Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authenticate]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Expiring EAP session with state 0x18f137d11df73a02 Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Finished EAP session with state 0x18f137d11df73a02 Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Previous EAP request found for state 0x18f137d11df73a02, released from the list Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Peer sent packet with method EAP TLS (13) Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Calling submodule eap_tls to process data Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: Continuing EAP-TLS Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: Peer sent flags --L Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: Peer indicated complete TLS record size will be 7 bytes Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: Got complete TLS record (7 bytes) Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: [eaptls verify] = length included Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: <<< recv TLS 1.2 [length 0002] Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: TLS_accept: Need to read more data: SSLv3/TLS write server done Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: TLS - In Handshake Phase Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: TLS - Application data. Fri Jul 19 18:02:48 2019 : ERROR: (6) eap_tls: TLS failed during operation Fri Jul 19 18:02:48 2019 : ERROR: (6) eap_tls: [eaptls process] = fail Fri Jul 19 18:02:48 2019 : Debug: tls: Removing session 7269671d2024f798db208987e944259582f95ddad1fd079609b4e93543d536ba from the cache Fri Jul 19 18:02:48 2019 : Debug: tls: Could not remove persisted session file /var/lib/radiusd/tlscache/7269671d2024f798db208987e944259582f95ddad1fd079609b4e93543d536ba.asn1: No such file or directory Fri Jul 19 18:02:48 2019 : ERROR: (6) eap: Failed continuing EAP TLS (13) session. EAP sub-module failed Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Sending EAP Failure (code 4) ID 6 length 4 Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Failed in EAP select Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[authenticate]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (6) [eap] = invalid Fri Jul 19 18:02:48 2019 : Debug: (6) } # authenticate = invalid Fri Jul 19 18:02:48 2019 : Debug: (6) Failed to authenticate the user Fri Jul 19 18:02:48 2019 : Debug: (6) Using Post-Auth-Type Reject Fri Jul 19 18:02:48 2019 : Debug: (6) # Executing group from file /etc/raddb/sites-enabled/default Fri Jul 19 18:02:48 2019 : Debug: (6) Post-Auth-Type REJECT { Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) Fri Jul 19 18:02:48 2019 : Debug: %{User-Name} Fri Jul 19 18:02:48 2019 : Debug: Parsed xlat tree: Fri Jul 19 18:02:48 2019 : Debug: attribute --> User-Name Fri Jul 19 18:02:48 2019 : Debug: (6) attr_filter.access_reject: EXPAND %{User-Name} Fri Jul 19 18:02:48 2019 : Debug: (6) attr_filter.access_reject: --> c4-b3-01-d9-4e-6b.v2@rocky*.de Fri Jul 19 18:02:48 2019 : Debug: (6) attr_filter.access_reject: Matched entry DEFAULT at line 11 Fri Jul 19 18:02:48 2019 : Debug: (6) attr_filter.access_reject: EAP-Message = 0x04060004 allowed by EAP-Message =* 0x Fri Jul 19 18:02:48 2019 : Debug: (6) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules Fri Jul 19 18:02:48 2019 : Debug: (6) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x Fri Jul 19 18:02:48 2019 : Debug: (6) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) Fri Jul 19 18:02:48 2019 : Debug: (6) [attr_filter.access_reject] = updated Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[post-auth]: calling eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (6) eap: Reply already contained an EAP-Message, not inserting EAP-Failure Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[post-auth]: returned from eap (rlm_eap) Fri Jul 19 18:02:48 2019 : Debug: (6) [eap] = noop Fri Jul 19 18:02:48 2019 : Debug: (6) policy remove_reply_message_if_eap { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&reply:EAP-Message && &reply:Reply-Message) { Fri Jul 19 18:02:48 2019 : Debug: (6) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Fri Jul 19 18:02:48 2019 : Debug: (6) else { Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[post-auth]: calling noop (rlm_always) Fri Jul 19 18:02:48 2019 : Debug: (6) modsingle[post-auth]: returned from noop (rlm_always) Fri Jul 19 18:02:48 2019 : Debug: (6) [noop] = noop Fri Jul 19 18:02:48 2019 : Debug: (6) } # else = noop Fri Jul 19 18:02:48 2019 : Debug: (6) } # policy remove_reply_message_if_eap = noop Fri Jul 19 18:02:48 2019 : Debug: (6) } # Post-Auth-Type REJECT = updated Fri Jul 19 18:02:48 2019 : Auth: (6) Login incorrect (eap_tls: TLS failed during operation): [c4-b3-01-d9-4e-6b.v2@rocky*.de/<via Auth-Type = eap>] (from client RockyMountains port 4 cli 10.0.2.117[4500]) Fri Jul 19 18:02:48 2019 : Debug: (6) Delaying response for 1.000000 seconds Fri Jul 19 18:02:48 2019 : Debug: Waking up in 0.6 seconds. Fri Jul 19 18:02:49 2019 : Debug: Waking up in 0.3 seconds. Fri Jul 19 18:02:49 2019 : Debug: (6) Sending delayed response Fri Jul 19 18:02:49 2019 : Debug: (6) Sent Access-Reject Id 21 from 10.0.3.11:1812 to 10.0.3.1:56782 length 44 Fri Jul 19 18:02:49 2019 : Debug: (6) EAP-Message = 0x04060004 Fri Jul 19 18:02:49 2019 : Debug: (6) Message-Authenticator = 0x00000000000000000000000000000000 Fri Jul 19 18:02:49 2019 : Debug: Waking up in 3.8 seconds.
-
Hey
As far as I see , the problem at you begins in this place of an exchange of messages , for some reason the client does not transfer the certificate to the server.
Pay attention to the size of the message.Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: Peer indicated complete TLS record size will be 7 bytes Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: Got complete TLS record (7 bytes) Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: [eaptls verify] = length included Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: <<< recv TLS 1.2 [length 0002] Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: TLS_accept: Need to read more data: SSLv3/TLS write server done Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: TLS - In Handshake Phase Fri Jul 19 18:02:48 2019 : Debug: (6) eap_tls: TLS - Application data. Fri Jul 19 18:02:48 2019 : ERROR: (6) eap_tls: TLS failed during operation Fri Jul 19 18:02:48 2019 : ERROR: (6) eap_tls: [eaptls process] = fail
Here's what this part of messaging looks like on my server
(3) eap_tls: Peer indicated complete TLS record size will be 767 bytes (3) eap_tls: Got complete TLS record (767 bytes) (3) eap_tls: [eaptls verify] = length included (3) eap_tls: <<< recv TLS 1.2 [length 0208] (3) eap_tls: Creating attributes from certificate OIDs (3) eap_tls: TLS-Cert-Serial := "YYYYYYYYYYYYYYYY" (3) eap_tls: TLS-Cert-Expiration := "210102174407Z" (3) eap_tls: TLS-Cert-Subject := "/C=XXX/O=XXXXX/CN=XXXX.XXXX.org" (3) eap_tls: TLS-Cert-Issuer := "/C=XXX/O=MXXXX/CN=XXXXXXXXXX" (3) eap_tls: TLS-Cert-Common-Name := "XXXX.XXXXX.org"
-
Hey Konstanti,
thanks for your reply :)
Yes, things look like the vpn client or strongswan stops the communication. Possibly because one of them doesn't trust the radius server. But none of their logs indicata a reason :/
Is there a more verbose ikev2 client I could try on MacOS?
For testing purpose I modified Radius, added a virtual_server using a new eap modul instance (eap_ikev2). eap_ike2 uses the strongswan certificate. As expected things work well then :/
RADIUS
(...) (1) eap_tls: Peer indicated complete TLS record size will be 151 bytes (1) eap_tls: Got complete TLS record (151 bytes) (1) eap_tls: [eaptls verify] = length included (1) eap_tls: (other): before SSL initialization (1) eap_tls: TLS_accept: before SSL initialization (1) eap_tls: TLS_accept: before SSL initialization (1) eap_tls: <<< recv TLS 1.3 [length 0092] (...) (10) eap_tls: <<< recv TLS 1.2 [length 0d37] (10) eap_tls: TLS - Creating attributes from certificate OIDs (10) eap_tls: TLS-Cert-Serial := "0b49247a7915c706a5a259bdcd2f8fdc91b3006b" (10) eap_tls: TLS-Cert-Expiration := "390217003004Z" (10) eap_tls: TLS-Cert-Subject := "/C=DE/ST=region/L=city/O=Rocky*/emailAddress=admin@example.org/CN=Rocky* Certificate Authority" (10) eap_tls: TLS-Cert-Issuer := "/C=DE/ST=region/L=city/O=Rocky*/emailAddress=admin@example.org/CN=Rocky* Certificate Authority" (10) eap_tls: TLS-Cert-Common-Name := "Rocky* Certificate Authority" (...)
[0_1563890595347_20190723_radius_ok.log](Lade 100% hoch) Please finde the complete log attached.
STRONGSWAN
Jul 23 15:17:44 charon 11[CFG] <con-mobile|36> lease 10.0.4.1 by 'c4-b3-01-d9-4e-6b.v2@rocky*.de' went offline Jul 23 15:17:44 charon 11[CHD] <con-mobile|36> CHILD_SA con-mobile{19} state change: INSTALLED => DESTROYING Jul 23 15:17:44 charon 11[IKE] <con-mobile|36> IKE_SA con-mobile[36] state change: DELETING => DESTROYING Jul 23 15:17:44 charon 11[NET] <con-mobile|36> sending packet: from 10.0.1.22[4500] to 91.224.227.248[8488] (80 bytes) Jul 23 15:17:44 charon 11[ENC] <con-mobile|36> generating INFORMATIONAL response 33 [ ] Jul 23 15:17:44 charon 11[CFG] <con-mobile|36> received RADIUS Accounting-Response from server 'radius01' Jul 23 15:17:44 charon 11[CFG] <con-mobile|36> sending RADIUS Accounting-Request to server 'radius01' Jul 23 15:17:44 charon 11[CFG] <con-mobile|36> RADIUS server 'radius01' is candidate: 210 Jul 23 15:17:44 charon 11[IKE] <con-mobile|36> IKE_SA deleted Jul 23 15:17:44 charon 11[IKE] <con-mobile|36> IKE_SA con-mobile[36] state change: ESTABLISHED => DELETING Jul 23 15:17:44 charon 11[IKE] <con-mobile|36> deleting IKE_SA con-mobile[36] between 10.0.1.22[vpn.*.de]...91.224.227.248[c4-b3-01-d9-4e-6b.v2@rocky*.de] Jul 23 15:17:44 charon 11[IKE] <con-mobile|36> received DELETE for IKE_SA con-mobile[36] Jul 23 15:17:44 charon 11[ENC] <con-mobile|36> parsed INFORMATIONAL request 33 [ D ] Jul 23 15:17:44 charon 11[NET] <con-mobile|36> received packet: from 91.224.227.248[8488] to 10.0.1.22[4500] (80 bytes) Jul 23 15:17:44 charon 11[IKE] <con-mobile|36> nothing to initiate Jul 23 15:17:44 charon 11[IKE] <con-mobile|36> activating new tasks Jul 23 15:17:44 charon 11[ENC] <con-mobile|36> parsed INFORMATIONAL response 1 [ ] Jul 23 15:17:44 charon 11[NET] <con-mobile|36> received packet: from 91.224.227.248[8488] to 10.0.1.22[4500] (80 bytes) Jul 23 15:17:44 charon 09[NET] <con-mobile|36> sending packet: from 10.0.1.22[4500] to 91.224.227.248[8488] (80 bytes) Jul 23 15:17:44 charon 09[ENC] <con-mobile|36> generating CREATE_CHILD_SA response 32 [ N(NO_PROP) ] Jul 23 15:17:44 charon 09[CHD] <con-mobile|36> CHILD_SA con-mobile{20} state change: CREATED => DESTROYING Jul 23 15:17:44 charon 09[CHD] <con-mobile|36> CHILD_SA con-mobile{19} state change: REKEYING => INSTALLED Jul 23 15:17:44 charon 09[CHD] <con-mobile|36> CHILD_SA con-mobile{19} state change: INSTALLED => REKEYING Jul 23 15:17:44 charon 09[IKE] <con-mobile|36> failed to establish CHILD_SA, keeping IKE_SA Jul 23 15:17:44 charon 09[IKE] <con-mobile|36> no acceptable proposal found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> configured proposals: ESP:AES_CBC_256/HMAC_SHA2_256_128/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_384_192/MODP_2048/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_512_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_16_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_16_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_16_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_12_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_12_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_12_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_8_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_8_256/MODP_2048/NO_EXT_SEQ, ESP:AES_GCM_8_256/MODP_2048/NO_EXT_SEQ Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> received proposals: ESP:AES_CBC_256/HMAC_SHA2_256_128/NO_EXT_SEQ Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable ENCRYPTION_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable INTEGRITY_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable INTEGRITY_ALGORITHM found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> no acceptable DIFFIE_HELLMAN_GROUP found Jul 23 15:17:44 charon 09[CFG] <con-mobile|36> selecting proposal: Jul 23 15:17:44 charon 09[ENC] <con-mobile|36> parsed CREATE_CHILD_SA request 32 [ N(REKEY_SA) SA No TSi TSr ] Jul 23 15:17:44 charon 09[NET] <con-mobile|36> received packet: from 91.224.227.248[8488] to 10.0.1.22[4500] (192 bytes) Jul 23 15:17:44 charon 09[NET] <con-mobile|36> sending packet: from 10.0.1.22[4500] to 91.224.227.248[8488] (80 bytes) Jul 23 15:17:44 charon 09[ENC] <con-mobile|36> generating INFORMATIONAL request 1 [ ] Jul 23 15:17:44 charon 09[IKE] <con-mobile|36> activating IKE_DPD task Jul 23 15:17:44 charon 09[IKE] <con-mobile|36> activating new tasks Jul 23 15:17:44 charon 09[IKE] <con-mobile|36> queueing IKE_DPD task Jul 23 15:17:44 charon 09[IKE] <con-mobile|36> sending DPD request
Can I server any othe helpfull information?
Marti
-
My opinion - problem with Mac OS + strongswan
Strongswan android client + strongswan log connection
(3) eap: Calling submodule eap_tls to process data (3) eap_tls: Continuing EAP-TLS (3) eap_tls: Peer indicated complete TLS record size will be 774 bytes (3) eap_tls: Got complete TLS record (774 bytes) (3) eap_tls: [eaptls verify] = length included (3) eap_tls: <<< recv TLS 1.2 [length 0202]
and
Mac OS client + strongswan log connection8) eap: Calling submodule eap_tls to process data (8) eap_tls: Continuing EAP-TLS (8) eap_tls: Peer indicated complete TLS record size will be 7 bytes (8) eap_tls: Got complete TLS record (7 bytes) (8) eap_tls: [eaptls verify] = length included (8) eap_tls: <<< recv TLS 1.2 [length 0002] (8) eap_tls: ERROR: TLS_accept: Failed in SSLv3 read client certificate A (8) eap_tls: ERROR: Failed in __FUNCTION__ (SSL_read): error:140940E5:SSL routines:ssl3_read_bytes:ssl handshake failure (8) eap_tls: ERROR: System call (I/O) error (-1) (8) eap_tls: ERROR: TLS receive handshake failed during operation (8) eap_tls: ERROR: [eaptls process] = fail (8) eap: ERROR: Failed continuing EAP TLS (13) session. EAP sub-module failed (8) eap: Sending EAP Failure (code 4) ID 3 length 4
-
I see your point.... I had "System call (I/O) error (-1)", too.
But when I use the same Radius server for WIFI EAP-TLS everything works great with MacOs. So there must be something else.
I googled this and am going to try it next...
The app does not send certificate requests. So unless the gateway's certificate is installed in the client's Keychain the server has to be configured with leftsendcert=always, otherwise, the client won't have the gateway's certificate available causing the authentication to fail.
[https://wiki.strongswan.org/projects/strongswan/wiki/MacOSX](Link Adresse)Marti
-
Hmmm.
I was able to connect using a native MacOS clientI filled out field Server Certificate Issuer in VPN profile (Apple Configurator 2)
I re-installed the profile
and(4) Login OK: [macbookpro2015.xxxxxx.org/<via Auth-Type = eap>] (from client xx.xxxxxxxx.org port 12 cli XXXX XXXX.XXX[56951]) (4) Sent Access-Accept Id 125 from 192.168.1.1:1812 to 10.10.100.2:47956 length 0 (4) MS-MPPE-Recv-Key = 0x102 (4) MS-MPPE-Send-Key = 0x77 (4) EAP-Message = 0x03040004 (4) Message-Authenticator = 0x00000000000000000000000000000000 (4) User-Name = "macbookpro2015.xxxxxxxxxx.org"
-
That's it!
It's the most important part of the whole Tutorial, which got lost just between the lines :/
In my case I had to enter "Rocky*** Certificate Authority".
@Konstanti: Thank you sooo much for your help! And I'm so sorry for asking such stupid questions :/
At least I know another possible way, I can setup my ikev2 without having to setup profiles
Marti