Windows 2000 ignoring Access-Accept

28 Jun 2006

      Hello All.

I'm having a rather odd problem and can no longer afford to bang my head on 
the desk.

I have Freeradius 1.1.1 working for winXP clients and Intermec CK30 bar code 
scanners using EAP-TLS authentication.  The issue I'm having is with win2k.  
According to my radius log an accesss-accept packet is being sent to the 
client, but the client seems to be ignoring it by continuing to send 
access-request packets.

Maybe a fresh pair eyes looking over my log will catch something I'm missing.

Again, the client is win2k with SP4.  Authentication method is EAP-TLS.  The 
machine uses a Cisco Aironet 350 11b PCI card with the latest drivers.  
Freeradius is version 1.1.1.

I have 16 of these system that I need to get working.

Any solution will get you big hug ;o)

-Doug

Here's the output of Freeradius:

Ready to process requests.
rad_recv: Access-Request packet from host 172.18.138.20:1645, id=252, 
length=160
        User-Name = "OIT07.plydex.decoma.com"
        Framed-MTU = 1400
        Called-Station-Id = "0016.4631.fdb0"
        Calling-Station-Id = "000b.5feb.e378"
        Service-Type = Login-User
        Message-Authenticator = 0xfa2fc8d43ca72a7493037b4063809fdc
        EAP-Message = 
0x0202001c014f495430372e706c796465782e6465636f6d612e636f6d
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 798
        NAS-IP-Address = 172.18.138.20
        NAS-Identifier = "AP1"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
  modcall[authorize]: module "preprocess" returns ok for request 0
  modcall[authorize]: module "chap" returns noop for request 0
  modcall[authorize]: module "mschap" returns noop for request 0
    rlm_realm: No '@' in User-Name = "OIT07.plydex.decoma.com", looking up 
realm NULL
    rlm_realm: No such realm "NULL"
  modcall[authorize]: module "suffix" returns noop for request 0
  rlm_eap: EAP packet type response id 2 length 28
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 0
    users: Matched DEFAULT at 152
  modcall[authorize]: module "files" returns ok for request 0
modcall: 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: group authenticate returns handled for request 0
Sending Access-Challenge of id 252 to 172.18.138.20:1645
        EAP-Message = 0x010300060d20
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x7d80c12e86b5280fc6bbb43135d7a0f6
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 172.18.138.20:1645, id=253, 
length=262
        User-Name = "OIT07.plydex.decoma.com"
        Framed-MTU = 1400
        Called-Station-Id = "0016.4631.fdb0"
        Calling-Station-Id = "000b.5feb.e378"
        Service-Type = Login-User
        Message-Authenticator = 0x7b11ea00e1a1ef7ae92d8b85d32d1fad
        EAP-Message = 
0x020300700d800000006616030100610100005d0301449c3941ac4e798194917f3a2ece3387637476b85e300b991aba12ab10cb2133201031998c0256343a7436ce53f69c84559c2c72bd37d5b85b246e4887ebcbbcf7001600040005000a000900640062000300060013001200630100
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 798
        State = 0x7d80c12e86b5280fc6bbb43135d7a0f6
        NAS-IP-Address = 172.18.138.20
        NAS-Identifier = "AP1"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 1
  modcall[authorize]: module "preprocess" returns ok for request 1
  modcall[authorize]: module "chap" returns noop for request 1
  modcall[authorize]: module "mschap" returns noop for request 1
    rlm_realm: No '@' in User-Name = "OIT07.plydex.decoma.com", looking up 
realm NULL
    rlm_realm: No such realm "NULL"
  modcall[authorize]: module "suffix" returns noop for request 1
  rlm_eap: EAP packet type response id 3 length 112
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 1
    users: Matched DEFAULT at 152
  modcall[authorize]: module "files" returns ok for request 1
modcall: 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 0061], 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 05f4], Certificate
    TLS_accept: SSLv3 write certificate A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 000d], 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: group authenticate returns handled for request 1
Sending Access-Challenge of id 253 to 172.18.138.20:1645
        EAP-Message = 
0x0104040a0dc00000065a160301004a020000460301449c394134edd93c41e6f8c71837aea360c49059e8c49a1445b6850cb27a5c532046dd63b430dd549790394ea5a857c4622df05efe91f7da62167b463f5ae7645e00040016030105f40b0005f00005ed00029e3082029a30820203a003020102020101300d06092a864886f70d0101040500307b310b30090603550406130243413110300e060355040813074f6e746172696f310f300d060355040713064175726f7261310f300d060355040a1306506c796465783111300f06035504031308506c7964657843413125302306092a864886f70d0109011616646f75675f77726967687440646563
        EAP-Message = 
