I am using the latest freeradius code with WiMax, Daloradius and MySQL. I am getting group rejects with the server complaining that it can't use MSCHAPv2. The confounding thing is that I had this working last week and it's now acting differently. Here is the debug:
Mon Dec 14 12:32:14 2009 : Info: Finished request 4. Mon Dec 14 12:32:14 2009 : Debug: Going to the next request Mon Dec 14 12:32:14 2009 : Debug: Waking up in 4.4 seconds. rad_recv: Access-Request packet from host 172.16.4.2 port 1812, id=86, length=393 User-Name = "{am=1}3ad1bc65fb314eb48f1606c0d23b1...@example.com" EAP-Message = 0x020600cc150016030100861000008200807017cf3a79f3fb411e2d6fd7407a0b146f5533cc 4ed1d262b63dc0113c12a37cd3dfdcd78c72324c7de0b95be31d39052b19d0573d97720ddb99 cbe195507cda4f494a8262712f1cf2c6547345a0c45d57451c70a9314d51504ad0027b49b194 495daf09f9d6eb5a6e9b663fb3419c9096209abd019557a31d3c39445633744b140301000101 16030100303a11c06474e810489e444268805b8ba59a82c0a00f83e5fbc9988a776d40aced1b 1b33674fce86da0e709034954a39c0 Message-Authenticator = 0x41ad7a4eb07c8f349351859e8eccd107 NAS-Identifier = "WC_LAB" NAS-IP-Address = 172.16.4.2 Calling-Station-Id = "00-12-CF-C7-4C-F2" WiMAX-BS-Id = 0x000002030209 NAS-Port-Type = 27 Framed-MTU = 2000 Service-Type = Framed-User WiMAX-GMT-Timezone-offset = 0 State = 0x1e32147e1a3401ed241a0e7b266a26bd Mon Dec 14 12:32:15 2009 : Info: +- entering group authorize {...} Mon Dec 14 12:32:15 2009 : Info: ++[preprocess] returns ok Mon Dec 14 12:32:15 2009 : Info: ++[chap] returns noop Mon Dec 14 12:32:15 2009 : Info: ++[mschap] returns noop Mon Dec 14 12:32:15 2009 : Info: ++[wimax] returns ok Mon Dec 14 12:32:15 2009 : Info: [suffix] Looking up realm "example.com" for User-Name = "{am=1}3ad1bc65fb314eb48f1606c0d23b1...@example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Found realm "example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Adding Realm = "example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Authentication realm is LOCAL. Mon Dec 14 12:32:15 2009 : Info: ++[suffix] returns ok Mon Dec 14 12:32:15 2009 : Info: [eap] EAP packet type response id 6 length 204 Mon Dec 14 12:32:15 2009 : Info: [eap] Continuing tunnel setup. Mon Dec 14 12:32:15 2009 : Info: ++[eap] returns ok Mon Dec 14 12:32:15 2009 : Info: Found Auth-Type = EAP Mon Dec 14 12:32:15 2009 : Info: +- entering group authenticate {...} Mon Dec 14 12:32:15 2009 : Info: [eap] Request found, released from the list Mon Dec 14 12:32:15 2009 : Info: [eap] EAP/ttls Mon Dec 14 12:32:15 2009 : Info: [eap] processing type ttls Mon Dec 14 12:32:15 2009 : Info: [ttls] Authenticate Mon Dec 14 12:32:15 2009 : Info: [ttls] processing EAP-TLS Mon Dec 14 12:32:15 2009 : Info: [ttls] eaptls_verify returned 7 Mon Dec 14 12:32:15 2009 : Info: [ttls] Done initial handshake Mon Dec 14 12:32:15 2009 : Info: [ttls] <<< TLS 1.0 Handshake [length 0086], ClientKeyExchange Mon Dec 14 12:32:15 2009 : Info: [ttls] TLS_accept: SSLv3 read client key exchange A Mon Dec 14 12:32:15 2009 : Info: [ttls] <<< TLS 1.0 ChangeCipherSpec [length 0001] Mon Dec 14 12:32:15 2009 : Info: [ttls] <<< TLS 1.0 Handshake [length 0010], Finished Mon Dec 14 12:32:15 2009 : Info: [ttls] TLS_accept: SSLv3 read finished A Mon Dec 14 12:32:15 2009 : Info: [ttls] >>> TLS 1.0 ChangeCipherSpec [length 0001] Mon Dec 14 12:32:15 2009 : Info: [ttls] TLS_accept: SSLv3 write change cipher spec A Mon Dec 14 12:32:15 2009 : Info: [ttls] >>> TLS 1.0 Handshake [length 0010], Finished Mon Dec 14 12:32:15 2009 : Info: [ttls] TLS_accept: SSLv3 write finished A Mon Dec 14 12:32:15 2009 : Info: [ttls] TLS_accept: SSLv3 flush data Mon Dec 14 12:32:15 2009 : Info: [ttls] (other): SSL negotiation finished successfully Mon Dec 14 12:32:15 2009 : Debug: SSL Connection Established Mon Dec 14 12:32:15 2009 : Info: [ttls] eaptls_process returned 13 Mon Dec 14 12:32:15 2009 : Info: ++[eap] returns handled Sending Access-Challenge of id 86 to 172.16.4.2 port 1812 EAP-Message = 0x0107004515800000003b14030100010116030100304b7f87751994ad5c4518d22e1b233a6a 30020ffd0d5a730904158eb7101a15696164fe1a50f24a526b2dc181690de5f0 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x1e32147e1b3501ed241a0e7b266a26bd Mon Dec 14 12:32:15 2009 : Info: Finished request 5. Mon Dec 14 12:32:15 2009 : Debug: Going to the next request Mon Dec 14 12:32:15 2009 : Debug: Waking up in 3.8 seconds. rad_recv: Access-Request packet from host 172.16.4.2 port 1812, id=87, length=381 User-Name = "{am=1}3ad1bc65fb314eb48f1606c0d23b1...@example.com" EAP-Message = 0x020700c015001703010020707edef0cc349370aca5964515a8be4538df0f153227178f706d e7533978e29917030100909acee26fddaca59612e605c32c57624fd42a6d929430c67520757f e01507bc4cf848203010af0367c64264c99fe07abe5460c6cb5f731cfea51e57879eabe1e18d 64876c5737b71aebcd5334b972e985c9203d861cc026279d9e7c0c2393b2e1d1ad960fe985a5 a0593083aa0fe26c20f7315f541b092e3745802a504e5a773679d1fabacb3471138c73243845 2aafdd Message-Authenticator = 0x906e115a16639fc8239a67adaa9011cb NAS-Identifier = "WC_LAB" NAS-IP-Address = 172.16.4.2 Calling-Station-Id = "00-12-CF-C7-4C-F2" WiMAX-BS-Id = 0x000002030209 NAS-Port-Type = 27 Framed-MTU = 2000 Service-Type = Framed-User WiMAX-GMT-Timezone-offset = 0 State = 0x1e32147e1b3501ed241a0e7b266a26bd Mon Dec 14 12:32:15 2009 : Info: +- entering group authorize {...} Mon Dec 14 12:32:15 2009 : Info: ++[preprocess] returns ok Mon Dec 14 12:32:15 2009 : Info: ++[chap] returns noop Mon Dec 14 12:32:15 2009 : Info: ++[mschap] returns noop Mon Dec 14 12:32:15 2009 : Info: ++[wimax] returns ok Mon Dec 14 12:32:15 2009 : Info: [suffix] Looking up realm "example.com" for User-Name = "{am=1}3ad1bc65fb314eb48f1606c0d23b1...@example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Found realm "example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Adding Realm = "example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Authentication realm is LOCAL. Mon Dec 14 12:32:15 2009 : Info: ++[suffix] returns ok Mon Dec 14 12:32:15 2009 : Info: [eap] EAP packet type response id 7 length 192 Mon Dec 14 12:32:15 2009 : Info: [eap] Continuing tunnel setup. Mon Dec 14 12:32:15 2009 : Info: ++[eap] returns ok Mon Dec 14 12:32:15 2009 : Info: Found Auth-Type = EAP Mon Dec 14 12:32:15 2009 : Info: +- entering group authenticate {...} Mon Dec 14 12:32:15 2009 : Info: [eap] Request found, released from the list Mon Dec 14 12:32:15 2009 : Info: [eap] EAP/ttls Mon Dec 14 12:32:15 2009 : Info: [eap] processing type ttls Mon Dec 14 12:32:15 2009 : Info: [ttls] Authenticate Mon Dec 14 12:32:15 2009 : Info: [ttls] processing EAP-TLS Mon Dec 14 12:32:15 2009 : Info: [ttls] eaptls_verify returned 7 Mon Dec 14 12:32:15 2009 : Info: [ttls] Done initial handshake Mon Dec 14 12:32:15 2009 : Info: [ttls] eaptls_process returned 7 Mon Dec 14 12:32:15 2009 : Info: [ttls] Session established. Proceeding to decode tunneled attributes. TTLS tunnel data in 0000: 00 00 00 01 40 00 00 1a 53 69 6c 76 65 72 40 65 TTLS tunnel data in 0010: 78 61 6d 70 6c 65 2e 63 6f 6d 00 00 00 00 00 0b TTLS tunnel data in 0020: c0 00 00 1c 00 00 01 37 8e fc 4f 90 b9 c9 af bb TTLS tunnel data in 0030: e2 85 67 5a c1 59 10 df 00 00 00 19 c0 00 00 3e TTLS tunnel data in 0040: 00 00 01 37 35 00 fe f7 66 bb 3b ea 86 dc ef 09 TTLS tunnel data in 0050: c6 ea ff 22 c9 c3 00 00 00 00 00 00 00 00 0d 2a TTLS tunnel data in 0060: 12 6b b1 3e 4d 46 b6 b0 cb 1b 75 f1 98 6c ea d8 TTLS tunnel data in 0070: 41 20 ad b7 e3 70 00 00 Mon Dec 14 12:32:15 2009 : Info: [ttls] Got tunneled request User-Name = "sil...@example.com" MS-CHAP-Challenge = 0x8efc4f90b9c9afbbe285675ac15910df MS-CHAP2-Response = 0x3500fef766bb3bea86dcef09c6eaff22c9c300000000000000000d2a126bb13e4d46b6b0cb 1b75f1986cead84120adb7e370 FreeRADIUS-Proxied-To = 127.0.0.1 Mon Dec 14 12:32:15 2009 : Info: [ttls] Sending tunneled request User-Name = "sil...@example.com" MS-CHAP-Challenge = 0x8efc4f90b9c9afbbe285675ac15910df MS-CHAP2-Response = 0x3500fef766bb3bea86dcef09c6eaff22c9c300000000000000000d2a126bb13e4d46b6b0cb 1b75f1986cead84120adb7e370 FreeRADIUS-Proxied-To = 127.0.0.1 NAS-Identifier = "WC_LAB" NAS-IP-Address = 172.16.4.2 Calling-Station-Id = "00-12-CF-C7-4C-F2" WiMAX-BS-Id = 0x000002030209 NAS-Port-Type = 27 Framed-MTU = 2000 Service-Type = Framed-User WiMAX-GMT-Timezone-offset = 0 server inner-tunnel { Mon Dec 14 12:32:15 2009 : Info: +- entering group authorize {...} Mon Dec 14 12:32:15 2009 : Info: ++[chap] returns noop Mon Dec 14 12:32:15 2009 : Info: [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Mon Dec 14 12:32:15 2009 : Info: ++[mschap] returns ok Mon Dec 14 12:32:15 2009 : Info: ++[unix] returns notfound Mon Dec 14 12:32:15 2009 : Info: [suffix] Looking up realm "example.com" for User-Name = "sil...@example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Found realm "example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Adding Realm = "example.com" Mon Dec 14 12:32:15 2009 : Info: [suffix] Authentication realm is LOCAL. Mon Dec 14 12:32:15 2009 : Info: ++[suffix] returns ok Mon Dec 14 12:32:15 2009 : Info: ++[control] returns ok Mon Dec 14 12:32:15 2009 : Info: [eap] No EAP-Message, not doing EAP Mon Dec 14 12:32:15 2009 : Info: ++[eap] returns noop Mon Dec 14 12:32:15 2009 : Info: ++[files] returns noop Mon Dec 14 12:32:15 2009 : Info: [sql] expand: %{User-Name} -> sil...@example.com Mon Dec 14 12:32:15 2009 : Info: [sql] sql_set_user escaped user --> 'sil...@example.com' Mon Dec 14 12:32:15 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 1 Mon Dec 14 12:32:15 2009 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'sil...@example.com' ORDER BY id Mon Dec 14 12:32:15 2009 : Info: [sql] User found in radcheck table Mon Dec 14 12:32:15 2009 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'sil...@example.com' ORDER BY id Mon Dec 14 12:32:15 2009 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'sil...@example.com' ORDER BY priority Mon Dec 14 12:32:15 2009 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'Silver' ORDER BY id Mon Dec 14 12:32:15 2009 : Info: [sql] User found in group Silver Mon Dec 14 12:32:15 2009 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'Silver' ORDER BY id Mon Dec 14 12:32:15 2009 : Debug: rlm_sql (sql): Released sql socket id: 1 Mon Dec 14 12:32:15 2009 : Info: ++[sql] returns ok Mon Dec 14 12:32:15 2009 : Info: ++[expiration] returns noop Mon Dec 14 12:32:15 2009 : Info: ++[logintime] returns noop Mon Dec 14 12:32:15 2009 : Info: [pap] Found existing Auth-Type, not changing it. Mon Dec 14 12:32:15 2009 : Info: ++[pap] returns noop Mon Dec 14 12:32:15 2009 : Info: Found Auth-Type = MSCHAP Mon Dec 14 12:32:15 2009 : Info: +- entering group MS-CHAP {...} Mon Dec 14 12:32:15 2009 : Info: [mschap] Told to do MS-CHAPv2 for sil...@example.com with NT-Password Mon Dec 14 12:32:15 2009 : Info: [mschap] FAILED: MS-CHAP2-Response is incorrect Mon Dec 14 12:32:15 2009 : Info: ++[mschap] returns reject Mon Dec 14 12:32:15 2009 : Info: Failed to authenticate the user. } # server inner-tunnel Mon Dec 14 12:32:15 2009 : Info: [ttls] Got tunneled reply code 3 Framed-Filter-Id := "Silver" MS-CHAP-Error = "5E=691 R=1" Mon Dec 14 12:32:15 2009 : Info: [ttls] Got tunneled Access-Reject Mon Dec 14 12:32:15 2009 : Info: [eap] Handler failed in EAP/ttls Mon Dec 14 12:32:15 2009 : Info: [eap] Failed in EAP select Mon Dec 14 12:32:15 2009 : Info: ++[eap] returns invalid Mon Dec 14 12:32:15 2009 : Info: Failed to authenticate the user. Mon Dec 14 12:32:15 2009 : Info: Using Post-Auth-Type Reject Mon Dec 14 12:32:15 2009 : Info: +- entering group REJECT {...} Mon Dec 14 12:32:15 2009 : Info: [attr_filter.access_reject] expand: %{User-Name} -> {am=1}3ad1bc65fb314eb48f1606c0d23b1...@example.com Mon Dec 14 12:32:15 2009 : Debug: attr_filter: Matched entry DEFAULT at line 11 Mon Dec 14 12:32:15 2009 : Info: ++[attr_filter.access_reject] returns updated Mon Dec 14 12:32:15 2009 : Info: Delaying reject of request 6 for 1 seconds Mon Dec 14 12:32:15 2009 : Debug: Going to the next request Mon Dec 14 12:32:15 2009 : Debug: Waking up in 0.9 seconds. Mon Dec 14 12:32:16 2009 : Info: Sending delayed reject for request 6 Sending Access-Reject of id 87 to 172.16.4.2 port 1812 EAP-Message = 0x04070004 Message-Authenticator = 0x00000000000000000000000000000000 - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html