R: Eap-Tls Problem

Matteo Lazzarini mlazzarini at crema.unimi.it
Wed Aug 23 19:11:17 CEST 2006


K. Hoercher wrote:

> .........
> 3. I more or less duplicated your setup from
> <44EB5C4F.2040504 at crema.unimi.it>and tested it here with
> freeradius-1.1.2, hostapd-0.5.3, wpa_supplicant-0.5.4. It worked as
> you wish and should be expected.
>
> 4. It even worked with the hard Auth-Type setting in users file
> (changed to local environment) despite that being unnecessary and
> insofar wrong. Please see
> http://deployingradius.com/documents/configuration/auth_type.html. I
> cannot understand french, but at least in this respect
> http://www.alphacore.net/spip/article.php3?id_article=33 seems to err.
>
Ok, i deleted Auth-Type setting in users file.
My user now is:

marcello

> 6. The radius.log you attached earlier didn't show any incoming
> EAP-Responses to the Challenges freeradius sent out.
> The snippets you keep posting since then show a part of the debug log,
> which doesn't exhibit a fault compared to what I'm getting here. If
> the cut off parts show the same  as in the attached file, the same
> problem exists: your client isn't responding properly.

> regards
> K. Hoercher 

This is what continuous to see when start radiusd - X:

rad_recv: Access-Request packet from host 192.168.1.5:1214, id=36, 
length=139
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 0x0223000d016d617263656c6c6f
        Message-Authenticator = 0x8afce08acace447ca9a52f94717767dd
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 27
  modcall[authorize]: module "preprocess" returns ok for request 27
radius_xlat:  
'/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823'
rlm_detail: 
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823
  modcall[authorize]: module "auth_log" returns ok for request 27
  rlm_eap: EAP packet type response id 35 length 13
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 27
    users: Matched entry marcello at line 7
  modcall[authorize]: module "files" returns ok for request 27
modcall: leaving group authorize (returns updated) for request 27
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 27
  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 27
modcall: leaving group authenticate (returns handled) for request 27
Sending Access-Challenge of id 36 to 192.168.1.5 port 1214
        EAP-Message = 0x012400060d20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x4a4231b4adfeba0f626bea47adfe79b3
Finished request 27
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.1.5:1214, id=37, 
length=224
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 
0x022400500d800000004616030100410100003d030144ec5fa59a64845898c9f5ad123fc6b0198a4905db195cec34455b869c4d4b1100001600040005000a000900640062000300060013001200630100 

        State = 0x4a4231b4adfeba0f626bea47adfe79b3
        Message-Authenticator = 0x954557a26d69418d4ec39d196da5d9b1
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 28
  modcall[authorize]: module "preprocess" returns ok for request 28
radius_xlat:  
'/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823'
rlm_detail: 
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823
  modcall[authorize]: module "auth_log" returns ok for request 28
  rlm_eap: EAP packet type response id 36 length 80
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 28
    users: Matched entry marcello at line 7
  modcall[authorize]: module "files" returns ok for request 28
modcall: leaving group authorize (returns updated) for request 28
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 28
  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 0715], Certificate  
    TLS_accept: SSLv3 write certificate A 
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 00c7], CertificateRequest  
    TLS_accept: SSLv3 write certificate request A 
    TLS_accept: SSLv3 flush data 
    TLS_accept:error in SSLv3 read client certificate A 
rlm_eap: SSL error error:00000000:lib(0):func(0):reason(0)
In SSL Handshake Phase 
In SSL Accept mode  
  eaptls_process returned 13 
  modcall[authenticate]: module "eap" returns handled for request 28
modcall: leaving group authenticate (returns handled) for request 28
Sending Access-Challenge of id 37 to 192.168.1.5 port 1214
        EAP-Message = 
0x0125040a0dc000000835160301004a02000046030144ec6005a36d16b4738f0725c7e28d3aacc9e100cee2b61fd3f8b5525dab88a12056e63ac6ba7034af4f37c7329304af510ee21461f940f7718850d502ebfad26200040016030107150b00071100070e0002fa308202f63082025fa003020102020900f224c648347dc88c300d06092a864886f70d01010405003081b5310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110300e06035504 

        EAP-Message = 
