Everything lookslike it works, but PC is not authentified

1 Sep 2006

      Hi,

I'am running Freeradius 1.1.0 on Suse 10.1 with certificates. After a 
lot of help from that list and a good FAQ I'am so far, that I generated 
the certs for server and client and that the communication between 
Client, Server and AP (Linksys Switch) works.

My problem is, that looking in the logs, the client should be 
authentified, but it isn't. The AP doesn't open the port. I assume the 
problem is windows, submitting the username as "host/computername" which 
brakes the certs (but I have no hint on the logfile). The PC tries to 
autheticate 13 times (I get at least 13 requests to the radius), but I 
get no error...

My users files contains that:

testuser        User-Password == "test2"

"host/vinfo-t1"  Auth-Type:= EAP

"vinfo-t1"  Auth-Type:= EAP

# On no match, the user is denied access.
DEFAULT Auth-Type := Reject
         Reply-Message = "Bye"

Please have a short look on my debuglog. I don't know where to look further.

TIA
  Alex

Debuglog:

radius:/etc/raddb # radiusd -A -X
Starting - reading configuration files ...
reread_config:  reading radiusd.conf
Config:   including file: /etc/raddb/clients.conf
Config:   including file: /etc/raddb/snmp.conf
Config:   including file: /etc/raddb/eap.conf
Config:   including file: /etc/raddb/sql.conf
  main: prefix = "/usr"
  main: localstatedir = "/var"
  main: logdir = "/var/log/radius"
  main: libdir = "/usr/lib/freeradius"
  main: radacctdir = "/var/log/radius/radacct"
  main: hostname_lookups = no
  main: max_request_time = 30
  main: cleanup_delay = 5
  main: max_requests = 1024
  main: delete_blocked_requests = 0
  main: port = 0
  main: allow_core_dumps = no
  main: log_stripped_names = no
  main: log_file = "/var/log/radius/radius.log"
  main: log_auth = no
  main: log_auth_badpass = no
  main: log_auth_goodpass = no
  main: pidfile = "/var/run/radiusd/radiusd.pid"
  main: user = "radiusd"
  main: group = "radiusd"
  main: usercollide = no
  main: lower_user = "no"
  main: lower_pass = "no"
  main: nospace_user = "no"
  main: nospace_pass = "no"
  main: checkrad = "/usr/sbin/checkrad"
  main: proxy_requests = no
  security: max_attributes = 200
  security: reject_delay = 1
  security: status_server = yes
  main: debug_level = 0
read_config_files:  reading dictionary
read_config_files:  reading naslist
read_config_files:  reading clients
read_config_files:  reading realms
radiusd:  entering modules setup
Module: Library search path is /usr/lib/freeradius
Module: Loaded expr
Module: Instantiated expr (expr)
Module: Loaded eap
  eap: default_eap_type = "tls"
  eap: timer_expire = 60
  eap: ignore_unknown_eap_types = no
  eap: cisco_accounting_username_bug = no
rlm_eap: Loaded and initialized type md5
rlm_eap: Loaded and initialized type leap
  gtc: challenge = "Password: "
  gtc: auth_type = "PAP"
rlm_eap: Loaded and initialized type gtc
  tls: rsa_key_exchange = no
  tls: dh_key_exchange = yes
  tls: rsa_key_length = 512
  tls: dh_key_length = 512
  tls: verify_depth = 0
  tls: CA_path = "(null)"
  tls: pem_file_type = yes
  tls: private_key_file = "/etc/raddb/certs/ssl/radius-neuer-cert-key.pem"
  tls: certificate_file = "/etc/raddb/certs/ssl/radius-neuer-cert-key.pem"
  tls: CA_file = 
"/etc/raddb/certs/ssl/ServiceCenter-IT_KHB_HfM_HfS-cacert.pem"
  tls: private_key_password = "secret"
  tls: dh_file = "/etc/raddb/certs/ssl/dh"
  tls: random_file = "/etc/raddb/certs/ssl/random"
  tls: fragment_size = 1024
  tls: include_length = yes
  tls: check_crl = no
  tls: check_cert_cn = "(null)"
