buffered-sql problem
Jouni Soini
soini.jouni at yahoo.com
Wed Feb 1 17:01:47 CET 2017
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
More information about the Freeradius-Users
mailing list