Freeradiusd-3.0.6 Wrong acctstartime, acctupdatetime, acctstoptime
Akash
akash at satelinknepal.com.np
Mon Dec 22 03:55:11 CET 2014
Please check the radiusd -X output
-------------------------------------------------------
(0) Received Access-Request Id 7 from 192.168.10.173:42023 to
192.168.10.172:1812 length 182
(0) Service-Type = Framed-User
(0) Framed-Protocol = PPP
(0) NAS-Port = 15728641
(0) NAS-Port-Type = Ethernet
(0) User-Name = 'akash'
(0) Calling-Station-Id = '00:0F:38:6B:45:D4'
(0) Called-Station-Id = 'PPPoE_B'
(0) NAS-Port-Id = 'PPP'
(0) MS-CHAP-Challenge = 0x646920acc4101ab50473e6e70c252b6c
(0) MS-CHAP2-Response =
0x0100e5ad8428463425468a35ee9399362a390000000000000000ed2b05b0d06766de27d4e4c6625e1d1087b38f85bdcba134
(0) NAS-Identifier = 'MikroTik'
(0) NAS-IP-Address = 192.168.10.173
(0) # Executing section authorize from file
/etc/raddb/sites-enabled/default
(0) authorize {
(0) policy filter_username {
(0) if (!&User-Name) {
(0) if (!&User-Name) -> FALSE
(0) if (&User-Name =~ / /) {
(0) if (&User-Name =~ / /) -> FALSE
(0) if (&User-Name =~ /@.*@/ ) {
(0) if (&User-Name =~ /@.*@/ ) -> FALSE
(0) if (&User-Name =~ /../ ) {
(0) if (&User-Name =~ /../ ) -> FALSE
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+).(.+)$/)) {
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+).(.+)$/)) -> FALSE
(0) if (&User-Name =~ /.$/) {
(0) if (&User-Name =~ /.$/) -> FALSE
(0) if (&User-Name =~ /@./) {
(0) if (&User-Name =~ /@./) -> FALSE
(0) } # policy filter_username = notfound
(0) [preprocess] = ok
(0) [chap] = noop
(0) mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap'
(0) [mschap] = ok
(0) [digest] = noop
(0) suffix: Checking for suffix after "@"
(0) suffix: No '@' in User-Name = "akash", looking up realm NULL
(0) suffix: No such realm "NULL"
(0) [suffix] = noop
(0) eap: No EAP-Message, not doing EAP
(0) [eap] = noop
(0) files: users: Matched entry DEFAULT at line 181
(0) [files] = ok
(0) sql: EXPAND %{User-Name}
(0) sql: --> akash
(0) sql: SQL-User-Name set to 'akash'
rlm_sql (sql): Reserved connection (4)
(0) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck
WHERE username = '%{SQL-User-Name}' ORDER BY id
(0) sql: --> SELECT id, username, attribute, value, op FROM radcheck
WHERE username = 'akash' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value,
op FROM radcheck WHERE username = 'akash' ORDER BY id'
(0) sql: User found in radcheck table
(0) sql: Conditional check items matched, merging assignment check items
(0) sql: Auth-Type = Local
(0) sql: Cleartext-Password := 'akash123'
(0) sql: Activation := 'Dec 21 2014 00:00:00 NPT'
(0) sql: Expiration := 'Jan 21 2015 00:00:00 NPT'
(0) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply
WHERE username = '%{SQL-User-Name}' ORDER BY id
(0) sql: --> SELECT id, username, attribute, value, op FROM radreply
WHERE username = 'akash' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value,
op FROM radreply WHERE username = 'akash' ORDER BY id'
(0) sql: EXPAND SELECT groupname FROM radusergroup WHERE username =
'%{SQL-User-Name}' ORDER BY priority
(0) sql: --> SELECT groupname FROM radusergroup WHERE username = 'akash'
ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup
WHERE username = 'akash' ORDER BY priority'
(0) sql: User found in the group table
(0) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM
radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id
(0) sql: --> SELECT id, groupname, attribute, Value, op FROM
radgroupcheck WHERE groupname = 'WiFi-2' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, groupname, attribute, Value,
op FROM radgroupcheck WHERE groupname = 'WiFi-2' ORDER BY id'
(0) sql: Group "WiFi-2": Conditional check items matched
(0) sql: Group "WiFi-2": Merging assignment check items
(0) sql: Simultaneous-Use := 1
(0) sql: Login-Time :=
'Su0000-2400,Mo0000-2400,Tu0000-2400,We0000-2400,Th0000-2400,Fr0000-2400,Sa0000-2400'
(0) sql: EXPAND SELECT id, groupname, attribute, value, op FROM
radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id
(0) sql: --> SELECT id, groupname, attribute, value, op FROM
radgroupreply WHERE groupname = 'WiFi-2' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, groupname, attribute, value,
op FROM radgroupreply WHERE groupname = 'WiFi-2' ORDER BY id'
(0) sql: Group "WiFi-2": Merging reply items
(0) sql: Service-Type = Framed-User
(0) sql: Framed-Compression = Van-Jacobson-TCP-IP
(0) sql: Framed-Protocol = PPP
(0) sql: Framed-IP-Address = 255.255.255.254
(0) sql: Framed-MTU = 1500
(0) sql: Idle-Timeout = 3600
(0) sql: Session-Timeout = 43200
(0) sql: Acct-Interim-Interval = 300
(0) sql: Mikrotik-Rate-Limit = '192k/256k'
(0) sql: Fall-Through = Yes
rlm_sql (sql): Released connection (4)
(0) [sql] = ok
(0) expiration: Account will expire at 'Jan 21 2015 00:00:00 NPT'
(0) [expiration] = ok
(0) logintime: Checking Login-Time
(0) [logintime] = ok
WARNING: (0) pap: Auth-Type already set. Not setting to PAP
(0) [pap] = noop
(0) } # authorize = ok
(0) Found Auth-Type = MSCHAP
(0) # Executing group from file /etc/raddb/sites-enabled/default
(0) Auth-Type MS-CHAP {
(0) mschap: Found Cleartext-Password, hashing to create NT-Password
(0) mschap: Found Cleartext-Password, hashing to create LM-Password
(0) mschap: Creating challenge hash with username: akash
(0) mschap: Client is using MS-CHAPv2
(0) mschap: Adding MS-CHAPv2 MPPE keys
(0) [mschap] = ok
(0) } # Auth-Type MS-CHAP = ok
(0) # Executing section session from file
/etc/raddb/sites-enabled/default
(0) session {
(0) [sql] = noop
(0) } # session = noop
(0) # Executing section post-auth from file
/etc/raddb/sites-enabled/default
(0) post-auth {
(0) update {
(0) No attributes updated
(0) } # update = noop
(0) sql: EXPAND .query
(0) sql: --> .query
(0) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(0) sql: EXPAND %{User-Name}
(0) sql: --> akash
(0) sql: SQL-User-Name set to 'akash'
(0) sql: EXPAND INSERT INTO radpostauth (username, pass, reply,
authdate) VALUES ( '%{SQL-User-Name}',
'%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(0) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate)
VALUES ( 'akash', '', 'Access-Accept', '2014-12-22 08:32:57')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username,
pass, reply, authdate) VALUES ( 'akash', '', 'Access-Accept',
'2014-12-22 08:32:57')'
rlm_sql (sql): Released connection (4)
(0) [sql] = ok
(0) [exec] = noop
(0) policy remove_reply_message_if_eap {
(0) if (&reply:EAP-Message && &reply:Reply-Message) {
(0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(0) else {
(0) [noop] = noop
(0) } # else = noop
(0) } # policy remove_reply_message_if_eap = noop
(0) } # post-auth = ok
(0) Login OK: [akash] (from client PPPoE port 1 cli 00:0F:38:6B:45:D4)
(0) Sent Access-Accept Id 7 from 192.168.10.172:1812 to
192.168.10.173:42023 length 244
(0) Framed-Protocol = PPP
(0) Framed-Compression = Van-Jacobson-TCP-IP
(0) Service-Type = Framed-User
(0) Framed-IP-Address = 255.255.255.254
(0) Framed-MTU = 1500
(0) Idle-Timeout = 3600
(0) Session-Timeout = 43200
(0) Acct-Interim-Interval = 300
(0) Mikrotik-Rate-Limit = '192k/256k'
(0) MS-CHAP2-Success =
0x01533d44383233434446463033363746384230443139424430374137443738363432353133443334333939
(0) MS-MPPE-Recv-Key = 0xad4dee2759a021938a33f14dd6729c10
(0) MS-MPPE-Send-Key = 0x91c03432a315ccd91af66038533c49be
(0) MS-MPPE-Encryption-Policy = Encryption-Allowed
(0) MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
(0) Finished request
Waking up in 0.2 seconds.
Waking up in 4.7 seconds.
(1) Received Accounting-Request Id 8 from 192.168.10.173:41349 to
192.168.10.172:1813 length 48
(1) Acct-Status-Type = Accounting-On
(1) NAS-Identifier = 'MikroTik'
(1) Acct-Delay-Time = 0
(1) NAS-IP-Address = 192.168.10.173
(1) # Executing section preacct from file
/etc/raddb/sites-enabled/default
(1) preacct {
(1) [preprocess] = ok
(1) policy acct_counters64.preacct {
(1) update request {
(1) Can't find &Acct-Input-Gigawords
(1) Can't find &Acct-Input-Octets
(1) EXPAND %{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets}
(1) --> 0
(1) &Acct-Input-Octets64 = 0
(1) Can't find &Acct-Output-Gigawords
(1) Can't find &Acct-Output-Octets
(1) EXPAND %{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets}
(1) --> 0
(1) &Acct-Output-Octets64 = 0
(1) } # update request = noop
(1) } # policy acct_counters64.preacct = noop
(1) policy acct_unique {
(1) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {
(1) EXPAND %{string:Class}
(1) -->
(1) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE
(1) else {
(1) update request {
(1) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(1) --> 749f84a53ba93440038dab91bbcda78b
(1) &Acct-Unique-Session-Id := "749f84a53ba93440038dab91bbcda78b"
(1) } # update request = noop
(1) } # else = noop
(1) } # policy acct_unique = noop
(1) [suffix] = noop
(1) [files] = noop
(1) } # preacct = ok
(1) # Executing section accounting from file
/etc/raddb/sites-enabled/default
(1) accounting {
(1) detail: EXPAND
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(1) detail: --> /var/log/radius/radacct/192.168.10.173/detail-20141222
(1) detail:
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/192.168.10.173/detail-20141222
(1) detail: EXPAND %t
(1) detail: --> Mon Dec 22 08:32:58 2014
(1) [detail] = ok
(1) [unix] = noop
(1) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(1) sql: --> type.accounting-on.query
(1) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(1) sql: EXPAND %{User-Name}
(1) sql: -->
(1) sql: SQL-User-Name set to ''
(1) sql: EXPAND UPDATE radacct SET acctstoptime =
%{%{integer:Event-Timestamp}:-date('now')}, acctsessiontime =
%{%{integer:Event-Timestamp}:-strftime('%%s', 'now')} - strftime('%%s',
acctstarttime)), acctterminatecause = '%{Acct-Terminate-Cause}' WHERE
acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND
acctstarttime <= %{integer:Event-Timestamp}
(1) sql: --> UPDATE radacct SET acctstoptime = 1419216478,
acctsessiontime = 1419216478 - strftime('%s', acctstarttime)),
acctterminatecause = '' WHERE acctstoptime IS NULL AND nasipaddress =
'192.168.10.173' AND acctstarttime <= 1419216478
rlm_sql (sql): Executing query: 'UPDATE radacct SET acctstoptime =
1419216478, acctsessiontime = 1419216478 - strftime('%s',
acctstarttime)), acctterminatecause = '' WHERE acctstoptime IS NULL AND
nasipaddress = '192.168.10.173' AND acctstarttime <= 1419216478'
rlm_sql_mysql: MYSQL check_error: 1064 received
rlm_sql (sql): You have an error in your SQL syntax; check the manual
that corresponds to your MariaDB server version for the right syntax to
use near '), acctterminatecause = '' WHERE acctstoptime IS NULL AND
nasipaddress = '202.' at line 1
rlm_sql_mysql: MYSQL check_error: 1064 received
rlm_sql_mysql: Cannot store result
rlm_sql_mysql: MySQL error 'You have an error in your SQL syntax; check
the manual that corresponds to your MariaDB server version for the right
syntax to use near '), acctterminatecause = '' WHERE acctstoptime IS
NULL AND nasipaddress = '202.' at line 1'
(1) sql: No additional queries configured
rlm_sql (sql): Released connection (4)
(1) [sql] = noop
(1) [exec] = noop
(1) attr_filter.accounting_response: EXPAND %{User-Name}
(1) attr_filter.accounting_response: -->
(1) [attr_filter.accounting_response] = noop
(1) } # accounting = ok
(1) Sent Accounting-Response Id 8 from 192.168.10.172:1813 to
192.168.10.173:41349 length 20
(1) Finished request
Waking up in 0.3 seconds.
(2) Received Accounting-Request Id 9 from 192.168.10.173:38228 to
192.168.10.172:1813 length 140
(2) Service-Type = Framed-User
(2) Framed-Protocol = PPP
(2) NAS-Port = 15728641
(2) NAS-Port-Type = Ethernet
(2) User-Name = 'akash'
(2) Calling-Station-Id = '00:0F:38:6B:45:D4'
(2) Called-Station-Id = 'PPPoE_B'
(2) NAS-Port-Id = 'PPP'
(2) Acct-Session-Id = '81100001'
(2) Framed-IP-Address = 10.20.10.254
(2) Acct-Authentic = RADIUS
(2) Event-Timestamp = 'Jan 8 1970 16:01:12 IST'
(2) Acct-Status-Type = Start
(2) NAS-Identifier = 'MikroTik'
(2) Acct-Delay-Time = 0
(2) NAS-IP-Address = 192.168.10.173
(2) # Executing section preacct from file
/etc/raddb/sites-enabled/default
(2) preacct {
(2) [preprocess] = ok
(2) policy acct_counters64.preacct {
(2) update request {
(2) Can't find &Acct-Input-Gigawords
(2) Can't find &Acct-Input-Octets
(2) EXPAND %{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets}
(2) --> 0
(2) &Acct-Input-Octets64 = 0
(2) Can't find &Acct-Output-Gigawords
(2) Can't find &Acct-Output-Octets
(2) EXPAND %{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets}
(2) --> 0
(2) &Acct-Output-Octets64 = 0
(2) } # update request = noop
(2) } # policy acct_counters64.preacct = noop
(2) policy acct_unique {
(2) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {
(2) EXPAND %{string:Class}
(2) -->
(2) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE
(2) else {
(2) update request {
(2) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(2) --> 5dd1de39a5bbc6068f844d22bb0e32fc
(2) &Acct-Unique-Session-Id := "5dd1de39a5bbc6068f844d22bb0e32fc"
(2) } # update request = noop
(2) } # else = noop
(2) } # policy acct_unique = noop
(2) suffix: Checking for suffix after "@"
(2) suffix: No '@' in User-Name = "akash", looking up realm NULL
(2) suffix: No such realm "NULL"
(2) [suffix] = noop
(2) [files] = noop
(2) } # preacct = ok
(2) # Executing section accounting from file
/etc/raddb/sites-enabled/default
(2) accounting {
(2) detail: EXPAND
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(2) detail: --> /var/log/radius/radacct/192.168.10.173/detail-20141222
(2) detail:
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/192.168.10.173/detail-20141222
(2) detail: EXPAND %t
(2) detail: --> Mon Dec 22 08:32:58 2014
(2) [detail] = ok
(2) [unix] = ok
(2) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(2) sql: --> type.start.query
(2) sql: Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(2) sql: EXPAND %{User-Name}
(2) sql: --> akash
(2) sql: SQL-User-Name set to 'akash'
(2) sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid,
username, realm, nasipaddress, nasportid, nasporttype, acctstarttime,
acctupdatetime, acctstoptime, acctsessiontime, acctauthentic,
connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets,
calledstationid, callingstationid, acctterminatecause, servicetype,
framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}',
'%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}',
'%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}',
%{%{integer:Event-Timestamp}:-date('now')},
%{%{integer:Event-Timestamp}:-date('now')}, NULL, '0',
'%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0',
'%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}',
'%{Framed-Protocol}', '%{Framed-IP-Address}')
(2) sql: --> INSERT INTO radacct (acctsessionid, acctuniqueid, username,
realm, nasipaddress, nasportid, nasporttype, acctstarttime,
acctupdatetime, acctstoptime, acctsessiontime, acctauthentic,
connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets,
calledstationid, callingstationid, acctterminatecause, servicetype,
framedprotocol, framedipaddress) VALUES ('81100001',
'5dd1de39a5bbc6068f844d22bb0e32fc', 'akash', '', '192.168.10.173',
'15728641', 'Ethernet', 642672, 642672, NULL, '0', 'RADIUS', '', '',
'0', '0', 'PPPoE_B', '00:0F:38:6B:45:D4', '', 'Framed-User', 'PPP',
'10.20.10.254')
rlm_sql (sql): Executing query: 'INSERT INTO radacct (acctsessionid,
acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype,
acctstarttime, acctupdatetime, acctstoptime, acctsessiontime,
acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets,
acctoutputoctets, calledstationid, callingstationid, acctterminatecause,
servicetype, framedprotocol, framedipaddress) VALUES ('81100001',
'5dd1de39a5bbc6068f844d22bb0e32fc', 'akash', '', '192.168.10.173',
'15728641', 'Ethernet', 642672, 642672, NULL, '0', 'RADIUS', '', '',
'0', '0', 'PPPoE_B', '00:0F:38:6B:45:D4', '', 'Framed-User', 'PPP',
'10.20.10.254')'
rlm_sql (sql): Released connection (4)
(2) [sql] = ok
(2) [exec] = noop
(2) attr_filter.accounting_response: EXPAND %{User-Name}
(2) attr_filter.accounting_response: --> akash
(2) attr_filter.accounting_response: Matched entry DEFAULT at line 12
(2) [attr_filter.accounting_response] = updated
(2) } # accounting = updated
(2) Sent Accounting-Response Id 9 from 192.168.10.172:1813 to
192.168.10.173:38228 length 20
(2) Finished request
Waking up in 0.3 seconds.
(1) <done>: Cleaning up request packet ID 8 with timestamp +20
(2) <done>: Cleaning up request packet ID 9 with timestamp +20
Waking up in 4.2 seconds.
(0) <done>: Cleaning up request packet ID 7 with timestamp +19
Ready to process requests
-------------------------------------------------------
On 2014-12-22 00:11, Alan DeKok wrote:
> Then post the debug output. As we say almost daily on this list, that is needed to answer these kind of questions.
>
> On Dec 21, 2014, at 11:53 AM, Akash <akash at satelinknepal.com.np> wrote:
>
> Ok'
>
> But the same NAS when used with freeradiusd-2.x, shows correct acctstarttime, and acctstoptime. So where can be the problem. i find the problem with freeradiusd-3.0.6.
>
> On 2014-12-21 22:09, Alan DeKok wrote:
>
> On Dec 21, 2014, at 4:19 AM, Akash <akash at satelinknepal.com.np> wrote:
> I'm using freeradiusd-3.0.6, with mariadb in CentOS-7. When use logs in the entry in radacct table for show 000-00-00 00:00:00 for both acctstarttime, and acctupdatetime and same for acctstoptime when use get disconnected. I'm using MikroTik as NAS. What may be the cause for the issue.
>
> Your NAS isn't sending the start time, etc. in the accounting packets.
>
> Alan DeKok.
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html [1]
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html [1]
-
List info/subscribe/unsubscribe? See
http://www.freeradius.org/list/users.html [1]
Links:
------
[1] http://www.freeradius.org/list/users.html
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20141222/975b7964/attachment-0001.html>
More information about the Freeradius-Users
mailing list