FreeRADIUSでEAP-TLS認証がしたい

前提・実現したいこと

FreeRADIUSを用いてEAP-TLS認証がしたいです。
ご教授お願いします。

＜条件等＞
FreeRADIUS-wpa_supplicantの接続
認証SW有
有線接続
MD5及びPEAPの認証は成功確認済

設定ファイル内容↓
<wpa_supplicant.conf>

ctrl_interface=/var/run/wpa_supplicant
ap_scan=0

network={

	key_mgmt=IEEE8021X
	eap=TLS
	identity="user"
	password="pass"
	ca_cert="/home/user/certs/ca.pem"
	client_cert="/home/user/certs/user@example.com.pem"
	private_key="/home/user/certs/client.key"
	private_key_passwd="whatever"
	
	eapol_flags=0
}

試したこと

クライアントPCよりeapol_testを行いました。
PEAPは成功したのに、TLSがうまくいきません。

補足情報

使用している証明書はプライベートCAを構築し、サーバー証明書とクライアント証明書を作成しました。
サーバー証明書とクライアント証明書の認証局は同じプライベートCAになります。

2018/03/29 9:45 追記

認証失敗時のログをできる限り省略せずに示します。
10000字制限により全ては書き込めませんでした。

FreeRADIUS -Xから"Reply-Message = "20180328Hello, user"が出たのでRADIUS側は成功しているのではと思ってしまいました。

<wpa_supplicant　ログ>（一部省略あり）

~# wpa_supplicant -i eth3 -c /etc/wpa_supplicant.conf -D wired -dd
wpa_supplicant v2.6
random: Trying to read entropy from /dev/random
Successfully initialized wpa_supplicant
Initializing interface 'eth3' conf '/etc/wpa_supplicant.conf' driver 'wired' ctrl_interface 'N/A' bridge 'N/A'
＊文字数制限のため省略します。
＊
＊省略終わり
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_PAE entering state RESTART
EAP: EAP entering state INITIALIZE
EAP: EAP entering state IDLE
EAPOL: SUPP_PAE entering state AUTHENTICATING
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=1 method=1 vendor=0 vendorMethod=0
EAP: EAP entering state IDENTITY
eth3: CTRL-EVENT-EAP-STARTED EAP authentication started
EAP: Status notification: started (param=)
EAP: EAP-Request Identity data - hexdump_ascii(len=0):
EAP: using real identity - hexdump_ascii(len=4):
     75 73 65 72                                       user            
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
TX EAPOL: dst=01:80:c2:xx:xx:xx
TX EAPOL - hexdump(len=13): 01 00 00 09 02 01 00 09 01 75 73 65 72
EAPOL: SUPP_BE entering state RECEIVE
l2_packet_receive: src=34:76:c5:xx:xx:xx len=46
eth3: RX EAPOL from 34:76:c5:xx:xx:xx
RX EAPOL - hexdump(len=46): 02 00 00 06 01 02 00 06 0d 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=2 method=13 vendor=0 vendorMethod=0
EAP: EAP entering state GET_METHOD
eth3: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=13
EAP: Status notification: accept proposed method (param=TLS)
EAP: Initialize selected EAP method: vendor 0 method 13 (TLS)
TLS: using phase1 config options
OpenSSL: tls_connection_ca_cert - Failed to load root certificates error:02001002:system library:fopen:No such file or directory
OpenSSL: pending error: error:2006D080:BIO routines:BIO_new_file:no such file
OpenSSL: pending error: error:0B084002:x509 certificate routines:X509_load_cert_crl_file:system lib
OpenSSL: tls_load_ca_der - Failed load CA in DER format error:02001002:system library:fopen:No such file or directory
OpenSSL: pending error: error:20074002:BIO routines:FILE_CTRL:system lib
OpenSSL: pending error: error:0B06F002:x509 certificate routines:X509_load_cert_file:system lib
TLS: Failed to set TLS connection parameters
ENGINE: engine deinit
EAP-TLS: Failed to initialize SSL.
eth3: EAP: Failed to initialize EAP method: vendor 0 method 13 (TLS)
EAP: Building EAP-Nak (requested type 13 vendor=0 method=0 not allowed)
EAP: allowed methods - hexdump(len=0):
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
EAPOL: SUPP_BE entering state RESPONSE
EAPOL: txSuppRsp
TX EAPOL: dst=01:80:c2:xx:xx:xx
TX EAPOL - hexdump(len=10): 01 00 00 06 02 02 00 06 03 00
EAPOL: SUPP_BE entering state RECEIVE
l2_packet_receive: src=34:76:c5:xx:xx:xx len=46
eth3: RX EAPOL from 34:76:c5:xx:xx:xx
RX EAPOL - hexdump(len=46): 02 00 00 04 04 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
EAPOL: Received EAP-Packet frame
EAPOL: SUPP_BE entering state REQUEST
EAPOL: getSuppRsp
EAP: EAP entering state RECEIVED
EAP: Received EAP-Failure
EAP: Status notification: completion (param=failure)
EAP: EAP entering state FAILURE
eth3: CTRL-EVENT-EAP-FAILURE EAP authentication failed
EAPOL: SUPP_PAE entering state HELD
EAPOL: Supplicant port status: Unauthorized
EAPOL: SUPP_BE entering state RECEIVE
EAPOL: SUPP_BE entering state FAIL
EAPOL: SUPP_BE entering state IDLE
EAPOL authentication completed - result=FAILURE

