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
On Jan 25, 2017, at 1:01 PM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
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
That's what you configured it to do. ...
(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)
Versus:
(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
One is running the "default" virtual server, and the other is "buffered-sql". The "default" virtual server doesn't write to SQL. So "test1" is written to the detail file, and then some time later, read from the detail file, and written to SQL. Alan DeKok.
So "test1" is written to the detail file, and then some time later, read from the detail file, and written to SQL.
my whole point was that "test1" is skipped. it is not written to database. it's sql logs even doesn't exist in debug. only "test2" which is the following accounting request is written to sql.
On Jan 25, 2017, at 2:19 PM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
So "test1" is written to the detail file, and then some time later, read from the detail file, and written to SQL.
my whole point was that "test1" is skipped. it is not written to database. it's sql logs even doesn't exist in debug.
You didn't show that in the debug output. I can only go by what you post.
only "test2" which is the following accounting request is written to sql.
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. Alan DeKok.
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
On Jan 25, 2017, at 3:28 PM, Jouni Soini <soini.jouni@yahoo.com> wrote:
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
The users are being written to TWO detail files: /var/log/freeradius/radacct/detail-20170125 and /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170125 You've configured the server to read from a detail file /var/log/freeradius/radacct/detail-*. which is fine. But, reading the REST of the debug output will help. The server prints out which detail files it's reading, and what it's doing. I don't see any of that in this tiny piece of the debug log. So what's happening is this: - server is reading from detail.work - packets are being written to detail-20170125 - you're wondering why packets written to detail-20170125 aren't in detail.work Well... keep reading the debug output. At some point, it will print this when it starts reading a detail file: DEBUG("detail (%s): Renaming %s -> %s", data->name, filename, data->filename_work); and it will print this when it's done reading the detail file: DEBUG("detail (%s): Unlinking %s", data->name, data->filename_work); Look for those. I've pushed some fixes to the v3.0.x branch which will make this a bit clearer. Alan DeKok.
I was using radmin to log debug to a file and it seems the lines you mentioned is still written to radius.log if running freeradius -X gives more info I can try that too. these are the lines in radius.log: Wed Jan 25 12:04:10 2017 : Debug: Waking up in 0.3 seconds. Wed Jan 25 12:04:10 2017 : Debug: Thread 1 got semaphore Wed Jan 25 12:04:10 2017 : Debug: Thread 1 handling request 494090, (69384 handled so far) Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: (duplicate lines) Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/radacct/detail-%Y%m%d Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/radacct/detail- Wed Jan 25 12:04:10 2017 : Debug: percent --> Y Wed Jan 25 12:04:10 2017 : Debug: percent --> m Wed Jan 25 12:04:10 2017 : Debug: percent --> d Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Wed Jan 25 12:04:10 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Renaming /var/log/freeradius/radacct/detail-20170125 -> /var/log/freeradius/radacct/detail.work Wed Jan 25 12:04:10 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Unlinking /var/log/freeradius/radacct/detail.work Wed Jan 25 12:04:10 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Detail listener state unopened waiting 1.223150 sec Wed Jan 25 12:04:10 2017 : Debug: %t Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: percent --> t Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/radacct/debug/ Wed Jan 25 12:04:10 2017 : Debug: if { Wed Jan 25 12:04:10 2017 : Debug: attribute --> Packet-Src-IP-Address Wed Jan 25 12:04:10 2017 : Debug: } Wed Jan 25 12:04:10 2017 : Debug: else { Wed Jan 25 12:04:10 2017 : Debug: attribute --> Packet-Src-IPv6-Address Wed Jan 25 12:04:10 2017 : Debug: } Wed Jan 25 12:04:10 2017 : Debug: literal --> /detail- Wed Jan 25 12:04:10 2017 : Debug: percent --> Y Wed Jan 25 12:04:10 2017 : Debug: percent --> m Wed Jan 25 12:04:10 2017 : Debug: percent --> d Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: %t Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: percent --> t Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: %{User-Name} Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: attribute --> User-Name Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Thread 1 waiting to be assigned a request Wed Jan 25 12:04:10 2017 : Debug: Waking up in 0.3 seconds. Wed Jan 25 12:04:10 2017 : Debug: Thread 8 got semaphore Wed Jan 25 12:04:10 2017 : Debug: Thread 8 handling request 494091, (49057 handled so far) Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: (duplicate) Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/radacct/detail-%Y%m%d Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/radacct/detail- Wed Jan 25 12:04:10 2017 : Debug: percent --> Y Wed Jan 25 12:04:10 2017 : Debug: percent --> m Wed Jan 25 12:04:10 2017 : Debug: percent --> d Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: %t Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: percent --> t Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/radacct/debug/ Wed Jan 25 12:04:10 2017 : Debug: if { Wed Jan 25 12:04:10 2017 : Debug: attribute --> Packet-Src-IP-Address Wed Jan 25 12:04:10 2017 : Debug: } Wed Jan 25 12:04:10 2017 : Debug: else { Wed Jan 25 12:04:10 2017 : Debug: attribute --> Packet-Src-IPv6-Address Wed Jan 25 12:04:10 2017 : Debug: } Wed Jan 25 12:04:10 2017 : Debug: literal --> /detail- Wed Jan 25 12:04:10 2017 : Debug: percent --> Y Wed Jan 25 12:04:10 2017 : Debug: percent --> m Wed Jan 25 12:04:10 2017 : Debug: percent --> d Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: %t Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: percent --> t Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: %{User-Name} Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: attribute --> User-Name Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Thread 8 waiting to be assigned a request Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:10 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:10 2017 : Info: Ready to process requests Wed Jan 25 12:04:11 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Wed Jan 25 12:04:11 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Renaming /var/log/freeradius/radacct/detail-20170125 -> /var/log/freeradius/radacct/detail.work Wed Jan 25 12:04:11 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Read packet from /var/log/freeradius/radacct/detail.work Wed Jan 25 12:04:11 2017 : Debug: Waking up in 0.3 seconds. Wed Jan 25 12:04:11 2017 : Debug: Thread 6 got semaphore Wed Jan 25 12:04:11 2017 : Debug: Thread 6 handling request 494092, (48855 handled so far) Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: %{tolower:type.%{Acct-Status-Type}.query} Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: xlat --> tolower Wed Jan 25 12:04:11 2017 : Debug: { Wed Jan 25 12:04:11 2017 : Debug: literal --> type. Wed Jan 25 12:04:11 2017 : Debug: attribute --> Acct-Status-Type Wed Jan 25 12:04:11 2017 : Debug: literal --> .query Wed Jan 25 12:04:11 2017 : Debug: } Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: rlm_sql (sql): Reserved connection (12) Wed Jan 25 12:04:11 2017 : Debug: %{User-Name} Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: attribute --> User-Name Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: 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}') Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES (' Wed Jan 25 12:04:11 2017 : Debug: attribute --> Acct-Session-Id Wed Jan 25 12:04:11 2017 : Debug: literal --> ', ' Wed Jan 25 12:04:11 2017 : Debug: attribute --> Acct-Unique-Session-Id Wed Jan 25 12:04:11 2017 : Debug: literal --> ', Wed Jan 25 12:04:11 2017 : Debug: xlat --> integer Wed Jan 25 12:04:11 2017 : Debug: { Wed Jan 25 12:04:11 2017 : Debug: literal --> Acct-Status-Type Wed Jan 25 12:04:11 2017 : Debug: } Wed Jan 25 12:04:11 2017 : Debug: literal --> , lower(trim(' Wed Jan 25 12:04:11 2017 : Debug: attribute --> SQL-User-Name Wed Jan 25 12:04:11 2017 : Debug: literal --> ')), ' Wed Jan 25 12:04:11 2017 : Debug: if { Wed Jan 25 12:04:11 2017 : Debug: attribute --> Called-Station-Id Wed Jan 25 12:04:11 2017 : Debug: } Wed Jan 25 12:04:11 2017 : Debug: else { Wed Jan 25 12:04:11 2017 : Debug: attribute --> NAS-IP-Address Wed Jan 25 12:04:11 2017 : Debug: } Wed Jan 25 12:04:11 2017 : Debug: literal --> ', ' Wed Jan 25 12:04:11 2017 : Debug: if { Wed Jan 25 12:04:11 2017 : Debug: attribute --> NAS-Port-Id Wed Jan 25 12:04:11 2017 : Debug: } Wed Jan 25 12:04:11 2017 : Debug: else { Wed Jan 25 12:04:11 2017 : Debug: attribute --> NAS-Port Wed Jan 25 12:04:11 2017 : Debug: } Wed Jan 25 12:04:11 2017 : Debug: literal --> ', NOW(), '0', '0', ' Wed Jan 25 12:04:11 2017 : Debug: attribute --> Called-Station-Id Wed Jan 25 12:04:11 2017 : Debug: literal --> ', ' Wed Jan 25 12:04:11 2017 : Debug: attribute --> Calling-Station-Id Wed Jan 25 12:04:11 2017 : Debug: literal --> ', '', ' Wed Jan 25 12:04:11 2017 : Debug: attribute --> Framed-IP-Address Wed Jan 25 12:04:11 2017 : Debug: literal --> ') Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: rlm_sql (sql): Released connection (12) Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Thread 6 waiting to be assigned a request Wed Jan 25 12:04:11 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Unlinking /var/log/freeradius/radacct/detail.work Wed Jan 25 12:04:11 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Wed Jan 25 12:04:11 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Detail listener state unopened waiting 1.169948 sec Wed Jan 25 12:04:11 2017 : Debug: /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Debug: Parsed xlat tree: Wed Jan 25 12:04:11 2017 : Debug: literal --> /var/log/freeradius/debug.log Wed Jan 25 12:04:11 2017 : Info: Ready to process requests Wed Jan 25 12:04:12 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Wed Jan 25 12:04:12 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Detail listener state unopened waiting 0.780303 sec
On Jan 26, 2017, at 2:23 AM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
I was using radmin to log debug to a file and it seems the lines you mentioned is still written to radius.log if running freeradius -X gives more info I can try that too.
It doesn't give *more* information, it gives timely information. If the logs are split between radius.log and another one... it's difficult to correlate the messages. Possible, but difficult.
these are the lines in radius.log:
That shows normal processing of the detail.work file. Again, are you clear that writing to detail-20170125 does *not* mean that the packet is immediately read into the detail.work file? I just don't see how the server "misses" packets from the detail file. The only evidence you've shown is the server writing to one file, and reading from another. That's how it works. If you wait a while, the server will finish the current detail.work, rename detail-20170125 to detail.work, and process that. If you see accounting packets being lost.. blame the NAS. FreeRADIUS doesn't throw packets away. The NAS does. Alan DeKok.
Again, are you clear that writing to detail-20170125 does *not* mean that the packet is immediately read into the detail.work file?
yes I am clear about it. the problem is not latency. some packets are NEVER read (or written) from detail file.
I just don't see how the server "misses" packets from the detail file.
I think the logs is clear enough. if you check them you can see that two accounting packets are received for users 'test1' and 'test2' at the same time. both are written to the detail file successfully (or at least the debugs says so) but while reading from this detail file only user 'test2' is saved into sql. there is no evidence of the user 'test1' in debugs and there is no row for it in the mysql table.
If you see accounting packets being lost.. blame the NAS. FreeRADIUS doesn't throw packets away. The NAS does.
there is no packet loss or NAS problem. FreeRadius accepted both requests. but only saved one of them to the database.
On Jan 26, 2017, at 10:57 AM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
Again, are you clear that writing to detail-20170125 does *not* mean that the packet is immediately read into the detail.work file?
yes I am clear about it. the problem is not latency. some packets are NEVER read (or written) from detail file.
You can manually check the contents of the detail file, too.
I just don't see how the server "misses" packets from the detail file.
I think the logs is clear enough. if you check them you can see that two accounting packets are received for users 'test1' and 'test2' at the same time. both are written to the detail file successfully (or at least the debugs says so) but while reading from this detail file only user 'test2' is saved into sql. there is no evidence of the user 'test1' in debugs and there is no row for it in the mysql table.
The debug log shows (at one point), it's reading an entry from the "detail" file, but that the entry contains no attributes. Please download the the v3.0.x branch from https://github.com/FreeRADIUS/freeradius-server/ I've put more debugging in so that it's clearer what happens. If you run with "-Xx", you'll see exactly what's going on. Including the detail module skipping empty packets, and not writing them to the detail file. Alan DeKok.
Please download the the v3.0.x branch from https://github.com/FreeRADIUS/freeradius-server/
I've put more debugging in so that it's clearer what happens. If you run with "-Xx", you'll see exactly what's going on. Including the detail module skipping empty packets, and not writing them to the detail file.
I installed the latest version from 3.0 branch and here is the logs for another occurrence. user 'mks779292' never queried and saved into database. I also noticed most (or all?) of these happen for stop request following the same user's start request in less than 10 seconds. Fri Jan 27 17:29:49 2017 : Debug: (8814) Received Accounting-Request Id 78 from 82.21.11.91:22564 to 82.21.11.50:1813 length 107 Fri Jan 27 17:29:49 2017 : Debug: (8814) User-Name = "mks779292" Fri Jan 27 17:29:49 2017 : Debug: (8814) NAS-IP-Address = 82.21.11.91 Fri Jan 27 17:29:49 2017 : Debug: (8814) NAS-Port = 2270 Fri Jan 27 17:29:49 2017 : Debug: (8814) Acct-Status-Type = Stop Fri Jan 27 17:29:49 2017 : Debug: (8814) Framed-IP-Address = 10.8.1.198 Fri Jan 27 17:29:49 2017 : Debug: (8814) Acct-Input-Gigawords = 0 Fri Jan 27 17:29:49 2017 : Debug: (8814) Acct-Input-Octets = 8319 Fri Jan 27 17:29:49 2017 : Debug: (8814) Acct-Output-Octets = 7908 Fri Jan 27 17:29:49 2017 : Debug: (8814) Acct-Session-Id = "1ql6re8tya2g" Fri Jan 27 17:29:49 2017 : Debug: (8814) Acct-Output-Gigawords = 0 Fri Jan 27 17:29:49 2017 : Debug: (8814) Calling-Station-Id = "127.0.0.1" Fri Jan 27 17:29:49 2017 : Debug: (8814) # Executing section preacct from file /etc/freeradius/sites-enabled/default Fri Jan 27 17:29:49 2017 : Debug: (8814) preacct { Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[preacct]: calling preprocess (rlm_preprocess) Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[preacct]: returned from preprocess (rlm_preprocess) Fri Jan 27 17:29:49 2017 : Debug: (8814) [preprocess] = ok Fri Jan 27 17:29:49 2017 : Debug: (8814) policy acct_unique { Fri Jan 27 17:29:49 2017 : Debug: (8814) update request { Fri Jan 27 17:29:49 2017 : Debug: (8814) Tmp-String-9 := "ai:" Fri Jan 27 17:29:49 2017 : Debug: (8814) } # update request = noop Fri Jan 27 17:29:49 2017 : Debug: (8814) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { Fri Jan 27 17:29:49 2017 : Debug: (8814) EXPAND %{hex:&Class} Fri Jan 27 17:29:49 2017 : Debug: (8814) --> Fri Jan 27 17:29:49 2017 : Debug: (8814) EXPAND ^%{hex:&Tmp-String-9} Fri Jan 27 17:29:49 2017 : Debug: (8814) --> ^61693a Fri Jan 27 17:29:49 2017 : Debug: (8814) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE Fri Jan 27 17:29:49 2017 : Debug: (8814) else { Fri Jan 27 17:29:49 2017 : Debug: (8814) update request { Fri Jan 27 17:29:49 2017 : Debug: (8814) EXPAND %{md5:%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Fri Jan 27 17:29:49 2017 : Debug: (8814) --> 35d2548e05f700bc972e5cb41314c215 Fri Jan 27 17:29:49 2017 : Debug: (8814) &Acct-Unique-Session-Id := 35d2548e05f700bc972e5cb41314c215 Fri Jan 27 17:29:49 2017 : Debug: (8814) } # update request = noop Fri Jan 27 17:29:49 2017 : Debug: (8814) } # else = noop Fri Jan 27 17:29:49 2017 : Debug: (8814) } # policy acct_unique = noop Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[preacct]: calling suffix (rlm_realm) Fri Jan 27 17:29:49 2017 : Debug: (8814) suffix: Checking for suffix after "@" Fri Jan 27 17:29:49 2017 : Debug: (8814) suffix: No '@' in User-Name = "mks779292", looking up realm NULL Fri Jan 27 17:29:49 2017 : Debug: (8814) suffix: No such realm "NULL" Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[preacct]: returned from suffix (rlm_realm) Fri Jan 27 17:29:49 2017 : Debug: (8814) [suffix] = noop Fri Jan 27 17:29:49 2017 : Debug: (8814) } # preacct = ok Fri Jan 27 17:29:49 2017 : Debug: (8814) # Executing section accounting from file /etc/freeradius/sites-enabled/default Fri Jan 27 17:29:49 2017 : Debug: (8814) accounting { Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[accounting]: calling detail (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: /var/log/freeradius/radacct/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: literal --> /var/log/freeradius/radacct/detail- Fri Jan 27 17:29:49 2017 : Debug: percent --> Y Fri Jan 27 17:29:49 2017 : Debug: percent --> m Fri Jan 27 17:29:49 2017 : Debug: percent --> d Fri Jan 27 17:29:49 2017 : Debug: (8814) detail: EXPAND /var/log/freeradius/radacct/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: (8814) detail: --> /var/log/freeradius/radacct/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: (8814) detail: /var/log/freeradius/radacct/detail-%Y%m%d expands to /var/log/freeradius/radacct/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: %t Fri Jan 27 17:29:49 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Unlinking /var/log/freeradius/radacct/detail.work Fri Jan 27 17:29:49 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Fri Jan 27 17:29:49 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Detail listener state unopened waiting 1.215169 sec Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: percent --> t Fri Jan 27 17:29:49 2017 : Debug: (8814) detail: EXPAND %t Fri Jan 27 17:29:49 2017 : Debug: (8814) detail: --> Fri Jan 27 17:29:49 2017 Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[accounting]: returned from detail (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: (8814) [detail] = ok Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[accounting]: calling detail2 (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: literal --> /var/log/freeradius/radacct/debug/ Fri Jan 27 17:29:49 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:49 2017 : Debug: attribute --> Packet-Src-IP-Address Fri Jan 27 17:29:49 2017 : Debug: } Fri Jan 27 17:29:49 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:49 2017 : Debug: attribute --> Packet-Src-IPv6-Address Fri Jan 27 17:29:49 2017 : Debug: } Fri Jan 27 17:29:49 2017 : Debug: literal --> /detail- Fri Jan 27 17:29:49 2017 : Debug: percent --> Y Fri Jan 27 17:29:49 2017 : Debug: percent --> m Fri Jan 27 17:29:49 2017 : Debug: percent --> d Fri Jan 27 17:29:49 2017 : Debug: (8814) detail2: EXPAND /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: (8814) detail2: --> /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: (8814) 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-20170127 Fri Jan 27 17:29:49 2017 : Debug: %t Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: percent --> t Fri Jan 27 17:29:49 2017 : Debug: (8814) detail2: EXPAND %t Fri Jan 27 17:29:49 2017 : Debug: (8814) detail2: --> Fri Jan 27 17:29:49 2017 Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[accounting]: returned from detail2 (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: (8814) [detail2] = ok Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[accounting]: calling exec (rlm_exec) Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[accounting]: returned from exec (rlm_exec) Fri Jan 27 17:29:49 2017 : Debug: (8814) [exec] = noop Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) Fri Jan 27 17:29:49 2017 : Debug: %{User-Name} Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: attribute --> User-Name Fri Jan 27 17:29:49 2017 : Debug: (8814) attr_filter.accounting_response: EXPAND %{User-Name} Fri Jan 27 17:29:49 2017 : Debug: (8814) attr_filter.accounting_response: --> mks779292 Fri Jan 27 17:29:49 2017 : Debug: (8814) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Fri Jan 27 17:29:49 2017 : Debug: (8814) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) Fri Jan 27 17:29:49 2017 : Debug: (8814) [attr_filter.accounting_response] = updated Fri Jan 27 17:29:49 2017 : Debug: (8814) } # accounting = updated Fri Jan 27 17:29:49 2017 : Debug: (8814) Sent Accounting-Response Id 78 from 82.21.11.50:1813 to 82.21.11.91:22564 length 0 Fri Jan 27 17:29:49 2017 : Debug: (8814) Finished request Fri Jan 27 17:29:49 2017 : Debug: (8814) Cleaning up request packet ID 78 with timestamp +3713 Fri Jan 27 17:29:49 2017 : Info: Ready to process requests Fri Jan 27 17:29:49 2017 : Debug: (8815) Received Accounting-Request Id 79 from 82.21.11.91:59683 to 82.21.11.50:1813 length 112 Fri Jan 27 17:29:49 2017 : Debug: (8815) User-Name = "mks298378" Fri Jan 27 17:29:49 2017 : Debug: (8815) NAS-IP-Address = 82.21.11.91 Fri Jan 27 17:29:49 2017 : Debug: (8815) NAS-Port = 2262 Fri Jan 27 17:29:49 2017 : Debug: (8815) Acct-Status-Type = Stop Fri Jan 27 17:29:49 2017 : Debug: (8815) Framed-IP-Address = 10.8.0.6 Fri Jan 27 17:29:49 2017 : Debug: (8815) Acct-Input-Gigawords = 0 Fri Jan 27 17:29:49 2017 : Debug: (8815) Acct-Input-Octets = 6953 Fri Jan 27 17:29:49 2017 : Debug: (8815) Acct-Output-Octets = 22971 Fri Jan 27 17:29:49 2017 : Debug: (8815) Acct-Session-Id = "741eo9p64vg7" Fri Jan 27 17:29:49 2017 : Debug: (8815) Acct-Output-Gigawords = 0 Fri Jan 27 17:29:49 2017 : Debug: (8815) Calling-Station-Id = "127.0.0.1" Fri Jan 27 17:29:49 2017 : Debug: (8815) # Executing section preacct from file /etc/freeradius/sites-enabled/default Fri Jan 27 17:29:49 2017 : Debug: (8815) preacct { Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[preacct]: calling preprocess (rlm_preprocess) Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[preacct]: returned from preprocess (rlm_preprocess) Fri Jan 27 17:29:49 2017 : Debug: (8815) [preprocess] = ok Fri Jan 27 17:29:49 2017 : Debug: (8815) policy acct_unique { Fri Jan 27 17:29:49 2017 : Debug: (8815) update request { Fri Jan 27 17:29:49 2017 : Debug: (8815) Tmp-String-9 := "ai:" Fri Jan 27 17:29:49 2017 : Debug: (8815) } # update request = noop Fri Jan 27 17:29:49 2017 : Debug: (8815) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { Fri Jan 27 17:29:49 2017 : Debug: (8815) EXPAND %{hex:&Class} Fri Jan 27 17:29:49 2017 : Debug: (8815) --> Fri Jan 27 17:29:49 2017 : Debug: (8815) EXPAND ^%{hex:&Tmp-String-9} Fri Jan 27 17:29:49 2017 : Debug: (8815) --> ^61693a Fri Jan 27 17:29:49 2017 : Debug: (8815) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE Fri Jan 27 17:29:49 2017 : Debug: (8815) else { Fri Jan 27 17:29:49 2017 : Debug: (8815) update request { Fri Jan 27 17:29:49 2017 : Debug: (8815) EXPAND %{md5:%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Fri Jan 27 17:29:49 2017 : Debug: (8815) --> fbe36847ca04d23d4793cf4f870837e8 Fri Jan 27 17:29:49 2017 : Debug: (8815) &Acct-Unique-Session-Id := fbe36847ca04d23d4793cf4f870837e8 Fri Jan 27 17:29:49 2017 : Debug: (8815) } # update request = noop Fri Jan 27 17:29:49 2017 : Debug: (8815) } # else = noop Fri Jan 27 17:29:49 2017 : Debug: (8815) } # policy acct_unique = noop Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[preacct]: calling suffix (rlm_realm) Fri Jan 27 17:29:49 2017 : Debug: (8815) suffix: Checking for suffix after "@" Fri Jan 27 17:29:49 2017 : Debug: (8815) suffix: No '@' in User-Name = "mks298378", looking up realm NULL Fri Jan 27 17:29:49 2017 : Debug: (8815) suffix: No such realm "NULL" Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[preacct]: returned from suffix (rlm_realm) Fri Jan 27 17:29:49 2017 : Debug: (8815) [suffix] = noop Fri Jan 27 17:29:49 2017 : Debug: (8815) } # preacct = ok Fri Jan 27 17:29:49 2017 : Debug: (8815) # Executing section accounting from file /etc/freeradius/sites-enabled/default Fri Jan 27 17:29:49 2017 : Debug: (8815) accounting { Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[accounting]: calling detail (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: /var/log/freeradius/radacct/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: literal --> /var/log/freeradius/radacct/detail- Fri Jan 27 17:29:49 2017 : Debug: percent --> Y Fri Jan 27 17:29:49 2017 : Debug: percent --> m Fri Jan 27 17:29:49 2017 : Debug: percent --> d Fri Jan 27 17:29:49 2017 : Debug: (8815) detail: EXPAND /var/log/freeradius/radacct/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: (8815) detail: --> /var/log/freeradius/radacct/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: (8815) detail: /var/log/freeradius/radacct/detail-%Y%m%d expands to /var/log/freeradius/radacct/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: %t Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: percent --> t Fri Jan 27 17:29:49 2017 : Debug: (8815) detail: EXPAND %t Fri Jan 27 17:29:49 2017 : Debug: (8815) detail: --> Fri Jan 27 17:29:49 2017 Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[accounting]: returned from detail (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: (8815) [detail] = ok Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[accounting]: calling detail2 (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: literal --> /var/log/freeradius/radacct/debug/ Fri Jan 27 17:29:49 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:49 2017 : Debug: attribute --> Packet-Src-IP-Address Fri Jan 27 17:29:49 2017 : Debug: } Fri Jan 27 17:29:49 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:49 2017 : Debug: attribute --> Packet-Src-IPv6-Address Fri Jan 27 17:29:49 2017 : Debug: } Fri Jan 27 17:29:49 2017 : Debug: literal --> /detail- Fri Jan 27 17:29:49 2017 : Debug: percent --> Y Fri Jan 27 17:29:49 2017 : Debug: percent --> m Fri Jan 27 17:29:49 2017 : Debug: percent --> d Fri Jan 27 17:29:49 2017 : Debug: (8815) detail2: EXPAND /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: (8815) detail2: --> /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: (8815) 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-20170127 Fri Jan 27 17:29:49 2017 : Debug: %t Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: percent --> t Fri Jan 27 17:29:49 2017 : Debug: (8815) detail2: EXPAND %t Fri Jan 27 17:29:49 2017 : Debug: (8815) detail2: --> Fri Jan 27 17:29:49 2017 Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[accounting]: returned from detail2 (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: (8815) [detail2] = ok Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[accounting]: calling exec (rlm_exec) Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[accounting]: returned from exec (rlm_exec) Fri Jan 27 17:29:49 2017 : Debug: (8815) [exec] = noop Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) Fri Jan 27 17:29:49 2017 : Debug: %{User-Name} Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: attribute --> User-Name Fri Jan 27 17:29:49 2017 : Debug: (8815) attr_filter.accounting_response: EXPAND %{User-Name} Fri Jan 27 17:29:49 2017 : Debug: (8815) attr_filter.accounting_response: --> mks298378 Fri Jan 27 17:29:49 2017 : Debug: (8815) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Fri Jan 27 17:29:49 2017 : Debug: (8815) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) Fri Jan 27 17:29:49 2017 : Debug: (8815) [attr_filter.accounting_response] = updated Fri Jan 27 17:29:49 2017 : Debug: (8815) } # accounting = updated Fri Jan 27 17:29:49 2017 : Debug: (8815) Sent Accounting-Response Id 79 from 82.21.11.50:1813 to 82.21.11.91:59683 length 0 Fri Jan 27 17:29:49 2017 : Debug: (8815) Finished request Fri Jan 27 17:29:49 2017 : Debug: (8815) Cleaning up request packet ID 79 with timestamp +3713 Fri Jan 27 17:29:49 2017 : Info: Ready to process requests Fri Jan 27 17:29:49 2017 : Debug: (8816) Received Accounting-Request Id 80 from 82.21.11.91:50849 to 82.21.11.50:1813 length 107 Fri Jan 27 17:29:49 2017 : Debug: (8816) User-Name = "mks398047" Fri Jan 27 17:29:49 2017 : Debug: (8816) NAS-IP-Address = 82.21.11.91 Fri Jan 27 17:29:49 2017 : Debug: (8816) NAS-Port = 2260 Fri Jan 27 17:29:49 2017 : Debug: (8816) Acct-Status-Type = Stop Fri Jan 27 17:29:49 2017 : Debug: (8816) Framed-IP-Address = 10.8.1.234 Fri Jan 27 17:29:49 2017 : Debug: (8816) Acct-Input-Gigawords = 0 Fri Jan 27 17:29:49 2017 : Debug: (8816) Acct-Input-Octets = 76679 Fri Jan 27 17:29:49 2017 : Debug: (8816) Acct-Output-Octets = 365994 Fri Jan 27 17:29:49 2017 : Debug: (8816) Acct-Session-Id = "fyb3b1d7u066" Fri Jan 27 17:29:49 2017 : Debug: (8816) Acct-Output-Gigawords = 0 Fri Jan 27 17:29:49 2017 : Debug: (8816) Calling-Station-Id = "127.0.0.1" Fri Jan 27 17:29:49 2017 : Debug: (8816) # Executing section preacct from file /etc/freeradius/sites-enabled/default Fri Jan 27 17:29:49 2017 : Debug: (8816) preacct { Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[preacct]: calling preprocess (rlm_preprocess) Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[preacct]: returned from preprocess (rlm_preprocess) Fri Jan 27 17:29:49 2017 : Debug: (8816) [preprocess] = ok Fri Jan 27 17:29:49 2017 : Debug: (8816) policy acct_unique { Fri Jan 27 17:29:49 2017 : Debug: (8816) update request { Fri Jan 27 17:29:49 2017 : Debug: (8816) Tmp-String-9 := "ai:" Fri Jan 27 17:29:49 2017 : Debug: (8816) } # update request = noop Fri Jan 27 17:29:49 2017 : Debug: (8816) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { Fri Jan 27 17:29:49 2017 : Debug: (8816) EXPAND %{hex:&Class} Fri Jan 27 17:29:49 2017 : Debug: (8816) --> Fri Jan 27 17:29:49 2017 : Debug: (8816) EXPAND ^%{hex:&Tmp-String-9} Fri Jan 27 17:29:49 2017 : Debug: (8816) --> ^61693a Fri Jan 27 17:29:49 2017 : Debug: (8816) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE Fri Jan 27 17:29:49 2017 : Debug: (8816) else { Fri Jan 27 17:29:49 2017 : Debug: (8816) update request { Fri Jan 27 17:29:49 2017 : Debug: (8816) EXPAND %{md5:%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Fri Jan 27 17:29:49 2017 : Debug: (8816) --> af229b95e3b342182f30c08f717c6e99 Fri Jan 27 17:29:49 2017 : Debug: (8816) &Acct-Unique-Session-Id := af229b95e3b342182f30c08f717c6e99 Fri Jan 27 17:29:49 2017 : Debug: (8816) } # update request = noop Fri Jan 27 17:29:49 2017 : Debug: (8816) } # else = noop Fri Jan 27 17:29:49 2017 : Debug: (8816) } # policy acct_unique = noop Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[preacct]: calling suffix (rlm_realm) Fri Jan 27 17:29:49 2017 : Debug: (8816) suffix: Checking for suffix after "@" Fri Jan 27 17:29:49 2017 : Debug: (8816) suffix: No '@' in User-Name = "mks398047", looking up realm NULL Fri Jan 27 17:29:49 2017 : Debug: (8816) suffix: No such realm "NULL" Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[preacct]: returned from suffix (rlm_realm) Fri Jan 27 17:29:49 2017 : Debug: (8816) [suffix] = noop Fri Jan 27 17:29:49 2017 : Debug: (8816) } # preacct = ok Fri Jan 27 17:29:49 2017 : Debug: (8816) # Executing section accounting from file /etc/freeradius/sites-enabled/default Fri Jan 27 17:29:49 2017 : Debug: (8816) accounting { Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[accounting]: calling detail (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: /var/log/freeradius/radacct/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: literal --> /var/log/freeradius/radacct/detail- Fri Jan 27 17:29:49 2017 : Debug: percent --> Y Fri Jan 27 17:29:49 2017 : Debug: percent --> m Fri Jan 27 17:29:49 2017 : Debug: percent --> d Fri Jan 27 17:29:49 2017 : Debug: (8816) detail: EXPAND /var/log/freeradius/radacct/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: (8816) detail: --> /var/log/freeradius/radacct/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: (8816) detail: /var/log/freeradius/radacct/detail-%Y%m%d expands to /var/log/freeradius/radacct/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: %t Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: percent --> t Fri Jan 27 17:29:49 2017 : Debug: (8816) detail: EXPAND %t Fri Jan 27 17:29:49 2017 : Debug: (8816) detail: --> Fri Jan 27 17:29:49 2017 Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[accounting]: returned from detail (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: (8816) [detail] = ok Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[accounting]: calling detail2 (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: literal --> /var/log/freeradius/radacct/debug/ Fri Jan 27 17:29:49 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:49 2017 : Debug: attribute --> Packet-Src-IP-Address Fri Jan 27 17:29:49 2017 : Debug: } Fri Jan 27 17:29:49 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:49 2017 : Debug: attribute --> Packet-Src-IPv6-Address Fri Jan 27 17:29:49 2017 : Debug: } Fri Jan 27 17:29:49 2017 : Debug: literal --> /detail- Fri Jan 27 17:29:49 2017 : Debug: percent --> Y Fri Jan 27 17:29:49 2017 : Debug: percent --> m Fri Jan 27 17:29:49 2017 : Debug: percent --> d Fri Jan 27 17:29:49 2017 : Debug: (8816) detail2: EXPAND /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: (8816) detail2: --> /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: (8816) 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-20170127 Fri Jan 27 17:29:49 2017 : Debug: %t Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: percent --> t Fri Jan 27 17:29:49 2017 : Debug: (8816) detail2: EXPAND %t Fri Jan 27 17:29:49 2017 : Debug: (8816) detail2: --> Fri Jan 27 17:29:49 2017 Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[accounting]: returned from detail2 (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: (8816) [detail2] = ok Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[accounting]: calling exec (rlm_exec) Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[accounting]: returned from exec (rlm_exec) Fri Jan 27 17:29:49 2017 : Debug: (8816) [exec] = noop Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) Fri Jan 27 17:29:49 2017 : Debug: %{User-Name} Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: attribute --> User-Name Fri Jan 27 17:29:49 2017 : Debug: (8816) attr_filter.accounting_response: EXPAND %{User-Name} Fri Jan 27 17:29:49 2017 : Debug: (8816) attr_filter.accounting_response: --> mks398047 Fri Jan 27 17:29:49 2017 : Debug: (8816) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Fri Jan 27 17:29:49 2017 : Debug: (8816) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) Fri Jan 27 17:29:49 2017 : Debug: (8816) [attr_filter.accounting_response] = updated Fri Jan 27 17:29:49 2017 : Debug: (8816) } # accounting = updated Fri Jan 27 17:29:49 2017 : Debug: (8816) Sent Accounting-Response Id 80 from 82.21.11.50:1813 to 82.21.11.91:50849 length 0 Fri Jan 27 17:29:49 2017 : Debug: (8816) Finished request Fri Jan 27 17:29:49 2017 : Debug: (8816) Cleaning up request packet ID 80 with timestamp +3713 Fri Jan 27 17:29:49 2017 : Info: Ready to process requests Fri Jan 27 17:29:49 2017 : Debug: (8817) Received Accounting-Request Id 81 from 82.21.11.91:22103 to 82.21.11.50:1813 length 83 Fri Jan 27 17:29:49 2017 : Debug: (8817) User-Name = "mks497257" Fri Jan 27 17:29:49 2017 : Debug: (8817) NAS-IP-Address = 82.21.11.91 Fri Jan 27 17:29:49 2017 : Debug: (8817) NAS-Port = 2274 Fri Jan 27 17:29:49 2017 : Debug: (8817) Acct-Status-Type = Start Fri Jan 27 17:29:49 2017 : Debug: (8817) Framed-IP-Address = 10.8.1.198 Fri Jan 27 17:29:49 2017 : Debug: (8817) Acct-Session-Id = "uejr8nr0c3px" Fri Jan 27 17:29:49 2017 : Debug: (8817) Calling-Station-Id = "127.0.0.1" Fri Jan 27 17:29:49 2017 : Debug: (8817) # Executing section preacct from file /etc/freeradius/sites-enabled/default Fri Jan 27 17:29:49 2017 : Debug: (8817) preacct { Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[preacct]: calling preprocess (rlm_preprocess) Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[preacct]: returned from preprocess (rlm_preprocess) Fri Jan 27 17:29:49 2017 : Debug: (8817) [preprocess] = ok Fri Jan 27 17:29:49 2017 : Debug: (8817) policy acct_unique { Fri Jan 27 17:29:49 2017 : Debug: (8817) update request { Fri Jan 27 17:29:49 2017 : Debug: (8817) Tmp-String-9 := "ai:" Fri Jan 27 17:29:49 2017 : Debug: (8817) } # update request = noop Fri Jan 27 17:29:49 2017 : Debug: (8817) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { Fri Jan 27 17:29:49 2017 : Debug: (8817) EXPAND %{hex:&Class} Fri Jan 27 17:29:49 2017 : Debug: (8817) --> Fri Jan 27 17:29:49 2017 : Debug: (8817) EXPAND ^%{hex:&Tmp-String-9} Fri Jan 27 17:29:49 2017 : Debug: (8817) --> ^61693a Fri Jan 27 17:29:49 2017 : Debug: (8817) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE Fri Jan 27 17:29:49 2017 : Debug: (8817) else { Fri Jan 27 17:29:49 2017 : Debug: (8817) update request { Fri Jan 27 17:29:49 2017 : Debug: (8817) EXPAND %{md5:%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Fri Jan 27 17:29:49 2017 : Debug: (8817) --> 98530cbbe2100dbda1ba0e93e35e2765 Fri Jan 27 17:29:49 2017 : Debug: (8817) &Acct-Unique-Session-Id := 98530cbbe2100dbda1ba0e93e35e2765 Fri Jan 27 17:29:49 2017 : Debug: (8817) } # update request = noop Fri Jan 27 17:29:49 2017 : Debug: (8817) } # else = noop Fri Jan 27 17:29:49 2017 : Debug: (8817) } # policy acct_unique = noop Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[preacct]: calling suffix (rlm_realm) Fri Jan 27 17:29:49 2017 : Debug: (8817) suffix: Checking for suffix after "@" Fri Jan 27 17:29:49 2017 : Debug: (8817) suffix: No '@' in User-Name = "mks497257", looking up realm NULL Fri Jan 27 17:29:49 2017 : Debug: (8817) suffix: No such realm "NULL" Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[preacct]: returned from suffix (rlm_realm) Fri Jan 27 17:29:49 2017 : Debug: (8817) [suffix] = noop Fri Jan 27 17:29:49 2017 : Debug: (8817) } # preacct = ok Fri Jan 27 17:29:49 2017 : Debug: (8817) # Executing section accounting from file /etc/freeradius/sites-enabled/default Fri Jan 27 17:29:49 2017 : Debug: (8817) accounting { Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[accounting]: calling detail (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: /var/log/freeradius/radacct/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: literal --> /var/log/freeradius/radacct/detail- Fri Jan 27 17:29:49 2017 : Debug: percent --> Y Fri Jan 27 17:29:49 2017 : Debug: percent --> m Fri Jan 27 17:29:49 2017 : Debug: percent --> d Fri Jan 27 17:29:49 2017 : Debug: (8817) detail: EXPAND /var/log/freeradius/radacct/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: (8817) detail: --> /var/log/freeradius/radacct/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: (8817) detail: /var/log/freeradius/radacct/detail-%Y%m%d expands to /var/log/freeradius/radacct/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: %t Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: percent --> t Fri Jan 27 17:29:49 2017 : Debug: (8817) detail: EXPAND %t Fri Jan 27 17:29:49 2017 : Debug: (8817) detail: --> Fri Jan 27 17:29:49 2017 Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[accounting]: returned from detail (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: (8817) [detail] = ok Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[accounting]: calling detail2 (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: literal --> /var/log/freeradius/radacct/debug/ Fri Jan 27 17:29:49 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:49 2017 : Debug: attribute --> Packet-Src-IP-Address Fri Jan 27 17:29:49 2017 : Debug: } Fri Jan 27 17:29:49 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:49 2017 : Debug: attribute --> Packet-Src-IPv6-Address Fri Jan 27 17:29:49 2017 : Debug: } Fri Jan 27 17:29:49 2017 : Debug: literal --> /detail- Fri Jan 27 17:29:49 2017 : Debug: percent --> Y Fri Jan 27 17:29:49 2017 : Debug: percent --> m Fri Jan 27 17:29:49 2017 : Debug: percent --> d Fri Jan 27 17:29:49 2017 : Debug: (8817) detail2: EXPAND /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Fri Jan 27 17:29:49 2017 : Debug: (8817) detail2: --> /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170127 Fri Jan 27 17:29:49 2017 : Debug: (8817) 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-20170127 Fri Jan 27 17:29:49 2017 : Debug: %t Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: percent --> t Fri Jan 27 17:29:49 2017 : Debug: (8817) detail2: EXPAND %t Fri Jan 27 17:29:49 2017 : Debug: (8817) detail2: --> Fri Jan 27 17:29:49 2017 Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[accounting]: returned from detail2 (rlm_detail) Fri Jan 27 17:29:49 2017 : Debug: (8817) [detail2] = ok Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[accounting]: calling exec (rlm_exec) Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[accounting]: returned from exec (rlm_exec) Fri Jan 27 17:29:49 2017 : Debug: (8817) [exec] = noop Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) Fri Jan 27 17:29:49 2017 : Debug: %{User-Name} Fri Jan 27 17:29:49 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:49 2017 : Debug: attribute --> User-Name Fri Jan 27 17:29:49 2017 : Debug: (8817) attr_filter.accounting_response: EXPAND %{User-Name} Fri Jan 27 17:29:49 2017 : Debug: (8817) attr_filter.accounting_response: --> mks497257 Fri Jan 27 17:29:49 2017 : Debug: (8817) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Fri Jan 27 17:29:49 2017 : Debug: (8817) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) Fri Jan 27 17:29:49 2017 : Debug: (8817) [attr_filter.accounting_response] = updated Fri Jan 27 17:29:49 2017 : Debug: (8817) } # accounting = updated Fri Jan 27 17:29:49 2017 : Debug: (8817) Sent Accounting-Response Id 81 from 82.21.11.50:1813 to 82.21.11.91:22103 length 0 Fri Jan 27 17:29:49 2017 : Debug: (8817) Finished request Fri Jan 27 17:29:49 2017 : Debug: (8817) Cleaning up request packet ID 81 with timestamp +3713 Fri Jan 27 17:29:49 2017 : Info: Ready to process requests Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Renaming /var/log/freeradius/radacct/detail-20170127 -> /var/log/freeradius/radacct/detail.work Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - User-Name = "mks298378" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - NAS-IP-Address = 82.21.11.91 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - NAS-Port = 2262 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Status-Type = Stop Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Framed-IP-Address = 10.8.0.6 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Input-Gigawords = 0 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Input-Octets = 6953 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Output-Octets = 22971 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Session-Id = "741eo9p64vg7" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Output-Gigawords = 0 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Calling-Station-Id = "127.0.0.1" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Event-Timestamp = "Jan 27 2017 17:29:49 GMT" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Tmp-String-9 = "ai:" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Unique-Session-Id = "fbe36847ca04d23d4793cf4f870837e8" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Read packet from /var/log/freeradius/radacct/detail.work Fri Jan 27 17:29:50 2017 : Debug: (8818) Empty preacct section in virtual server "buffered-sql". Using default return values. Fri Jan 27 17:29:50 2017 : Debug: (8818) # Executing section accounting from file /etc/freeradius/sites-enabled/buffered-sql Fri Jan 27 17:29:50 2017 : Debug: (8818) accounting { Fri Jan 27 17:29:50 2017 : Debug: (8818) modsingle[accounting]: calling sql (rlm_sql) Fri Jan 27 17:29:50 2017 : Debug: %{tolower:type.%{Acct-Status-Type}.query} Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: xlat --> tolower Fri Jan 27 17:29:50 2017 : Debug: { Fri Jan 27 17:29:50 2017 : Debug: literal --> type. Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Status-Type Fri Jan 27 17:29:50 2017 : Debug: literal --> .query Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: --> type.stop.query Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: Using query template 'query' Fri Jan 27 17:29:50 2017 : Debug: rlm_sql (sql): Reserved connection (1) Fri Jan 27 17:29:50 2017 : Debug: %{User-Name} Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: attribute --> User-Name Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: EXPAND %{User-Name} Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: --> mks298378 Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: SQL-User-Name set to 'mks298378' Fri Jan 27 17:29:50 2017 : Debug: 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(), '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Framed-IP-Address}') Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: literal --> INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES (' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Session-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Unique-Session-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', Fri Jan 27 17:29:50 2017 : Debug: xlat --> integer Fri Jan 27 17:29:50 2017 : Debug: { Fri Jan 27 17:29:50 2017 : Debug: literal --> Acct-Status-Type Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> , lower(trim(' Fri Jan 27 17:29:50 2017 : Debug: attribute --> SQL-User-Name Fri Jan 27 17:29:50 2017 : Debug: literal --> ')), ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Called-Station-Id Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-IP-Address Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-Port-Id Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-Port Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', NOW(), ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Input-Gigawords Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: literal --> 0 Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ' << 32 | ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Input-Octets Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: literal --> 0 Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Output-Gigawords Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: literal --> 0 Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ' << 32 | ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Output-Octets Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: literal --> 0 Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Called-Station-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Calling-Station-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Terminate-Cause Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Framed-IP-Address Fri Jan 27 17:29:50 2017 : Debug: literal --> ') Fri Jan 27 17:29:50 2017 : Debug: (8818) 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(), '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Framed-IP-Address}') Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: --> INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('741eo9p64vg7', 'fbe36847ca04d23d4793cf4f870837e8', 2, lower(trim('mks298378')), '82.21.11.91', '2262', NOW(), '0' << 32 | '6953', '0' << 32 | '22971', '', '127.0.0.1', '', '10.8.0.6') Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: Executing query: INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('741eo9p64vg7', 'fbe36847ca04d23d4793cf4f870837e8', 2, lower(trim('mks298378')), '82.21.11.91', '2262', NOW(), '0' << 32 | '6953', '0' << 32 | '22971', '', '127.0.0.1', '', '10.8.0.6') Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: SQL query returned: success Fri Jan 27 17:29:50 2017 : Debug: (8818) sql: 1 record(s) updated Fri Jan 27 17:29:50 2017 : Debug: rlm_sql (sql): Released connection (1) Fri Jan 27 17:29:50 2017 : Debug: (8818) modsingle[accounting]: returned from sql (rlm_sql) Fri Jan 27 17:29:50 2017 : Debug: (8818) [sql] = ok Fri Jan 27 17:29:50 2017 : Debug: (8818) } # accounting = ok Fri Jan 27 17:29:50 2017 : Debug: (8818) detail (/var/log/freeradius/radacct/detail-*): Done Accounting-Request packet. Fri Jan 27 17:29:50 2017 : Debug: (8818) detail (/var/log/freeradius/radacct/detail-*): Received response for request 8818. Will read the next packet in 0 seconds Fri Jan 27 17:29:50 2017 : Debug: (8818) Finished request Fri Jan 27 17:29:50 2017 : Debug: (8818) Cleaning up request packet ID 47 with timestamp +3714 Fri Jan 27 17:29:50 2017 : Info: Ready to process requests Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - User-Name = "mks398047" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - NAS-IP-Address = 82.21.11.91 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - NAS-Port = 2260 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Status-Type = Stop Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Framed-IP-Address = 10.8.1.234 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Input-Gigawords = 0 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Input-Octets = 76679 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Output-Octets = 365994 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Session-Id = "fyb3b1d7u066" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Output-Gigawords = 0 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Calling-Station-Id = "127.0.0.1" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Event-Timestamp = "Jan 27 2017 17:29:49 GMT" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Tmp-String-9 = "ai:" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Unique-Session-Id = "af229b95e3b342182f30c08f717c6e99" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Read packet from /var/log/freeradius/radacct/detail.work Fri Jan 27 17:29:50 2017 : Debug: (8819) Empty preacct section in virtual server "buffered-sql". Using default return values. Fri Jan 27 17:29:50 2017 : Debug: (8819) # Executing section accounting from file /etc/freeradius/sites-enabled/buffered-sql Fri Jan 27 17:29:50 2017 : Debug: (8819) accounting { Fri Jan 27 17:29:50 2017 : Debug: (8819) modsingle[accounting]: calling sql (rlm_sql) Fri Jan 27 17:29:50 2017 : Debug: %{tolower:type.%{Acct-Status-Type}.query} Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: xlat --> tolower Fri Jan 27 17:29:50 2017 : Debug: { Fri Jan 27 17:29:50 2017 : Debug: literal --> type. Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Status-Type Fri Jan 27 17:29:50 2017 : Debug: literal --> .query Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: --> type.stop.query Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: Using query template 'query' Fri Jan 27 17:29:50 2017 : Debug: rlm_sql (sql): Reserved connection (8) Fri Jan 27 17:29:50 2017 : Debug: %{User-Name} Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: attribute --> User-Name Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: EXPAND %{User-Name} Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: --> mks398047 Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: SQL-User-Name set to 'mks398047' Fri Jan 27 17:29:50 2017 : Debug: 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(), '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Framed-IP-Address}') Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: literal --> INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES (' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Session-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Unique-Session-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', Fri Jan 27 17:29:50 2017 : Debug: xlat --> integer Fri Jan 27 17:29:50 2017 : Debug: { Fri Jan 27 17:29:50 2017 : Debug: literal --> Acct-Status-Type Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> , lower(trim(' Fri Jan 27 17:29:50 2017 : Debug: attribute --> SQL-User-Name Fri Jan 27 17:29:50 2017 : Debug: literal --> ')), ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Called-Station-Id Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-IP-Address Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-Port-Id Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-Port Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', NOW(), ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Input-Gigawords Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: literal --> 0 Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ' << 32 | ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Input-Octets Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: literal --> 0 Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Output-Gigawords Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: literal --> 0 Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ' << 32 | ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Output-Octets Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: literal --> 0 Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Called-Station-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Calling-Station-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Terminate-Cause Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Framed-IP-Address Fri Jan 27 17:29:50 2017 : Debug: literal --> ') Fri Jan 27 17:29:50 2017 : Debug: (8819) 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(), '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Framed-IP-Address}') Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: --> INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('fyb3b1d7u066', 'af229b95e3b342182f30c08f717c6e99', 2, lower(trim('mks398047')), '82.21.11.91', '2260', NOW(), '0' << 32 | '76679', '0' << 32 | '365994', '', '127.0.0.1', '', '10.8.1.234') Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: Executing query: INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('fyb3b1d7u066', 'af229b95e3b342182f30c08f717c6e99', 2, lower(trim('mks398047')), '82.21.11.91', '2260', NOW(), '0' << 32 | '76679', '0' << 32 | '365994', '', '127.0.0.1', '', '10.8.1.234') Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: SQL query returned: success Fri Jan 27 17:29:50 2017 : Debug: (8819) sql: 1 record(s) updated Fri Jan 27 17:29:50 2017 : Debug: rlm_sql (sql): Released connection (8) Fri Jan 27 17:29:50 2017 : Debug: (8819) modsingle[accounting]: returned from sql (rlm_sql) Fri Jan 27 17:29:50 2017 : Debug: (8819) [sql] = ok Fri Jan 27 17:29:50 2017 : Debug: (8819) } # accounting = ok Fri Jan 27 17:29:50 2017 : Debug: (8819) detail (/var/log/freeradius/radacct/detail-*): Done Accounting-Request packet. Fri Jan 27 17:29:50 2017 : Debug: (8819) detail (/var/log/freeradius/radacct/detail-*): Received response for request 8819. Will read the next packet in 0 seconds Fri Jan 27 17:29:50 2017 : Debug: (8819) Finished request Fri Jan 27 17:29:50 2017 : Debug: (8819) Cleaning up request packet ID 48 with timestamp +3714 Fri Jan 27 17:29:50 2017 : Info: Ready to process requests Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - User-Name = "mks497257" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - NAS-IP-Address = 82.21.11.91 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - NAS-Port = 2274 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Status-Type = Start Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Framed-IP-Address = 10.8.1.198 Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Session-Id = "uejr8nr0c3px" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Calling-Station-Id = "127.0.0.1" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Event-Timestamp = "Jan 27 2017 17:29:49 GMT" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Tmp-String-9 = "ai:" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Trying to read VP from line - Acct-Unique-Session-Id = "98530cbbe2100dbda1ba0e93e35e2765" Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Read packet from /var/log/freeradius/radacct/detail.work Fri Jan 27 17:29:50 2017 : Debug: (8820) Empty preacct section in virtual server "buffered-sql". Using default return values. Fri Jan 27 17:29:50 2017 : Debug: (8820) # Executing section accounting from file /etc/freeradius/sites-enabled/buffered-sql Fri Jan 27 17:29:50 2017 : Debug: (8820) accounting { Fri Jan 27 17:29:50 2017 : Debug: (8820) modsingle[accounting]: calling sql (rlm_sql) Fri Jan 27 17:29:50 2017 : Debug: %{tolower:type.%{Acct-Status-Type}.query} Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: xlat --> tolower Fri Jan 27 17:29:50 2017 : Debug: { Fri Jan 27 17:29:50 2017 : Debug: literal --> type. Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Status-Type Fri Jan 27 17:29:50 2017 : Debug: literal --> .query Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: --> type.start.query Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: Using query template 'query' Fri Jan 27 17:29:50 2017 : Debug: rlm_sql (sql): Reserved connection (6) Fri Jan 27 17:29:50 2017 : Debug: %{User-Name} Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: attribute --> User-Name Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: EXPAND %{User-Name} Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: --> mks497257 Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: SQL-User-Name set to 'mks497257' Fri Jan 27 17:29:50 2017 : Debug: 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}') Fri Jan 27 17:29:50 2017 : Debug: Parsed xlat tree: Fri Jan 27 17:29:50 2017 : Debug: literal --> INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES (' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Session-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Acct-Unique-Session-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', Fri Jan 27 17:29:50 2017 : Debug: xlat --> integer Fri Jan 27 17:29:50 2017 : Debug: { Fri Jan 27 17:29:50 2017 : Debug: literal --> Acct-Status-Type Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> , lower(trim(' Fri Jan 27 17:29:50 2017 : Debug: attribute --> SQL-User-Name Fri Jan 27 17:29:50 2017 : Debug: literal --> ')), ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> Called-Station-Id Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-IP-Address Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: XLAT-IF { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-Port-Id Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: XLAT-ELSE { Fri Jan 27 17:29:50 2017 : Debug: attribute --> NAS-Port Fri Jan 27 17:29:50 2017 : Debug: } Fri Jan 27 17:29:50 2017 : Debug: literal --> ', NOW(), '0', '0', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Called-Station-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Calling-Station-Id Fri Jan 27 17:29:50 2017 : Debug: literal --> ', '', ' Fri Jan 27 17:29:50 2017 : Debug: attribute --> Framed-IP-Address Fri Jan 27 17:29:50 2017 : Debug: literal --> ') Fri Jan 27 17:29:50 2017 : Debug: (8820) 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}') Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: --> INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('uejr8nr0c3px', '98530cbbe2100dbda1ba0e93e35e2765', 1, lower(trim('mks497257')), '82.21.11.91', '2274', NOW(), '0', '0', '', '127.0.0.1', '', '10.8.1.198') Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: Executing query: INSERT INTO radcalls (acctsessionid, acctuniqueid, acctstatus, username, nasipaddress, nasportid, calltime, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, framedipaddress) VALUES ('uejr8nr0c3px', '98530cbbe2100dbda1ba0e93e35e2765', 1, lower(trim('mks497257')), '82.21.11.91', '2274', NOW(), '0', '0', '', '127.0.0.1', '', '10.8.1.198') Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: SQL query returned: success Fri Jan 27 17:29:50 2017 : Debug: (8820) sql: 1 record(s) updated Fri Jan 27 17:29:50 2017 : Debug: rlm_sql (sql): Released connection (6) Fri Jan 27 17:29:50 2017 : Debug: (8820) modsingle[accounting]: returned from sql (rlm_sql) Fri Jan 27 17:29:50 2017 : Debug: (8820) [sql] = ok Fri Jan 27 17:29:50 2017 : Debug: (8820) } # accounting = ok Fri Jan 27 17:29:50 2017 : Debug: (8820) detail (/var/log/freeradius/radacct/detail-*): Done Accounting-Request packet. Fri Jan 27 17:29:50 2017 : Debug: (8820) detail (/var/log/freeradius/radacct/detail-*): Received response for request 8820. Will read the next packet in 0 seconds Fri Jan 27 17:29:50 2017 : Debug: (8820) Finished request Fri Jan 27 17:29:50 2017 : Debug: (8820) Cleaning up request packet ID 49 with timestamp +3714 Fri Jan 27 17:29:50 2017 : Info: Ready to process requests Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Unlinking /var/log/freeradius/radacct/detail.work Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Fri Jan 27 17:29:50 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Detail listener state unopened waiting 1.125527 sec
On Jan 27, 2017, at 12:47 PM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
I installed the latest version from 3.0 branch and here is the logs for another occurrence. user 'mks779292' never queried and saved into database. I also noticed most (or all?) of these happen for stop request following the same user's start request in less than 10 seconds.
Well, I'm not sure what's happening. I've never seen that. I'd suggest editing the source and/or config to make a backup of the "detail" file every time it writes a user. You can then feed each detail file to the reader, to see which packets aren't read. There's really no magic here. If a user 'mks779292' is written to the detail file, then it should be written to the detail file. The only way for that user to *not* appear in the detail file is if the OS is lying to the server, and not writing the data. You might also try changing the detail filename to %Y%m%d%H%e which creates detail files for each second. Alan DeKok.
I'd suggest editing the source and/or config to make a backup of the "detail" file every time it writes a user. You can then feed each detail file to the reader, to see which packets aren't read.
that was why I used detail module twice. in the second detail file the packet is logged successfully. I am not familiar with C and might ask somebody else do it. how can I do backup thing with config?
You might also try changing the detail filename to %Y%m%d%H%e which creates detail files for each second.
I didn't understand the point of this. all those files are deleted as soon as they are read by buffered-sql I was also wondering why this procedure is writing/reading to/from disk instead of memory?
On Fri, Jan 27, 2017 at 10:17:07PM +0000, Jouni Soini via Freeradius-Users wrote:
I was also wondering why this procedure is writing/reading to/from disk instead of memory?
What happens if FreeRADIUS stops or is restarted between receiving (and acknowledging) the accounting packet, and writing it to the database? Matthew -- Matthew Newton, Ph.D. <mcn4@leicester.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
Well, I'm not sure what's happening. I've never seen that.
I'd suggest editing the source and/or config to make a backup of the "detail" file every time it writes a user. You can then feed each detail file to the reader, to see which packets aren't read.
I was hoping you help fix this issue. when I switch to direct sql module, it works fine. so there is definitely some issue with buffered-sql
On Jan 30, 2017, at 9:46 AM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
I was hoping you help fix this issue.
I can't magically reach into your system and figure out what's wrong. This open source software. If you don't care enough to track down bugs that affect you, then I don't care about those bugs, either.
when I switch to direct sql module, it works fine. so there is definitely some issue with buffered-sql
If only there was some way to track down the problem and fix it. Oh well. You've made it clear that you're not interested in doing that. So I'm not interested either. Alan DeKok.
I can't magically reach into your system and figure out what's wrong.
This open source software. If you don't care enough to track down bugs that affect you, then I don't care about those bugs, either.
I installed the latest v3.0.x branch and sent all debug logs as you requested I even tried logging in seconds without any luck. you said something about changing config to make copy of each detail file but didn't explain much.
I asked a C developer to change source and backup detail.work file right before deleting. I noticed the skipped packets are already there in detail.work file, but they are not being read by buffered-sql module and then are deleted. developer also added a new debug line which is "Backup to mybackup.log". this line is always shown right before "Unlinking /var/log/freeradius/radacct/detail.work" except in the skipped packets which are shown before or while receiving accounting request. following is the debug for a packet which is not read from detail.work. Wed Feb 1 15:28:40 2017 : Debug: (35371) Received Accounting-Request Id 13 from 82.21.11.91:28342 to 82.21.11.50:1813 length 108 Wed Feb 1 15:28:40 2017 : Debug: (35371) User-Name = "mks539293" Wed Feb 1 15:28:40 2017 : Debug: (35371) NAS-IP-Address = 82.21.11.91 Wed Feb 1 15:28:40 2017 : Debug: (35371) NAS-Port = 8884 Wed Feb 1 15:28:40 2017 : Debug: (35371) Acct-Status-Type = Stop Wed Feb 1 15:28:40 2017 : Debug: (35371) Framed-IP-Address = 10.8.0.62 Wed Feb 1 15:28:40 2017 : Debug: (35371) Acct-Input-Gigawords = 0 Wed Feb 1 15:28:40 2017 : Debug: (35371) Acct-Input-Octets = 25093 Wed Feb 1 15:28:40 2017 : Debug: (35371) Acct-Output-Octets = 40276 Wed Feb 1 15:28:40 2017 : Debug: (35371) Acct-Session-Id = "daivfc6wehcv" Wed Feb 1 15:28:40 2017 : Debug: (35371) Acct-Output-Gigawords = 0 Wed Feb 1 15:28:40 2017 : Debug: (35371) Calling-Station-Id = "88.230.19.102" Wed Feb 1 15:28:40 2017 : Debug: (35371) # Executing section preacct from file /etc/freeradius/sites-enabled/default Wed Feb 1 15:28:40 2017 : Debug: (35371) preacct { Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[preacct]: calling preprocess (rlm_preprocess) Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[preacct]: returned from preprocess (rlm_preprocess) Wed Feb 1 15:28:40 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Backup to mybackup.log Wed Feb 1 15:28:40 2017 : Debug: (35371) [preprocess] = ok Wed Feb 1 15:28:40 2017 : Debug: (35371) policy acct_unique { Wed Feb 1 15:28:40 2017 : Debug: (35371) update request { Wed Feb 1 15:28:40 2017 : Debug: (35371) Tmp-String-9 := "ai:" Wed Feb 1 15:28:40 2017 : Debug: (35371) } # update request = noop Wed Feb 1 15:28:40 2017 : Debug: (35371) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { Wed Feb 1 15:28:40 2017 : Debug: (35371) EXPAND %{hex:&Class} Wed Feb 1 15:28:40 2017 : Debug: (35371) --> Wed Feb 1 15:28:40 2017 : Debug: (35371) EXPAND ^%{hex:&Tmp-String-9} Wed Feb 1 15:28:40 2017 : Debug: (35371) --> ^61693a Wed Feb 1 15:28:40 2017 : Debug: (35371) if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE Wed Feb 1 15:28:40 2017 : Debug: (35371) else { Wed Feb 1 15:28:40 2017 : Debug: (35371) update request { Wed Feb 1 15:28:40 2017 : Debug: (35371) EXPAND %{md5:%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Wed Feb 1 15:28:40 2017 : Debug: (35371) --> fcc3dd2a5b00a62e7d6fc0b5f35316a4 Wed Feb 1 15:28:40 2017 : Debug: (35371) &Acct-Unique-Session-Id := fcc3dd2a5b00a62e7d6fc0b5f35316a4 Wed Feb 1 15:28:40 2017 : Debug: (35371) } # update request = noop Wed Feb 1 15:28:40 2017 : Debug: (35371) } # else = noop Wed Feb 1 15:28:40 2017 : Debug: (35371) } # policy acct_unique = noop Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[preacct]: calling suffix (rlm_realm) Wed Feb 1 15:28:40 2017 : Debug: (35371) suffix: Checking for suffix after "@" Wed Feb 1 15:28:40 2017 : Debug: (35371) suffix: No '@' in User-Name = "mks539293", looking up realm NULL Wed Feb 1 15:28:40 2017 : Debug: (35371) suffix: No such realm "NULL" Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[preacct]: returned from suffix (rlm_realm) Wed Feb 1 15:28:40 2017 : Debug: (35371) [suffix] = noop Wed Feb 1 15:28:40 2017 : Debug: (35371) } # preacct = ok Wed Feb 1 15:28:40 2017 : Debug: (35371) # Executing section accounting from file /etc/freeradius/sites-enabled/default Wed Feb 1 15:28:40 2017 : Debug: (35371) accounting { Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[accounting]: calling detail (rlm_detail) Wed Feb 1 15:28:40 2017 : Debug: /var/log/freeradius/radacct/detail-%S Wed Feb 1 15:28:40 2017 : Debug: Parsed xlat tree: Wed Feb 1 15:28:40 2017 : Debug: literal --> /var/log/freeradius/radacct/detail- Wed Feb 1 15:28:40 2017 : Debug: percent --> S Wed Feb 1 15:28:40 2017 : Debug: (35371) detail: EXPAND /var/log/freeradius/radacct/detail-%S Wed Feb 1 15:28:40 2017 : Debug: (35371) detail: --> /var/log/freeradius/radacct/detail-2017-02-01 15:28:40 Wed Feb 1 15:28:40 2017 : Debug: (35371) detail: /var/log/freeradius/radacct/detail-%S expands to /var/log/freeradius/radacct/detail-2017-02-01 15:28:40 Wed Feb 1 15:28:40 2017 : Debug: %t Wed Feb 1 15:28:40 2017 : Debug: Parsed xlat tree: Wed Feb 1 15:28:40 2017 : Debug: percent --> t Wed Feb 1 15:28:40 2017 : Debug: (35371) detail: EXPAND %t Wed Feb 1 15:28:40 2017 : Debug: (35371) detail: --> Wed Feb 1 15:28:40 2017 Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[accounting]: returned from detail (rlm_detail) Wed Feb 1 15:28:40 2017 : Debug: (35371) [detail] = ok Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[accounting]: calling detail2 (rlm_detail) Wed Feb 1 15:28:40 2017 : Debug: /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Wed Feb 1 15:28:40 2017 : Debug: Parsed xlat tree: Wed Feb 1 15:28:40 2017 : Debug: literal --> /var/log/freeradius/radacct/debug/ Wed Feb 1 15:28:40 2017 : Debug: XLAT-IF { Wed Feb 1 15:28:40 2017 : Debug: attribute --> Packet-Src-IP-Address Wed Feb 1 15:28:40 2017 : Debug: } Wed Feb 1 15:28:40 2017 : Debug: XLAT-ELSE { Wed Feb 1 15:28:40 2017 : Debug: attribute --> Packet-Src-IPv6-Address Wed Feb 1 15:28:40 2017 : Debug: } Wed Feb 1 15:28:40 2017 : Debug: literal --> /detail- Wed Feb 1 15:28:40 2017 : Debug: percent --> Y Wed Feb 1 15:28:40 2017 : Debug: percent --> m Wed Feb 1 15:28:40 2017 : Debug: percent --> d Wed Feb 1 15:28:40 2017 : Debug: (35371) detail2: EXPAND /var/log/freeradius/radacct/debug/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Wed Feb 1 15:28:40 2017 : Debug: (35371) detail2: --> /var/log/freeradius/radacct/debug/82.21.11.91/detail-20170201 Wed Feb 1 15:28:40 2017 : Debug: (35371) 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-20170201 Wed Feb 1 15:28:40 2017 : Debug: %t Wed Feb 1 15:28:40 2017 : Debug: Parsed xlat tree: Wed Feb 1 15:28:40 2017 : Debug: percent --> t Wed Feb 1 15:28:40 2017 : Debug: (35371) detail2: EXPAND %t Wed Feb 1 15:28:40 2017 : Debug: (35371) detail2: --> Wed Feb 1 15:28:40 2017 Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[accounting]: returned from detail2 (rlm_detail) Wed Feb 1 15:28:40 2017 : Debug: (35371) [detail2] = ok Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[accounting]: calling exec (rlm_exec) Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[accounting]: returned from exec (rlm_exec) Wed Feb 1 15:28:40 2017 : Debug: (35371) [exec] = noop Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) Wed Feb 1 15:28:40 2017 : Debug: %{User-Name} Wed Feb 1 15:28:40 2017 : Debug: Parsed xlat tree: Wed Feb 1 15:28:40 2017 : Debug: attribute --> User-Name Wed Feb 1 15:28:40 2017 : Debug: (35371) attr_filter.accounting_response: EXPAND %{User-Name} Wed Feb 1 15:28:40 2017 : Debug: (35371) attr_filter.accounting_response: --> mks539293 Wed Feb 1 15:28:40 2017 : Debug: (35371) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Wed Feb 1 15:28:40 2017 : Debug: (35371) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) Wed Feb 1 15:28:40 2017 : Debug: (35371) [attr_filter.accounting_response] = updated Wed Feb 1 15:28:40 2017 : Debug: (35371) } # accounting = updated Wed Feb 1 15:28:40 2017 : Debug: (35371) Sent Accounting-Response Id 13 from 82.21.11.50:1813 to 82.21.11.91:28342 length 0 Wed Feb 1 15:28:40 2017 : Debug: (35371) Finished request Wed Feb 1 15:28:40 2017 : Debug: (35371) Cleaning up request packet ID 13 with timestamp +15280 Wed Feb 1 15:28:40 2017 : Info: Ready to process requests Wed Feb 1 15:28:40 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Unlinking /var/log/freeradius/radacct/detail.work Wed Feb 1 15:28:40 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Wed Feb 1 15:28:40 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Detail listener state unopened waiting 1.134560 sec Wed Feb 1 15:28:41 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Wed Feb 1 15:28:41 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Detail listener state unopened waiting 1.117968 sec
On Feb 1, 2017, at 11:01 AM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
I asked a C developer to change source and backup detail.work file right before deleting. I noticed the skipped packets are already there in detail.work file, but they are not being read by buffered-sql module and then are deleted. developer also added a new debug line which is "Backup to mybackup.log". this line is always shown right before "Unlinking /var/log/freeradius/radacct/detail.work" except in the skipped packets which are shown before or while receiving accounting request.
Please send the problem detail file to me off-list. If I don't have access to it, it's really hard to reproduce or debug the problem. Alan DeKok.
Please send the problem detail file to me off-list. If I don't have access to it, it's really hard to reproduce or debug the problem.
it doesn't seem to be any problem with detail.work file. but the skipped packet is always the last request in this file and it somehow is not being read. here is the section for user 'mks539293' which was skipped. I can give you access to a server if you want. ----- new backup section ----- Wed Feb 1 15:28:40 2017 User-Name = "mks854028" NAS-IP-Address = 82.21.11.91 NAS-Port = 8900 Acct-Status-Type = Stop Framed-IP-Address = 10.8.0.146 Acct-Input-Gigawords = 0 Acct-Input-Octets = 10445 Acct-Output-Octets = 20930 Acct-Session-Id = "qkljh1rv5ixf" Acct-Output-Gigawords = 0 Calling-Station-Id = "127.0.0.1" Event-Timestamp = "Feb 1 2017 15:28:40 GMT" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "70cbf92ce5800b11dbc663e6567ad772" Timestamp = 1485950320 Wed Feb 1 15:28:40 2017 User-Name = "mks193422" NAS-IP-Address = 82.21.11.91 NAS-Port = 8903 Acct-Status-Type = Start Framed-IP-Address = 10.8.1.146 Acct-Session-Id = "esvso4ql5cm5" Calling-Station-Id = "127.0.0.1" Event-Timestamp = "Feb 1 2017 15:28:40 GMT" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "bb49875a2a7cd388a2ddecdfa6a0199a" Timestamp = 1485950320 Wed Feb 1 15:28:40 2017 User-Name = "mks539293" NAS-IP-Address = 82.21.11.91 NAS-Port = 8884 Acct-Status-Type = Stop Framed-IP-Address = 10.8.0.62 Acct-Input-Gigawords = 0 Acct-Input-Octets = 25093 Acct-Output-Octets = 40276 Acct-Session-Id = "daivfc6wehcv" Acct-Output-Gigawords = 0 Calling-Station-Id = "127.0.0.1" Event-Timestamp = "Feb 1 2017 15:28:40 GMT" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "fcc3dd2a5b00a62e7d6fc0b5f35316a4" Timestamp = 1485950320 ----- new backup section ----- Wed Feb 1 15:28:45 2017 User-Name = "mks47101" NAS-IP-Address = 82.21.11.91 NAS-Port = 8905 Acct-Status-Type = Start Framed-IP-Address = 10.8.1.46 Acct-Session-Id = "xbuvdfahshwo" Calling-Station-Id = "127.0.0.1" Event-Timestamp = "Feb 1 2017 15:28:45 GMT" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "cc8c54c823d9d1d77f0a9091f88f1685" Timestamp = 1485950325 Wed Feb 1 15:28:45 2017 User-Name = "mks151379" NAS-IP-Address = 82.21.11.91 NAS-Port = 8904 Acct-Status-Type = Start Framed-IP-Address = 10.8.0.146 Acct-Session-Id = "mk5jtwpimom8" Calling-Station-Id = "127.0.0.1" Event-Timestamp = "Feb 1 2017 15:28:45 GMT" Tmp-String-9 = "ai:" Acct-Unique-Session-Id = "ab15d7a4ed688689afd0baa1ea859343" Timestamp = 1485950325
On Feb 1, 2017, at 3:30 PM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
it doesn't seem to be any problem with detail.work file. but the skipped packet is always the last request in this file and it somehow is not being read.
Hmm... that's telling.
here is the section for user 'mks539293' which was skipped. I can give you access to a server if you want.
No, just the sample detail files are fine. I'll take a look today / tomorrow. Alan DeKok.
No, just the sample detail files are fine. I'll take a look today / tomorrow.
could you find any problem? I asked developer to rename detail.work to a distinct name each time. I noticed the skipping packet is seen in debug right after renaming detail.work say to backup-1000.work if packet is received after renaming and deleting detail.work why it exists in backup-1000.work instead of backup-1001.work? or maybe everything is happening exactly at the same time and the order of debug lines is not accurate. this is sample debug: Tue Feb 7 16:55:02 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Renaming to /var/log/freeradius/radacct/backup-1000.work Tue Feb 7 16:55:02 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Unlinking /var/log/freeradius/radacct/detail.work Tue Feb 7 16:55:02 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Polling for detail file Tue Feb 7 16:55:02 2017 : Debug: detail (/var/log/freeradius/radacct/detail-*): Detail listener state unopened waiting 0.952720 sec Tue Feb 7 16:55:02 2017 : Debug: (6449) Received Accounting-Request Id 162 from 82.21.11.91:18886 to 82.21.11.50:1813 length 107 Tue Feb 7 16:55:02 2017 : Debug: (6449) User-Name = "mks8435" Tue Feb 7 16:55:02 2017 : Debug: (6449) NAS-IP-Address = 82.21.11.91 Tue Feb 7 16:55:02 2017 : Debug: (6449) NAS-Port = 1152 Tue Feb 7 16:55:02 2017 : Debug: (6449) Acct-Status-Type = Stop .... (this is the packet which is in backup-1000.work and was never read by module)
On Feb 7, 2017, at 9:36 AM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
No, just the sample detail files are fine. I'll take a look today / tomorrow.
could you find any problem?
No. It works fine for me, and there's no code path I can see where there would be a problem with your scenario.
I asked developer to rename detail.work to a distinct name each time. I noticed the skipping packet is seen in debug right after renaming detail.work say to backup-1000.work if packet is received after renaming and deleting detail.work why it exists in backup-1000.work instead of backup-1001.work?
That just shouldn't happen. The detail writer locks the file. The detail reader renames it, and tries to lock the file. If it can't get the lock, the reader retries after a while. It it can get the lock, it knows that the writer is done writing. And, that the detail file writer is now writing to a *different* file. My guess is this: a) you don't have "locking = yes" in the detail module configuration or b) the detail files are on an NFS mount, which is notorious for being bad at locking. Alan DeKok.
No. It works fine for me, and there's no code path I can see where there would be a problem with your scenario.
testing this is difficult. It only happens once in a few thousands requests.
My guess is this:
a) you don't have "locking = yes" in the detail module configuration
it is already enabled.
or>
b) the detail files are on an NFS mount, which is notorious for being bad at locking.
file system type is the default ext4
On Feb 7, 2017, at 11:35 AM, Jouni Soini via Freeradius-Users <freeradius-users@lists.freeradius.org> wrote:
b) the detail files are on an NFS mount, which is notorious for being bad at locking.
file system type is the default ext4
Well, all I can say is that the server depends on locking. If the locking fails, then all bets are off. If the locking works, then no entry in the detail file should be skipped. Alan DeKok.
participants (3)
-
Alan DeKok -
Jouni Soini -
Matthew Newton