buffered-sql problem
Jouni Soini
soini.jouni at yahoo.com
Wed Jan 25 19:01:53 CET 2017
there seems to be a problem with buffered-sql
it sometimes doesn't pick the accounting request from detail file and just skip it.
this happens once in a few million requests and I had to debug and monitor this for several days to find one (looking for a user who remains online)
nothing special exists in debug logs. the accounting request is logged to detail file but the sql statement part doesn't exits.
following is the debug logs as you can see the accounting request is logged to detail file (in my tests to two separate files for extra monitoring) but it is not sent to sql database
tested with 3.0.12 version on Ubuntu 16.04
as you can see the sql query for user 'test1' is skipped
(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
...
logs for next request "test2"
...
(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
More information about the Freeradius-Users
mailing list