0x6f6d612e636f6d301e170d3036303532353139323632365a170d3037303532353139323632365a308191310b30090603550406130243413110300e060355040813074f6e746172696f310f300d060355040713064175726f7261310f300d060355040a1306506c79646578312730250603550403131e706c79646175726f6c6e78312e706c796465782e6465636f6d612e636f6d3125302306092a864886f70d0109011616646f75675f777269676874406465636f6d612e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100c656d7cc5505f305ffc573886fcca45addcd5adf6e11fe1f28c52e69536898faee514480bb
        EAP-Message = 
0x998c2a9679f708d3d2bed65c9c3a62d20d0cddafea11fc998c242dd67b54c6d8d99ba6738ef6840a0b44403f3850b884ca37259afeeae5c1c7cf5a165f8b73368004277d045a54ce2d2d06979047616ab2365d1166636c430aabe70203010001a317301530130603551d25040c300a06082b06010505070301300d06092a864886f70d0101040500038181008bcf71a8eb491cae9e03168b0b46616a3395ff4bec078cd482d4eba9fa50b4212401ef7b7f56252736ab94d3a3227d0ded7630d675fb285dd7b95e7e09278012a2463e1432c4faea96d7814ddce757d84427432e0484a1ed5fc935437b0d02c33fa151cabdbfe8715af5e9acb58295eefe
        EAP-Message = 
0x5a02ef2a512cd683ec4b538e7acb3f00034930820345308202aea003020102020100300d06092a864886f70d0101040500307b310b30090603550406130243413110300e060355040813074f6e746172696f310f300d060355040713064175726f7261310f300d060355040a1306506c796465783111300f06035504031308506c7964657843413125302306092a864886f70d0109011616646f75675f777269676874406465636f6d612e636f6d301e170d3036303532353139313730375a170d3037303532353139313730375a307b310b30090603550406130243413110300e060355040813074f6e746172696f310f300d06035504071306417572
        EAP-Message = 0x6f7261310f300d060355040a1306506c796465783111
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xaec47358975f09a64d8cce861cbf8335
Finished request 1
Going to the next request
--- Walking the entire request list ---
Waking up in 5 seconds...
rad_recv: Access-Request packet from host 172.18.138.20:1645, id=254, 
length=156
        User-Name = "OIT07.plydex.decoma.com"
        Framed-MTU = 1400
        Called-Station-Id = "0016.4631.fdb0"
        Calling-Station-Id = "000b.5feb.e378"
        Service-Type = Login-User
        Message-Authenticator = 0x9edbd507114b004bd2cf51148c6c374e
        EAP-Message = 0x020400060d00
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 798
        State = 0xaec47358975f09a64d8cce861cbf8335
        NAS-IP-Address = 172.18.138.20
        NAS-Identifier = "AP1"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 2
  modcall[authorize]: module "preprocess" returns ok for request 2
  modcall[authorize]: module "chap" returns noop for request 2
  modcall[authorize]: module "mschap" returns noop for request 2
    rlm_realm: No '@' in User-Name = "OIT07.plydex.decoma.com", looking up 
realm NULL
    rlm_realm: No such realm "NULL"
  modcall[authorize]: module "suffix" returns noop 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 DEFAULT at 152
  modcall[authorize]: module "files" returns ok for request 2
modcall: 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: group authenticate returns handled for request 2
Sending Access-Challenge of id 254 to 172.18.138.20:1645
        EAP-Message = 
0x010502640d800000065a300f06035504031308506c7964657843413125302306092a864886f70d0109011616646f75675f777269676874406465636f6d612e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100b6932cc2234b01a7c89df348f1956964a6c19d29ec4e079ce9f84ddd4d263cc3c37821ee5ce9965e5ae2871b1a37dc64585c7b308f1b3da2250989db4913d07a73a6a8813e24939afa45fa557f994e9c5851a3d4d9a2b527ae6698ab0fb1a40cad550b5570bc218bd82efa5fd76479f8fd3fed3e5a2e7928e6ab019ce40cffd50203010001a381d83081d5301d0603551d0e041604143d8af973813c2fd8
        EAP-Message = 
