rlm_sqlcounter doesn't increase counter

Tue Feb 28 16:30:36 CET 2012

>>
> >> > examples from http://wiki.freeradius.org/Rlm_sqlcounter, but my
> counter
> >> > doesn't still increase.? What am I missing please.
> >>
> >>
> >> Do you have accounting records for that user in radacct?
> >>
> >
> > mmm. no Fajar, I have checked from mysql and do not have any record for
> > service type= Framed-User. I only have record for service
> type=NAS-Prompt-User.
> > What could be the reason why accounting records are not captured in
> radacct
> > for a Framed-User?
>
> Does your NAS send accounting packets?
>

Yes i found some accounting packets, but only for telnet logins users. My
NAS is a Cisco 2960 switch.

Feb 28 15:16:07.111: AAA/ACCT/EXEC(00000118): Queueing record is UPDATE
Feb 28 15:16:07.111: AAA/ACCT(00000118): Sending periodic record type=EXEC
user=pam
Feb 28 15:16:07.111: AAA/ACCT(00000118): Accounting method=radius (RADIUS)
Feb 28 15:16:07.111: RADIUS/ENCODE(00000118):Orig. component type = EXEC
Feb 28 15:16:07.111: RADIUS(00000118): Config NAS IP: 0.0.0.0
Feb 28 15:16:07.111: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:07.111: RADIUS(00000118): Send Accounting-Request to
10.1.7.202:1813 id 1646/45, len 132
Feb 28 15:16:07.111: RADIUS(00000118): Started 5 sec timeout
Feb 28 15:16:07.111: RADIUS: Received from id 1646/45 10.1.7.202:1813,
Accounting-response, len 20
Feb 28 15:16:07.111: AAA/ACCT/EXEC(00000118): UPDATE protocol reply PASS
Feb 28 15:16:07.111: AAA/ACCT(00000118): Resetting Periodic timer
Feb 28 15:16:35.532: AAA/ACCT/HC(00000125): Update DOT1X/03194F10
Feb 28 15:16:35.532: AAA/ACCT/HC(00000125): DOT1X/03194F10 [pre-sess]
(rx/tx) base 149953679/386909991 pre 150010061/386953971 c
Feb 28 15:16:35.532: AAA/ACCT/HC(00000125): DOT1X/03194F10 [pre-sess]
(rx/tx) adjusted, pre 56382/43980 call 0/0
Feb 28 15:16:35.532: AAA/ACCT/HC(00000125): Update DOT1X/03194F10
Feb 28 15:16:35.532: AAA/ACCT/HC(00000125): DOT1X/03194F10 [sess] (rx/tx)
base 149953679/386909991 pre 150010061/386953971 call
Feb 28 15:16:35.532: AAA/ACCT/HC(00000125): DOT1X/03194F10 [sess] (rx/tx)
adjusted, pre 56382/43980 call 0/0
Feb 28 15:16:35.532: AAA/ACCT/HC(00000125): Deregister DOT1X/03194F10
Feb 28 15:16:35.540: AAA/ACCT/EVENT/(00000125): CALL STOP
Feb 28 15:16:35.540: AAA/ACCT/CALL STOP(00000125): Sending stop requests
Feb 28 15:16:35.540: AAA/ACCT(00000125): Send all stops
Feb 28 15:16:35.540: AAA/ACCT/NET(00000125): STOP
Feb 28 15:16:35.540: AAA/ACCT/NET(00000125): Method list not found
Feb 28 15:16:35.540: AAA/ACCT(00000125): del node, session 293
Feb 28 15:16:35.540: AAA/ACCT/NET(00000125): free_rec, count 0
Feb 28 15:16:35.540: AAA/ACCT/NET(00000125) reccnt 0, csr TRUE, osr 0
Feb 28 15:16:35.540: AAA/ACCT/NET(00000125): Last rec in db, intf not
enqueued
Feb 28 15:16:36.530: %LINEPROTO-5-UPDOWN: Line protocol on Interface
FastEthernet0/9, changed state to down
Feb 28 15:16:37.218: AAA/ACCT/HC(00000126): Register DOT1X/03194F10 0bit/s,
assuming 100Mbit/s, poll every 5m 0s
Feb 28 15:16:37.218: AAA/ACCT/HC(00000126): Update DOT1X/03194F10
Feb 28 15:16:37.218: AAA/ACCT/HC(00000126): DOT1X/03194F10 [init-sess]
(rx/tx) base 150010061/386953971 pre 150010061/386953971
Feb 28 15:16:37.218: AAA/ACCT/HC(00000126): DOT1X/03194F10 [init-sess]
(rx/tx) adjusted, pre 0/0 call 0/0
Feb 28 15:16:37.218: AAA/ACCT/EVENT/(00000126): CALL START
Feb 28 15:16:37.218: Getting session id for NET(00000126) : db=3567CE4
Feb 28 15:16:37.218: AAA/ACCT(00000000): add node, session 294
Feb 28 15:16:37.218: AAA/ACCT/NET(00000126): add, count 1
Feb 28 15:16:37.218: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:37.411: %AUTHMGR-5-START: Starting 'dot1x' for client
(001e.33d5.7a68) on Interface Fa0/9 AuditSessionID 0A01050400
Feb 28 15:16:38.535: %LINEPROTO-5-UPDOWN: Line protocol on Interface
FastEthernet0/9, changed state to up
Feb 28 15:16:45.523: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:45.523: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:45.523: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:45.523: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:45.523: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/179, len 193
Feb 28 15:16:45.523: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:45.531: RADIUS: Received from id 1645/179 10.1.7.202:1812,
Access-Challenge, len 76
Feb 28 15:16:45.531: RADIUS/DECODE: EAP-Message fragments, 6, total 6 bytes
Feb 28 15:16:45.531: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:45.531: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:45.531: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:45.531: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:45.540: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/180, len 352
Feb 28 15:16:45.540: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:45.607: RADIUS: Received from id 1645/180 10.1.7.202:1812,
Access-Challenge, len 1112
Feb 28 15:16:45.607: RADIUS/DECODE: EAP-Message fragments,
253+253+253+253+22, total 1034 bytes
Feb 28 15:16:45.615: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:45.615: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:45.615: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:45.615: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:45.615: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/181, len 207
Feb 28 15:16:45.615: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:45.623: RADIUS: Received from id 1645/181 10.1.7.202:1812,
Access-Challenge, len 842
Feb 28 15:16:45.623: RADIUS/DECODE: EAP-Message fragments, 253+253+253+7,
total 766 bytes
Feb 28 15:16:45.632: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:45.632: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:45.632: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:45.632: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:45.632: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/182, len 409
Feb 28 15:16:45.632: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:45.732: RADIUS: Received from id 1645/182 10.1.7.202:1812,
Access-Challenge, len 135
Feb 28 15:16:45.732: RADIUS/DECODE: EAP-Message fragments, 65, total 65
bytes
Feb 28 15:16:45.741: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:45.741: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:45.741: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:45.741: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:45.741: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/183, len 207
Feb 28 15:16:45.741: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:45.749: RADIUS: Received from id 1645/183 10.1.7.202:1812,
Access-Challenge, len 113
Feb 28 15:16:45.749: RADIUS/DECODE: EAP-Message fragments, 43, total 43
bytes
Feb 28 15:16:45.758: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:45.758: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:45.758: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:45.758: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:45.758: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/184, len 244
Feb 28 15:16:45.758: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:45.850: RADIUS: Received from id 1645/184 10.1.7.202:1812,
Access-Challenge, len 129
Feb 28 15:16:45.850: RADIUS/DECODE: EAP-Message fragments, 59, total 59
bytes
Feb 28 15:16:45.867: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:45.867: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:45.867: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:45.867: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:45.867: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/185, len 308
Feb 28 15:16:45.867: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:46.060: RADIUS: Received from id 1645/185 10.1.7.202:1812,
Access-Challenge, len 161
Feb 28 15:16:46.060: RADIUS/DECODE: EAP-Message fragments, 91, total 91
bytes
Feb 28 15:16:46.068: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:46.068: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:46.068: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:46.068: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:46.068: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/186, len 244
Feb 28 15:16:46.068: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:46.076: RADIUS: Received from id 1645/186 10.1.7.202:1812,
Access-Challenge, len 113
Feb 28 15:16:46.076: RADIUS/DECODE: EAP-Message fragments, 43, total 43
bytes
Feb 28 15:16:46.085: RADIUS/ENCODE(00000126):Orig. component type = DOT1X
Feb 28 15:16:46.085: RADIUS(00000126): Config NAS IP: 0.0.0.0
Feb 28 15:16:46.085: Getting session id for DOT1X(00000126) : db=3567CE4
Feb 28 15:16:46.085: RADIUS/ENCODE: Best Local IP-Address 10.1.5.4 for
Radius-Server 10.1.7.202
Feb 28 15:16:46.085: RADIUS(00000126): Send Access-Request to
10.1.7.202:1812 id 1645/187, len 244
Feb 28 15:16:46.085: RADIUS(00000126): Started 5 sec timeout
Feb 28 15:16:46.177: RADIUS: Received from id 1645/187 10.1.7.202:1812,
Access-Accept, len 180
Feb 28 15:16:46.177: RADIUS/DECODE: EAP-Message fragments, 4, total 4 bytes
Feb 28 15:16:46.177: %DOT1X-5-SUCCESS: Authentication successful for client
(001e.33d5.7a68) on Interface Fa0/9 AuditSessionID
Feb 28 15:16:46.177: %AUTHMGR-7-RESULT: Authentication result 'success'
from 'dot1x' for client (001e.33d5.7a68) on Interface Fa
Feb 28 15:16:47.217: %AUTHMGR-5-SUCCESS: Authorization succeeded for client
(001e.33d5.7a68) on Interface Fa0/9 AuditSessionID 0
Feb 28 15:17:07.619: AAA/ACCT/EXEC(00000118): Queueing record is UPDATE
Feb 28 15:17:07.619: AAA/ACCT(00000118): Sending periodic record type=EXEC
user=pam
Feb 28 15:17:07.619: AAA/ACCT(00000118): Accounting method=radius (RADIUS)
Feb 28 15:17:07.619: RADIUS/ENCODE(00000118):Orig. component type = EXEC

