Group and SQL issue

14 Dec 2009


      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}3ad1bc65fb314eb48f1606c0d23b1459@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}3ad1bc65fb314eb48f1606c0d23b1459@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}3ad1bc65fb314eb48f1606c0d23b1459@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}3ad1bc65fb314eb48f1606c0d23b1459@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 = "Silver@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 = "Silver@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 = "Silver@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} -> Silver@example.com
Mon Dec 14 12:32:15 2009 : Info: [sql] sql_set_user escaped user -->
'Silver@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 =
'Silver@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 =
'Silver@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 = 'Silver@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 Silver@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}3ad1bc65fb314eb48f1606c0d23b1459@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

Group and SQL issue

David Peterson