Strange things with android phone
I have configured and working wifi with eap-tls authentication. I want to use another root ca, so I did the following steps. openssl genrsa -aes256 -out private/wifi,beta,ca.key 4096 openssl req -new -out cacerts/wifi,beta,ca.pem -subj "/C=PL/ST=Mazowieckie/L=Warszawa/O=beta/OU=wifi/CN=beta-wifi-ca/emailAddress=kjonca@poczta.onet.pl" -x509 -days 3650 -extensions v3_ca -key private/wifi,beta,ca.key openssl req -new -out req.csr -subj "/C=PL/ST=Mazowieckie/O=beta/OU=beta.kjonca/CN=selen.kjonca" -key ../private/selen.kjonca.1.key #this is phone key openssl ca -in req.csr -cert cacerts/wifi,beta,ca.pem -keyfile private/wifi,beta,ca.key -extensions xpclient_ext -extfile ../xp.ext -out certs/wifi,selen,1.pem openssl x509 -x509toreq -in certs/wifi,beta-wifi-beta,2,1.pem -out req.csr -signkey private/wifi,beta-wifi-beta,2.key #this is key for freeradius instance openssl ca -in req.csr -cert cacerts/wifi,beta,ca.pem -keyfile private/wifi,beta,ca.key -out certs/wifi,beta-wifi-beta,2.5.pem openssl pkcs12 -export -certfile cacerts/wifi,beta,ca.pem -in certs/wifi,selen,1.pem -inkey ../private/selen.kjonca.1.key -out wifi,selen.p12 Then *.p12 file was sent to phone and imported into cert store. And strange things happen: When "CA cert" field in wifi network definition is set then phone can't connect. When is empty - eweything works. Here some logs. 12:02:28 2015 : Info: Cleaning up request 83 ID 240 with timestamp +1556 Sat Aug 22 12:02:28 2015 : Info: Cleaning up request 84 ID 241 with timestamp +1556 Sat Aug 22 12:02:28 2015 : Info: Cleaning up request 85 ID 242 with timestamp +1556 Sat Aug 22 12:02:28 2015 : Info: Cleaning up request 86 ID 243 with timestamp +1556 Sat Aug 22 12:02:28 2015 : Info: Cleaning up request 87 ID 244 with timestamp +1556 Sat Aug 22 12:02:28 2015 : Info: Cleaning up request 88 ID 245 with timestamp +1556 Sat Aug 22 12:02:28 2015 : Info: Ready to process requests. Sat Aug 22 12:04:43 2015 : Debug: Thread 5 got semaphore Sat Aug 22 12:04:43 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:04:43 2015 : Debug: Thread 5 handling request 89, (18 handled so far) Sat Aug 22 12:04:43 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:43 2015 : Info: +group authorize { Sat Aug 22 12:04:43 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:04:43 2015 : Info: ++[chap] = noop Sat Aug 22 12:04:43 2015 : Info: ++[mschap] = noop Sat Aug 22 12:04:43 2015 : Info: ++[digest] = noop Sat Aug 22 12:04:43 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:04:43 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:04:43 2015 : Info: ++[suffix] = noop Sat Aug 22 12:04:43 2015 : Info: [eap] EAP packet type response id 154 length 17 Sat Aug 22 12:04:43 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:04:43 2015 : Info: ++[eap] = updated Sat Aug 22 12:04:43 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:04:43 2015 : Info: ++[files] = ok Sat Aug 22 12:04:43 2015 : Info: ++[expiration] = noop Sat Aug 22 12:04:43 2015 : Info: ++[logintime] = noop Sat Aug 22 12:04:43 2015 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this. Sat Aug 22 12:04:43 2015 : Info: ++[pap] = noop Sat Aug 22 12:04:43 2015 : Info: +} # group authorize = updated Sat Aug 22 12:04:43 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:04:43 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:43 2015 : Info: +group authenticate { Sat Aug 22 12:04:43 2015 : Info: [eap] EAP Identity Sat Aug 22 12:04:43 2015 : Info: [eap] processing type tls Sat Aug 22 12:04:43 2015 : Info: [tls] Requiring client certificate Sat Aug 22 12:04:43 2015 : Info: [tls] Initiate Sat Aug 22 12:04:43 2015 : Info: [tls] Start returned 1 Sat Aug 22 12:04:43 2015 : Info: ++[eap] = handled Sat Aug 22 12:04:43 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:04:43 2015 : Info: Finished request 89. Sat Aug 22 12:04:43 2015 : Debug: Going to the next request Sat Aug 22 12:04:43 2015 : Debug: Thread 5 waiting to be assigned a request Sat Aug 22 12:04:43 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:04:43 2015 : Debug: Thread 3 got semaphore Sat Aug 22 12:04:43 2015 : Debug: Thread 3 handling request 90, (19 handled so far) Sat Aug 22 12:04:43 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:43 2015 : Info: +group authorize { Sat Aug 22 12:04:43 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:04:43 2015 : Info: ++[chap] = noop Sat Aug 22 12:04:43 2015 : Info: ++[mschap] = noop Sat Aug 22 12:04:43 2015 : Info: ++[digest] = noop Sat Aug 22 12:04:43 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:04:43 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:04:43 2015 : Info: ++[suffix] = noop Sat Aug 22 12:04:43 2015 : Info: [eap] EAP packet type response id 155 length 204 Sat Aug 22 12:04:43 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:04:43 2015 : Info: ++[eap] = updated Sat Aug 22 12:04:43 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:04:43 2015 : Info: ++[files] = ok Sat Aug 22 12:04:43 2015 : Info: ++[expiration] = noop Sat Aug 22 12:04:43 2015 : Info: ++[logintime] = noop Sat Aug 22 12:04:43 2015 : Info: ++[pap] = noop Sat Aug 22 12:04:43 2015 : Info: +} # group authorize = updated Sat Aug 22 12:04:43 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:04:43 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:43 2015 : Info: +group authenticate { Sat Aug 22 12:04:43 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:04:43 2015 : Info: [eap] EAP/tls Sat Aug 22 12:04:43 2015 : Info: [eap] processing type tls Sat Aug 22 12:04:43 2015 : Info: [tls] Authenticate Sat Aug 22 12:04:43 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:04:43 2015 : Info: [tls] eaptls_verify returned 7 Sat Aug 22 12:04:43 2015 : Info: [tls] Done initial handshake Sat Aug 22 12:04:43 2015 : Info: [tls] (other): before/accept initialization Sat Aug 22 12:04:43 2015 : Info: [tls] TLS_accept: before/accept initialization Sat Aug 22 12:04:43 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:04:43 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 00c1], ClientHello Sat Aug 22 12:04:43 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:43 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:04:43 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0039], ServerHello Sat Aug 22 12:04:43 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:43 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:04:43 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0695], Certificate Sat Aug 22 12:04:43 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:43 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:04:43 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 00cb], ServerKeyExchange Sat Aug 22 12:04:43 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:43 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:04:43 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 000e], CertificateRequest Sat Aug 22 12:04:43 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:43 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:43 2015 : Info: [tls] TLS_accept: Need to read more data: unknown state Sat Aug 22 12:04:43 2015 : Debug: In SSL Handshake Phase Sat Aug 22 12:04:43 2015 : Debug: In SSL Accept mode Sat Aug 22 12:04:43 2015 : Info: [tls] eaptls_process returned 13 Sat Aug 22 12:04:43 2015 : Info: ++[eap] = handled Sat Aug 22 12:04:43 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:04:43 2015 : Info: Finished request 90. Sat Aug 22 12:04:43 2015 : Debug: Going to the next request Sat Aug 22 12:04:43 2015 : Debug: Thread 3 waiting to be assigned a request Sat Aug 22 12:04:43 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:04:43 2015 : Debug: Thread 4 got semaphore Sat Aug 22 12:04:43 2015 : Debug: Thread 4 handling request 91, (19 handled so far) Sat Aug 22 12:04:43 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:43 2015 : Info: +group authorize { Sat Aug 22 12:04:43 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:04:43 2015 : Info: ++[chap] = noop Sat Aug 22 12:04:43 2015 : Info: ++[mschap] = noop Sat Aug 22 12:04:43 2015 : Info: ++[digest] = noop Sat Aug 22 12:04:43 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:04:43 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:04:43 2015 : Info: ++[suffix] = noop Sat Aug 22 12:04:43 2015 : Info: [eap] EAP packet type response id 156 length 6 Sat Aug 22 12:04:43 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:04:43 2015 : Info: ++[eap] = updated Sat Aug 22 12:04:43 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:04:43 2015 : Info: ++[files] = ok Sat Aug 22 12:04:43 2015 : Info: ++[expiration] = noop Sat Aug 22 12:04:43 2015 : Info: ++[logintime] = noop Sat Aug 22 12:04:43 2015 : Info: ++[pap] = noop Sat Aug 22 12:04:43 2015 : Info: +} # group authorize = updated Sat Aug 22 12:04:43 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:04:43 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:43 2015 : Info: +group authenticate { Sat Aug 22 12:04:43 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:04:43 2015 : Info: [eap] EAP/tls Sat Aug 22 12:04:43 2015 : Info: [eap] processing type tls Sat Aug 22 12:04:43 2015 : Info: [tls] Authenticate Sat Aug 22 12:04:43 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:04:43 2015 : Info: [tls] Received TLS ACK Sat Aug 22 12:04:43 2015 : Info: [tls] ACK handshake fragment handler Sat Aug 22 12:04:43 2015 : Info: [tls] eaptls_verify returned 1 Sat Aug 22 12:04:43 2015 : Info: [tls] eaptls_process returned 13 Sat Aug 22 12:04:43 2015 : Info: ++[eap] = handled Sat Aug 22 12:04:43 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:04:43 2015 : Info: Finished request 91. Sat Aug 22 12:04:43 2015 : Debug: Going to the next request Sat Aug 22 12:04:43 2015 : Debug: Thread 4 waiting to be assigned a request Sat Aug 22 12:04:44 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:04:44 2015 : Debug: Thread 1 got semaphore Sat Aug 22 12:04:44 2015 : Debug: Thread 1 handling request 92, (19 handled so far) Sat Aug 22 12:04:44 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:44 2015 : Info: +group authorize { Sat Aug 22 12:04:44 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:04:44 2015 : Info: ++[chap] = noop Sat Aug 22 12:04:44 2015 : Info: ++[mschap] = noop Sat Aug 22 12:04:44 2015 : Info: ++[digest] = noop Sat Aug 22 12:04:44 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:04:44 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:04:44 2015 : Info: ++[suffix] = noop Sat Aug 22 12:04:44 2015 : Info: [eap] EAP packet type response id 157 length 253 Sat Aug 22 12:04:44 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:04:44 2015 : Info: ++[eap] = updated Sat Aug 22 12:04:44 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:04:44 2015 : Info: ++[files] = ok Sat Aug 22 12:04:44 2015 : Info: ++[expiration] = noop Sat Aug 22 12:04:44 2015 : Info: ++[logintime] = noop Sat Aug 22 12:04:44 2015 : Info: ++[pap] = noop Sat Aug 22 12:04:44 2015 : Info: +} # group authorize = updated Sat Aug 22 12:04:44 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:04:44 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:44 2015 : Info: +group authenticate { Sat Aug 22 12:04:44 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:04:44 2015 : Info: [eap] EAP/tls Sat Aug 22 12:04:44 2015 : Info: [eap] processing type tls Sat Aug 22 12:04:44 2015 : Info: [tls] Authenticate Sat Aug 22 12:04:44 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:04:44 2015 : Debug: TLS Length 1577 Sat Aug 22 12:04:44 2015 : Info: [tls] Received EAP-TLS First Fragment of the message Sat Aug 22 12:04:44 2015 : Info: [tls] eaptls_verify returned 9 Sat Aug 22 12:04:44 2015 : Info: [tls] eaptls_process returned 13 Sat Aug 22 12:04:44 2015 : Info: ++[eap] = handled Sat Aug 22 12:04:44 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:04:44 2015 : Info: Finished request 92. Sat Aug 22 12:04:44 2015 : Debug: Going to the next request Sat Aug 22 12:04:44 2015 : Debug: Thread 1 waiting to be assigned a request Sat Aug 22 12:04:44 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:04:44 2015 : Debug: Thread 2 got semaphore Sat Aug 22 12:04:44 2015 : Debug: Thread 2 handling request 93, (19 handled so far) Sat Aug 22 12:04:44 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:44 2015 : Info: +group authorize { Sat Aug 22 12:04:44 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:04:44 2015 : Info: ++[chap] = noop Sat Aug 22 12:04:44 2015 : Info: ++[mschap] = noop Sat Aug 22 12:04:44 2015 : Info: ++[digest] = noop Sat Aug 22 12:04:44 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:04:44 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:04:44 2015 : Info: ++[suffix] = noop Sat Aug 22 12:04:44 2015 : Info: [eap] EAP packet type response id 158 length 185 Sat Aug 22 12:04:44 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:04:44 2015 : Info: ++[eap] = updated Sat Aug 22 12:04:44 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:04:44 2015 : Info: ++[files] = ok Sat Aug 22 12:04:44 2015 : Info: ++[expiration] = noop Sat Aug 22 12:04:44 2015 : Info: ++[logintime] = noop Sat Aug 22 12:04:44 2015 : Info: ++[pap] = noop Sat Aug 22 12:04:44 2015 : Info: +} # group authorize = updated Sat Aug 22 12:04:44 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:04:44 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:44 2015 : Info: +group authenticate { Sat Aug 22 12:04:44 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:04:44 2015 : Info: [eap] EAP/tls Sat Aug 22 12:04:44 2015 : Info: [eap] processing type tls Sat Aug 22 12:04:44 2015 : Info: [tls] Authenticate Sat Aug 22 12:04:44 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:04:44 2015 : Info: [tls] eaptls_verify returned 7 Sat Aug 22 12:04:44 2015 : Info: [tls] Done initial handshake Sat Aug 22 12:04:44 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:04:44 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0493], Certificate Sat Aug 22 12:04:44 2015 : Info: [tls] chain-depth=1, Sat Aug 22 12:04:44 2015 : Info: [tls] error=0 Sat Aug 22 12:04:44 2015 : Info: [tls] --> User-Name = selen.kjonca Sat Aug 22 12:04:44 2015 : Info: [tls] --> BUF-Name = beta-wifi-ca-2 Sat Aug 22 12:04:44 2015 : Info: [tls] --> subject = /C=PL/ST=Mazowieckie/L=Warszawa/O=beta/OU=wifi/CN=beta-wifi-ca-2/emailAddress=kjonca@poczta.onet.pl Sat Aug 22 12:04:44 2015 : Info: [tls] --> issuer = /C=PL/ST=Mazowieckie/L=Warszawa/O=beta/OU=wifi/CN=beta-wifi-ca-2/emailAddress=kjonca@poczta.onet.pl Sat Aug 22 12:04:44 2015 : Info: [tls] --> verify return:1 Sat Aug 22 12:04:44 2015 : Info: [tls] expand: %{User-Name} -> selen.kjonca Sat Aug 22 12:04:44 2015 : Info: [tls] checking certificate CN (selen.kjonca) with xlat'ed value (selen.kjonca) Sat Aug 22 12:04:44 2015 : Info: [tls] chain-depth=0, Sat Aug 22 12:04:44 2015 : Info: [tls] error=0 Sat Aug 22 12:04:44 2015 : Info: [tls] --> User-Name = selen.kjonca Sat Aug 22 12:04:44 2015 : Info: [tls] --> BUF-Name = selen.kjonca Sat Aug 22 12:04:44 2015 : Info: [tls] --> subject = /C=PL/ST=Mazowieckie/O=beta/OU=beta.kjonca/CN=selen.kjonca Sat Aug 22 12:04:44 2015 : Info: [tls] --> issuer = /C=PL/ST=Mazowieckie/L=Warszawa/O=beta/OU=wifi/CN=beta-wifi-ca-2/emailAddress=kjonca@poczta.onet.pl Sat Aug 22 12:04:44 2015 : Info: [tls] --> verify return:1 Sat Aug 22 12:04:44 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:44 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:04:44 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange Sat Aug 22 12:04:44 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:44 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:04:44 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0106], CertificateVerify Sat Aug 22 12:04:44 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:44 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:04:44 2015 : Info: [tls] <<< TLS 1.0 ChangeCipherSpec [length 0001] Sat Aug 22 12:04:44 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:04:44 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0010], Finished Sat Aug 22 12:04:44 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:44 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:04:44 2015 : Info: [tls] >>> TLS 1.0 ChangeCipherSpec [length 0001] Sat Aug 22 12:04:44 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:44 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:04:44 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0010], Finished Sat Aug 22 12:04:44 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:44 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:04:44 2015 : Info: [tls] (other): SSL negotiation finished successfully Sat Aug 22 12:04:44 2015 : Debug: SSL Connection Established Sat Aug 22 12:04:44 2015 : Info: [tls] eaptls_process returned 13 Sat Aug 22 12:04:44 2015 : Info: ++[eap] = handled Sat Aug 22 12:04:44 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:04:44 2015 : Info: Finished request 93. Sat Aug 22 12:04:44 2015 : Debug: Going to the next request Sat Aug 22 12:04:44 2015 : Debug: Thread 2 waiting to be assigned a request Sat Aug 22 12:04:44 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:04:44 2015 : Debug: Thread 5 got semaphore Sat Aug 22 12:04:44 2015 : Debug: Thread 5 handling request 94, (19 handled so far) Sat Aug 22 12:04:44 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:44 2015 : Info: +group authorize { Sat Aug 22 12:04:44 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:04:44 2015 : Info: ++[chap] = noop Sat Aug 22 12:04:44 2015 : Info: ++[mschap] = noop Sat Aug 22 12:04:44 2015 : Info: ++[digest] = noop Sat Aug 22 12:04:44 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:04:44 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:04:44 2015 : Info: ++[suffix] = noop Sat Aug 22 12:04:44 2015 : Info: [eap] EAP packet type response id 159 length 6 Sat Aug 22 12:04:44 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:04:44 2015 : Info: ++[eap] = updated Sat Aug 22 12:04:44 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:04:44 2015 : Info: ++[files] = ok Sat Aug 22 12:04:44 2015 : Info: ++[expiration] = noop Sat Aug 22 12:04:44 2015 : Info: ++[logintime] = noop Sat Aug 22 12:04:44 2015 : Info: ++[pap] = noop Sat Aug 22 12:04:44 2015 : Info: +} # group authorize = updated Sat Aug 22 12:04:44 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:04:44 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:44 2015 : Info: +group authenticate { Sat Aug 22 12:04:44 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:04:44 2015 : Info: [eap] EAP/tls Sat Aug 22 12:04:44 2015 : Info: [eap] processing type tls Sat Aug 22 12:04:44 2015 : Info: [tls] Authenticate Sat Aug 22 12:04:44 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:04:44 2015 : Info: [tls] Received TLS ACK Sat Aug 22 12:04:44 2015 : Info: [tls] ACK handshake is finished Sat Aug 22 12:04:44 2015 : Info: [tls] eaptls_verify returned 3 Sat Aug 22 12:04:44 2015 : Info: [tls] eaptls_process returned 3 Sat Aug 22 12:04:44 2015 : Info: [tls] Adding user data to cached session Sat Aug 22 12:04:44 2015 : Info: [eap] Freeing handler Sat Aug 22 12:04:44 2015 : Info: ++[eap] = ok Sat Aug 22 12:04:44 2015 : Info: +} # group authenticate = ok Sat Aug 22 12:04:44 2015 : Auth: Login OK: [selen.kjonca] (from client ni port 2 cli 00-08-22-4F-62-54) Sat Aug 22 12:04:44 2015 : Info: # Executing section post-auth from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:04:44 2015 : Info: +group post-auth { Sat Aug 22 12:04:44 2015 : Info: ++[exec] = noop Sat Aug 22 12:04:44 2015 : Info: +} # group post-auth = noop Sat Aug 22 12:04:44 2015 : Info: Finished request 94. Sat Aug 22 12:04:44 2015 : Debug: Going to the next request Sat Aug 22 12:04:44 2015 : Debug: Thread 5 waiting to be assigned a request Sat Aug 22 12:04:45 2015 : Debug: Waking up in 3.9 seconds. Sat Aug 22 12:04:48 2015 : Info: Cleaning up request 89 ID 246 with timestamp +1696 Sat Aug 22 12:04:48 2015 : Info: Cleaning up request 90 ID 247 with timestamp +1696 Sat Aug 22 12:04:48 2015 : Info: Cleaning up request 91 ID 248 with timestamp +1696 Sat Aug 22 12:04:49 2015 : Info: Cleaning up request 92 ID 249 with timestamp +1697 Sat Aug 22 12:04:49 2015 : Info: Cleaning up request 93 ID 250 with timestamp +1697 Sat Aug 22 12:04:49 2015 : Info: Cleaning up request 94 ID 251 with timestamp +1697 Sat Aug 22 12:04:49 2015 : Info: Ready to process requests. Sat Aug 22 12:05:05 2015 : Debug: Thread 3 got semaphore Sat Aug 22 12:05:05 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:05:05 2015 : Debug: Thread 3 handling request 95, (20 handled so far) Sat Aug 22 12:05:05 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group authorize { Sat Aug 22 12:05:05 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:05:05 2015 : Info: ++[chap] = noop Sat Aug 22 12:05:05 2015 : Info: ++[mschap] = noop Sat Aug 22 12:05:05 2015 : Info: ++[digest] = noop Sat Aug 22 12:05:05 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:05:05 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:05:05 2015 : Info: ++[suffix] = noop Sat Aug 22 12:05:05 2015 : Info: [eap] EAP packet type response id 60 length 17 Sat Aug 22 12:05:05 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:05:05 2015 : Info: ++[eap] = updated Sat Aug 22 12:05:05 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:05:05 2015 : Info: ++[files] = ok Sat Aug 22 12:05:05 2015 : Info: ++[expiration] = noop Sat Aug 22 12:05:05 2015 : Info: ++[logintime] = noop Sat Aug 22 12:05:05 2015 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this. Sat Aug 22 12:05:05 2015 : Info: ++[pap] = noop Sat Aug 22 12:05:05 2015 : Info: +} # group authorize = updated Sat Aug 22 12:05:05 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:05:05 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group authenticate { Sat Aug 22 12:05:05 2015 : Info: [eap] EAP Identity Sat Aug 22 12:05:05 2015 : Info: [eap] processing type tls Sat Aug 22 12:05:05 2015 : Info: [tls] Requiring client certificate Sat Aug 22 12:05:05 2015 : Info: [tls] Initiate Sat Aug 22 12:05:05 2015 : Info: [tls] Start returned 1 Sat Aug 22 12:05:05 2015 : Info: ++[eap] = handled Sat Aug 22 12:05:05 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:05:05 2015 : Info: Finished request 95. Sat Aug 22 12:05:05 2015 : Debug: Going to the next request Sat Aug 22 12:05:05 2015 : Debug: Thread 3 waiting to be assigned a request Sat Aug 22 12:05:05 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:05:05 2015 : Debug: Thread 4 got semaphore Sat Aug 22 12:05:05 2015 : Debug: Thread 4 handling request 96, (20 handled so far) Sat Aug 22 12:05:05 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group authorize { Sat Aug 22 12:05:05 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:05:05 2015 : Info: ++[chap] = noop Sat Aug 22 12:05:05 2015 : Info: ++[mschap] = noop Sat Aug 22 12:05:05 2015 : Info: ++[digest] = noop Sat Aug 22 12:05:05 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:05:05 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:05:05 2015 : Info: ++[suffix] = noop Sat Aug 22 12:05:05 2015 : Info: [eap] EAP packet type response id 61 length 204 Sat Aug 22 12:05:05 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:05:05 2015 : Info: ++[eap] = updated Sat Aug 22 12:05:05 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:05:05 2015 : Info: ++[files] = ok Sat Aug 22 12:05:05 2015 : Info: ++[expiration] = noop Sat Aug 22 12:05:05 2015 : Info: ++[logintime] = noop Sat Aug 22 12:05:05 2015 : Info: ++[pap] = noop Sat Aug 22 12:05:05 2015 : Info: +} # group authorize = updated Sat Aug 22 12:05:05 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:05:05 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group authenticate { Sat Aug 22 12:05:05 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:05:05 2015 : Info: [eap] EAP/tls Sat Aug 22 12:05:05 2015 : Info: [eap] processing type tls Sat Aug 22 12:05:05 2015 : Info: [tls] Authenticate Sat Aug 22 12:05:05 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:05:05 2015 : Info: [tls] eaptls_verify returned 7 Sat Aug 22 12:05:05 2015 : Info: [tls] Done initial handshake Sat Aug 22 12:05:05 2015 : Info: [tls] (other): before/accept initialization Sat Aug 22 12:05:05 2015 : Info: [tls] TLS_accept: before/accept initialization Sat Aug 22 12:05:05 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:05:05 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 00c1], ClientHello Sat Aug 22 12:05:05 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:05 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:05:05 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0039], ServerHello Sat Aug 22 12:05:05 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:05 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:05:05 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0695], Certificate Sat Aug 22 12:05:05 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:05 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:05:05 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 00cb], ServerKeyExchange Sat Aug 22 12:05:05 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:05 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:05:05 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 000e], CertificateRequest Sat Aug 22 12:05:05 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:05 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:05 2015 : Info: [tls] TLS_accept: Need to read more data: unknown state Sat Aug 22 12:05:05 2015 : Debug: In SSL Handshake Phase Sat Aug 22 12:05:05 2015 : Debug: In SSL Accept mode Sat Aug 22 12:05:05 2015 : Info: [tls] eaptls_process returned 13 Sat Aug 22 12:05:05 2015 : Info: ++[eap] = handled Sat Aug 22 12:05:05 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:05:05 2015 : Info: Finished request 96. Sat Aug 22 12:05:05 2015 : Debug: Going to the next request Sat Aug 22 12:05:05 2015 : Debug: Thread 4 waiting to be assigned a request Sat Aug 22 12:05:05 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:05:05 2015 : Debug: Thread 1 got semaphore Sat Aug 22 12:05:05 2015 : Debug: Thread 1 handling request 97, (20 handled so far) Sat Aug 22 12:05:05 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group authorize { Sat Aug 22 12:05:05 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:05:05 2015 : Info: ++[chap] = noop Sat Aug 22 12:05:05 2015 : Info: ++[mschap] = noop Sat Aug 22 12:05:05 2015 : Info: ++[digest] = noop Sat Aug 22 12:05:05 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:05:05 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:05:05 2015 : Info: ++[suffix] = noop Sat Aug 22 12:05:05 2015 : Info: [eap] EAP packet type response id 62 length 6 Sat Aug 22 12:05:05 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:05:05 2015 : Info: ++[eap] = updated Sat Aug 22 12:05:05 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:05:05 2015 : Info: ++[files] = ok Sat Aug 22 12:05:05 2015 : Info: ++[expiration] = noop Sat Aug 22 12:05:05 2015 : Info: ++[logintime] = noop Sat Aug 22 12:05:05 2015 : Info: ++[pap] = noop Sat Aug 22 12:05:05 2015 : Info: +} # group authorize = updated Sat Aug 22 12:05:05 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:05:05 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group authenticate { Sat Aug 22 12:05:05 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:05:05 2015 : Info: [eap] EAP/tls Sat Aug 22 12:05:05 2015 : Info: [eap] processing type tls Sat Aug 22 12:05:05 2015 : Info: [tls] Authenticate Sat Aug 22 12:05:05 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:05:05 2015 : Info: [tls] Received TLS ACK Sat Aug 22 12:05:05 2015 : Info: [tls] ACK handshake fragment handler Sat Aug 22 12:05:05 2015 : Info: [tls] eaptls_verify returned 1 Sat Aug 22 12:05:05 2015 : Info: [tls] eaptls_process returned 13 Sat Aug 22 12:05:05 2015 : Info: ++[eap] = handled Sat Aug 22 12:05:05 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:05:05 2015 : Info: Finished request 97. Sat Aug 22 12:05:05 2015 : Debug: Going to the next request Sat Aug 22 12:05:05 2015 : Debug: Thread 1 waiting to be assigned a request Sat Aug 22 12:05:05 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:05:05 2015 : Debug: Thread 2 got semaphore Sat Aug 22 12:05:05 2015 : Debug: Thread 2 handling request 98, (20 handled so far) Sat Aug 22 12:05:05 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group authorize { Sat Aug 22 12:05:05 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:05:05 2015 : Info: ++[chap] = noop Sat Aug 22 12:05:05 2015 : Info: ++[mschap] = noop Sat Aug 22 12:05:05 2015 : Info: ++[digest] = noop Sat Aug 22 12:05:05 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:05:05 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:05:05 2015 : Info: ++[suffix] = noop Sat Aug 22 12:05:05 2015 : Info: [eap] EAP packet type response id 63 length 13 Sat Aug 22 12:05:05 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:05:05 2015 : Info: ++[eap] = updated Sat Aug 22 12:05:05 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:05:05 2015 : Info: ++[files] = ok Sat Aug 22 12:05:05 2015 : Info: ++[expiration] = noop Sat Aug 22 12:05:05 2015 : Info: ++[logintime] = noop Sat Aug 22 12:05:05 2015 : Info: ++[pap] = noop Sat Aug 22 12:05:05 2015 : Info: +} # group authorize = updated Sat Aug 22 12:05:05 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:05:05 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group authenticate { Sat Aug 22 12:05:05 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:05:05 2015 : Info: [eap] EAP/tls Sat Aug 22 12:05:05 2015 : Info: [eap] processing type tls Sat Aug 22 12:05:05 2015 : Info: [tls] Authenticate Sat Aug 22 12:05:05 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:05:05 2015 : Info: [tls] eaptls_verify returned 7 Sat Aug 22 12:05:05 2015 : Info: [tls] Done initial handshake Sat Aug 22 12:05:05 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:05:05 2015 : Info: [tls] <<< TLS 1.0 Alert [length 0002], fatal unknown_ca Sat Aug 22 12:05:05 2015 : Error: TLS Alert read:fatal:unknown CA Sat Aug 22 12:05:05 2015 : Error: TLS_accept: failed in unknown state Sat Aug 22 12:05:05 2015 : Error: rlm_eap: SSL error error:14094418:SSL routines:ssl3_read_bytes:tlsv1 alert unknown ca Sat Aug 22 12:05:05 2015 : Error: SSL: SSL_read failed inside of TLS (-1), TLS session fails. Sat Aug 22 12:05:05 2015 : Debug: TLS receive handshake failed during operation Sat Aug 22 12:05:05 2015 : Info: [tls] eaptls_process returned 4 Sat Aug 22 12:05:05 2015 : Info: [eap] Handler failed in EAP/tls Sat Aug 22 12:05:05 2015 : Info: [eap] Failed in EAP select Sat Aug 22 12:05:05 2015 : Info: ++[eap] = invalid Sat Aug 22 12:05:05 2015 : Info: +} # group authenticate = invalid Sat Aug 22 12:05:05 2015 : Info: Failed to authenticate the user. Sat Aug 22 12:05:05 2015 : Auth: Login incorrect (TLS Alert read:fatal:unknown CA): [selen.kjonca] (from client ni port 2 cli 00-08-22-4F-62-54) Sat Aug 22 12:05:05 2015 : Info: Using Post-Auth-Type REJECT Sat Aug 22 12:05:05 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:05 2015 : Info: +group REJECT { Sat Aug 22 12:05:05 2015 : Info: [attr_filter.access_reject] expand: %{User-Name} -> selen.kjonca Sat Aug 22 12:05:05 2015 : Debug: attr_filter: Matched entry DEFAULT at line 11 Sat Aug 22 12:05:05 2015 : Info: ++[attr_filter.access_reject] = updated Sat Aug 22 12:05:05 2015 : Info: +} # group REJECT = updated Sat Aug 22 12:05:05 2015 : Info: Delaying reject of request 98 for 1 seconds Sat Aug 22 12:05:05 2015 : Debug: Going to the next request Sat Aug 22 12:05:05 2015 : Debug: Thread 2 waiting to be assigned a request Sat Aug 22 12:05:06 2015 : Info: Sending delayed reject for request 98 Sat Aug 22 12:05:06 2015 : Debug: Waking up in 3.9 seconds. Sat Aug 22 12:05:07 2015 : Debug: Thread 5 got semaphore Sat Aug 22 12:05:07 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:05:07 2015 : Debug: Thread 5 handling request 99, (20 handled so far) Sat Aug 22 12:05:07 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group authorize { Sat Aug 22 12:05:07 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:05:07 2015 : Info: ++[chap] = noop Sat Aug 22 12:05:07 2015 : Info: ++[mschap] = noop Sat Aug 22 12:05:07 2015 : Info: ++[digest] = noop Sat Aug 22 12:05:07 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:05:07 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:05:07 2015 : Info: ++[suffix] = noop Sat Aug 22 12:05:07 2015 : Info: [eap] EAP packet type response id 162 length 17 Sat Aug 22 12:05:07 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:05:07 2015 : Info: ++[eap] = updated Sat Aug 22 12:05:07 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:05:07 2015 : Info: ++[files] = ok Sat Aug 22 12:05:07 2015 : Info: ++[expiration] = noop Sat Aug 22 12:05:07 2015 : Info: ++[logintime] = noop Sat Aug 22 12:05:07 2015 : Info: [pap] WARNING! No "known good" password found for the user. Authentication may fail because of this. Sat Aug 22 12:05:07 2015 : Info: ++[pap] = noop Sat Aug 22 12:05:07 2015 : Info: +} # group authorize = updated Sat Aug 22 12:05:07 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:05:07 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group authenticate { Sat Aug 22 12:05:07 2015 : Info: [eap] EAP Identity Sat Aug 22 12:05:07 2015 : Info: [eap] processing type tls Sat Aug 22 12:05:07 2015 : Info: [tls] Requiring client certificate Sat Aug 22 12:05:07 2015 : Info: [tls] Initiate Sat Aug 22 12:05:07 2015 : Info: [tls] Start returned 1 Sat Aug 22 12:05:07 2015 : Info: ++[eap] = handled Sat Aug 22 12:05:07 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:05:07 2015 : Info: Finished request 99. Sat Aug 22 12:05:07 2015 : Debug: Going to the next request Sat Aug 22 12:05:07 2015 : Debug: Thread 5 waiting to be assigned a request Sat Aug 22 12:05:07 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:05:07 2015 : Debug: Thread 3 got semaphore Sat Aug 22 12:05:07 2015 : Debug: Thread 3 handling request 100, (21 handled so far) Sat Aug 22 12:05:07 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group authorize { Sat Aug 22 12:05:07 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:05:07 2015 : Info: ++[chap] = noop Sat Aug 22 12:05:07 2015 : Info: ++[mschap] = noop Sat Aug 22 12:05:07 2015 : Info: ++[digest] = noop Sat Aug 22 12:05:07 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:05:07 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:05:07 2015 : Info: ++[suffix] = noop Sat Aug 22 12:05:07 2015 : Info: [eap] EAP packet type response id 163 length 204 Sat Aug 22 12:05:07 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:05:07 2015 : Info: ++[eap] = updated Sat Aug 22 12:05:07 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:05:07 2015 : Info: ++[files] = ok Sat Aug 22 12:05:07 2015 : Info: ++[expiration] = noop Sat Aug 22 12:05:07 2015 : Info: ++[logintime] = noop Sat Aug 22 12:05:07 2015 : Info: ++[pap] = noop Sat Aug 22 12:05:07 2015 : Info: +} # group authorize = updated Sat Aug 22 12:05:07 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:05:07 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group authenticate { Sat Aug 22 12:05:07 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:05:07 2015 : Info: [eap] EAP/tls Sat Aug 22 12:05:07 2015 : Info: [eap] processing type tls Sat Aug 22 12:05:07 2015 : Info: [tls] Authenticate Sat Aug 22 12:05:07 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:05:07 2015 : Info: [tls] eaptls_verify returned 7 Sat Aug 22 12:05:07 2015 : Info: [tls] Done initial handshake Sat Aug 22 12:05:07 2015 : Info: [tls] (other): before/accept initialization Sat Aug 22 12:05:07 2015 : Info: [tls] TLS_accept: before/accept initialization Sat Aug 22 12:05:07 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:05:07 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 00c1], ClientHello Sat Aug 22 12:05:07 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:07 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:05:07 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0039], ServerHello Sat Aug 22 12:05:07 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:07 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:05:07 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0695], Certificate Sat Aug 22 12:05:07 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:07 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:05:07 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 00cb], ServerKeyExchange Sat Aug 22 12:05:07 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:07 2015 : Info: [tls] >>> Unknown TLS version [length 0005] Sat Aug 22 12:05:07 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 000e], CertificateRequest Sat Aug 22 12:05:07 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:07 2015 : Info: [tls] TLS_accept: unknown state Sat Aug 22 12:05:07 2015 : Info: [tls] TLS_accept: Need to read more data: unknown state Sat Aug 22 12:05:07 2015 : Debug: In SSL Handshake Phase Sat Aug 22 12:05:07 2015 : Debug: In SSL Accept mode Sat Aug 22 12:05:07 2015 : Info: [tls] eaptls_process returned 13 Sat Aug 22 12:05:07 2015 : Info: ++[eap] = handled Sat Aug 22 12:05:07 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:05:07 2015 : Info: Finished request 100. Sat Aug 22 12:05:07 2015 : Debug: Going to the next request Sat Aug 22 12:05:07 2015 : Debug: Thread 3 waiting to be assigned a request Sat Aug 22 12:05:07 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:05:07 2015 : Debug: Thread 4 got semaphore Sat Aug 22 12:05:07 2015 : Debug: Thread 4 handling request 101, (21 handled so far) Sat Aug 22 12:05:07 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group authorize { Sat Aug 22 12:05:07 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:05:07 2015 : Info: ++[chap] = noop Sat Aug 22 12:05:07 2015 : Info: ++[mschap] = noop Sat Aug 22 12:05:07 2015 : Info: ++[digest] = noop Sat Aug 22 12:05:07 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:05:07 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:05:07 2015 : Info: ++[suffix] = noop Sat Aug 22 12:05:07 2015 : Info: [eap] EAP packet type response id 164 length 6 Sat Aug 22 12:05:07 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:05:07 2015 : Info: ++[eap] = updated Sat Aug 22 12:05:07 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:05:07 2015 : Info: ++[files] = ok Sat Aug 22 12:05:07 2015 : Info: ++[expiration] = noop Sat Aug 22 12:05:07 2015 : Info: ++[logintime] = noop Sat Aug 22 12:05:07 2015 : Info: ++[pap] = noop Sat Aug 22 12:05:07 2015 : Info: +} # group authorize = updated Sat Aug 22 12:05:07 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:05:07 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group authenticate { Sat Aug 22 12:05:07 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:05:07 2015 : Info: [eap] EAP/tls Sat Aug 22 12:05:07 2015 : Info: [eap] processing type tls Sat Aug 22 12:05:07 2015 : Info: [tls] Authenticate Sat Aug 22 12:05:07 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:05:07 2015 : Info: [tls] Received TLS ACK Sat Aug 22 12:05:07 2015 : Info: [tls] ACK handshake fragment handler Sat Aug 22 12:05:07 2015 : Info: [tls] eaptls_verify returned 1 Sat Aug 22 12:05:07 2015 : Info: [tls] eaptls_process returned 13 Sat Aug 22 12:05:07 2015 : Info: ++[eap] = handled Sat Aug 22 12:05:07 2015 : Info: +} # group authenticate = handled Sat Aug 22 12:05:07 2015 : Info: Finished request 101. Sat Aug 22 12:05:07 2015 : Debug: Going to the next request Sat Aug 22 12:05:07 2015 : Debug: Thread 4 waiting to be assigned a request Sat Aug 22 12:05:07 2015 : Debug: Waking up in 0.9 seconds. Sat Aug 22 12:05:07 2015 : Debug: Thread 1 got semaphore Sat Aug 22 12:05:07 2015 : Debug: Thread 1 handling request 102, (21 handled so far) Sat Aug 22 12:05:07 2015 : Info: # Executing section authorize from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group authorize { Sat Aug 22 12:05:07 2015 : Info: ++[preprocess] = ok Sat Aug 22 12:05:07 2015 : Info: ++[chap] = noop Sat Aug 22 12:05:07 2015 : Info: ++[mschap] = noop Sat Aug 22 12:05:07 2015 : Info: ++[digest] = noop Sat Aug 22 12:05:07 2015 : Info: [suffix] No '@' in User-Name = "selen.kjonca", looking up realm NULL Sat Aug 22 12:05:07 2015 : Info: [suffix] No such realm "NULL" Sat Aug 22 12:05:07 2015 : Info: ++[suffix] = noop Sat Aug 22 12:05:07 2015 : Info: [eap] EAP packet type response id 165 length 13 Sat Aug 22 12:05:07 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Sat Aug 22 12:05:07 2015 : Info: ++[eap] = updated Sat Aug 22 12:05:07 2015 : Info: [files] users: Matched entry selen.kjonca at line 12 Sat Aug 22 12:05:07 2015 : Info: ++[files] = ok Sat Aug 22 12:05:07 2015 : Info: ++[expiration] = noop Sat Aug 22 12:05:07 2015 : Info: ++[logintime] = noop Sat Aug 22 12:05:07 2015 : Info: ++[pap] = noop Sat Aug 22 12:05:07 2015 : Info: +} # group authorize = updated Sat Aug 22 12:05:07 2015 : Info: Found Auth-Type = EAP Sat Aug 22 12:05:07 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group authenticate { Sat Aug 22 12:05:07 2015 : Info: [eap] Request found, released from the list Sat Aug 22 12:05:07 2015 : Info: [eap] EAP/tls Sat Aug 22 12:05:07 2015 : Info: [eap] processing type tls Sat Aug 22 12:05:07 2015 : Info: [tls] Authenticate Sat Aug 22 12:05:07 2015 : Info: [tls] processing EAP-TLS Sat Aug 22 12:05:07 2015 : Info: [tls] eaptls_verify returned 7 Sat Aug 22 12:05:07 2015 : Info: [tls] Done initial handshake Sat Aug 22 12:05:07 2015 : Info: [tls] <<< Unknown TLS version [length 0005] Sat Aug 22 12:05:07 2015 : Info: [tls] <<< TLS 1.0 Alert [length 0002], fatal unknown_ca Sat Aug 22 12:05:07 2015 : Error: TLS Alert read:fatal:unknown CA Sat Aug 22 12:05:07 2015 : Error: TLS_accept: failed in unknown state Sat Aug 22 12:05:07 2015 : Error: rlm_eap: SSL error error:14094418:SSL routines:ssl3_read_bytes:tlsv1 alert unknown ca Sat Aug 22 12:05:07 2015 : Error: SSL: SSL_read failed inside of TLS (-1), TLS session fails. Sat Aug 22 12:05:07 2015 : Debug: TLS receive handshake failed during operation Sat Aug 22 12:05:07 2015 : Info: [tls] eaptls_process returned 4 Sat Aug 22 12:05:07 2015 : Info: [eap] Handler failed in EAP/tls Sat Aug 22 12:05:07 2015 : Info: [eap] Failed in EAP select Sat Aug 22 12:05:07 2015 : Info: ++[eap] = invalid Sat Aug 22 12:05:07 2015 : Info: +} # group authenticate = invalid Sat Aug 22 12:05:07 2015 : Info: Failed to authenticate the user. Sat Aug 22 12:05:07 2015 : Auth: Login incorrect (TLS Alert read:fatal:unknown CA): [selen.kjonca] (from client ni port 2 cli 00-08-22-4F-62-54) Sat Aug 22 12:05:07 2015 : Info: Using Post-Auth-Type REJECT Sat Aug 22 12:05:07 2015 : Info: # Executing group from file /etc/freeradius/sites-enabled/default Sat Aug 22 12:05:07 2015 : Info: +group REJECT { Sat Aug 22 12:05:07 2015 : Info: [attr_filter.access_reject] expand: %{User-Name} -> selen.kjonca Sat Aug 22 12:05:07 2015 : Debug: attr_filter: Matched entry DEFAULT at line 11 Sat Aug 22 12:05:07 2015 : Info: ++[attr_filter.access_reject] = updated Sat Aug 22 12:05:07 2015 : Info: +} # group REJECT = updated Sat Aug 22 12:05:07 2015 : Info: Delaying reject of request 102 for 1 seconds Sat Aug 22 12:05:07 2015 : Debug: Going to the next request Sat Aug 22 12:05:07 2015 : Debug: Thread 1 waiting to be assigned a request Sat Aug 22 12:05:08 2015 : Info: Sending delayed reject for request 102 Sat Aug 22 12:05:08 2015 : Debug: Waking up in 1.7 seconds. Sat Aug 22 12:05:10 2015 : Info: Cleaning up request 95 ID 252 with timestamp +1718 Sat Aug 22 12:05:10 2015 : Info: Cleaning up request 96 ID 253 with timestamp +1718 Sat Aug 22 12:05:10 2015 : Info: Cleaning up request 97 ID 254 with timestamp +1718 Sat Aug 22 12:05:10 2015 : Debug: Waking up in 1.0 seconds. Sat Aug 22 12:05:11 2015 : Info: Cleaning up request 98 ID 255 with timestamp +1718 Sat Aug 22 12:05:11 2015 : Debug: Waking up in 1.2 seconds. Sat Aug 22 12:05:12 2015 : Info: Cleaning up request 99 ID 0 with timestamp +1720 Sat Aug 22 12:05:12 2015 : Info: Cleaning up request 100 ID 1 with timestamp +1720 Sat Aug 22 12:05:12 2015 : Info: Cleaning up request 101 ID 2 with timestamp +1720 Sat Aug 22 12:05:12 2015 : Debug: Waking up in 1.0 seconds. Sat Aug 22 12:05:13 2015 : Info: Cleaning up request 102 ID 3 with timestamp +1720 Sat Aug 22 12:05:13 2015 : Info: Ready to process requests. -- http://wolnelektury.pl/wesprzyj/teraz/ share, n.: To give in, endure humiliation.
Hi,
I have configured and working wifi with eap-tls authentication. I want to use another root ca, so I did the following steps.
yep - but if you are making new CAs and addign them to clients, you ALSO have to re-configure your FreeRADIUS server to use that new CA. you can see in your logs: Sat Aug 22 12:05:05 2015 : Auth: Login incorrect (TLS Alert read:fatal:unknown CA): [selen.kjonca] (from client ni port 2 cli 00-08-22-4F-62-54) Sat Aug 22 12:05:05 2015 : Info: Using Post-Auth-Type REJECT (and plenty of other 'Unknown CA' messages) alan
A.L.M.Buxey@lboro.ac.uk writes:
Hi,
I have configured and working wifi with eap-tls authentication. I want to use another root ca, so I did the following steps.
yep - but if you are making new CAs and addign them to clients, you ALSO have to re-configure your FreeRADIUS server to use that new CA. you can see in your logs:
Sat Aug 22 12:05:05 2015 : Auth: Login incorrect (TLS Alert read:fatal:unknown CA): [selen.kjonca] (from client ni port 2 cli 00-08-22-4F-62-54) Sat Aug 22 12:05:05 2015 : Info: Using Post-Auth-Type REJECT
(and plenty of other 'Unknown CA' messages)
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
I have copied new ca file to CA_path, and done c_rehash. What else should I do? BTW. excerpt from my eap.conf eap { default_eap_type = tls timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = 4096 tls { certdir = ${confdir}/certs cadir = ${confdir}/certs private_key_password = [.....] private_key_file = [....] certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2,1.pem certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2.5.pem dh_file = /etc/ssl/dh.pem random_file = /dev/urandom CA_path = ${cadir} check_cert_cn = %{User-Name} cipher_list = "DEFAULT" make_cert_command = "${certdir}/bootstrap" [....] -- http://wolnelektury.pl/wesprzyj/teraz/ This fortune intentionally not included.
kjonca@o2.pl (Kamil Jońca) writes: [...]
I have copied new ca file to CA_path, and done c_rehash. What else should I do? BTW. excerpt from my eap.conf eap { default_eap_type = tls timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = 4096 tls { certdir = ${confdir}/certs cadir = ${confdir}/certs private_key_password = [.....] private_key_file = [....] certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2,1.pem certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2.5.pem dh_file = /etc/ssl/dh.pem random_file = /dev/urandom CA_path = ${cadir} check_cert_cn = %{User-Name} cipher_list = "DEFAULT" make_cert_command = "${certdir}/bootstrap"
[....]
It looks like problem is in --8<---------------cut here---------------start------------->8--- certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2,1.pem certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2.5.pem --8<---------------cut here---------------end--------------->8--- both of these certs are created for key from "private_key_file". One of them is signed by one CA ("old") and second by by my new CA. When client with cert signed by "new" CA wants connect it ends with first file which is signed by 'wrong" CA. (As I understand) I tried to bundle both certs into single file but with no success. So my question is: I have some certs for clients signed by OLD ca. I want to "migrate" gradually migrate to "new" CA. How can I make to use two CA's [1] and two cert file for server [2]? KJ [1] - it looks simple [2] - but this not -- http://wolnelektury.pl/wesprzyj/teraz/ Women, when they are not in love, have all the cold blood of an experienced attorney. -- Honor'e de Balzac
On 22 Aug 2015, at 12:11, Kamil Jońca <kjonca@o2.pl> wrote:
kjonca@o2.pl (Kamil Jońca) writes:
[...]
I have copied new ca file to CA_path, and done c_rehash. What else should I do? BTW. excerpt from my eap.conf eap { default_eap_type = tls timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = 4096 tls { certdir = ${confdir}/certs cadir = ${confdir}/certs private_key_password = [.....] private_key_file = [....] certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2,1.pem certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2.5.pem dh_file = /etc/ssl/dh.pem random_file = /dev/urandom CA_path = ${cadir} check_cert_cn = %{User-Name} cipher_list = "DEFAULT" make_cert_command = "${certdir}/bootstrap"
[....]
It looks like problem is in
--8<---------------cut here---------------start------------->8--- certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2,1.pem certificate_file = ${confdir}/certs/wifi,beta-wifi-beta,2.5.pem --8<---------------cut here---------------end--------------->8--- both of these certs are created for key from "private_key_file". One of them is signed by one CA ("old") and second by by my new CA. When client with cert signed by "new" CA wants connect it ends with first file which is signed by 'wrong" CA. (As I understand)
I tried to bundle both certs into single file but with no success.
So my question is: I have some certs for clients signed by OLD ca. I want to "migrate" gradually migrate to "new" CA. How can I make to use two CA's [1] and two cert file for server [2]?
Concatenate them together in the same CA file. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
If you tried this already and it didn't work, you did it wrong. Make sure both certs are in PEM format and base64 armoured. cat ./cert1.pem >> ca.pem cat ./cert2.pem >> ca.pem It works. I know, because i've tried it very recently. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Arran Cudbard-Bell <a.cudbardb@freeradius.org> writes: [...]
Concatenate them together in the same CA file.
I tried with CA - and it is no problem. I tried with "server certs" - with no success. (Ie client cant authenticate) KJ -- http://stopstopnop.pl/stop_stopnop.pl_o_nas.html Vanilla wafer.
On 22 Aug 2015, at 12:34, Kamil Jońca <kjonca@o2.pl> wrote:
Arran Cudbard-Bell <a.cudbardb@freeradius.org> writes:
[...]
Concatenate them together in the same CA file.
I tried with CA - and it is no problem. I tried with "server certs" - with no success. (Ie client cant authenticate)
You can't present multiple server certificates. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
participants (3)
-
A.L.M.Buxey＠lboro.ac.uk -
Arran Cudbard-Bell -
kjonca＠o2.pl