buffered-sql problem
Jouni Soini
soini.jouni at yahoo.com
Wed Jan 25 21:28:15 CET 2017
> Again, the *full* debug log is useful here. If you say that the debug log does (or doesn't) show something, then post the log. Not *part* of the log which doesn't show what you said.
>
> The server doesn't randomly skip entries in the detail file. If something is skipped, there's a reason. And the reason is in the > debug log.
I don't see anything in logs. anyway I am sending the full logs starting from accounting request for 'test1'
as you can see there is no sql section for this user
(494090) Wed Jan 25 12:04:10 2017: Debug: Received Accounting-Request Id 188 from 82.21.11.91:28850 to 82.21.11.50:1813 length 107
(494090) Wed Jan 25 12:04:10 2017: Debug: User-Name = "test1"
(494090) Wed Jan 25 12:04:10 2017: Debug: NAS-IP-Address = 82.21.11.91
(494090) Wed Jan 25 12:04:10 2017: Debug: NAS-Port = 23449
(494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Status-Type = Stop
(494090) Wed Jan 25 12:04:10 2017: Debug: Framed-IP-Address = 10.8.0.98
(494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Input-Gigawords = 0
(494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Input-Octets = 8323
(494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Output-Octets = 8111
(494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Session-Id = "68r3xt2pb8y8"
(494090) Wed Jan 25 12:04:10 2017: Debug: Acct-Output-Gigawords = 0
(494090) Wed Jan 25 12:04:10 2017: Debug: Calling-Station-Id = "127.0.0.1"
(494090) Wed Jan 25 12:04:10 2017: Debug: # Executing section preacct from file /etc/freeradius/sites-enabled/default
(494090) Wed Jan 25 12:04:10 2017: Debug: preacct {
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: calling preprocess (rlm_preprocess)
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: returned from preprocess (rlm_preprocess)
(494090) Wed Jan 25 12:04:10 2017: Debug: [preprocess] = ok
(494090) Wed Jan 25 12:04:10 2017: Debug: policy acct_unique {
(494090) Wed Jan 25 12:04:10 2017: Debug: update request {
(494090) Wed Jan 25 12:04:10 2017: Debug: Tmp-String-9 := "ai:"
(494090) Wed Jan 25 12:04:10 2017: Debug: } # update request = noop
(494090) Wed Jan 25 12:04:10 2017: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
(494090) Wed Jan 25 12:04:10 2017: Debug: EXPAND %{hex:&Class}
(494090) Wed Jan 25 12:04:10 2017: Debug: -->
(494090) Wed Jan 25 12:04:10 2017: Debug: EXPAND ^%{hex:&Tmp-String-9}
(494090) Wed Jan 25 12:04:10 2017: Debug: --> ^61693a
(494090) Wed Jan 25 12:04:10 2017: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE
(494090) Wed Jan 25 12:04:10 2017: Debug: else {
(494090) Wed Jan 25 12:04:10 2017: Debug: update request {
(494090) Wed Jan 25 12:04:10 2017: Debug: EXPAND %{md5:%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(494090) Wed Jan 25 12:04:10 2017: Debug: --> b1cbd13cc01616d5f451e33b24aeb893
(494090) Wed Jan 25 12:04:10 2017: Debug: &Acct-Unique-Session-Id := b1cbd13cc01616d5f451e33b24aeb893
(494090) Wed Jan 25 12:04:10 2017: Debug: } # update request = noop
(494090) Wed Jan 25 12:04:10 2017: Debug: } # else = noop
(494090) Wed Jan 25 12:04:10 2017: Debug: } # policy acct_unique = noop
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: calling suffix (rlm_realm)
(494090) Wed Jan 25 12:04:10 2017: Debug: suffix: Checking for suffix after "@"
(494090) Wed Jan 25 12:04:10 2017: Debug: suffix: No '@' in User-Name = "test1", looking up realm NULL
(494090) Wed Jan 25 12:04:10 2017: Debug: suffix: No such realm "NULL"
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: returned from suffix (rlm_realm)
(494090) Wed Jan 25 12:04:10 2017: Debug: [suffix] = noop
(494090) Wed Jan 25 12:04:10 2017: Debug: } # preacct = ok
(494090) Wed Jan 25 12:04:10 2017: Debug: # Executing section accounting from file /etc/freeradius/sites-enabled/default
(494090) Wed Jan 25 12:04:10 2017: Debug: accounting {
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling detail (rlm_detail)
(494090) Wed Jan 25 12:04:10 2017: Debug: detail: EXPAND /var/log/freeradius/radacct/detail-%Y%m%d
(494090) Wed Jan 25 12:04:10 2017: Debug: detail: --> /var/log/freeradius/radacct/detail-20170125
(494090) Wed Jan 25 12:04:10 2017: Debug: detail: /var/log/freeradius/radacct/detail-%Y%m%d expands to /var/log/freeradius/radacct/detail-20170125
(494090) Wed Jan 25 12:04:10 2017: Debug: detail: EXPAND %t
(494090) Wed Jan 25 12:04:10 2017: Debug: detail: --> Wed Jan 25 12:04:10 2017
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from detail (rlm_detail)
(494090) Wed Jan 25 12:04:10 2017: Debug: [detail] = ok
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling detail2 (rlm_detail)
(494090) Wed Jan 25 12:04:10 2017: Debug: detail2: EXPAND /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(494090) Wed Jan 25 12:04:10 2017: Debug: detail2: --> /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170125
(494090) Wed Jan 25 12:04:10 2017: Debug: detail2: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170125
(494090) Wed Jan 25 12:04:10 2017: Debug: detail2: EXPAND %t
(494090) Wed Jan 25 12:04:10 2017: Debug: detail2: --> Wed Jan 25 12:04:10 2017
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from detail2 (rlm_detail)
(494090) Wed Jan 25 12:04:10 2017: Debug: [detail2] = ok
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling exec (rlm_exec)
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from exec (rlm_exec)
(494090) Wed Jan 25 12:04:10 2017: Debug: [exec] = noop
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter)
(494090) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: EXPAND %{User-Name}
(494090) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: --> test1
(494090) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: Matched entry DEFAULT at line 12
(494090) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter)
(494090) Wed Jan 25 12:04:10 2017: Debug: [attr_filter.accounting_response] = updated
(494090) Wed Jan 25 12:04:10 2017: Debug: } # accounting = updated
(494090) Wed Jan 25 12:04:10 2017: Debug: Sent Accounting-Response Id 188 from 82.21.11.50:1813 to 82.21.11.91:28850 length 0
(494090) Wed Jan 25 12:04:10 2017: Debug: Finished request
(494091) Wed Jan 25 12:04:10 2017: Debug: Received Accounting-Request Id 189 from 82.21.11.91:57448 to 82.21.11.50:1813 length 79
(494091) Wed Jan 25 12:04:10 2017: Debug: User-Name = "test2"
(494091) Wed Jan 25 12:04:10 2017: Debug: NAS-IP-Address = 82.21.11.91
(494091) Wed Jan 25 12:04:10 2017: Debug: NAS-Port = 23453
(494091) Wed Jan 25 12:04:10 2017: Debug: Acct-Status-Type = Start
(494091) Wed Jan 25 12:04:10 2017: Debug: Framed-IP-Address = 10.8.0.98
(494091) Wed Jan 25 12:04:10 2017: Debug: Acct-Session-Id = "1u8xlmlcphbf"
(494091) Wed Jan 25 12:04:10 2017: Debug: Calling-Station-Id = "127.0.0.1"
(494091) Wed Jan 25 12:04:10 2017: Debug: # Executing section preacct from file /etc/freeradius/sites-enabled/default
(494091) Wed Jan 25 12:04:10 2017: Debug: preacct {
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: calling preprocess (rlm_preprocess)
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: returned from preprocess (rlm_preprocess)
(494091) Wed Jan 25 12:04:10 2017: Debug: [preprocess] = ok
(494091) Wed Jan 25 12:04:10 2017: Debug: policy acct_unique {
(494091) Wed Jan 25 12:04:10 2017: Debug: update request {
(494091) Wed Jan 25 12:04:10 2017: Debug: Tmp-String-9 := "ai:"
(494091) Wed Jan 25 12:04:10 2017: Debug: } # update request = noop
(494091) Wed Jan 25 12:04:10 2017: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) {
(494091) Wed Jan 25 12:04:10 2017: Debug: EXPAND %{hex:&Class}
(494091) Wed Jan 25 12:04:10 2017: Debug: -->
(494091) Wed Jan 25 12:04:10 2017: Debug: EXPAND ^%{hex:&Tmp-String-9}
(494091) Wed Jan 25 12:04:10 2017: Debug: --> ^61693a
(494091) Wed Jan 25 12:04:10 2017: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE
(494091) Wed Jan 25 12:04:10 2017: Debug: else {
(494091) Wed Jan 25 12:04:10 2017: Debug: update request {
(494091) Wed Jan 25 12:04:10 2017: Debug: EXPAND %{md5:%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(494091) Wed Jan 25 12:04:10 2017: Debug: --> 4f90530db6450d8d919eb30b02f4b2d4
(494091) Wed Jan 25 12:04:10 2017: Debug: &Acct-Unique-Session-Id := 4f90530db6450d8d919eb30b02f4b2d4
(494091) Wed Jan 25 12:04:10 2017: Debug: } # update request = noop
(494091) Wed Jan 25 12:04:10 2017: Debug: } # else = noop
(494091) Wed Jan 25 12:04:10 2017: Debug: } # policy acct_unique = noop
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: calling suffix (rlm_realm)
(494091) Wed Jan 25 12:04:10 2017: Debug: suffix: Checking for suffix after "@"
(494091) Wed Jan 25 12:04:10 2017: Debug: suffix: No '@' in User-Name = "test2", looking up realm NULL
(494091) Wed Jan 25 12:04:10 2017: Debug: suffix: No such realm "NULL"
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[preacct]: returned from suffix (rlm_realm)
(494091) Wed Jan 25 12:04:10 2017: Debug: [suffix] = noop
(494091) Wed Jan 25 12:04:10 2017: Debug: } # preacct = ok
(494091) Wed Jan 25 12:04:10 2017: Debug: # Executing section accounting from file /etc/freeradius/sites-enabled/default
(494091) Wed Jan 25 12:04:10 2017: Debug: accounting {
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling detail (rlm_detail)
(494091) Wed Jan 25 12:04:10 2017: Debug: detail: EXPAND /var/log/freeradius/radacct/detail-%Y%m%d
(494091) Wed Jan 25 12:04:10 2017: Debug: detail: --> /var/log/freeradius/radacct/detail-20170125
(494091) Wed Jan 25 12:04:10 2017: Debug: detail: /var/log/freeradius/radacct/detail-%Y%m%d expands to /var/log/freeradius/radacct/detail-20170125
(494091) Wed Jan 25 12:04:10 2017: Debug: detail: EXPAND %t
(494091) Wed Jan 25 12:04:10 2017: Debug: detail: --> Wed Jan 25 12:04:10 2017
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from detail (rlm_detail)
(494091) Wed Jan 25 12:04:10 2017: Debug: [detail] = ok
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling detail2 (rlm_detail)
(494091) Wed Jan 25 12:04:10 2017: Debug: detail2: EXPAND /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(494091) Wed Jan 25 12:04:10 2017: Debug: detail2: --> /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170125
(494091) Wed Jan 25 12:04:10 2017: Debug: detail2: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170125
(494091) Wed Jan 25 12:04:10 2017: Debug: detail2: EXPAND %t
(494091) Wed Jan 25 12:04:10 2017: Debug: detail2: --> Wed Jan 25 12:04:10 2017
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from detail2 (rlm_detail)
(494091) Wed Jan 25 12:04:10 2017: Debug: [detail2] = ok
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling exec (rlm_exec)
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from exec (rlm_exec)
(494091) Wed Jan 25 12:04:10 2017: Debug: [exec] = noop
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter)
(494091) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: EXPAND %{User-Name}
(494091) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: --> test2
(494091) Wed Jan 25 12:04:10 2017: Debug: attr_filter.accounting_response: Matched entry DEFAULT at line 12
(494091) Wed Jan 25 12:04:10 2017: Debug: modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter)
(494091) Wed Jan 25 12:04:10 2017: Debug: [attr_filter.accounting_response] = updated
(494091) Wed Jan 25 12:04:10 2017: Debug: } # accounting = updated
(494091) Wed Jan 25 12:04:10 2017: Debug: Sent Accounting-Response Id 189 from 82.21.11.50:1813 to 82.21.11.91:57448 length 0
(494091) Wed Jan 25 12:04:10 2017: Debug: Finished request
(494090) Wed Jan 25 12:04:10 2017: Debug: Cleaning up request packet ID 188 with timestamp +243824
(494091) Wed Jan 25 12:04:10 2017: Debug: Cleaning up request packet ID 189 with timestamp +243824
(494092) Wed Jan 25 12:04:11 2017: Debug: Empty preacct section in virtual server "buffered-sql". Using default return values.
(494092) Wed Jan 25 12:04:11 2017: Debug: # Executing section accounting from file /etc/freeradius/sites-enabled/buffered-sql
(494092) Wed Jan 25 12:04:11 2017: Debug: accounting {
(494092) Wed Jan 25 12:04:11 2017: Debug: modsingle[accounting]: calling sql (rlm_sql)
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: --> type.start.query
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: Using query template 'query'
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: EXPAND %{User-Name}
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: --> test2
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: SQL-User-Name set to 'test2'
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: EXPAND INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', %{integer:Acct-Status-Type}, lower(trim('%{SQL-User-Name}')), '%{%{Called-Station-Id}:-%{NAS-IP-Address}}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', NOW(), '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Framed-IP-Address}')
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: --> INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('1u8xlmlcphbf', '4f90530db6450d8d919eb30b02f4b2d4', 1, lower(trim('test2')), '82.21.11.91', '23453', NOW(), '0', '0', '', '127.0.0.1', '', '10.8.0.98')
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: Executing query: INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('1u8xlmlcphbf', '4f90530db6450d8d919eb30b02f4b2d4', 1, lower(trim('test2')), '82.21.11.91', '23453', NOW(), '0', '0', '', '127.0.0.1', '', '10.8.0.98')
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: SQL query returned: success
(494092) Wed Jan 25 12:04:11 2017: Debug: sql: 1 record(s) updated
(494092) Wed Jan 25 12:04:11 2017: Debug: modsingle[accounting]: returned from sql (rlm_sql)
(494092) Wed Jan 25 12:04:11 2017: Debug: [sql] = ok
(494092) Wed Jan 25 12:04:11 2017: Debug: } # accounting = ok
(494092) Wed Jan 25 12:04:11 2017: Debug: Sent Accounting-Response Id 254 from 127.0.0.0:1027 to 255.255.255.255:1220 length 0
(494092) Wed Jan 25 12:04:11 2017: Debug: detail (/var/log/freeradius/radacct/detail-*): Received response for request 494092. Will read the next packet in 0 seconds
(494092) Wed Jan 25 12:04:11 2017: Debug: Finished request
(494092) Wed Jan 25 12:04:11 2017: Debug: Cleaning up request packet ID 254 with timestamp +243825
(145912) Mon Jan 23 12:04:12 2017: Debug: Cleaning up request packet ID 247 with timestamp +71025
(145913) Mon Jan 23 12:04:12 2017: Debug: Cleaning up request packet ID 248 with timestamp +71025
(145914) Mon Jan 23 12:04:12 2017: Debug: Cleaning up request packet ID 249 with timestamp +71025
(145915) Mon Jan 23 12:04:12 2017: Debug: Cleaning up request packet ID 250 with timestamp +71025
(145916) Mon Jan 23 12:04:12 2017: Debug: Cleaning up request packet ID 251 with timestamp +71025
(145917) Mon Jan 23 12:04:12 2017: Debug: Cleaning up request packet ID 252 with timestamp +71025
(145918) Mon Jan 23 12:04:12 2017: Debug: Cleaning up request packet ID 253 with timestamp +71025
More information about the Freeradius-Users
mailing list