duplicate acctsessionid when connectin to ocserv

[Mehrzad Jalali]

in my vps centos 7 with ocserv 12.5 and freeradius 3.0.5 standard installation 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


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