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