<freeradius -X　ログ>（省略なし）


Ready to process requests.
rad_recv: Access-Request packet from host 192.168.1.253 port 19181, id=136, length=123
	NAS-IP-Address = 192.168.1.253
	NAS-Port = 5
	User-Name = "user"
	Called-Station-Id = "34-76-C5-70-F4-14"
	Calling-Station-Id = "00-22-CF-F9-2E-04"
	Service-Type = Framed-User
	Framed-MTU = 1300
	NAS-Port-Type = Ethernet
	Message-Authenticator = 0x1d0cf8f2a5cdb24657f4d76dfb804dc2
	EAP-Message = 0x020100090175736572
# Executing section authorize from file /etc/freeradius/sites-enabled/default
+group authorize {
++[preprocess] = ok
++[chap] = noop
++[mschap] = noop
++[digest] = noop
[suffix] No '@' in User-Name = "user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] = noop
[eap] EAP packet type response id 1 length 9
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] = updated
[files] users: Matched entry user at line 94
[files] 	expand: 20180328Hello, %{User-Name} -> 20180328Hello, user
++[files] = ok
++[expiration] = noop
++[logintime] = noop
[pap] WARNING: Auth-Type already set.  Not setting to PAP
++[pap] = noop
+} # group authorize = updated
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+group authenticate {
[eap] EAP Identity
[eap] processing type tls
[tls] Requiring client certificate
[tls] Initiate
[tls] Start returned 1
++[eap] = handled
+} # group authenticate = handled
Sending Access-Challenge of id 136 to 192.168.1.253 port 19181
	Reply-Message = "20180328Hello, user"
	EAP-Message = 0x010200060d20
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x67ee941c67ec99990c723ec61783218e
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.253 port 50587, id=136, length=138
	NAS-IP-Address = 192.168.1.253
	NAS-Port = 5
	User-Name = "user"
	Called-Station-Id = "34-76-C5-70-F4-14"
	Calling-Station-Id = "00-22-CF-F9-2E-04"
	Service-Type = Framed-User
	Framed-MTU = 1300
	NAS-Port-Type = Ethernet
	Message-Authenticator = 0xc32aa9880c71f8baab1c716b57118412
	EAP-Message = 0x020200060300
	State = 0x67ee941c67ec99990c723ec61783218e
# Executing section authorize from file /etc/freeradius/sites-enabled/default
+group authorize {
++[preprocess] = ok
++[chap] = noop
++[mschap] = noop
++[digest] = noop
[suffix] No '@' in User-Name = "user", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] = noop
[eap] EAP packet type response id 2 length 6
[eap] No EAP Start, assuming it's an on-going EAP conversation
++[eap] = updated
[files] users: Matched entry user at line 94
[files] 	expand: 20180328Hello, %{User-Name} -> 20180328Hello, user
++[files] = ok
++[expiration] = noop
++[logintime] = noop
[pap] WARNING: Auth-Type already set.  Not setting to PAP
++[pap] = noop
+} # group authorize = updated
Found Auth-Type = EAP
# Executing group from file /etc/freeradius/sites-enabled/default
+group authenticate {
[eap] Request found, released from the list
[eap] EAP NAK
[eap] NAK asked for bad type 0
[eap] Failed in EAP select
++[eap] = invalid
+} # group authenticate = invalid
Failed to authenticate the user.
Login incorrect: [user/<via Auth-Type = EAP>] (from client private-network-1 port 5 cli 00-22-CF-F9-2E-04)
Using Post-Auth-Type Reject
# Executing group from file /etc/freeradius/sites-enabled/default
+group REJECT {
[eap] Reply already contained an EAP-Message, not inserting EAP-Failure
++[eap] = noop
[attr_filter.access_reject] 	expand: %{User-Name} -> user
attr_filter: Matched entry DEFAULT at line 11
++[attr_filter.access_reject] = updated
+} # group REJECT = updated
Delaying reject of request 1 for 1 seconds
Going to the next request
Waking up in 0.9 seconds.
Sending delayed reject for request 1
Sending Access-Reject of id 136 to 192.168.1.253 port 50587
	Reply-Message = "20180328Hello, user"
	EAP-Message = 0x04020004
	Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 3.9 seconds.
Cleaning up request 0 ID 136 with timestamp +6
Waking up in 1.0 seconds.
Cleaning up request 1 ID 136 with timestamp +6
Ready to process requests.

TaichiYanagiya

2018/03/28 15:48

"radiusd -X" の出力を見ても認証に成功しているようには見えませんし、eap_tls モジュールが利用された形跡もありません。ログを省略せずに記載ください。また、PC から認証スイッチを経由する場合は wpa_supplicant を使い、radiusd 単体のテストは FreeRADIUS サーバー自身で eapol_test を実行した方が混乱がなくていいと思います。