0x0b1307696d692073726c311630140603550403130d43412d467265657261646975733126302406092a864886f70d0109011617667265657261646975734067727570706f696d692e6974301e170d3036303832323136333935375a170d3037303832323136333935375a3081aa310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110300e060355040b1307696d692073726c310f300d060355040313066a61676765723122302006092a864886 

        EAP-Message = 
0xf70d01090116136a61676765724067727570706f696d692e697430819f300d06092a864886f70d010101050003818d0030818902818100c2889e425836d09f8235751e0ff076778dfad149ef3ef3f5d474375ad07c6d7d8924c1626b2c5478638564287fb4023b5ce68bcd0ffd7c21ac57d06ef8ef98f5ab9d5de84379f4f64bdef487a93350102d22f58200f16000756e3e98a677881f171155a679058c72d7a23d88e9d29daa1be63a014dca55ab45ac4383f04dbf610203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d010104050003818100b2288be7befe02ede8b87a2965337aaa586ac346be 

        EAP-Message = 
0x14150f8914a326d60ec602e4e2076441b2266b013a2a5a6a083adf3abad567d1581e42fe22dfba9ae4b1a6e08333fe84d50950a5ff6a918f1bdcde276c6563d208ab5b6e95128e38e9454314e3a8be08896e031ef2f1332347d9b93e6caa8761ef5e9758ef6618946f816e00040e3082040a30820373a003020102020900f224c648347dc88a300d06092a864886f70d01010405003081b5310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110 

        EAP-Message = 0x300e060355040b1307696d692073726c311630140603
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xd61433c363fad2062dd0ed86dd317d38
Finished request 28
Going to the next request
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 27 ID 36 with timestamp 44ec6005
Cleaning up request 28 ID 37 with timestamp 44ec6005
Nothing to do.  Sleeping until we see a request.
rad_recv: Access-Request packet from host 192.168.1.5:1214, id=38, 
length=139
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 0x0226000d016d617263656c6c6f
        Message-Authenticator = 0xdc2e7392680a90e16f7675db392ae62a
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 29
  modcall[authorize]: module "preprocess" returns ok for request 29
radius_xlat:  
'/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823'
rlm_detail: 
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823
  modcall[authorize]: module "auth_log" returns ok for request 29
  rlm_eap: EAP packet type response id 38 length 13
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 29
    users: Matched entry marcello at line 7
  modcall[authorize]: module "files" returns ok for request 29
modcall: leaving group authorize (returns updated) for request 29
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 29
  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 29
modcall: leaving group authenticate (returns handled) for request 29
Sending Access-Challenge of id 38 to 192.168.1.5 port 1214
        EAP-Message = 0x012700060d20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xbe099fcd698213125f5c1f9b6f57edf0
Finished request 29
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.1.5:1214, id=39, 
length=224
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 
0x022700500d800000004616030100410100003d030144ec5fc3b3c0a02d79dde2cbaee6994cb365bda0921afe69fea98cf513ae68be00001600040005000a000900640062000300060013001200630100 

        State = 0xbe099fcd698213125f5c1f9b6f57edf0
        Message-Authenticator = 0xd6d1ed5825fe4c35f5a1d60b5898697c
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 30
  modcall[authorize]: module "preprocess" returns ok for request 30
radius_xlat:  
'/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823'
rlm_detail: 
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823
  modcall[authorize]: module "auth_log" returns ok for request 30
  rlm_eap: EAP packet type response id 39 length 80
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 30
    users: Matched entry marcello at line 7
  modcall[authorize]: module "files" returns ok for request 30
modcall: leaving group authorize (returns updated) for request 30
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 30
  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 0715], Certificate  
    TLS_accept: SSLv3 write certificate A 
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 00c7], CertificateRequest  
    TLS_accept: SSLv3 write certificate request A 
    TLS_accept: SSLv3 flush data 
    TLS_accept:error in SSLv3 read client certificate A 
rlm_eap: SSL error error:00000000:lib(0):func(0):reason(0)
In SSL Handshake Phase 
In SSL Accept mode  
  eaptls_process returned 13 
  modcall[authenticate]: module "eap" returns handled for request 30
