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@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@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