duplicate acctsessionid when connectin to ocserv

Thu Jan 2 17:35:12 CET 2020

Hi Mehrzad,

> On 2 Jan 2020, at 01:23, Mehrzad Jalali via Freeradius-Users <freeradius-users at lists.freeradius.org> wrote:
> 
> in my vps centos 7 with ocserv 12.5 and freeradius 3.0.5 standard installation

The 3.0.5 is from 2014. Please, upgrade to the latest 3.0.20 version building directly from the code or using official packages available in http://packages.networkradius.com <http://packages.networkradius.com/>
> when in connect from clinet to server 2 database record created with same "acctsessionid" and in daloradius i see 2 connect with same user id but when i disconnected 1 of records terminate and clear from daloradius online user but other don't and if i limit Simultaneous-Use := 1 or 2 after that can't connect until manualy delet that session from online user, please help if pasible

Try to double check the informations directly in the database. (Maybe some bug with Daloradius GUI, even we don’t support it.)

> ### radiusd -Xoutput for connect
> 
> Ready to process requests
> (0) Received Access-Request Id 40 from 127.0.0.1:40914 to 127.0.0.1:1812 length 122
> (0) User-Name = "0001"
> (0) User-Password = "6028"
> (0) Calling-Station-Id = "185.131.136.61"
> (0) Connect-Info = "AnyConnect Windows 4.8.01090"
> (0) Service-Type = Authenticate-Only
> (0) NAS-Port-Type = Async
> (0) NAS-Port = 2565
> (0) NAS-IP-Address = 127.0.0.1
> (0) NAS-Identifier = "ocserv"
> (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) -> TRUE
> (0) if (&User-Name) {
> (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 !~ /@(.+).(.+)$/)) -> FALS E
> (0) if (&User-Name =~ /.$/) {
> (0) if (&User-Name =~ /.$/) -> FALSE
> (0) if (&User-Name =~ /@./) {
> (0) if (&User-Name =~ /@./) -> FALSE
> (0) } # if (&User-Name) = notfound
> (0) } # policy filter_username = notfound
> (0) [preprocess] = ok
> (0) [chap] = noop
> (0) [mschap] = noop
> (0) [digest] = noop
> (0) suffix: Checking for suffix after "@"
> (0) suffix: No '@' in User-Name = "0001", 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) sql: EXPAND %{User-Name}
> (0) sql: --> 0001
> (0) sql: SQL-User-Name set to '0001'
> rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 64 seconds
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 64 seconds
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 64 seconds
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (4): Hit idle_timeout, was idle for 64 seconds
> rlm_sql (sql): You probably need to lower "min"
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (0): Hit idle_timeout, was idle for 64 seconds
> rlm_sql (sql): You probably need to lower "min"
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (5): Hit idle_timeout, was idle for 64 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 (6), 1 of 32 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, serv er version 5.5.64-MariaDB, protocol version 10
> rlm_sql (sql): Reserved connection (6)
> (0) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE us ername = '%{SQL-User-Name}' ORDER BY id
> (0) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE us ername = '0001' ORDER BY id
> (0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '0001' ORDER BY id
> (0) sql: User found in radcheck table
> (0) sql: Conditional check items matched, merging assignment check items
> (0) sql: Cleartext-Password := "6028"
> (0) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE us ername = '%{SQL-User-Name}' ORDER BY id
> (0) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE us ername = '0001' ORDER BY id
> (0) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = '0001' 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 = '0001' ORDER BY priority
> (0) sql: Executing select query: SELECT groupname FROM radusergroup WHERE userna me = '0001' ORDER BY priority
> (0) sql: User found in the group table
> (0) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WH ERE groupname = '%{SQL-Group}' ORDER BY id
> (0) sql: --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WH ERE groupname = '01-month' ORDER BY id
> (0) sql: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '01-month' ORDER BY id
> (0) sql: Group "01-month": Conditional check items matched
> (0) sql: Group "01-month": Merging assignment check items
> (0) sql: Simultaneous-Use := 12
> (0) sql: Expire-After := 2592000
> (0) sql: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WH ERE groupname = '%{SQL-Group}' ORDER BY id
> (0) sql: --> SELECT id, groupname, attribute, value, op FROM radgroupreply WH ERE groupname = '01-month' ORDER BY id
> (0) sql: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '01-month' ORDER BY id
> (0) sql: Group "01-month": Merging reply items
> rlm_sql (sql): Released connection (6)
> Need 2 more connections to reach min connections (3)
> rlm_sql (sql): Opening additional connection (7), 1 of 31 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, serv er version 5.5.64-MariaDB, protocol version 10
> (0) [sql] = ok
> (0) [expiration] = noop
> (0) [logintime] = noop
> sqlcounter_expand: 'SELECT IFNULL( MAX(TIME_TO_SEC(TIMEDIFF(NOW(), acctstarttime ))),0) FROM radacct WHERE UserName='%{User-Name}' ORDER BY acctstarttime LIMIT 1 ;'
> (0) expire_on_login: EXPAND %{User-Name}
> (0) expire_on_login: --> 0001
> (0) expire_on_login: SQL-User-Name set to '0001'
> rlm_sql (sql): Reserved connection (6)
> (0) expire_on_login: Executing select query: SELECT IFNULL( MAX(TIME_TO_SEC(TIME DIFF(NOW(), acctstarttime))),0) FROM radacct WHERE UserName='0001' ORDER BY acct starttime LIMIT 1;
> rlm_sql (sql): Released connection (6)
> (0) expire_on_login: EXPAND %{sql:SELECT IFNULL( MAX(TIME_TO_SEC(TIMEDIFF(NOW(), acctstarttime))),0) FROM radacct WHERE UserName='%{User-Name}' ORDER BY acctsta rttime LIMIT 1;}
> (0) expire_on_login: --> 262897
> (0) expire_on_login: Allowing user, &control:Expire-After value (2592000) is gre ater than counter value (262897)
> (0) expire_on_login: Setting &reply:Session-Timeout value to 2329103
> (0) [expire_on_login] = ok
> (0) [pap] = updated
> (0) } # authorize = updated
> (0) Found Auth-Type = PAP
> (0) # Executing group from file /etc/raddb/sites-enabled/default
> (0) Auth-Type PAP {
> (0) pap: Login attempt with password
> (0) pap: Comparing with "known good" Cleartext-Password
> (0) pap: User authenticated successfully
> (0) [pap] = ok
> (0) } # Auth-Type PAP = ok
> (0) # Executing section session from file /etc/raddb/sites-enabled/default
> (0) session {
> (0) sql: EXPAND %{User-Name}
> (0) sql: --> 0001
> (0) sql: SQL-User-Name set to '0001'
> (0) sql: EXPAND SELECT COUNT() FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL
> (0) sql: --> SELECT COUNT() FROM radacct WHERE username = '0001' AND acctsto ptime IS NULL
> rlm_sql (sql): Reserved connection (7)
> (0) sql: Executing select query: SELECT COUNT(*) FROM radacct WHERE username = ' 0001' AND acctstoptime IS NULL
> rlm_sql (sql): Released connection (7)
> (0) [sql] = ok
> (0) } # session = ok
> (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 (6)
> (0) sql: EXPAND %{User-Name}
> (0) sql: --> 0001
> (0) sql: SQL-User-Name set to '0001'
> (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 ( '0001', '6028', 'Access-Accept', '2020-01-01 02:23:25.578473')
> (0) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authda te) VALUES ( '0001', '6028', 'Access-Accept', '2020-01-01 02:23:25.578473')
> (0) sql: SQL query returned: success
> (0) sql: 1 record(s) updated
> rlm_sql (sql): Released connection (6)
> (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: [0001/6028] (from client localhost port 2565 cli 185.131.136.61)
> (0) Sent Access-Accept Id 40 from 127.0.0.1:1812 to 127.0.0.1:40914 length 0
> (0) Session-Timeout = 2329103
> (0) Finished request
> Waking up in 4.9 seconds.
> (0) Cleaning up request packet ID 40 with timestamp +64
> Ready to process requests
> (1) Received Accounting-Request Id 195 from 127.0.0.1:56449 to 127.0.0.1:1813 le ngth 152
> (1) Acct-Status-Type = Start
> (1) Connect-Info = "AnyConnect Windows 4.8.01090"
> (1) User-Name = "0001"
> (1) Service-Type = Framed-User
> (1) Framed-Protocol = PPP
> (1) Calling-Station-Id = "185.131.136.61"
> (1) Acct-Session-Id = "YokGL5neiA2JyiM49N9Bytg0hYk="
> (1) Acct-Authentic = RADIUS
> (1) NAS-Port = 2565
> (1) Acct-Delay-Time = 0
> (1) NAS-IP-Address = 127.0.0.1
> (1) NAS-Identifier = "ocserv"
> (1) # Executing section preacct from file /etc/raddb/sites-enabled/default
> (1) preacct {
> (1) [preprocess] = ok
> (1) policy acct_unique {
> (1) update request {
> (1) &Tmp-String-9 := "ai:"
> (1) } # update request = noop
> (1) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:& Class}" =~ /^ai:([0-9a-f]{32})/i)) {
> (1) EXPAND %{hex:&Class}
> (1) -->
> (1) EXPAND ^%{hex:&Tmp-String-9}
> (1) --> ^61693a
> (1) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{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) --> 440bf34dbf28bc1cb53423b82d8bad65
> (1) &Acct-Unique-Session-Id := 440bf34dbf28bc1cb53423b82d8bad65
> (1) } # update request = noop
> (1) } # else = noop
> (1) } # policy acct_unique = noop
> (1) suffix: Checking for suffix after "@"
> (1) suffix: No '@' in User-Name = "0001", looking up realm NULL
> (1) suffix: No such realm "NULL"
> (1) [suffix] = 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/127.0.0.1/detail-20200101
> (1) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv 6-Address}}/detail-%Y%m%d expands to /var/log/radius/radacct/127.0.0.1/detail-20 200101
> (1) detail: EXPAND %t
> (1) detail: --> Wed Jan 1 02:23:34 2020
> (1) [detail] = ok
> (1) [unix] = ok
> (1) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
> (1) sql: --> type.start.query
> (1) sql: Using query template 'query'
> rlm_sql (sql): Reserved connection (7)
> (1) sql: EXPAND %{User-Name}
> (1) sql: --> 0001
> (1) sql: SQL-User-Name set to '0001'
> (1) sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid, u sername, realm, nasipaddress, nasportid, nasporttype,a cctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinpu toctets, acctoutputoctets, calledstationid, callingstationid, acctte rminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm }', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', F ROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestam p}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called- Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol }', '%{Framed-IP-Address}')
> (1) sql: --> INSERT INTO radacct (acctsessionid, acctuniqueid, u sername, realm, nasipaddress, nasportid, nasporttype,a cctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinpu toctets, acctoutputoctets, calledstationid, callingstationid, acctte rminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('YokGL5neiA2JyiM49N9Bytg0hYk=3D', '440bf34dbf28bc1cb53423b82d8bad65', '0001', ' ', '127.0.0.1', '2565', '', FROM_UNIXTIME(1577832814), FROM_UNIXTIME(1577832814) , NULL, '0', 'RADIUS', 'AnyConnect Windows 4.8.01090', '', '0', '0', '', '185.13 1.136.61', '', 'Framed-User', 'PPP', '')
> (1) sql: Executing query: INSERT INTO radacct (acctsessionid, acctuniq ueid, username, realm, nasipaddress, n asportid, nasporttype, acctstarttime, acctupdatetime, acctstop time, acctsessiontime, acctauthentic, connectinfo_start, c onnectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedpr otocol, framedipaddress) VALUES ('YokGL5neiA2JyiM49N9Bytg0hYk=3D', '440bf34dbf28 bc1cb53423b82d8bad65', '0001', '', '127.0.0.1', '2565', '', FROM_UNIXTIME(157783 2814), FROM_UNIXTIME(1577832814), NULL, '0', 'RADIUS', 'AnyConnect Windows 4.8.0 1090', '', '0', '0', '', '185.131.136.61', '', 'Framed-User', 'PPP', '')
> (1) sql: SQL query returned: success
> (1) sql: 1 record(s) updated
> rlm_sql (sql): Released connection (7)
> Need 1 more connections to reach min connections (3)
> rlm_sql (sql): Opening additional connection (8), 1 of 30 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, serv er version 5.5.64-MariaDB, protocol version 10
> (1) [sql] = ok
> (1) [exec] = noop
> (1) attr_filter.accounting_response: EXPAND %{User-Name}
> (1) attr_filter.accounting_response: --> 0001
> (1) attr_filter.accounting_response: Matched entry DEFAULT at line 12
> (1) [attr_filter.accounting_response] = updated
> (1) } # accounting = updated
> (1) Sent Accounting-Response Id 195 from 127.0.0.1:1813 to 127.0.0.1:56449 lengt h 0
> (1) Finished request
> (1) Cleaning up request packet ID 195 with timestamp +73
> Ready to process requests
> (2) Received Accounting-Request Id 32 from 127.0.0.1:36675 to 127.0.0.1:1813 len gth 152
> (2) Acct-Status-Type = Interim-Update
> (2) User-Name = "0001"
> (2) Service-Type = Framed-User
> (2) Framed-Protocol = PPP
> (2) Framed-IP-Address = 10.10.1.186
> (2) Calling-Station-Id = "185.131.136.61"
> (2) Acct-Session-Id = "YokGL5neiA2JyiM49N9Bytg0hYk="
> (2) Acct-Authentic = RADIUS
> (2) Acct-Input-Octets = 0
> (2) Acct-Output-Octets = 0
> (2) Acct-Input-Gigawords = 0
> (2) Acct-Output-Gigawords = 0
> (2) NAS-Port = 2575
> (2) Acct-Delay-Time = 0
> (2) NAS-IP-Address = 127.0.0.1
> (2) NAS-Identifier = "ocserv"
> (2) # Executing section preacct from file /etc/raddb/sites-enabled/default
> (2) preacct {
> (2) [preprocess] = ok
> (2) policy acct_unique {
> (2) update request {
> (2) &Tmp-String-9 := "ai:"
> (2) } # update request = noop
> (2) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:& Class}" =~ /^ai:([0-9a-f]{32})/i)) {
> (2) EXPAND %{hex:&Class}
> (2) -->
> (2) EXPAND ^%{hex:&Tmp-String-9}
> (2) --> ^61693a
> (2) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{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) --> 2f664aa021eff0bd90754442f6900278
> (2) &Acct-Unique-Session-Id := 2f664aa021eff0bd90754442f6900278
> (2) } # update request = noop
> (2) } # else = noop
> (2) } # policy acct_unique = noop
> (2) suffix: Checking for suffix after "@"
> (2) suffix: No '@' in User-Name = "0001", looking up realm NULL
> (2) suffix: No such realm "NULL"
> (2) [suffix] = 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/127.0.0.1/detail-20200101
> (2) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv 6-Address}}/detail-%Y%m%d expands to /var/log/radius/radacct/127.0.0.1/detail-20 200101
> (2) detail: EXPAND %t
> (2) detail: --> Wed Jan 1 02:23:34 2020
> (2) [detail] = ok
> (2) [unix] = noop
> (2) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
> (2) sql: --> type.interim-update.query
> (2) sql: Using query template 'query'
> rlm_sql (sql): Reserved connection (6)
> (2) sql: EXPAND %{User-Name}
> (2) sql: --> 0001
> (2) sql: SQL-User-Name set to '0001'
> (2) sql: EXPAND UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctu pdatetime), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctint erval = %{integer:Event-Timestamp} - UNIX_TIMESTAMP(@acctupdatetime_old), fra medipaddress = '%{Framed-IP-Address}', acctsessiontime = %{%{Acct-Session-Time}: -NULL}, acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Inpu t-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{% {Acct-Output-Octets}:-0}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'
> (2) sql: --> UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctu pdatetime), acctupdatetime = FROM_UNIXTIME(1577832814), acctinterval = 15778 32814 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '10.10.1.186', ac ctsessiontime = NULL, acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0' WHERE AcctUniqueId = '2f664aa021eff0bd90754442f6900278'
> (2) sql: Executing query: UPDATE radacct SET acctupdatetime = (@acctupdatetime_ old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1577832814), acctinterval = 1577832814 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '10.10. 1.186', acctsessiontime = NULL, acctinputoctets = '0' << 32 | '0', acctoutputoct ets = '0' << 32 | '0' WHERE AcctUniqueId = '2f664aa021eff0bd90754442f6900278'
> rlm_sql_mysql: Rows matched: 0 Changed: 0 Warnings: 0
> (2) sql: SQL query returned: success
> (2) sql: 0 record(s) updated
> (2) sql: Trying next query...
> (2) sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid, u sername, realm, nasipaddress, nasportid, nasporttype,a cctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinpu toctets, acctoutputoctets, calledstationid, callingstationid, acctte rminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm }', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', F ROM_UNIXTIME(%{integer:Event-Timestamp} - %{%{Acct-Session-Time}:-0}), FROM_UNIX TIME(%{integer:Event-Timestamp}), NULL, %{%{Acct-Session-Time}:-NULL}, '%{Acct-A uthentic}', '%{Connect-Info}', '', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{ Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Outp ut-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service -Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')
> (2) sql: --> INSERT INTO radacct (acctsessionid, acctuniqueid, u sername, realm, nasipaddress, nasportid, nasporttype,a cctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinpu toctets, acctoutputoctets, calledstationid, callingstationid, acctte rminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('YokGL5neiA2JyiM49N9Bytg0hYk=3D', '2f664aa021eff0bd90754442f6900278', '0001', ' ', '127.0.0.1', '2575', '', FROM_UNIXTIME(1577832814 - 0), FROM_UNIXTIME(1577832 814), NULL, NULL, 'RADIUS', '', '', '0' << 32 | '0', '0' << 32 | '0', '', '185.1 31.136.61', '', 'Framed-User', 'PPP', '10.10.1.186')
> (2) sql: Executing query: INSERT INTO radacct (acctsessionid, acctuniq ueid, username, realm, nasipaddress, n asportid, nasporttype, acctstarttime, acctupdatetime, acctstop time, acctsessiontime, acctauthentic, connectinfo_start, c onnectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedpr otocol, framedipaddress) VALUES ('YokGL5neiA2JyiM49N9Bytg0hYk=3D', '2f664aa021ef f0bd90754442f6900278', '0001', '', '127.0.0.1', '2575', '', FROM_UNIXTIME(157783 2814 - 0), FROM_UNIXTIME(1577832814), NULL, NULL, 'RADIUS', '', '', '0' << 32 | '0', '0' << 32 | '0', '', '185.131.136.61', '', 'Framed-User', 'PPP', '10.10.1.1 86')
> (2) sql: SQL query returned: success
> (2) sql: 1 record(s) updated
> rlm_sql (sql): Released connection (6)
> (2) [sql] = ok
> (2) [exec] = noop
> (2) attr_filter.accounting_response: EXPAND %{User-Name}
> (2) attr_filter.accounting_response: --> 0001
> (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 32 from 127.0.0.1:1813 to 127.0.0.1:36675 length 0
> (2) Finished request
> (2) Cleaning up request packet ID 32 with timestamp +73
> Ready to process requests
> (3) Received Accounting-Request Id 95 from 127.0.0.1:50916 to 127.0.0.1:1813 len gth 158
> (3) Acct-Status-Type = Interim-Update
> (3) User-Name = "0001"
> (3) Service-Type = Framed-User
> (3) Framed-Protocol = PPP
> (3) Framed-IP-Address = 10.10.1.186
> (3) Calling-Station-Id = "185.131.136.61"
> (3) Acct-Session-Id = "YokGL5neiA2JyiM49N9Bytg0hYk="
> (3) Acct-Authentic = RADIUS
> (3) Acct-Session-Time = 97
> (3) Acct-Input-Octets = 26528
> (3) Acct-Output-Octets = 11973
> (3) Acct-Input-Gigawords = 0
> (3) Acct-Output-Gigawords = 0
> (3) NAS-Port = 2575
> (3) Acct-Delay-Time = 0
> (3) NAS-IP-Address = 127.0.0.1
> (3) NAS-Identifier = "ocserv"
> (3) # Executing section preacct from file /etc/raddb/sites-enabled/default
> (3) preacct {
> (3) [preprocess] = ok
> (3) policy acct_unique {
> (3) update request {
> (3) &Tmp-String-9 := "ai:"
> (3) } # update request = noop
> (3) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:& Class}" =~ /^ai:([0-9a-f]{32})/i)) {
> (3) EXPAND %{hex:&Class}
> (3) -->
> (3) EXPAND ^%{hex:&Tmp-String-9}
> (3) --> ^61693a
> (3) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:& Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE
> (3) else {
> (3) update request {
> (3) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address} :-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
> (3) --> 2f664aa021eff0bd90754442f6900278
> (3) &Acct-Unique-Session-Id := 2f664aa021eff0bd90754442f6900278
> (3) } # update request = noop
> (3) } # else = noop
> (3) } # policy acct_unique = noop
> (3) suffix: Checking for suffix after "@"
> (3) suffix: No '@' in User-Name = "0001", looking up realm NULL
> (3) suffix: No such realm "NULL"
> (3) [suffix] = noop
> (3) } # preacct = ok
> (3) # Executing section accounting from file /etc/raddb/sites-enabled/default
> (3) accounting {
> (3) detail: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet- Src-IPv6-Address}}/detail-%Y%m%d
> (3) detail: --> /var/log/radius/radacct/127.0.0.1/detail-20200101
> (3) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv 6-Address}}/detail-%Y%m%d expands to /var/log/radius/radacct/127.0.0.1/detail-20 200101
> (3) detail: EXPAND %t
> (3) detail: --> Wed Jan 1 02:25:11 2020
> (3) [detail] = ok
> (3) [unix] = noop
> (3) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
> (3) sql: --> type.interim-update.query
> (3) sql: Using query template 'query'
> rlm_sql (sql): Closing connection (7): Hit idle_timeout, was idle for 97 seconds
> rlm_sql (sql): You probably need to lower "min"
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (8): Hit idle_timeout, was idle for 97 seconds
> rlm_sql (sql): You probably need to lower "min"
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (6): Hit idle_timeout, was idle for 97 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 (9), 1 of 32 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, serv er version 5.5.64-MariaDB, protocol version 10
> rlm_sql (sql): Reserved connection (9)
> (3) sql: EXPAND %{User-Name}
> (3) sql: --> 0001
> (3) sql: SQL-User-Name set to '0001'
> (3) sql: EXPAND UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctu pdatetime), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctint erval = %{integer:Event-Timestamp} - UNIX_TIMESTAMP(@acctupdatetime_old), fra medipaddress = '%{Framed-IP-Address}', acctsessiontime = %{%{Acct-Session-Time}: -NULL}, acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Inpu t-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{% {Acct-Output-Octets}:-0}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'
> (3) sql: --> UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctu pdatetime), acctupdatetime = FROM_UNIXTIME(1577832911), acctinterval = 15778 32911 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '10.10.1.186', ac ctsessiontime = 97, acctinputoctets = '0' << 32 | '26528', acctoutputoctets = '0 ' << 32 | '11973' WHERE AcctUniqueId = '2f664aa021eff0bd90754442f6900278'
> (3) sql: Executing query: UPDATE radacct SET acctupdatetime = (@acctupdatetime_ old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1577832911), acctinterval = 1577832911 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '10.10. 1.186', acctsessiontime = 97, acctinputoctets = '0' << 32 | '26528', acctoutputo ctets = '0' << 32 | '11973' WHERE AcctUniqueId = '2f664aa021eff0bd90754442f69002 78'
> rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0
> (3) sql: SQL query returned: success
> (3) sql: 1 record(s) updated
> rlm_sql (sql): Released connection (9)
> Need 2 more connections to reach min connections (3)
> rlm_sql (sql): Opening additional connection (10), 1 of 31 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, serv er version 5.5.64-MariaDB, protocol version 10
> (3) [sql] = ok
> (3) [exec] = noop
> (3) attr_filter.accounting_response: EXPAND %{User-Name}
> (3) attr_filter.accounting_response: --> 0001
> (3) attr_filter.accounting_response: Matched entry DEFAULT at line 12
> (3) [attr_filter.accounting_response] = updated
> (3) } # accounting = updated
> (3) Sent Accounting-Response Id 95 from 127.0.0.1:1813 to 127.0.0.1:50916 length 0
> (3) Finished request
> (3) Cleaning up request packet ID 95 with timestamp +170
> Ready to process requests
> (4) Received Accounting-Request Id 155 from 127.0.0.1:33090 to 127.0.0.1:1813 le ngth 158
> (4) Acct-Status-Type = Interim-Update
> (4) User-Name = "0001"
> (4) Service-Type = Framed-User
> (4) Framed-Protocol = PPP
> (4) Framed-IP-Address = 10.10.1.186
> (4) Calling-Station-Id = "185.131.136.61"
> (4) Acct-Session-Id = "YokGL5neiA2JyiM49N9Bytg0hYk="
> (4) Acct-Authentic = RADIUS
> (4) Acct-Session-Time = 209
> (4) Acct-Input-Octets = 31377
> (4) Acct-Output-Octets = 18986
> (4) Acct-Input-Gigawords = 0
> (4) Acct-Output-Gigawords = 0
> (4) NAS-Port = 2575
> (4) Acct-Delay-Time = 0
> (4) NAS-IP-Address = 127.0.0.1
> (4) NAS-Identifier = "ocserv"
> (4) # Executing section preacct from file /etc/raddb/sites-enabled/default
> (4) preacct {
> (4) [preprocess] = ok
> (4) policy acct_unique {
> (4) update request {
> (4) &Tmp-String-9 := "ai:"
> (4) } # update request = noop
> (4) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:& Class}" =~ /^ai:([0-9a-f]{32})/i)) {
> (4) EXPAND %{hex:&Class}
> (4) -->
> (4) EXPAND ^%{hex:&Tmp-String-9}
> (4) --> ^61693a
> (4) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:& Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE
> (4) else {
> (4) update request {
> (4) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address} :-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
> (4) --> 2f664aa021eff0bd90754442f6900278
> (4) &Acct-Unique-Session-Id := 2f664aa021eff0bd90754442f6900278
> (4) } # update request = noop
> (4) } # else = noop
> (4) } # policy acct_unique = noop
> (4) suffix: Checking for suffix after "@"
> (4) suffix: No '@' in User-Name = "0001", looking up realm NULL
> (4) suffix: No such realm "NULL"
> (4) [suffix] = noop
> (4) } # preacct = ok
> (4) # Executing section accounting from file /etc/raddb/sites-enabled/default
> (4) accounting {
> (4) detail: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet- Src-IPv6-Address}}/detail-%Y%m%d
> (4) detail: --> /var/log/radius/radacct/127.0.0.1/detail-20200101
> (4) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv 6-Address}}/detail-%Y%m%d expands to /var/log/radius/radacct/127.0.0.1/detail-20 200101
> (4) detail: EXPAND %t
> (4) detail: --> Wed Jan 1 02:27:03 2020
> (4) [detail] = ok
> (4) [unix] = noop
> (4) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
> (4) sql: --> type.interim-update.query
> (4) sql: Using query template 'query'
> rlm_sql (sql): Closing connection (9): Hit idle_timeout, was idle for 112 second s
> rlm_sql (sql): You probably need to lower "min"
> rlm_sql_mysql: Socket destructor called, closing socket
> rlm_sql (sql): Closing connection (10): Hit idle_timeout, was idle for 112 secon ds
> 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 (11), 1 of 32 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, serv er version 5.5.64-MariaDB, protocol version 10
> rlm_sql (sql): Reserved connection (11)
> (4) sql: EXPAND %{User-Name}
> (4) sql: --> 0001
> (4) sql: SQL-User-Name set to '0001'
> (4) sql: EXPAND UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctu pdatetime), acctupdatetime = FROM_UNIXTIME(%{integer:Event-Timestamp}), acctint erval = %{integer:Event-Timestamp} - UNIX_TIMESTAMP(@acctupdatetime_old), fra medipaddress = '%{Framed-IP-Address}', acctsessiontime = %{%{Acct-Session-Time}: -NULL}, acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Inpu t-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{% {Acct-Output-Octets}:-0}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'
> (4) sql: --> UPDATE radacct SET acctupdatetime = (@acctupdatetime_old:=acctu pdatetime), acctupdatetime = FROM_UNIXTIME(1577833023), acctinterval = 15778 33023 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '10.10.1.186', ac ctsessiontime = 209, acctinputoctets = '0' << 32 | '31377', acctoutputoctets = ' 0' << 32 | '18986' WHERE AcctUniqueId = '2f664aa021eff0bd90754442f6900278'
> (4) sql: Executing query: UPDATE radacct SET acctupdatetime = (@acctupdatetime_ old:=acctupdatetime), acctupdatetime = FROM_UNIXTIME(1577833023), acctinterval = 1577833023 - UNIX_TIMESTAMP(@acctupdatetime_old), framedipaddress = '10.10. 1.186', acctsessiontime = 209, acctinputoctets = '0' << 32 | '31377', acctoutput octets = '0' << 32 | '18986' WHERE AcctUniqueId = '2f664aa021eff0bd90754442f6900 278'
> rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0
> (4) sql: SQL query returned: success
> (4) sql: 1 record(s) updated
> rlm_sql (sql): Released connection (11)
> Need 2 more connections to reach min connections (3)
> rlm_sql (sql): Opening additional connection (12), 1 of 31 pending slots used
> rlm_sql_mysql: Starting connect to MySQL server
> rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, serv er version 5.5.64-MariaDB, protocol version 10
> (4) [sql] = ok
> (4) [exec] = noop
> (4) attr_filter.accounting_response: EXPAND %{User-Name}
> (4) attr_filter.accounting_response: --> 0001
> (4) attr_filter.accounting_response: Matched entry DEFAULT at line 12
> (4) [attr_filter.accounting_response] = updated
> (4) } # accounting = updated
> (4) Sent Accounting-Response Id 155 from 127.0.0.1:1813 to 127.0.0.1:33090 lengt h 0
> (4) Finished request
> (4) Cleaning up request packet ID 155 with timestamp +282
> Ready to process requests
> 
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html