EAP-TTLS/PAP tunneling issue

Edwin van Zyl edwinvanzyl at conor.co.za
Wed Feb 13 10:23:37 CET 2008 

That worked. thx.

rad_recv: Access-Request packet from host 127.0.0.1:50067, id=101,  
length=79
	User-Name = "edwinvanzyl"
	Called-Station-Id = "internet"
	EAP-Message = 0x0200001001656477696e76616e7a796c
	Message-Authenticator = 0xd649ab055e13bef1b25863bcab47f81e
Wed Feb 13 11:22:56 2008 : Debug:   Processing the authorize section  
of radiusd.conf
Wed Feb 13 11:22:56 2008 : Debug: modcall: entering group authorize  
for request 4
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: calling eap  
(rlm_eap) for request 4
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: EAP packet type response  
id 0 length 16
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: No EAP Start, assuming  
it's an on-going EAP conversation
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: returned  
from eap (rlm_eap) for request 4
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authorize]: module "eap"  
returns updated for request 4
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: calling  
files (rlm_files) for request 4
Wed Feb 13 11:22:56 2008 : Debug:     users: Matched entry edwinvanzyl  
at line 80
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: returned  
from files (rlm_files) for request 4
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authorize]: module "files"  
returns ok for request 4
Wed Feb 13 11:22:56 2008 : Debug: modcall: leaving group authorize  
(returns updated) for request 4
Wed Feb 13 11:22:56 2008 : Debug:   rad_check_password:  Found Auth- 
Type EAP
Wed Feb 13 11:22:56 2008 : Debug: auth: type "EAP"
Wed Feb 13 11:22:56 2008 : Debug:   Processing the authenticate  
section of radiusd.conf
Wed Feb 13 11:22:56 2008 : Debug: modcall: entering group authenticate  
for request 4
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authenticate]: calling  
eap (rlm_eap) for request 4
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: EAP Identity
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: processing type tls
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: Initiate
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: Start returned 1
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authenticate]: returned  
from eap (rlm_eap) for request 4
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authenticate]: module  
"eap" returns handled for request 4
Wed Feb 13 11:22:56 2008 : Debug: modcall: leaving group authenticate  
(returns handled) for request 4
Sending Access-Challenge of id 101 to 127.0.0.1 port 50067
	EAP-Message = 0x010100061520
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xad2f0e60790267d123b90ade481ecca5
Wed Feb 13 11:22:56 2008 : Debug: Finished request 4
Wed Feb 13 11:22:56 2008 : Debug: Going to the next request
Wed Feb 13 11:22:56 2008 : Debug: --- Walking the entire request list  
---
Wed Feb 13 11:22:56 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:50067, id=102,  
length=145
	User-Name = "edwinvanzyl"
	Called-Station-Id = "internet"
	State = 0xad2f0e60790267d123b90ade481ecca5
	EAP-Message =  
0x0201004015800000003a16030100310100002d030147b2b6f06db8377eae44af2b54c47b7c102f291a22bb62187200777ccdf66216000006002f003300320100
	Message-Authenticator = 0x21c075be78867ae66bd77f002e447701