modcall: leaving group authenticate (returns handled) for request 30
Sending Access-Challenge of id 39 to 192.168.1.5 port 1214
        EAP-Message = 
0x0128040a0dc000000835160301004a02000046030144ec602379b9029259e24bf1b103bb550102f05bfed202c361b441e98891a58c20c0328494ad8c1af13e31715a0d7c244a442af30d449dd3b72f9811946120d00200040016030107150b00071100070e0002fa308202f63082025fa003020102020900f224c648347dc88c300d06092a864886f70d01010405003081b5310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110300e06035504 

        EAP-Message = 
0x0b1307696d692073726c311630140603550403130d43412d467265657261646975733126302406092a864886f70d0109011617667265657261646975734067727570706f696d692e6974301e170d3036303832323136333935375a170d3037303832323136333935375a3081aa310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110300e060355040b1307696d692073726c310f300d060355040313066a61676765723122302006092a864886 

        EAP-Message = 
0xf70d01090116136a61676765724067727570706f696d692e697430819f300d06092a864886f70d010101050003818d0030818902818100c2889e425836d09f8235751e0ff076778dfad149ef3ef3f5d474375ad07c6d7d8924c1626b2c5478638564287fb4023b5ce68bcd0ffd7c21ac57d06ef8ef98f5ab9d5de84379f4f64bdef487a93350102d22f58200f16000756e3e98a677881f171155a679058c72d7a23d88e9d29daa1be63a014dca55ab45ac4383f04dbf610203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d010104050003818100b2288be7befe02ede8b87a2965337aaa586ac346be 

        EAP-Message = 
0x14150f8914a326d60ec602e4e2076441b2266b013a2a5a6a083adf3abad567d1581e42fe22dfba9ae4b1a6e08333fe84d50950a5ff6a918f1bdcde276c6563d208ab5b6e95128e38e9454314e3a8be08896e031ef2f1332347d9b93e6caa8761ef5e9758ef6618946f816e00040e3082040a30820373a003020102020900f224c648347dc88a300d06092a864886f70d01010405003081b5310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110 

        EAP-Message = 0x300e060355040b1307696d692073726c311630140603
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x20848349a7d8931898eab18b497b7eaa
Finished request 30
Going to the next request
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 29 ID 38 with timestamp 44ec6023
Cleaning up request 30 ID 39 with timestamp 44ec6023
Nothing to do.  Sleeping until we see a request.
rad_recv: Access-Request packet from host 192.168.1.5:1214, id=40, 
length=139
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 0x0229000d016d617263656c6c6f
        Message-Authenticator = 0xa1721cbe7301b0520d0be5a419388965
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 31
  modcall[authorize]: module "preprocess" returns ok for request 31
radius_xlat:  
'/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823'
rlm_detail: 
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823
  modcall[authorize]: module "auth_log" returns ok for request 31
  rlm_eap: EAP packet type response id 41 length 13
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 31
    users: Matched entry marcello at line 7
  modcall[authorize]: module "files" returns ok for request 31
modcall: leaving group authorize (returns updated) for request 31
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 31
  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 31
modcall: leaving group authenticate (returns handled) for request 31
Sending Access-Challenge of id 40 to 192.168.1.5 port 1214
        EAP-Message = 0x012a00060d20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x6e1434ca3d57d931af8880e288a906a5
Finished request 31
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.1.5:1214, id=41, 
length=224
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 
0x022a00500d800000004616030100410100003d030144ec5fe1afe282c139685d0cc920d57ec74fadd16301b2b11d962a4c48167e9a00001600040005000a000900640062000300060013001200630100 

        State = 0x6e1434ca3d57d931af8880e288a906a5
        Message-Authenticator = 0x562492cb1ddbe4fe6e6f26676b04641a
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 32
  modcall[authorize]: module "preprocess" returns ok for request 32
radius_xlat:  
'/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823'
rlm_detail: 
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823
  modcall[authorize]: module "auth_log" returns ok for request 32
  rlm_eap: EAP packet type response id 42 length 80
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 32
    users: Matched entry marcello at line 7
  modcall[authorize]: module "files" returns ok for request 32
