buffered-sql problem
Jouni Soini
soini.jouni at yahoo.com
Fri Jan 27 18:47:12 CET 2017
> 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
More information about the Freeradius-Users
mailing list