>
> What does FR debug log shows like when it's receiving accounting packets?
>

Debug  log from FR looks like below. I am not sure if it recieves
accounting packets.

Going to the next request
Waking up in 6 seconds...
rad_recv: Access-Request packet from host 10.1.5.4:1645, id=186, length=244
        User-Name = "clare"
        Service-Type = Framed-User
        Framed-MTU = 1500
        Called-Station-Id = "EC-30-91-1D-69-89"
        Calling-Station-Id = "00-1E-33-D5-7A-68"
        EAP-Message =
0x0208002b19001703010020d06936f660c0fb15857fffd011a62ae19dfcc280b9bf19b74398bda313b99706
        Message-Authenticator = 0x0064b79e63b6b1ad0add9398f8ba9751
        Cisco-AVPair = "audit-session-id=0A0105040000011F08185C13"
        NAS-Port-Type = Ethernet
        NAS-Port = 50009
        NAS-Port-Id = "FastEthernet0/9"
        State = 0x00f91a7e57066443fa1652468504ce18
        NAS-IP-Address = 10.1.5.4
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 100
  modcall[authorize]: module "preprocess" returns ok for request 100
  modcall[authorize]: module "mschap" returns noop for request 100
    rlm_realm: No '@' in User-Name = "clare", looking up realm NULL
    rlm_realm: No such realm "NULL"
  modcall[authorize]: module "suffix" returns noop for request 100
  rlm_eap: EAP packet type response id 8 length 43
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 100
    users: Matched entry clare at line 97
  modcall[authorize]: module "files" returns ok for request 100
