SQL session start
Marcin Marszałkowski
m.marszal at wp.pl
Thu Sep 12 23:25:14 CEST 2019
Hi,
As per config files it’s enough to enable sql_session_start in default server and toggle set of queries - start section in queries.conf (freeradius 3.0.20):
# When using "sql_session_start", you should comment out
# the previous query, and enable this one.
Mainly changing sql query INSERT to UPDATE in queries.conf.
Is this all or I’m missing something? Description in policy.d/accounting doesn’t say anything more.
The reason I’m asking is accounting became useless as lots of data is missing (like acctupdatetime, acctstoptime and acctinterval and so on) when this feature is enabled…
Accounting request debug with sql_session_start on:
Ready to process requests
(8) Received Accounting-Request Id 217 from 172.16.0.4:60220 to 172.16.0.12:1813 length 264
(8) Acct-Status-Type = Interim-Update
(8) Acct-Authentic = RADIUS
(8) User-Name = "Mark"
(8) Framed-IP-Address = 172.16.4.6
(8) NAS-Identifier = "fdecea88ef4d"
(8) Called-Station-Id = "FD-EC-EA-88-EF-4D:Site"
(8) NAS-Port-Type = Wireless-802.11
(8) Service-Type = Framed-User
(8) Calling-Station-Id = „A8-63-C7-20-A6-BC"
(8) Connect-Info = "CONNECT 0Mbps 802.11b"
(8) Acct-Session-Id = "4989DEE1E63DA03B"
(8) WLAN-Pairwise-Cipher = 1027076
(8) WLAN-Group-Cipher = 1027076
(8) WLAN-AKM-Suite = 1027073
(8) Class = 0x61693a6135626131326534323930313730623036636231383032303437383138313738
(8) Event-Timestamp = "Sep 12 2019 22:45:48 CEST"
(8) Acct-Delay-Time = 0
(8) Acct-Session-Time = 3985
(8) Acct-Input-Packets = 982894
(8) Acct-Output-Packets = 988539
(8) Acct-Input-Octets = 86555066
(8) Acct-Input-Gigawords = 0
(8) Acct-Output-Octets = 1008668910
(8) Acct-Output-Gigawords = 0
(8) # Executing section preacct from file /etc/freeradius/sites-enabled/default
(8) preacct {
(8) [preprocess] = ok
(8) policy acct_counters64.preacct {
(8) update request {
(8) EXPAND %{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets}
(8) --> 86555066
(8) &Acct-Input-Octets64 = 86555066
(8) EXPAND %{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets}
(8) --> 1008668910
(8) &Acct-Output-Octets64 = 1008668910
(8) } # update request = noop
(8) } # policy acct_counters64.preacct = noop
(8) update request {
(8) EXPAND %{expr: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0}}
(8) --> 1568317163
(8) &FreeRADIUS-Acct-Session-Start-Time = Sep 12 2019 21:39:23 CEST
(8) } # update request = noop
(8) policy acct_unique {
(8) update request {
(8) &Tmp-String-9 := "ai:"
(8) } # update request = noop
(8) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
(8) EXPAND %{hex:&Class}
(8) --> 61693a6135626131326534323930313730623036636231383032303437383138313738
(8) EXPAND ^%{hex:&Tmp-String-9}
(8) --> ^61693a
(8) EXPAND %{string:&Class}
(8) --> ai:a5ba12e4290170b06cb1802047818178
(8) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> TRUE
(8) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
(8) update request {
(8) EXPAND %{md5:%{1},%{Acct-Session-ID}}
(8) --> 6d2b000d2e24857d10699c46ad662bff
(8) &Acct-Unique-Session-Id := 6d2b000d2e24857d10699c46ad662bff
(8) } # update request = noop
(8) } # if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) = noop
(8) ... skipping else: Preceding "if" was taken
(8) } # policy acct_unique = noop
(8) suffix: Checking for suffix after "@"
(8) suffix: No '@' in User-Name = "Mark", looking up realm NULL
(8) suffix: No such realm "NULL"
(8) [suffix] = noop
(8) } # preacct = ok
(8) # Executing section accounting from file /etc/freeradius/sites-enabled/default
(8) accounting {
(8) detail: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(8) detail: --> /var/log/freeradius/radacct/172.16.0.4/detail-20190912
(8) detail: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/172.16.0.4/detail-20190912
(8) detail: EXPAND %t
(8) detail: --> Thu Sep 12 22:45:48 2019
(8) [detail] = ok
(8) sql: EXPAND %{tolower:type.%{%{Acct-Status-Type}:-%{Request-Processing-Stage}}.query}
(8) sql: --> type.interim-update.query
(8) sql: Using query template 'query'
rlm_sql (sql): Closing connection (14): Hit idle_timeout, was idle for 224 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (15): Hit idle_timeout, was idle for 224 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): 0 of 0 connections in use. You may need to increase "spare"
rlm_sql (sql): Opening additional connection (16), 1 of 32 pending slots used
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql_mysql: Connected to database 'radius' on 172.16.0.13 via TCP/IP, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10
rlm_sql (sql): Reserved connection (16)
(8) sql: EXPAND %{User-Name}
(8) sql: --> Mark
(8) sql: SQL-User-Name set to 'Mark'
(8) sql: EXPAND UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctinterval = %{integer:Event-Timestamp} - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '%{Framed-IP-Address}', framedipv6address = '%{Framed-IPv6-Address}', framedipv6prefix = '%{Framed-IPv6-Prefix}', framedinterfaceid = '%{Framed-Interface-Id}', delegatedipv6prefix = '%{Delegated-IPv6-Prefix}', acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'
(8) sql: --> UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1568321148), acctinterval = 1568321148 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', acctsessiontime = 3985, acctinputoctets = '0' << 32 | '86555066', acctoutputoctets = '0' << 32 | '1008668910' WHERE AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff'
(8) sql: Executing query: UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1568321148), acctinterval = 1568321148 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', acctsessiontime = 3985, acctinputoctets = '0' << 32 | '86555066', acctoutputoctets = '0' << 32 | '1008668910' WHERE AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff'
rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
(8) sql: SQL query returned: success
(8) sql: 0 record(s) updated
(8) sql: Trying next query...
(8) sql: EXPAND UPDATE radacct SET AcctSessionId = '%{Acct-Session-Id}', AcctUniqueId = '%{Acct-Unique-Session-Id}', AcctAuthentic = '%{Acct-Authentic}', ConnectInfo_start = '%{Connect-Info}', ServiceType = '%{Service-Type}', FramedProtocol = '%{Framed-Protocol}', framedipaddress = '%{Framed-IP-Address}', framedipv6address = '%{Framed-IPv6-Address}', framedipv6prefix = '%{Framed-IPv6-Prefix}', framedinterfaceid = '%{Framed-Interface-Id}', delegatedipv6prefix = '%{Delegated-IPv6-Prefix}', AcctUpdateTime = FROM_UNIXTIME(%{integer:Event-Timestamp}), AcctSessionTime = %{%{Acct-Session-Time}:-NULL}, AcctInputOctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', AcctOutputOctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE UserName = '%{SQL-User-Name}' AND NASIPAddress = '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}' AND NASPortId = '%{%{NAS-Port-ID}:-%{NAS-Port}}' AND NASPortType = '%{NAS-Port-Type}' AND AcctStopTime IS NULL
(8) sql: --> UPDATE radacct SET AcctSessionId = '4989DEE1E63DA03B', AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff', AcctAuthentic = 'RADIUS', ConnectInfo_start = 'CONNECT 0Mbps 802.11b', ServiceType = 'Framed-User', FramedProtocol = '', framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', AcctUpdateTime = FROM_UNIXTIME(1568321148), AcctSessionTime = 3985, AcctInputOctets = '0' << 32 | '86555066', AcctOutputOctets = '0' << 32 | '1008668910' WHERE UserName = 'Mark' AND NASIPAddress = '172.16.0.4' AND NASPortId = '' AND NASPortType = 'Wireless-802.11' AND AcctStopTime IS NULL
(8) sql: Executing query: UPDATE radacct SET AcctSessionId = '4989DEE1E63DA03B', AcctUniqueId = '6d2b000d2e24857d10699c46ad662bff', AcctAuthentic = 'RADIUS', ConnectInfo_start = 'CONNECT 0Mbps 802.11b', ServiceType = 'Framed-User', FramedProtocol = '', framedipaddress = '172.16.4.6', framedipv6address = '', framedipv6prefix = '', framedinterfaceid = '', delegatedipv6prefix = '', AcctUpdateTime = FROM_UNIXTIME(1568321148), AcctSessionTime = 3985, AcctInputOctets = '0' << 32 | '86555066', AcctOutputOctets = '0' << 32 | '1008668910' WHERE UserName = 'Mark' AND NASIPAddress = '172.16.0.4' AND NASPortId = '' AND NASPortType = 'Wireless-802.11' AND AcctStopTime IS NULL
rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
(8) sql: SQL query returned: success
(8) sql: 0 record(s) updated
(8) sql: No additional queries configured
rlm_sql (sql): Released connection (16)
Need 2 more connections to reach min connections (3)
rlm_sql (sql): Opening additional connection (17), 1 of 31 pending slots used
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql_mysql: Connected to database 'radius' on 172.16.0.13 via TCP/IP, server version 5.7.27-0ubuntu0.18.04.1, protocol version 10
(8) [sql] = noop
(8) [exec] = noop
(8) attr_filter.accounting_response: EXPAND %{User-Name}
(8) attr_filter.accounting_response: --> Mark
(8) attr_filter.accounting_response: Matched entry DEFAULT at line 12
(8) [attr_filter.accounting_response] = updated
(8) } # accounting = updated
(8) Sent Accounting-Response Id 217 from 172.16.0.12:1813 to 172.16.0.4:60220 length 0
(8) Finished request
(8) Cleaning up request packet ID 217 with timestamp +613
Regards
Martin
More information about the Freeradius-Users
mailing list