rlm_eap_tls: Loading the certificate file as a chain
rlm_eap: Loaded and initialized type tls
  ttls: default_eap_type = "md5"
  ttls: copy_request_to_tunnel = no
  ttls: use_tunneled_reply = no
rlm_eap: Loaded and initialized type ttls
  peap: default_eap_type = "mschapv2"
  peap: copy_request_to_tunnel = no
  peap: use_tunneled_reply = no
  peap: proxy_tunneled_request_as_eap = yes
rlm_eap: Loaded and initialized type peap
  mschapv2: with_ntdomain_hack = no
rlm_eap: Loaded and initialized type mschapv2
Module: Instantiated eap (eap)
Module: Loaded preprocess
  preprocess: huntgroups = "/etc/raddb/huntgroups"
  preprocess: hints = "/etc/raddb/hints"
  preprocess: with_ascend_hack = no
  preprocess: ascend_channels_per_line = 23
  preprocess: with_ntdomain_hack = no
  preprocess: with_specialix_jetstream_hack = no
  preprocess: with_cisco_vsa_hack = no
Module: Instantiated preprocess (preprocess)
Module: Loaded files
  files: usersfile = "/etc/raddb/users"
  files: acctusersfile = "/etc/raddb/acct_users"
  files: preproxy_usersfile = "/etc/raddb/preproxy_users"
  files: compat = "no"
Module: Instantiated files (files)
Module: Loaded Acct-Unique-Session-Id
  acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, 
Client-IP-Address, NAS-Port"
Module: Instantiated acct_unique (acct_unique)
Module: Loaded detail
  detail: detailfile = 
"/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
  detail: detailperm = 384
  detail: dirperm = 493
  detail: locking = no
Module: Instantiated detail (detail)
Listening on authentication *:1812
Listening on accounting *:1813
Ready to process requests.

rad_recv: Access-Request packet from host 10.48.244.21:49154, id=0, 
length=91
         NAS-IP-Address = 10.48.244.21
         NAS-Port-Type = Ethernet
         NAS-Port = 3
         User-Name = "host/vinfo-t1"
         EAP-Message = 0x0202001201686f73742f76696e666f2d7431
         Message-Authenticator = 0xc1f35f98d7fadcae44c1da0404dfb946
   Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
   modcall[authorize]: module "preprocess" returns ok for request 0
   rlm_eap: EAP packet type response id 2 length 18
   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
   modcall[authorize]: module "eap" returns updated for request 0
     users: Matched entry host/vinfo-t1 at line 219
   modcall[authorize]: module "files" returns ok for request 0
modcall: leaving group authorize (returns updated) for request 0
   rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
   Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 0
   rlm_eap: EAP Identity
   rlm_eap: processing type tls
  rlm_eap_tls: Requiring client certificate
   rlm_eap_tls: Initiate
   rlm_eap_tls: Start returned 1
   modcall[authenticate]: module "eap" returns handled for request 0
modcall: leaving group authenticate (returns handled) for request 0
Sending Access-Challenge of id 0 to 10.48.244.21 port 49154
         EAP-Message = 0x010300060d20
         Message-Authenticator = 0x00000000000000000000000000000000
         State = 0xa888eb3548ccbf70991a8073e4917860
Finished request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 10.48.244.21:49154, id=0, 
length=171
         NAS-IP-Address = 10.48.244.21
         NAS-Port-Type = Ethernet
         NAS-Port = 3
         User-Name = "host/vinfo-t1"
         State = 0xa888eb3548ccbf70991a8073e4917860
         EAP-Message = 
