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.
    


  • @MartiMcFly

    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

    20190723_radius_ok.txt



  • @MartiMcFly

    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 connection

    8) 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



  • @MartiMcFly

    Hmmm.
    I was able to connect using a native MacOS client

    I filled out field Server Certificate Issuer in VPN profile (Apple Configurator 2)

    9bd94bcb-dc6f-4d34-b636-ad4f5169efdc-image.png

    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".

    Bildschirmfoto 2019-07-23 um 19.16.46.png

    @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


Log in to reply