Hi,
I captured the log file and it shows the message exchanged between Radius
server and XP client. I hope this shed some
light about the "rlm_eap_tls: Invalid ACK received" problem:
<abreviate the initialization log>
Listening on IP address *, ports 1812/udp and 1813/udp, with proxy on 1814/udp.
Ready to process requests.
rad_recv: Access-Request packet from host 66.135.138.204:21449, id=65, length=149
User-Name = "kevin"
Cisco-AVPair = "ssid=tsunami"
NAS-IP-Address = 192.168.0.8
Called-Station-Id = "004096495de0"
Calling-Station-Id = "0006250baad2"
NAS-Identifier = "AP350-495de0"
NAS-Port = 37
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Service-Type = Login-User
EAP-Message = "\002\251\000\n\001kevin"
Message-Authenticator = 0x89271b8b136af79caf85134130674905
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "eap" returns updated
rlm_realm: No '@' in User-Name = "kevin", looking up realm NULL
rlm_realm: No such realm NULL
modcall[authorize]: module "suffix" returns noop
users: Matched kevin at 95
modcall[authorize]: module "files" returns ok
modcall: group authorize returns updated
rad_check_password: Found Auth-Type EAP
auth: type "EAP"
modcall: entering group authenticate
rlm_eap: processing type tls
modcall[authenticate]: module "eap" returns ok
modcall: group authenticate returns ok
Sending Access-Challenge of id 65 to 66.135.138.204:21449
EAP-Message = "\001\252\000\006\r "
Message-Authenticator = 0x00000000000000000000000000000000
State =
0x5f52a22ef018af7fe7c1e6c255581de73332d43d32f09ee1e733b3fe93c939d2f2c4148a
Finished request 0
Going to the next request
SMUX connect try 2
Can't connect to SNMP agent with SMUX: Connection refused
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 66.135.138.204:21450, id=66, length=257
User-Name = "kevin"
Cisco-AVPair = "ssid=tsunami"
NAS-IP-Address = 192.168.0.8
Called-Station-Id = "004096495de0"
Calling-Station-Id = "0006250baad2"
NAS-Identifier = "AP350-495de0"
NAS-Port = 37
Framed-MTU = 1400
State =
0x5f52a22ef018af7fe7c1e6c255581de73332d43d32f09ee1e733b3fe93c939d2f2c4148a
NAS-Port-Type = Wireless-802.11
Service-Type = Login-User
EAP-Message =
"\002\252\000P\r\200\000\000\000F\026\003\001\000A\001\000\000=\003\001=\324
2\230\267]\376\363&\001\327dK\353\251\336\266\2161\014`M$5\312\215\037}Z\260\236&\000\000\026\000\
004\000\005\000\n\000\t\000d\000b\000\003\000\006\000\023\000\022\000c\001"
Message-Authenticator = 0x4a95e372bb9e28244d1226b62f0ed921
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "eap" returns updated
rlm_realm: No '@' in User-Name = "kevin", looking up realm NULL
rlm_realm: No such realm NULL
modcall[authorize]: module "suffix" returns noop
users: Matched kevin at 95
modcall[authorize]: module "files" returns ok
modcall: group authorize returns updated
rad_check_password: Found Auth-Type EAP
auth: type "EAP"
modcall: entering group authenticate
rlm_eap: Request found, released from the list
rlm_eap: EAP_TYPE - tls
rlm_eap: processing type tls
rlm_eap_tls: Length Included
undefined: before/accept initialization
TLS_accept: before/accept initialization
<<< TLS 1.0 Handshake [length 0041], ClientHello
TLS_accept: SSLv3 read client hello A
>>> TLS 1.0 Handshake [length 004a], ServerHello
TLS_accept: SSLv3 write server hello A
>>> TLS 1.0 Handshake [length 02e1], Certificate
TLS_accept: SSLv3 write certificate A
>>> TLS 1.0 Handshake [length 00b5], CertificateRequest
TLS_accept: SSLv3 write certificate request A
TLS_accept: SSLv3 flush data
TLS_accept:error in SSLv3 read client certificate A
rlm_eap_tls: SSL_read Error
Error code is ..... 2
SSL Error ..... 2
modcall[authenticate]: module "eap" returns ok
modcall: group authenticate returns ok
Sending Access-Challenge of id 66 to 66.135.138.204:21450
EAP-Message =
"\001\253\003\371\r\200\000\000\003\357\026\003\001\000J\002\000\000F\003\00
1=\32423\373\253\247\373\217u`\204\034\315\004I\260\3644&\253\270\306\267\3542\310#\204\255\033\25
7
\3018\302\360\322^\325\254\002p^\324\035\205\315me\000.u\270c\tl\035kO\023pV#\301\000\004\000\02
6\003\001\002\341\013\000\002\335\000\002\332\000\002\3270\202\002\3230\202\002<\240\003\002\001\0
02\002\001\0020\r\006\t*\206H\206\367\r\001\001\004\005\0000\201\2421\0130\t\006\003U\004\006\023\
002US1\0230\021\006\003U\004\010\023\nCalif"
EAP-Message =
"urve.esignx.com1\0370\035\006\t*\206H\206\367\r\001\t\001\026\020curve@esig
nx.com0\036\027\r021113185626Z\027\r031113185626Z0\201\2421\0130\t\006\003U\004\006\023\002US1\023
0\021\006\003U\004\010\023\nCalifornia1\0220\020\006\003U\004\007\023\tCupertino1\0330\031\006\003
U\004\n\023\022eSignX
Corporation1\0210\017\006\003U\004\013\023\010Wireless1\0310\027\006\003U\00
4\003\023\020curve.esignx.com1\0370\035\006\t*\206H\206\367\r\001\t\001\026\[EMAIL PROTECTED]\2
01\2370\r\006\t"
EAP-Message =
"*\206H\206\367\r\001\001\001\005\000\003\201\215\0000\201\211\002\201\201\0
00\307yX6\221#\003\322y\3762\313Z\212\rl\273K\2026\355J\242\274\013m\370*\005Y\365\320\314C^\023\2
77\036\001\273+\244M1\022E\275bt\265j\331\032\311;\253\006%:\337/\304F\374.\316\274\335\317\271\30
4\355\367\263\315\322#\035\277v\334]\005\317b\007\255\023(\034Z\256\022\333q\232_\021\334!m92<\260
\022\010\023\377PT\205\027\003D\004Pg\214\310\246\033!$WqE\002\003\001\000\001\243\0270\0250\023\0
06\003U\035%\004\0140\n\006\010+\006\001\005"
EAP-Message =
"Itp!\rF{\241\347\342+\351\017\217\215\225\377\336]E\036!!\334\\\250\230\220
3h\010\266\350\022#\031\036\375l\366\244\271\371\356\214)\033\347;\345\002\300\020D\271J\003\264K\
254uL}tv\350!;\257\342\001\343\366d1\026\003\001\000\265\r\000\000\255\003\001\002\005\000\247\000
\2450\201\2421\0130\t\006\003U\004\006\023\002US1\0230\021\006\003U\004\010\023\nCalifornia1\0220\
020\006\003U\004\007\023\tCupertino1\0330\031\006\003U\004\n\023\022eSignX
Corporation1\0210\017\0
06\003U\004\013\023\010Wireless1\0310\027\006"
EAP-Message = "x.com\016\000\000"
Message-Authenticator = 0x00000000000000000000000000000000
State =
0x06f755fcdfc305b5ce96394ad2f7ac893332d43dcc1688b49c932ddbe9ea2583fe8a49a9
Finished request 1
Going to the next request
SMUX connect try 3
Can't connect to SNMP agent with SMUX: Connection refused
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 66.135.138.204:21451, id=67, length=183
User-Name = "kevin"
Cisco-AVPair = "ssid=tsunami"
NAS-IP-Address = 192.168.0.8
Called-Station-Id = "004096495de0"
Calling-Station-Id = "0006250baad2"
NAS-Identifier = "AP350-495de0"
NAS-Port = 37
Framed-MTU = 1400
State =
0x06f755fcdfc305b5ce96394ad2f7ac893332d43dcc1688b49c932ddbe9ea2583fe8a49a9
NAS-Port-Type = Wireless-802.11
Service-Type = Login-User
EAP-Message = "\002\253\000\006\r"
Message-Authenticator = 0x01eca2910ee08bf4dad733265baca7c4
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "eap" returns updated
rlm_realm: No '@' in User-Name = "kevin", looking up realm NULL
rlm_realm: No such realm NULL
modcall[authorize]: module "suffix" returns noop
users: Matched kevin at 95
modcall[authorize]: module "files" returns ok
modcall: group authorize returns updated
rad_check_password: Found Auth-Type EAP
auth: type "EAP"
modcall: entering group authenticate
rlm_eap: Request found, released from the list
rlm_eap: EAP_TYPE - tls
rlm_eap: processing type tls
rlm_eap_tls: Received EAP-TLS ACK message
rlm_eap_tls: Invalid ACK received
modcall[authenticate]: module "eap" returns invalid
modcall: group authenticate returns invalid
auth: Failed to validate the user.
Delaying request 2 for 1 seconds
Finished request 2
Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 66.135.138.204:21451, id=67, length=183
Sending Access-Reject of id 67 to 66.135.138.204:21451
EAP-Message = "\004\253\000\004"
Message-Authenticator = 0x00000000000000000000000000000000
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Cleaning up request 0 ID 65 with timestamp 3dd43233
Cleaning up request 1 ID 66 with timestamp 3dd43233
Cleaning up request 2 ID 67 with timestamp 3dd43233
Nothing to do. Sleeping until we see a request.
rad_recv: Access-Request packet from host 66.135.138.204:21452, id=68, length=149
User-Name = "kevin"
Cisco-AVPair = "ssid=tsunami"
NAS-IP-Address = 192.168.0.8
Called-Station-Id = "004096495de0"
Calling-Station-Id = "0006250baad2"
NAS-Identifier = "AP350-495de0"
NAS-Port = 37
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
Service-Type = Login-User
EAP-Message = "\002\254\000\n\001kevin"
Message-Authenticator = 0xee07aae60beeefbff9092c1e1f493c48
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "eap" returns updated
rlm_realm: No '@' in User-Name = "kevin", looking up realm NULL
rlm_realm: No such realm NULL
modcall[authorize]: module "suffix" returns noop
users: Matched kevin at 95
modcall[authorize]: module "files" returns ok
modcall: group authorize returns updated
rad_check_password: Found Auth-Type EAP
auth: type "EAP"
modcall: entering group authenticate
rlm_eap: processing type tls
modcall[authenticate]: module "eap" returns ok
modcall: group authenticate returns ok
Sending Access-Challenge of id 68 to 66.135.138.204:21452
EAP-Message = "\001\255\000\006\r "
Message-Authenticator = 0x00000000000000000000000000000000
State =
0xd83640f07807c964d194532e0f3e060f3a32d43d1e97af6dbef309adf0e7381838138e4e
Finished request 4
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 66.135.138.204:21453, id=69, length=257
User-Name = "kevin"
Cisco-AVPair = "ssid=tsunami"
NAS-IP-Address = 192.168.0.8
Called-Station-Id = "004096495de0"
Calling-Station-Id = "0006250baad2"
NAS-Identifier = "AP350-495de0"
NAS-Port = 37
Framed-MTU = 1400
State =
0xd83640f07807c964d194532e0f3e060f3a32d43d1e97af6dbef309adf0e7381838138e4e
NAS-Port-Type = Wireless-802.11
Service-Type = Login-User
EAP-Message =
"\002\255\000P\r\200\000\000\000F\026\003\001\000A\001\000\000=\003\001=\324
2\237^\226\013r\307\301\347\341\270k1\330\0247\253\3258\214\270\037\277Q^\372a.`t\000\000\026\000\
004\000\005\000\n\000\t\000d\000b\000\003\000\006\000\023\000\022\000c\001"
Message-Authenticator = 0x7556caf9e2d9849737243243e12896a1
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "eap" returns updated
rlm_realm: No '@' in User-Name = "kevin", looking up realm NULL
rlm_realm: No such realm NULL
modcall[authorize]: module "suffix" returns noop
users: Matched kevin at 95
modcall[authorize]: module "files" returns ok
modcall: group authorize returns updated
rad_check_password: Found Auth-Type EAP
auth: type "EAP"
modcall: entering group authenticate
rlm_eap: Request found, released from the list
rlm_eap: EAP_TYPE - tls
rlm_eap: processing type tls
rlm_eap_tls: Length Included
undefined: before/accept initialization
TLS_accept: before/accept initialization
<<< TLS 1.0 Handshake [length 0041], ClientHello
TLS_accept: SSLv3 read client hello A
>>> TLS 1.0 Handshake [length 004a], ServerHello
TLS_accept: SSLv3 write server hello A
>>> TLS 1.0 Handshake [length 02e1], Certificate
TLS_accept: SSLv3 write certificate A
>>> TLS 1.0 Handshake [length 00b5], CertificateRequest
TLS_accept: SSLv3 write certificate request A
TLS_accept: SSLv3 flush data
TLS_accept:error in SSLv3 read client certificate A
rlm_eap_tls: SSL_read Error
Error code is ..... 2
SSL Error ..... 2
modcall[authenticate]: module "eap" returns ok
modcall: group authenticate returns ok
Sending Access-Challenge of id 69 to 66.135.138.204:21453
EAP-Message =
"\001\256\003\371\r\200\000\000\003\357\026\003\001\000J\002\000\000F\003\00
1=\3242;\227n\227\266\345\2718\201\266\034\304\322y\231+\316\326)\366\212$\321D;A\017\372\003
\334
W\207\002\211\366\250_\017U\303\216\243\300$\334-\232r\272\247\307\014\3012\001\237)#\310\277\000\
004\000\026\003\001\002\341\013\000\002\335\000\002\332\000\002\3270\202\002\3230\202\002<\240\003
\002\001\002\002\001\0020\r\006\t*\206H\206\367\r\001\001\004\005\0000\201\2421\0130\t\006\003U\00
4\006\023\002US1\0230\021\006\003U\004\010"
EAP-Message =
"urve.esignx.com1\0370\035\006\t*\206H\206\367\r\001\t\001\026\020curve@esig
nx.com0\036\027\r021113185626Z\027\r031113185626Z0\201\2421\0130\t\006\003U\004\006\023\002US1\023
0\021\006\003U\004\010\023\nCalifornia1\0220\020\006\003U\004\007\023\tCupertino1\0330\031\006\003
U\004\n\023\022eSignX
Corporation1\0210\017\006\003U\004\013\023\010Wireless1\0310\027\006\003U\00
4\003\023\020curve.esignx.com1\0370\035\006\t*\206H\206\367\r\001\t\001\026\[EMAIL PROTECTED]\2
01\2370\r\006\t"
EAP-Message =
"*\206H\206\367\r\001\001\001\005\000\003\201\215\0000\201\211\002\201\201\0
00\307yX6\221#\003\322y\3762\313Z\212\rl\273K\2026\355J\242\274\013m\370*\005Y\365\320\314C^\023\2
77\036\001\273+\244M1\022E\275bt\265j\331\032\311;\253\006%:\337/\304F\374.\316\274\335\317\271\30
4\355\367\263\315\322#\035\277v\334]\005\317b\007\255\023(\034Z\256\022\333q\232_\021\334!m92<\260
\022\010\023\377PT\205\027\003D\004Pg\214\310\246\033!$WqE\002\003\001\000\001\243\0270\0250\023\0
06\003U\035%\004\0140\n\006\010+\006\001\005"
EAP-Message =
"Itp!\rF{\241\347\342+\351\017\217\215\225\377\336]E\036!!\334\\\250\230\220
3h\010\266\350\022#\031\036\375l\366\244\271\371\356\214)\033\347;\345\002\300\020D\271J\003\264K\
254uL}tv\350!;\257\342\001\343\366d1\026\003\001\000\265\r\000\000\255\003\001\002\005\000\247\000
\2450\201\2421\0130\t\006\003U\004\006\023\002US1\0230\021\006\003U\004\010\023\nCalifornia1\0220\
020\006\003U\004\007\023\tCupertino1\0330\031\006\003U\004\n\023\022eSignX
Corporation1\0210\017\0
06\003U\004\013\023\010Wireless1\0310\027\006"
EAP-Message = "x.com\016\000\000"
Message-Authenticator = 0x00000000000000000000000000000000
State =
0xc03122b972be51e629b70123ec4104d53b32d43d015f4a6e93e0f4ff41f1729d4501e320
Finished request 5
Going to the next request
--- Walking the entire request list ---
Waking up in 5 seconds...
rad_recv: Access-Request packet from host 66.135.138.204:21454, id=70, length=183
User-Name = "kevin"
Cisco-AVPair = "ssid=tsunami"
NAS-IP-Address = 192.168.0.8
Called-Station-Id = "004096495de0"
Calling-Station-Id = "0006250baad2"
NAS-Identifier = "AP350-495de0"
NAS-Port = 37
Framed-MTU = 1400
State =
0xc03122b972be51e629b70123ec4104d53b32d43d015f4a6e93e0f4ff41f1729d4501e320
NAS-Port-Type = Wireless-802.11
Service-Type = Login-User
EAP-Message = "\002\256\000\006\r"
Message-Authenticator = 0x75e819fc4bb8a71850148e5095f2900b
modcall: entering group authorize
modcall[authorize]: module "preprocess" returns ok
modcall[authorize]: module "eap" returns updated
rlm_realm: No '@' in User-Name = "kevin", looking up realm NULL
rlm_realm: No such realm NULL
modcall[authorize]: module "suffix" returns noop
users: Matched kevin at 95
modcall[authorize]: module "files" returns ok
modcall: group authorize returns updated
rad_check_password: Found Auth-Type EAP
auth: type "EAP"
modcall: entering group authenticate
rlm_eap: Request found, released from the list
rlm_eap: EAP_TYPE - tls
rlm_eap: processing type tls
rlm_eap_tls: Received EAP-TLS ACK message
rlm_eap_tls: Invalid ACK received
modcall[authenticate]: module "eap" returns invalid
modcall: group authenticate returns invalid
auth: Failed to validate the user.
Delaying request 6 for 1 seconds
Finished request 6
Going to the next request
Waking up in 5 seconds...
rad_recv: Access-Request packet from host 66.135.138.204:21454, id=70, length=183
Sending Access-Reject of id 70 to 66.135.138.204:21454
EAP-Message = "\004\256\000\004"
Message-Authenticator = 0x00000000000000000000000000000000
--- Walking the entire request list ---
Cleaning up request 4 ID 68 with timestamp 3dd4323a
--------------------------------------
hi
> "rlm_eap_tls: Received EAP-TLS ACK message
> rlm_eap_tls: Invalid ACK received
> modcall[authenticate]: module "eap" returns invalid"
> I know I am very close. Just don't know where to proceed to fix the problem.
> I compared with the sample log file:
> "rlm_eap_tls: Received EAP-TLS ACK message
> modcall[authenticate]: module "eap" returns ok"
that's true, it's bizar... have no idea what it could be, check the
exchanged messages (at least length etc. issues), check software package
versions, etc....
difficult to say just by your explication. if you can't figure it out,
record the message exchange with the newest ethereal version and try to
understand what's happening... send it to the list.
but first verify the first point.
ciao
artur
--
Artur Hecker
artur[at]hecker.info
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