0x307abe1022222c12674682d23081a50603551d2304819d30819a80143d8af973813c2fd8307abe1022222c12674682d2a17fa47d307b310b30090603550406130243413110300e060355040813074f6e746172696f310f300d060355040713064175726f7261310f300d060355040a1306506c796465783111300f06035504031308506c7964657843413125302306092a864886f70d0109011616646f75675f777269676874406465636f6d612e636f6d820100300c0603551d13040530030101ff300d06092a864886f70d010104050003818100830cef19176b28c84c766f7655f0a6e04b4fb7a3f688c97b29aa0006963dc84d6041edf686847d4d
        EAP-Message = 
0x3b04c86d63464ec39d2a5a35b506266cf330024461c3ff3eb36ac04562aac7974ab325a48c35d33585eea50f490691956debac5f24e6f6c9de01ea24ed3492566848de69deb56ee93eff3aa5a37a79993a6051b6d1a97232160301000d0d00000502010200000e000000
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x4722e062dffe964833f0197306e90f96
Finished request 2
Going to the next request
Waking up in 5 seconds...
rad_recv: Access-Request packet from host 172.18.138.20:1645, id=255, 
length=1115
        User-Name = "OIT07.plydex.decoma.com"
        Framed-MTU = 1400
        Called-Station-Id = "0016.4631.fdb0"
        Calling-Station-Id = "000b.5feb.e378"
        Service-Type = Login-User
        Message-Authenticator = 0x3f265d734d4ae1d6329fbb1329421cf8
        EAP-Message = 
0x020503bf0d80000003b516030103850b00027500027200026f3082026b308201d4a003020102020104300d06092a864886f70d0101040500307b310b30090603550406130243413110300e060355040813074f6e746172696f310f300d060355040713064175726f7261310f300d060355040a1306506c796465783111300f06035504031308506c7964657843413125302306092a864886f70d0109011616646f75675f777269676874406465636f6d612e636f6d301e170d3036303632323138353832345a170d3037303632323138353832345a3063310b30090603550406130243413110300e060355040813074f6e746172696f310f300d060355
        EAP-Message = 
0x040713064175726f7261310f300d060355040a1306506c796465783120301e060355040313174f495430372e706c796465782e6465636f6d612e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100d924ecde1f7aa18f6af2d29c922c5daf2b63b2f1a5e911bfc858ef633fd79073357e3bb0f298b00beeb01da787bffd028f1275a6a3168c4a3259eefa7051dbee7127e9a1b5e2567ebbb7edc0a709fd292ecbe27465001e8179ebd5967fb6e93e15c7fccd760968c131bd61f7dd858f53dc5140bb9fbf59f575942151b4db1c0d0203010001a317301530130603551d25040c300a06082b06010505070302300d06092a
        EAP-Message = 
0x864886f70d01010405000381810011d142d85106e8cb3ed2fe681104d6776043434b70eb84132844a2363feb2361cb06634992ef6d77acae965d80bd80ed547c37d0ce57090bf9096ed98449b96188fc5d2c78b5e6d1d3f86aeb51a4224dfe42bb452d1644ea026c27ed251382339cfbb504a6fb4c56cafdf5fdac2b94a73eb4930344a5eb49897d072a0005d91710000082008030f526ec446de24317ecfc14746633b4ed414fcf82e90caf5149ee96992dc3ef848a7ef3af07f797319267d4005def7acd7c02790d62b39b15bd6059a0274542a5b19342aa1add69839c54c45bdf54361364f2f4326f27cefac4cdd7f41cdb5ee79ef278ef22225860
        EAP-Message = 
0xef5663c9fdac2cd5b2914714191ddd3cf6b9cfe6c5ae1f0f0000820080aea6f752be3600a1eda98981d013fe040130f8abf2e94c3631ac876a10418de665cc3bb59f255579f2a61647a5b89aef8f73d5088c66608c3ec45b77f491d735b2d3e1df230fabb263d9f5db3daa404d5a7f943cd9dccb6c38bcffabc78cf194c211a94d06cd0c1ccdf8c54b5e73bb02e6ab60dfac4d342d1b8694a200db86b61403010001011603010020c5728382030014b2d1d4f8894011d79a874b19ea3c07c46a2d7743af90c4683e
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 798
        State = 0x4722e062dffe964833f0197306e90f96
        NAS-IP-Address = 172.18.138.20
        NAS-Identifier = "AP1"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 3
  modcall[authorize]: module "preprocess" returns ok for request 3
  modcall[authorize]: module "chap" returns noop for request 3
  modcall[authorize]: module "mschap" returns noop for request 3
    rlm_realm: No '@' in User-Name = "OIT07.plydex.decoma.com", looking up 