Wed Feb 13 11:22:56 2008 : Debug:   Processing the authorize section  
of radiusd.conf
Wed Feb 13 11:22:56 2008 : Debug: modcall: entering group authorize  
for request 5
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: calling eap  
(rlm_eap) for request 5
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: EAP packet type response  
id 1 length 64
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: No EAP Start, assuming  
it's an on-going EAP conversation
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: returned  
from eap (rlm_eap) for request 5
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authorize]: module "eap"  
returns updated for request 5
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: calling  
files (rlm_files) for request 5
Wed Feb 13 11:22:56 2008 : Debug:     users: Matched entry edwinvanzyl  
at line 80
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: returned  
from files (rlm_files) for request 5
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authorize]: module "files"  
returns ok for request 5
Wed Feb 13 11:22:56 2008 : Debug: modcall: leaving group authorize  
(returns updated) for request 5
Wed Feb 13 11:22:56 2008 : Debug:   rad_check_password:  Found Auth- 
Type EAP
Wed Feb 13 11:22:56 2008 : Debug: auth: type "EAP"
Wed Feb 13 11:22:56 2008 : Debug:   Processing the authenticate  
section of radiusd.conf
Wed Feb 13 11:22:56 2008 : Debug: modcall: entering group authenticate  
for request 5
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authenticate]: calling  
eap (rlm_eap) for request 5
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: Request found, released  
from the list
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: EAP/ttls
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: processing type ttls
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_ttls: Authenticate
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Feb 13 11:22:56 2008 : Debug: rlm_eap_tls:  Length Included
Wed Feb 13 11:22:56 2008 : Debug:   eaptls_verify returned 11
Wed Feb 13 11:22:56 2008 : Debug:     (other): before/accept  
initialization
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: before/accept  
initialization
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake  
[length 0031], ClientHello
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 read client  
hello A
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake  
[length 004a], ServerHello
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 write server  
hello A
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake  
[length 024f], Certificate
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 write  
certificate A
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake  
[length 0004], ServerHelloDone
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 write server  
done A
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 flush data
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: Need to read more  
data: SSLv3 read client certificate A
Wed Feb 13 11:22:56 2008 : Debug: In SSL Handshake Phase
Wed Feb 13 11:22:56 2008 : Debug: In SSL Accept mode
Wed Feb 13 11:22:56 2008 : Debug:   eaptls_process returned 13
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authenticate]: returned  
from eap (rlm_eap) for request 5
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authenticate]: module  
"eap" returns handled for request 5
Wed Feb 13 11:22:56 2008 : Debug: modcall: leaving group authenticate  
(returns handled) for request 5
Sending Access-Challenge of id 102 to 127.0.0.1 port 50067
	EAP-Message =  
0x010202b21500160301004a02000046030147b2b6f05cb491bf2deb1d0bb035590d20dc810639878320773425fd0c84dba4201fa66fa4064e36e8fcf4da3971bb0e26ecb0c26b42041474485586703259d4fe002f00160301024f0b00024b00024800024530820241308201aa0203100001300d06092a864886f70d0101040500307431173015060355040a130e616c636174656c2d6c7563656e74310e300c060355040b130557694d4158310c300a06035504071303465344310f300d0603550408130670756e6a6162310b300906035504061302706b311d301b060355040313146161617365727665722e616c636174656c2e706b301e170d303730
	EAP-Message =  
0x3531343131353334365a170d3038303531333131353334365a305c310b300906035504061302706b310f300d0603550408130670756e6a616231173015060355040a130e616c636174656c2d6c7563656e74310e300c060355040b130557694d4158311330110603550403130a7a7978656c2e7573657230819f300d06092a864886f70d010101050003818d0030818902818100baaf122e60946da7ee1dc1101854e1836e848c0f3d5372be31e29eef2566a673f138809b9a118846e6846280408d822960c6345a6ce922155463fe3a267bc8d047aa8a435f506d9df7670e9d5dcc381f48d99662943546c4acca0db93665023181924fa574b52fb8ec
	EAP-Message =  
0x7a05a85edf77fc408350e82f41536fb4584afe6671fd5f0203010001300d06092a864886f70d01010405000381810065c020869992c43b685a15a53ffee8ea31743ac9fe71a741b5265dbc1caa2d01e614820b4d05d2f5bd5bf04804259abfdad4d492877574946c10afba0c07a04304876701ac9e29a8297b2a9f1d6bb5e080d2fc5b633d63433f63e4be896dc4bd9db1606e80af636c2a1eabba9e0c3d73059bfc66efc9d06b8af35a8d2862971416030100040e000000
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0xa906824b1c0687f85073022f0177c03d
Wed Feb 13 11:22:56 2008 : Debug: Finished request 5
Wed Feb 13 11:22:56 2008 : Debug: Going to the next request
Wed Feb 13 11:22:56 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:50067, id=103,  
length=289
	User-Name = "edwinvanzyl"
	Called-Station-Id = "internet"
	State = 0xa906824b1c0687f85073022f0177c03d
	EAP-Message =  
