Re: rlm_sqlcounter doesn't increase counter
I have sql declared in accounting module. I have followed
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 record for service type=NAS-Prompt-User. What could be the reason why accounting records are not captured in radacct for a Framed-User? mysql> select * from radacct where username="clare" and AcctStartTime like "%2012-02-28%"; | RadAcctId | AcctSessionId | AcctUniqueId | UserName | Realm | NASIPAddress | NASPortId | NASPortType | AcctStartTime | AcctStopTime | AcctSessionTime | AcctAuthentic | ConnectInfo_start | ConnectInfo_stop | AcctInputOctets | AcctOutputOctets | CalledStationId | CallingStationId | AcctTerminateCause | ServiceType | FramedProtocol | FramedIPAddress | AcctStartDelay | AcctStopDelay | +-----------+---------------+------------------+----------+-------+--------------+-----------+-------------+---------------------+---------------------+-----------------+---------------+-------------------+------------------+-----------------+------------------+-----------------+------------------+--------------------+-----------------+----------------+-----------------+----------------+---------------+ | 395 | 000000F0 | 5f2c6316d5e5945b | clare | | 10.1.5.4 | 6 | Virtual | 2012-02-28 14:21:12 | 0000-00-00 00:00:00 | 0 | RADIUS | | | 0 | 0 | | 10.1.5.12 | | NAS-Prompt-User | | | 0 | 0 | ------- Pamela Pomary ICT Assistant, University Of Ghana. skype: ppomary
On Tue, Feb 28, 2012 at 9:32 PM, pamela pomary <ppomary@gmail.com> wrote:
>I have sql declared in accounting module. I have followed
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 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? What does FR debug log shows like when it's receiving accounting packets? -- Fajar
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
On Tue, Feb 28, 2012 at 10:30 PM, pamela pomary <ppomary@gmail.com> wrote:
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.
Then ask your NAS vendor (or read its documentation) on how to make it send accounting packets for Framed-User. I don't use cisco switch as NAS, so I can't help you much there. Sorry.
rad_recv: Access-Request packet from host 10.1.5.4:1645, id=186, length=244
This is not accounting packet. Your root cause of problem seems to be that your NAS isn't sending accounting packets (at least not for the service you want). You need to fix that. -- Fajar
Hi, logins for Cisco wont do decent accounting for login sessions - for authenticated sessions on edge ports they can sent accounting...eg aaa accounting dot1x default start-stop group RADIUS alan
Hello Alan,
logins for Cisco wont do decent accounting for login sessions - for authenticated sessions on edge ports they can sent accounting...eg
aaa accounting dot1x default start-stop group RADIUS
alan
Sorry, I didn't quiet understand your submission.Please are you saying Cisco 2960 is unable to send accounting packets to the radius server. I have the following on my Cisco 2960 switch. aaa accounting send stop-record authentication failure aaa accounting suppress null-username aaa accounting session-duration ntp-adjusted aaa accounting update newinfo periodic 1 aaa accounting exec default start-stop group radius aaa accounting network default start-stop group radius aaa accounting connection default start-stop group radius aaa accounting resource default start-stop-failure group radius Do I have too many entries for accounting?
Hi,
logins for Cisco wont do decent accounting for login sessions - for authenticated sessions on edge ports they can sent accounting...eg
aaa accounting dot1x default start-stop group RADIUS
did you read what I typed? I dont see a line like this inyour provided config - which means that any dot1x authenticated client WONT be sending any accounting updates. alan
Thanks Alan for pointing it out. I am happy I am getting close to the solution.I have added the line aaa accounting dot1x default start-stop group RADIUS to the switch. accounting packets are being sent to the radius server now. I also have accounting details recorded in radacct table in mysql. But counter doesn't increase.Users are not logged off when they reach their Maximum Daily session. #####Radius Debug##### 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 257 ####/etc/raddb/users########### clare Max-Daily-Session := 120, User-Password := "password" Service-Type = Framed-User log from tail /var/log/radius/radacct/10.1.5.4/detail-20120229 doesn't give much NAS-Port-Id = "FastEthernet0/9" Called-Station-Id = "EC-30-91-1D-69-89" Calling-Station-Id = "00-1E-33-D5-7A-68" Service-Type = Framed-User NAS-IP-Address = 10.1.5.4 Acct-Delay-Time = 0 Client-IP-Address = 10.1.5.4 Acct-Unique-Session-Id = "d5e43dc3a98bea70" Timestamp = 1330522011
On Wed, Feb 29, 2012 at 8:29 PM, pamela pomary <ppomary@gmail.com> wrote:
But counter doesn't increase.Users are not logged off when they reach their Maximum Daily session.
#####Radius Debug#####
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 257
A complete output of what attributes FR sends would be nice. Lacking that, I assume from the above snippet that FR sends Session-Timeout = 120. Does your NAS honor Session-Timeout? As usual, if you don't know the answer, look at its documentation or ask the vendor. -- Fajar
participants (3)
-
Alan Buxey -
Fajar A. Nugraha -
pamela pomary