0x020300500d800000004616030100410100003d030144f82ec02d87663894bd52ff81b6e458129ee76d422652e5d90c0184b3ab2c4b00001600040005000a000900640062000300060013001200630100
         Message-Authenticator = 0x393361b2d5cc0e7f8caf5a584d4aab7d
   Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
   modcall[authorize]: module "preprocess" returns ok for request 1
   rlm_eap: EAP packet type response id 3 length 80
   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
   modcall[authorize]: module "eap" returns updated for request 1
     users: Matched entry host/vinfo-t1 at line 219
   modcall[authorize]: module "files" returns ok for request 1
modcall: leaving group authorize (returns updated) for request 1
   rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
   Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 1
   rlm_eap: Request found, released from the list
   rlm_eap: EAP/tls
   rlm_eap: processing type tls
   rlm_eap_tls: Authenticate
   rlm_eap_tls: processing TLS
rlm_eap_tls:  Length Included
   eaptls_verify returned 11
     (other): before/accept initialization
     TLS_accept: before/accept initialization
   rlm_eap_tls: <<< TLS 1.0 Handshake [length 0041], ClientHello
     TLS_accept: SSLv3 read client hello A
   rlm_eap_tls: >>> TLS 1.0 Handshake [length 004a], ServerHello
     TLS_accept: SSLv3 write server hello A
   rlm_eap_tls: >>> TLS 1.0 Handshake [length 0ef8], Certificate
     TLS_accept: SSLv3 write certificate A
   rlm_eap_tls: >>> TLS 1.0 Handshake [length 00bd], CertificateRequest
     TLS_accept: SSLv3 write certificate request A
     TLS_accept: SSLv3 flush data
     TLS_accept:error in SSLv3 read client certificate A
In SSL Handshake Phase
In SSL Accept mode
   eaptls_process returned 13
   modcall[authenticate]: module "eap" returns handled for request 1
modcall: leaving group authenticate (returns handled) for request 1
Sending Access-Challenge of id 0 to 10.48.244.21 port 49154
         EAP-Message = 
0x0104040a0dc00000100e160301004a02000046030144cbfc6ec473fda5a1d6059b489343f31dc6ce6ead7e88eaa9f0529253a6b97720dccbf137a27e973554fc428b8a2f075a212e34712e6ed1721fb1e456c90e62640004001603010ef80b000ef4000ef100077f3082077b30820563a003020102020128300d06092a864886f70d01010505003081aa310b3009060355040613024445310f300d060355040813064265726c696e310f300d060355040713064265726c696e31143012060355040a130b4b48422048664d2048665331193017060355040b13105365727669636543656e7465722d4954312530230603550403141c5365727669636543
         EAP-Message = 
0x656e7465722d49545f4b48425f48664d5f4866533121301f06092a864886f70d010901161273632d6974406b682d6265726c696e2e6465301e170d3036303831303039333334335a170d3037303831303039333334335a3081ac310b3009060355040613024445310f300d060355040813064265726c696e310f300d060355040713064265726c696e31143012060355040a130b4b48422048664d2048665331193017060355040b13105365727669636543656e7465722d4954312730250603550403131e7261646975732e76657277616c74756e672e6b682d6265726c696e2e64653121301f06092a864886f70d010901161273632d6974406b682d
         EAP-Message = 
0x6265726c696e2e646530820222300d06092a864886f70d01010105000382020f003082020a02820201009d061598c850223454cb70a58cae0a1ac2db0b6a963d25c96c632b1eb2a9177e3e8a066fa9c3596c4a1b035def3b6c589a12209a6d7ab7aa4144de890803c34cb5239cdb3b7266426049d475ed3e354fe494dee46a17e7478065c7332f6ac621d9b754d46812dc4ffda7a39bf33987fbe6951a591aee791c9468cc70f5a821683640675bafea24fe5291d6750c30a1b0a4c52cbeb6a18ce514038432f3dc83ce12657de67976dff9a7643b7ad340240e5e69385355b64d3e77f4bb0dfbc8fd63258a308c2a6e82f9c0c92e7e4ccadf848cc3bb
         EAP-Message = 