modcall: leaving group authorize (returns updated) for request 32
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 32
  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 0715], Certificate  
    TLS_accept: SSLv3 write certificate A 
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 00c7], CertificateRequest  
    TLS_accept: SSLv3 write certificate request A 
    TLS_accept: SSLv3 flush data 
    TLS_accept:error in SSLv3 read client certificate A 
rlm_eap: SSL error error:00000000:lib(0):func(0):reason(0)
In SSL Handshake Phase 
In SSL Accept mode  
  eaptls_process returned 13 
  modcall[authenticate]: module "eap" returns handled for request 32
modcall: leaving group authenticate (returns handled) for request 32
Sending Access-Challenge of id 41 to 192.168.1.5 port 1214
        EAP-Message = 
0x012b040a0dc000000835160301004a02000046030144ec6041b7dd765e8e8522dafce7f647e1e3f83e07194d2445c0e8ed0f6eb448205e608aec3f12e3763220cc2838cfe79c1a371553d637835c640b8cf3fa9ea46c00040016030107150b00071100070e0002fa308202f63082025fa003020102020900f224c648347dc88c300d06092a864886f70d01010405003081b5310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110300e06035504 

        EAP-Message = 
0x0b1307696d692073726c311630140603550403130d43412d467265657261646975733126302406092a864886f70d0109011617667265657261646975734067727570706f696d692e6974301e170d3036303832323136333935375a170d3037303832323136333935375a3081aa310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110300e060355040b1307696d692073726c310f300d060355040313066a61676765723122302006092a864886 

        EAP-Message = 
0xf70d01090116136a61676765724067727570706f696d692e697430819f300d06092a864886f70d010101050003818d0030818902818100c2889e425836d09f8235751e0ff076778dfad149ef3ef3f5d474375ad07c6d7d8924c1626b2c5478638564287fb4023b5ce68bcd0ffd7c21ac57d06ef8ef98f5ab9d5de84379f4f64bdef487a93350102d22f58200f16000756e3e98a677881f171155a679058c72d7a23d88e9d29daa1be63a014dca55ab45ac4383f04dbf610203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d010104050003818100b2288be7befe02ede8b87a2965337aaa586ac346be 

        EAP-Message = 
0x14150f8914a326d60ec602e4e2076441b2266b013a2a5a6a083adf3abad567d1581e42fe22dfba9ae4b1a6e08333fe84d50950a5ff6a918f1bdcde276c6563d208ab5b6e95128e38e9454314e3a8be08896e031ef2f1332347d9b93e6caa8761ef5e9758ef6618946f816e00040e3082040a30820373a003020102020900f224c648347dc88a300d06092a864886f70d01010405003081b5310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110 

        EAP-Message = 0x300e060355040b1307696d692073726c311630140603
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xc9750d7b7c4f4c25d35382ef3c495bf3
Finished request 32
Going to the next request
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 31 ID 40 with timestamp 44ec6041
Cleaning up request 32 ID 41 with timestamp 44ec6041
Nothing to do.  Sleeping until we see a request.
rad_recv: Access-Request packet from host 192.168.1.5:1214, id=42, 
length=139
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 0x022c000d016d617263656c6c6f
        Message-Authenticator = 0x490a18c23fc91fdc1c9b8e643b1e369c
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 33
  modcall[authorize]: module "preprocess" returns ok for request 33
radius_xlat:  
'/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823'
rlm_detail: 
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823
  modcall[authorize]: module "auth_log" returns ok for request 33
  rlm_eap: EAP packet type response id 44 length 13
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 33
    users: Matched entry marcello at line 7
  modcall[authorize]: module "files" returns ok for request 33
modcall: leaving group authorize (returns updated) for request 33
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 33
  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 33
modcall: leaving group authenticate (returns handled) for request 33
Sending Access-Challenge of id 42 to 192.168.1.5 port 1214
        EAP-Message = 0x012d00060d20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x03c28905812b5b3f6b129e967146cf6f