realm NULL
    rlm_realm: No such realm "NULL"
  modcall[authorize]: module "suffix" returns noop for request 3
  rlm_eap: EAP packet type response id 5 length 253
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 3
    users: Matched DEFAULT at 152
  modcall[authorize]: module "files" returns ok for request 3
modcall: group authorize returns updated for request 3
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 3
  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
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0279], Certificate
chain-depth=1,
error=0
--> User-Name = OIT07.plydex.decoma.com
--> BUF-Name = PlydexCA
--> subject 
= /C=CA/ST=Ontario/L=Aurora/O=Plydex/CN=PlydexCA/emailAddress=email@removed
--> issuer  
= /C=CA/ST=Ontario/L=Aurora/O=Plydex/CN=PlydexCA/emailAddress=email@removed
--> verify return:1
chain-depth=0,
error=0
--> User-Name = OIT07.plydex.decoma.com
--> BUF-Name = OIT07.plydex.decoma.com
--> subject = /C=CA/ST=Ontario/L=Aurora/O=Plydex/CN=OIT07.plydex.decoma.com
--> issuer  
= /C=CA/ST=Ontario/L=Aurora/O=Plydex/CN=PlydexCA/emailAddress=email@removed
--> verify return:1
    TLS_accept: SSLv3 read client certificate A
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange
    TLS_accept: SSLv3 read client key exchange A
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0086], CertificateVerify
    TLS_accept: SSLv3 read certificate verify A
  rlm_eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001]
  rlm_eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished
    TLS_accept: SSLv3 read finished A
  rlm_eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001]
    TLS_accept: SSLv3 write change cipher spec A
  rlm_eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished
    TLS_accept: SSLv3 write finished A
    TLS_accept: SSLv3 flush data
    (other): SSL negotiation finished successfully
SSL Connection Established
  eaptls_process returned 13
  modcall[authenticate]: module "eap" returns handled for request 3
modcall: group authenticate returns handled for request 3
Sending Access-Challenge of id 255 to 172.18.138.20:1645
        EAP-Message = 
0x010600350d800000002b1403010001011603010020b8b4f57f295b4706f1c13f0a233a08a705f2d6ed81bb348cf49e3582c8b00a9d
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0x3a71f9a7fae3456bb07741128506b959
Finished request 3
Going to the next request
Waking up in 5 seconds...
rad_recv: Access-Request packet from host 172.18.138.20:1645, id=0, length=156
        User-Name = "OIT07.plydex.decoma.com"
        Framed-MTU = 1400
        Called-Station-Id = "0016.4631.fdb0"
        Calling-Station-Id = "000b.5feb.e378"
        Service-Type = Login-User
        Message-Authenticator = 0x41501d063e64fb9d73449627920f5d6e
        EAP-Message = 0x020600060d00
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 798
        State = 0x3a71f9a7fae3456bb07741128506b959
        NAS-IP-Address = 172.18.138.20
        NAS-Identifier = "AP1"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 4
  modcall[authorize]: module "preprocess" returns ok for request 4
  modcall[authorize]: module "chap" returns noop for request 4
  modcall[authorize]: module "mschap" returns noop for request 4
    rlm_realm: No '@' in User-Name = "OIT07.plydex.decoma.com", looking up 
realm NULL
    rlm_realm: No such realm "NULL"
  modcall[authorize]: module "suffix" returns noop for request 4
  rlm_eap: EAP packet type response id 6 length 6
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 4
    users: Matched DEFAULT at 152
  modcall[authorize]: module "files" returns ok for request 4
modcall: group authorize returns updated for request 4
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 4
  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 is finished
  eaptls_verify returned 3
  eaptls_process returned 3
  rlm_eap: Freeing handler
  modcall[authenticate]: module "eap" returns ok for request 4
modcall: group authenticate returns ok for request 4
Sending Access-Accept of id 0 to 172.18.138.20:1645
        MS-MPPE-Recv-Key = 
0x420d5505960fc3512b1d50f8c1a82f51a94dbcb139d5ecd1ab5bcea1ed1acf7c
        MS-MPPE-Send-Key = 
0xaf2ee042f92c04f8d1105d207bf7e46c8eeef5f4eb2c814177b9dff5cf353982
        EAP-Message = 0x03060004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "OIT07.plydex.decoma.com"
Finished request 4
Going to the next request
Waking up in 5 seconds...

Windows 2000 ignoring Access-Accept

Doug Wright