0x020200d01580000000ca1603010086100000820080a7846d9c489947c24ca5fe72f8894e2a00f06ffa6628b5f779f2fdeac11978a11438e8102bc929c7ebbc26d09514408471ee6a7ed9faba03c7986cf2a2e8a47603d15f927257e90fac15026e83aef21f1621ba13edafa3c7539647c6582f5413d9c84af5172853966b80b3e26165ce3963faecec04a6da531079c633ffc36dcc14030100010116030100308646fe17348800449f912361f8f22d58b1f0a921533e0ec562c2a034735a723074d7deb42440e08a36d06c81b4273add
	Message-Authenticator = 0xccf19c9005bab3b128e6dbfb8624d438
Wed Feb 13 11:22:56 2008 : Debug:   Processing the authorize section  
of radiusd.conf
Wed Feb 13 11:22:56 2008 : Debug: modcall: entering group authorize  
for request 6
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: calling eap  
(rlm_eap) for request 6
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: EAP packet type response  
id 2 length 208
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: No EAP Start, assuming  
it's an on-going EAP conversation
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: returned  
from eap (rlm_eap) for request 6
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authorize]: module "eap"  
returns updated for request 6
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: calling  
files (rlm_files) for request 6
Wed Feb 13 11:22:56 2008 : Debug:     users: Matched entry edwinvanzyl  
at line 80
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: returned  
from files (rlm_files) for request 6
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authorize]: module "files"  
returns ok for request 6
Wed Feb 13 11:22:56 2008 : Debug: modcall: leaving group authorize  
(returns updated) for request 6
Wed Feb 13 11:22:56 2008 : Debug:   rad_check_password:  Found Auth- 
Type EAP
Wed Feb 13 11:22:56 2008 : Debug: auth: type "EAP"
Wed Feb 13 11:22:56 2008 : Debug:   Processing the authenticate  
section of radiusd.conf
Wed Feb 13 11:22:56 2008 : Debug: modcall: entering group authenticate  
for request 6
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authenticate]: calling  
eap (rlm_eap) for request 6
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: Request found, released  
from the list
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: EAP/ttls
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: processing type ttls
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_ttls: Authenticate
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Feb 13 11:22:56 2008 : Debug: rlm_eap_tls:  Length Included
Wed Feb 13 11:22:56 2008 : Debug:   eaptls_verify returned 11
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake  
[length 0086], ClientKeyExchange
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 read client  
key exchange A
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0  
ChangeCipherSpec [length 0001]
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: <<< TLS 1.0 Handshake  
[length 0010], Finished
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 read finished A
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0  
ChangeCipherSpec [length 0001]
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 write change  
cipher spec A
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: >>> TLS 1.0 Handshake  
[length 0010], Finished
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 write finished A
Wed Feb 13 11:22:56 2008 : Debug:     TLS_accept: SSLv3 flush data
Wed Feb 13 11:22:56 2008 : Debug:     (other): SSL negotiation  
finished successfully
Wed Feb 13 11:22:56 2008 : Debug: SSL Connection Established
Wed Feb 13 11:22:56 2008 : Debug:   eaptls_process returned 13
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authenticate]: returned  
from eap (rlm_eap) for request 6
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authenticate]: module  
"eap" returns handled for request 6
Wed Feb 13 11:22:56 2008 : Debug: modcall: leaving group authenticate  
(returns handled) for request 6
Sending Access-Challenge of id 103 to 127.0.0.1 port 50067
	EAP-Message =  
0x01030041150014030100010116030100306e67219d42247698b9a3a37e6205bbf5432619a2c997a30809f82412d93286b9410636ff327ff3b62df678e540bae2bc
	Message-Authenticator = 0x00000000000000000000000000000000
	State = 0x868bf596b4e632edce8c663e4ff20895
Wed Feb 13 11:22:56 2008 : Debug: Finished request 6
Wed Feb 13 11:22:56 2008 : Debug: Going to the next request
Wed Feb 13 11:22:56 2008 : Debug: Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:50067, id=104,  
length=160
	User-Name = "edwinvanzyl"
	Called-Station-Id = "internet"
	State = 0x868bf596b4e632edce8c663e4ff20895
	EAP-Message =  