Finished request 33
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 192.168.1.5:1214, id=43, 
length=224
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 
0x022d00500d800000004616030100410100003d030144ec5fff1ddc76fd1cd92cf4a616ed25f594f37b078d23151e633e7adbaa807d00001600040005000a000900640062000300060013001200630100 

        State = 0x03c28905812b5b3f6b129e967146cf6f
        Message-Authenticator = 0x7d908821b7b8043f3af46b45ea38b038
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 34
  modcall[authorize]: module "preprocess" returns ok for request 34
radius_xlat:  
'/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823'
rlm_detail: 
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d 
expands to 
/usr/local/var/log/radius/radacct/192.168.1.5/auth-detail-20060823
  modcall[authorize]: module "auth_log" returns ok for request 34
  rlm_eap: EAP packet type response id 45 length 80
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 34
    users: Matched entry marcello at line 7
  modcall[authorize]: module "files" returns ok for request 34
modcall: leaving group authorize (returns updated) for request 34
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 34
  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 0715], Certificate  
    TLS_accept: SSLv3 write certificate A 
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 00c7], CertificateRequest  
    TLS_accept: SSLv3 write certificate request A 
    TLS_accept: SSLv3 flush data 
    TLS_accept:error in SSLv3 read client certificate A 
rlm_eap: SSL error error:00000000:lib(0):func(0):reason(0)
In SSL Handshake Phase 
In SSL Accept mode  
  eaptls_process returned 13 
  modcall[authenticate]: module "eap" returns handled for request 34
modcall: leaving group authenticate (returns handled) for request 34
Sending Access-Challenge of id 43 to 192.168.1.5 port 1214
        EAP-Message = 
0x012e040a0dc000000835160301004a02000046030144ec605fb82c174431ef92debba911fd499931199bf231f28652609ac0b808f6200f53f7874c685ad093cdc266a254182b21efc28655f8deb62304a41f7a23f9d500040016030107150b00071100070e0002fa308202f63082025fa003020102020900f224c648347dc88c300d06092a864886f70d01010405003081b5310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110300e06035504 

        EAP-Message = 
0x0b1307696d692073726c311630140603550403130d43412d467265657261646975733126302406092a864886f70d0109011617667265657261646975734067727570706f696d692e6974301e170d3036303832323136333935375a170d3037303832323136333935375a3081aa310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110300e060355040b1307696d692073726c310f300d060355040313066a61676765723122302006092a864886 

        EAP-Message = 
0xf70d01090116136a61676765724067727570706f696d692e697430819f300d06092a864886f70d010101050003818d0030818902818100c2889e425836d09f8235751e0ff076778dfad149ef3ef3f5d474375ad07c6d7d8924c1626b2c5478638564287fb4023b5ce68bcd0ffd7c21ac57d06ef8ef98f5ab9d5de84379f4f64bdef487a93350102d22f58200f16000756e3e98a677881f171155a679058c72d7a23d88e9d29daa1be63a014dca55ab45ac4383f04dbf610203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d010104050003818100b2288be7befe02ede8b87a2965337aaa586ac346be 

        EAP-Message = 
0x14150f8914a326d60ec602e4e2076441b2266b013a2a5a6a083adf3abad567d1581e42fe22dfba9ae4b1a6e08333fe84d50950a5ff6a918f1bdcde276c6563d208ab5b6e95128e38e9454314e3a8be08896e031ef2f1332347d9b93e6caa8761ef5e9758ef6618946f816e00040e3082040a30820373a003020102020900f224c648347dc88a300d06092a864886f70d01010405003081b5310b3009060355040613024954310e300c060355040813054954414c593110300e0603550407130742657267616d6f31123010060355040a130947727570706f696d69311e301c060355040a13153830322e31782041757468656e7469636174696f6e3110 

        EAP-Message = 0x300e060355040b1307696d692073726c311630140603
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xeacc5432cc73aaa14a0bb9aae4a1c3cb
Finished request 34
Going to the next request
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 33 ID 42 with timestamp 44ec605f
Cleaning up request 34 ID 43 with timestamp 44ec605f