0x57d592dcf46930c794fa0b338c9db103b9a7162352ff8cac3b680d64ec0b865bf74778839cd1530d79ba553a2bd9ffb112534cd758bb3b3dba26037ed1c158089af8903e9f5b684061ddd413fb192cfc5024c03b177184101d68bc7111ccdcb6bee8c98d1642bbc547e8211dab2fd5d45488da089a17edaa9b4dd4357d4adcb0e33553210a5ad0e84edc9f9a769297649672d5f78e2f3687e99c411abea88e0363fe1afb7dcf05a8838ef07cec88337f903a94a6207893b5e9ff80441a12b6847ff008eb8c257878f6711a8f8c053315d4ae87b36661cdee73a3cbaca92d14f480804c7476d36665c417db9c954795423ca49de599eb3ed3a6cc55f03b
         EAP-Message = 0xad529359b0a55e5bffa9cf65b3034d48c263c491b24a
         Message-Authenticator = 0x00000000000000000000000000000000
         State = 0x8ada72f87d56fd2eeffabef3ec09dc62
Finished request 1
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 10.48.244.21:49154, id=0, 
length=97
         NAS-IP-Address = 10.48.244.21
         NAS-Port-Type = Ethernet
         NAS-Port = 3
         User-Name = "host/vinfo-t1"
         State = 0x8ada72f87d56fd2eeffabef3ec09dc62
         EAP-Message = 0x020400060d00
         Message-Authenticator = 0x8d34aa0b0247b80bb0bc1f1fcb163af7
   Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 2
   modcall[authorize]: module "preprocess" returns ok for request 2
   rlm_eap: EAP packet type response id 4 length 6
   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
   modcall[authorize]: module "eap" returns updated for request 2
     users: Matched entry host/vinfo-t1 at line 219
   modcall[authorize]: module "files" returns ok for request 2
modcall: leaving group authorize (returns updated) for request 2
   rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
   Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 2
   rlm_eap: Request found, released from the list
   rlm_eap: EAP/tls
   rlm_eap: processing type tls
   rlm_eap_tls: Authenticate
   rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
   rlm_eap_tls: ack handshake fragment handler
   eaptls_verify returned 1
   eaptls_process returned 13
   modcall[authenticate]: module "eap" returns handled for request 2
modcall: leaving group authenticate (returns handled) for request 2
Sending Access-Challenge of id 0 to 10.48.244.21 port 49154
         EAP-Message = 
0x0105040a0dc00000100ed9f9f74b6ea9cea17710efc22bc0d77f58b0a5d3589ab19f13f90203010001a38201a6308201a230090603551d1304023000301106096086480186f8420101040403020640302b06096086480186f842010d041e161c54696e7943412047656e657261746564204365727469666963617465301d0603551d0e0416041442a94a9f048871b178d41a5d00a5668e78c045ff3081df0603551d230481d73081d48014b939b6ce8a52912eaece162418b1f4d8303d042ea181b0a481ad3081aa310b3009060355040613024445310f300d060355040813064265726c696e310f300d060355040713064265726c696e311430120603
         EAP-Message = 
0x55040a130b4b48422048664d2048665331193017060355040b13105365727669636543656e7465722d4954312530230603550403141c5365727669636543656e7465722d49545f4b48425f48664d5f4866533121301f06092a864886f70d010901161273632d6974406b682d6265726c696e2e6465820900890d6f61ac0ce005301d0603551d1204163014811273632d6974406b682d6265726c696e2e6465301d0603551d1104163014811273632d6974406b682d6265726c696e2e646530160603551d250101ff040c300a06082b06010505070301300d06092a864886f70d01010505000382020100c0925f1aa48825e5c192abc4a792cb36b69953
         EAP-Message = 