0x0203004f158000000049170301004092cf380f7dcc8e70a90786295ec7d8501d9b66debb6c833e413c3e97d1de6575a0946e29604e8e5c918a430d8abe24a8fb902e747e8564a530aa3cf4d9c45bf3
	Message-Authenticator = 0x2f5fa680eb9fd89cebdbc5f34e07eaa6
Wed Feb 13 11:22:56 2008 : Debug:   Processing the authorize section  
of radiusd.conf
Wed Feb 13 11:22:56 2008 : Debug: modcall: entering group authorize  
for request 7
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: calling eap  
(rlm_eap) for request 7
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: EAP packet type response  
id 3 length 79
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: No EAP Start, assuming  
it's an on-going EAP conversation
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: returned  
from eap (rlm_eap) for request 7
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authorize]: module "eap"  
returns updated for request 7
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: calling  
files (rlm_files) for request 7
Wed Feb 13 11:22:56 2008 : Debug:     users: Matched entry edwinvanzyl  
at line 80
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authorize]: returned  
from files (rlm_files) for request 7
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authorize]: module "files"  
returns ok for request 7
Wed Feb 13 11:22:56 2008 : Debug: modcall: leaving group authorize  
(returns updated) for request 7
Wed Feb 13 11:22:56 2008 : Debug:   rad_check_password:  Found Auth- 
Type EAP
Wed Feb 13 11:22:56 2008 : Debug: auth: type "EAP"
Wed Feb 13 11:22:56 2008 : Debug:   Processing the authenticate  
section of radiusd.conf
Wed Feb 13 11:22:56 2008 : Debug: modcall: entering group authenticate  
for request 7
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authenticate]: calling  
eap (rlm_eap) for request 7
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: Request found, released  
from the list
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: EAP/ttls
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: processing type ttls
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_ttls: Authenticate
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_tls: processing TLS
Wed Feb 13 11:22:56 2008 : Debug: rlm_eap_tls:  Length Included
Wed Feb 13 11:22:56 2008 : Debug:   eaptls_verify returned 11
Wed Feb 13 11:22:56 2008 : Debug:   eaptls_process returned 7
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_ttls: Session  
established.  Proceeding to decode tunneled attributes.
   TTLS tunnel data in 0000: 01 0d 65 64 77 69 6e 76 61 6e 7a 79 6c 02  
09 74
   TTLS tunnel data in 0010: 65 73 74 69 6e 67 1e 0a 69 6e 74 65 72 6e  
65 74
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap_ttls:  Non-RADIUS  
attribute in tunneled authentication is not supported
Wed Feb 13 11:22:56 2008 : Debug:  rlm_eap: Handler failed in EAP/ttls
Wed Feb 13 11:22:56 2008 : Debug:   rlm_eap: Failed in EAP select
Wed Feb 13 11:22:56 2008 : Debug:   modsingle[authenticate]: returned  
from eap (rlm_eap) for request 7
Wed Feb 13 11:22:56 2008 : Debug:   modcall[authenticate]: module  
"eap" returns invalid for request 7
Wed Feb 13 11:22:56 2008 : Debug: modcall: leaving group authenticate  
(returns invalid) for request 7
Wed Feb 13 11:22:56 2008 : Debug: auth: Failed to validate the user.
Wed Feb 13 11:22:56 2008 : Debug: Delaying request 7 for 1 seconds
Wed Feb 13 11:22:56 2008 : Debug: Finished request 7
Wed Feb 13 11:22:56 2008 : Debug: Going to the next request
Wed Feb 13 11:22:56 2008 : Debug: Waking up in 6 seconds...
Wed Feb 13 11:23:02 2008 : Debug: --- Walking the entire reques


On 13 Feb 2008, at 11:09 AM, Alan DeKok wrote:

> Edwin van Zyl wrote:
>> I've configured with the following options:  ./configure --enable- 
>> debug
>> --enable-developer and re-build, but still don't see the raw data.  
>> I've
>> looked at the binary traces and can see that the EAP message contains
>> encrypted application data and the size is less then 100bytes. Am I
>> configuring with the wrong options?
>
>  Hmm... try running with with -Xxx
>
>  Alan DeKok.
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

More information about the Freeradius-Users mailing list