Probably it is like you said; "If the cut off parts show the same  as in 
the attached file, the same problem exists: your client isn't responding 
properly."...
The clients system is Windows XP SP2 and I used the default supplicant. 
It is subject to particular problems? Many guides speak about as to 
configure an win xp supplicant and I have made like they without to 
change nothing.

They could be the certs not-compatible?
It could be AP not to send the messages correctly? The AP's log are very 
poors. Only see the Access-Request from the user "marcello".


Aug/23/2006 16:48:48  Send Accounting logout message marcello
Aug/23/2006 16:48:48  EAP-Failure 00-0C-F1-15-17-59
Aug/23/2006 16:48:48  state: paeDISCONNECTED 
Aug/23/2006 16:48:43  EAP-Request/Identity
Aug/23/2006 16:48:38  EAP-Request/Identity 
Aug/23/2006 16:48:33  EAP-Request/Identity 
Aug/23/2006 16:48:28  EAP-Request/Identity 
Aug/23/2006 16:48:23  EAP-Request/Identity 
Aug/23/2006 16:48:18  EAP-Request/Identity 
Aug/23/2006 16:48:13  EAP-Request/Identity 
Aug/23/2006 16:48:08  EAP-Request/Identity 
Aug/23/2006 16:48:04  Authentication timeout 00-0C-F1-15-17-59
Aug/23/2006 16:48:04  EAP-Request/Identity 
Aug/23/2006 16:48:04  EAP-Failure 00-0C-F1-15-17-59
Aug/23/2006 16:48:04  EAP-Request/Identity
Aug/23/2006 16:48:04  EAP-Failure 00-0C-F1-15-17-59
Aug/23/2006 16:48:00  EAP-Response/Identity marcello
Aug/23/2006 16:48:00  EAP-Request/Identity 
Aug/23/2006 16:47:56  Authentication timeout 00-0C-F1-15-17-59
Aug/23/2006 16:47:56  EAP-Request/Identity 
Aug/23/2006 16:47:56  EAP-Failure 00-0C-F1-15-17-59
Aug/23/2006 16:47:52  EAP-Response/Identity marcello
Aug/23/2006 16:47:52  EAP-Request/Identity

This is a .../radacct/192.168.1.5/auth-detail-20060823 log file:

Packet-Type = Access-Request
Wed Aug 23 16:04:15 2006
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 
0x022d00500d800000004616030100410100003d030144ec5fff1ddc7$
        State = 0x03c28905812b5b3f6b129e967146cf6f
        Message-Authenticator = 0x7d908821b7b8043f3af46b45ea38b038

Packet-Type = Access-Request
Wed Aug 23 16:04:15 2006
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 
0x022d00500d800000004616030100410100003d030144ec5fff1ddc76fd1cd92cf4a616ed25f594f37b078d23151e633e7adbaa807d00001600040005000a0009006$
        State = 0x03c28905812b5b3f6b129e967146cf6f
        Message-Authenticator = 0x7d908821b7b8043f3af46b45ea38b038
        Client-IP-Address = 192.168.1.5

Packet-Type = Access-Request
Wed Aug 23 16:54:41 2006
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 0x0207000d016d617263656c6c6f
        Message-Authenticator = 0x35dce2ba502963e6a55781a6863ee665
        Client-IP-Address = 192.168.1.5

Packet-Type = Access-Request
Wed Aug 23 16:54:41 2006
        User-Name = "marcello"
        NAS-IP-Address = 192.168.1.5
        NAS-Port = 0
        Called-Station-Id = "00-40-05-30-C5-86"
        Calling-Station-Id = "00-0C-F1-15-17-59"
        NAS-Identifier = "DLink-900AP+"
        Framed-MTU = 1380
        NAS-Port-Type = Wireless-802.11
        EAP-Message = 
0x020800500d800000004616030100410100003d030144ec6bd18e05eb916c88e10b9cc8e5b620271365a5b4ea1f40965f1b1d18a19600001600040005000a0009006$
        State = 0xfd9cd50d382b9c1e0da734eb064d896d
        Message-Authenticator = 0xb4f18cd8d063fcdc0b2291f37307a047
        Client-IP-Address = 192.168.1.5




More information about the Freeradius-Devel mailing list