0x782adc04d3e24436b4322312505087f51371012554b69768c152ed7083dba76437cc2bd09ed94b2a08a9ce1ad303a04ee2459c219c6e8341c44175cdcf5426ab7d10b9512877be1cd89204061f78c7f9296b5c73bcc315b281029163cd1f05d9fff0f772fd26964959a4493ef045f91dda761420537f2845a12d7a0f7f04502390dd6fb1e7cbff2891d8eee5abcf7da435ab6b163e2475fad3ccf8cfdc7ad019fbbe1deb47fbcad40dd4f57d2ed127665ca99cc035d93bf5df6ad79529fa142cb7f03eedd1aca47ad648db900e6dcd1966efb52a2c9dfa5ce5148ad4bd37716414c3a82bcb9a8cd805f1ea4e66f0171174e8099310d720186c2774cdc2
         EAP-Message = 
0xf80283f897fa84a1281e34c77148ca68508cd2eaf3f9167f76b41df115df8bcf02746dac891da3f58b4a45e5085dcbb3e9129106bb999f2b6b4722b86a32e18732260fa1093643a982b52951d7011141f3ea9ec18429482b3977620aa50aa40cd30eb3ed16f1a1c77d07df0672abdf64d608ff85a9076b95afb5a12a3a1fc231024403628b1db8cf04d474be335f83e230d506eb574b91fd672e092dd86088ea95edbe95aaecc00f4610520cd6a624103c64d1e8f6ebb8027ec42fa27ff3fdad82731a8511b8a68751452ebcbd13e11a0abe6d1f82fd5ce98af910ce7e62a69e9ac2383ee9b3dc0a973af95706a3a1c700076c3082076830820550a003
         EAP-Message = 0x020102020900890d6f61ac0ce005300d06092a864886
         Message-Authenticator = 0x00000000000000000000000000000000
         State = 0x9a47ab7f9de113ebbe793cdba4b8eac5
Finished request 2
[...]
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 10.48.244.21:49154, id=0, 
length=97
         NAS-IP-Address = 10.48.244.21
         NAS-Port-Type = Ethernet
         NAS-Port = 3
         User-Name = "host/vinfo-t1"
         State = 0x02e56d8de12a870049b3b02e1f4ad162
         EAP-Message = 0x021100060d00
         Message-Authenticator = 0x8a9e680cc21b98a2835861c9ef08faea
   Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 13
   modcall[authorize]: module "preprocess" returns ok for request 13
   rlm_eap: EAP packet type response id 17 length 6
   rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
   modcall[authorize]: module "eap" returns updated for request 13
     users: Matched entry host/vinfo-t1 at line 219
   modcall[authorize]: module "files" returns ok for request 13
modcall: leaving group authorize (returns updated) for request 13
   rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
   Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 13
   rlm_eap: Request found, released from the list
   rlm_eap: EAP/tls
   rlm_eap: processing type tls
   rlm_eap_tls: Authenticate
   rlm_eap_tls: processing TLS
rlm_eap_tls: Received EAP-TLS ACK message
   rlm_eap_tls: ack handshake fragment handler
   eaptls_verify returned 1
   eaptls_process returned 13
   modcall[authenticate]: module "eap" returns handled for request 13
modcall: leaving group authenticate (returns handled) for request 13
Sending Access-Challenge of id 0 to 10.48.244.21 port 49154
         EAP-Message = 0x0112000a0d8000000000
         Message-Authenticator = 0x00000000000000000000000000000000
         State = 0x3f9387f3adb41ddea578c30fd328358f
Finished request 13
Going to the next request
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 13 ID 0 with timestamp 44cbfc94
Nothing to do.  Sleeping until we see a request.

-- 
ServiceCenter IT - Alexandros Gougousoudis (Leiter)

Gemeinsame Einrichtung der Kunsthochschule Berlin-Weissensee, Hochschule 
für Musik "Hanns Eisler" und der Hochschule für Schauspielkunst "Ernst 
Busch".

Tel.: 030 / 477 05 - 444 * Fax.: 030 / 477 05 - 445