radius_xlat:  'clare'
rlm_sql (sql): sql_set_user escaped user --> 'clare'
radius_xlat:  'SELECT id, UserName, Attribute, Value, op           FROM
radcheck           WHERE Username = 'clare'           ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 0
rlm_sql (sql): User clare not found in radcheck
radius_xlat:  'SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op
FROM radgroupcheck,usergroup WHERE usergroup.Username = 'clare' AND
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op
FROM radgroupreply,usergroup WHERE usergroup.Username = 'clare' AND
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): User clare not found in radgroupcheck
rlm_sql (sql): Released sql socket id: 0
rlm_sql (sql): User not found
  modcall[authorize]: module "sql" returns notfound for request 100
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 100
rlm_sqlcounter: Entering module authorize code
sqlcounter_expand:  'SELECT SUM(AcctSessionTime - GREATEST((1330387200 -
UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE
UserName='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime
> '1330387200''
radius_xlat:  'SELECT SUM(AcctSessionTime - GREATEST((1330387200 -
UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='clare' AND
UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1330387200''
sqlcounter_expand:  '%{sqlcca3:SELECT SUM(AcctSessionTime -
GREATEST((1330387200 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct
WHERE UserName='clare' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime
> '1330387200'}'
WARNING: Attempt to use unknown xlat function, or non-existent attribute in
string %{sqlcca3:SELECT SUM(AcctSessionTime - GREATEST((1330387200 -
UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='clare' AND
UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1330387200'}
radius_xlat:  ''
rlm_sqlcounter: (Check item - counter) is greater than zero
rlm_sqlcounter: Authorized user clare, check_item=120, counter=0
rlm_sqlcounter: Sent Reply-Item for user clare, Type=Session-Timeout,
value=120
  modcall[authorize]: module "dailycounter" returns ok for request 100
modcall: leaving group authorize (returns updated) for request 100
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 100
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/peap
  rlm_eap: processing type peap
  rlm_eap_peap: Authenticate
  rlm_eap_tls: processing TLS
  eaptls_verify returned 7
  rlm_eap_tls: Done initial handshake
  eaptls_process returned 7
  rlm_eap_peap: EAPTLS_OK
  rlm_eap_peap: Session established.  Decoding tunneled attributes.
  rlm_eap_peap: EAP type mschapv2
  rlm_eap_peap: Tunneled data is valid.
  PEAP: Got tunneled EAP-Message
        EAP-Message = 0x020800061a03
  PEAP: Setting User-Name to clare
  PEAP: Adding old state with 3b b3
  PEAP: Sending tunneled request
        EAP-Message = 0x020800061a03
        FreeRADIUS-Proxied-To = 127.0.0.1
        User-Name = "clare"
        State = 0x3bb38a486193de91b9a05ac2529e2912
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 100
  modcall[authorize]: module "preprocess" returns ok for request 100
  modcall[authorize]: module "mschap" returns noop for request 100
    rlm_realm: No '@' in User-Name = "clare", looking up realm NULL
    rlm_realm: No such realm "NULL"
  modcall[authorize]: module "suffix" returns noop for request 100
  rlm_eap: EAP packet type response id 8 length 6
  rlm_eap: No EAP Start, assuming it's an on-going EAP conversation
  modcall[authorize]: module "eap" returns updated for request 100
    users: Matched entry clare at line 97
  modcall[authorize]: module "files" returns ok for request 100
radius_xlat:  'clare'
rlm_sql (sql): sql_set_user escaped user --> 'clare'
radius_xlat:  'SELECT id, UserName, Attribute, Value, op           FROM
radcheck           WHERE Username = 'clare'           ORDER BY id'
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): User clare not found in radcheck
radius_xlat:  'SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op
FROM radgroupcheck,usergroup WHERE usergroup.Username = 'clare' AND
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat:  'SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op
FROM radgroupreply,usergroup WHERE usergroup.Username = 'clare' AND
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): User clare not found in radgroupcheck
rlm_sql (sql): Released sql socket id: 4
rlm_sql (sql): User not found
  modcall[authorize]: module "sql" returns notfound for request 100
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
  modcall[authorize]: module "noresetcounter" returns noop for request 100
rlm_sqlcounter: Entering module authorize code
sqlcounter_expand:  'SELECT SUM(AcctSessionTime - GREATEST((1330387200 -
UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE
UserName='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime
> '1330387200''
radius_xlat:  'SELECT SUM(AcctSessionTime - GREATEST((1330387200 -
UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='clare' AND
UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1330387200''
sqlcounter_expand:  '%{sqlcca3:SELECT SUM(AcctSessionTime -
GREATEST((1330387200 - UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct
WHERE UserName='clare' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime
> '1330387200'}'
WARNING: Attempt to use unknown xlat function, or non-existent attribute in
string %{sqlcca3:SELECT SUM(AcctSessionTime - GREATEST((1330387200 -
UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE UserName='clare' AND
UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '1330387200'}
radius_xlat:  ''
rlm_sqlcounter: (Check item - counter) is greater than zero
rlm_sqlcounter: Authorized user clare, check_item=120, counter=0
rlm_sqlcounter: Sent Reply-Item for user clare, Type=Session-Timeout,
value=120
  modcall[authorize]: module "dailycounter" returns ok for request 100
modcall: leaving group authorize (returns updated) for request 100
  rad_check_password:  Found Auth-Type EAP
auth: type "EAP"
  Processing the authenticate section of radiusd.conf
modcall: entering group authenticate for request 100
  rlm_eap: Request found, released from the list
  rlm_eap: EAP/mschapv2
  rlm_eap: processing type mschapv2
  rlm_eap: Freeing handler
  modcall[authenticate]: module "eap" returns ok for request 100
modcall: leaving group authenticate (returns ok) for request 100
Login OK: [clare] (from client localhost port 0)
  PEAP: Got tunneled reply RADIUS code 2
        Service-Type = Framed-User
        Session-Timeout = 120
        EAP-Message = 0x03080004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "clare"
  PEAP: Processing from tunneled session code 0x9cec000 2
        Service-Type = Framed-User
        Session-Timeout = 120
        EAP-Message = 0x03080004
        Message-Authenticator = 0x00000000000000000000000000000000
        User-Name = "clare"
  PEAP: Tunneled authentication was successful.
  rlm_eap_peap: SUCCESS
  modcall[authenticate]: module "eap" returns handled for request 100
modcall: leaving group authenticate (returns handled) for request 100
Sending Access-Challenge of id 186 to 10.1.5.4 port 1645
        Service-Type = Framed-User
        Session-Timeout = 120
        EAP-Message =
0x0109002b19001703010020894b0248edb8c12721f80e332c6365548e99e020c086b8db7ed0a3d462d6dc37
        Message-Authenticator = 0x00000000000000000000000000000000
        State = 0xa91be12e67268f7d04712d947281391b
Finished request 100

>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120228/240c8c60/attachment.html>