Freeradius 3.0.7 and multiple buffered-sql servers - detail file issues

Rygl Aleš ales at rygl.net
Sat Apr 18 00:16:29 CEST 2015


Hello Arran.

I do not see anything wrong. Let me paste a bit longer parto of the debug.

> Can you look and see if there's anything obviously wrong before that error?
> Like complaints from other areas of the code.
> 
> Seems like something close the file descriptor for the current work file.

Fri Apr 17 23:10:40 2015 : Debug: Polling for detail file /var/log/freeradius/radacct/detail.dsl/detail-*
Fri Apr 17 23:10:40 2015 : Debug: Detail - Renaming /var/log/freeradius/radacct/detail.dsl/detail-2015041723 -> /var/log/freeradius/radacct/detail.dsl/detail.work
detail_recv: Read packet from /var/log/freeradius/radacct/detail.dsl/detail.work
        User-Name = 'O2'
        Acct-Status-Type = Interim-Update
        Acct-Session-Id = '0000FFFF68024B9C-5530BFFA'
        Service-Type = Framed-User
        Framed-Protocol = PPP
        Acct-Update-Reason = AAA-LOAD-ACCT-PERIODIC
        NAS-Identifier = 'BRAS_CTX'
        NAS-IP-Address = 10.231.0.129
        NAS-Port = 285228649
        NAS-Real-Port = 299474955
        NAS-Port-Type = Virtual
        NAS-Port-Id = 'PHAskut atm 4/5:8.48'
        Medium-Type = DSL
        Mac-Addr = 'ac-9e-17-50-01-d4'
        Connect-Info = 'dot1q_bulk'
        Platform-Type = 6
        OS-Version = '12.1.1.5'
        Agent-Circuit-Id = 0x504841736b75742061746d20342f353a382e3438
        ADSL-Agent-Circuit-Id = 0x504841736b75742061746d20342f353a382e3438
        Acct-Authentic = RADIUS
        Client-DNS-Pri = 93.153.117.1
        Client-DNS-Sec = 93.153.117.33
        Context-Name = 'vrf-internet'
        Framed-IP-Address = 78.80.158.204
        Framed-IP-Netmask = 255.255.255.255
        Source-Validation = Enabled
        Delegated-IPv6-Prefix = 2001:1ae9:282e:3700::/56
        Framed-IPv6-Prefix = 2001:1ae9:2ff8:2e37::/64
        Acct-Session-Time = 46801
        Acct-Input-Packets = 128870
        Acct-Output-Packets = 114354
        Acct-Input-Octets = 21485810
        Acct-Output-Octets = 66723218
        Acct-Input-Gigawords = 0
        Acct-Output-Gigawords = 0
        Acct-Input-Packets-64 = 128870
        Acct-Output-Packets-64 = 114354
        Acct-Input-Octets-64 = 21485810
        Acct-Output-Octets-64 = 66723218
        Attr-26.2352.214 = 0x010b6255
        Attr-26.2352.215 = 0x03c4d0b4
        Attr-26.2352.216 = 0x0001d5ef
        Attr-26.2352.217 = 0x0001a03d
        Attr-26.2352.218 = 0x00000000
        Attr-26.2352.219 = 0x00000000
        Acct-Mcast-In-Packets = 0
        Acct-Mcast-Out-Packets = 0
        Acct-Mcast-In-Octets = 0
        Acct-Mcast-Out-Octets = 0
        Acct-Mcast-In-Packets-64 = 0
        Acct-Mcast-Out-Packets-64 = 0
        Acct-Mcast-In-Octets-64 = 0
        Acct-Mcast-Out-Octets-64 = 0
        Qos-Policy-Queuing = '8192_512_1:50_out'
        Qos-Policing-Profile-Name = '512_in'
        Event-Timestamp = 'Apr 17 2015 23:10:36 CEST'
        Acct-Unique-Session-Id = '2c50b78d9c67b698fed00c015c76192f'
        Packet-Original-Timestamp = 'Apr 17 2015 23:10:35 CEST'
        Acct-Delay-Time = 4
        Packet-Transmit-Counter = 1
Fri Apr 17 23:10:40 2015 : Debug: (19349) Empty preacct section.  Using default return values.
Fri Apr 17 23:10:40 2015 : Debug: (19349) # Executing section accounting from file /etc/freeradius/sites-enabled/buffered-sql-dsl
Fri Apr 17 23:10:40 2015 : Debug: (19349)   accounting {
Fri Apr 17 23:10:40 2015 : Debug: (19349)     modsingle[accounting]: calling sql_instance_dsl (rlm_sql) for request 19349
Fri Apr 17 23:10:40 2015 : Debug: %{tolower:type.%{Acct-Status-Type}.query}
Fri Apr 17 23:10:40 2015 : Debug: Parsed xlat tree:
Fri Apr 17 23:10:40 2015 : Debug: xlat --> tolower
Fri Apr 17 23:10:40 2015 : Debug: {
Fri Apr 17 23:10:40 2015 : Debug:       literal --> type.
Fri Apr 17 23:10:40 2015 : Debug:       attribute --> Acct-Status-Type
Fri Apr 17 23:10:40 2015 : Debug:       literal --> .query
Fri Apr 17 23:10:40 2015 : Debug: }
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: EXPAND %{tolower:type.%{Acct-Status-Type}.query}
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl:    --> type.interim-update.query
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: Using query template 'query'
Fri Apr 17 23:10:40 2015 : Debug: rlm_sql (sql_instance_dsl): Reserved connection (4)
Fri Apr 17 23:10:40 2015 : Debug: %{User-Name}
Fri Apr 17 23:10:40 2015 : Debug: Parsed xlat tree:
Fri Apr 17 23:10:40 2015 : Debug: attribute --> User-Name
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: EXPAND %{User-Name}
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl:    --> O2
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: SQL-User-Name set to 'O2'
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: FROM 1 TO 60 MAX 61
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: Examining SQL-User-Name
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: APPENDING SQL-User-Name FROM 0 TO 60
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: TO in 60 out 61
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[0] = User-Name
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[1] = Acct-Status-Type
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[2] = Acct-Session-Id
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[3] = Service-Type
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[4] = Framed-Protocol
... 
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[54] = Qos-Policing-Profile-Name
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[55] = Event-Timestamp
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[56] = Acct-Unique-Session-Id
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[57] = Packet-Original-Timestamp
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[58] = Acct-Delay-Time
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[59] = Packet-Transmit-Counter
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: ::: to[60] = SQL-User-Name
Fri Apr 17 23:10:40 2015 : Debug: UPDATE radacct SET AcctUpdateTime  = FROM_UNIXTIME(%{integer:Event-Timestamp}), AcctSessionTime = '%{Acct-Session-Time}', 
AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctInputGigawords = '%{Acct-Input-Gigawords}', AcctOutputGigawords = '%{Acct-
Output-Gigawords}',  AcctInputPackets64 = '%{Acct-Input-Packets-64}', AcctOutputPackets64 = '%{Acct-Output-Packets-64}', AcctInputOctets64 = '%{Acct-Input-Octets-64}', 
AcctOutputOctets64 = '%{Acct-Output-Octets-64}', AcctStatusType = '%{Acct-Status-Type}' WHERE AcctUniqueSessionId = '%{Acct-Unique-Session-Id}'
Fri Apr 17 23:10:40 2015 : Debug: Parsed xlat tree:
Fri Apr 17 23:10:40 2015 : Debug: literal --> UPDATE radacct SET AcctUpdateTime  = FROM_UNIXTIME(
Fri Apr 17 23:10:40 2015 : Debug: xlat --> integer
Fri Apr 17 23:10:40 2015 : Debug: {
Fri Apr 17 23:10:40 2015 : Debug:       literal --> Event-Timestamp
Fri Apr 17 23:10:40 2015 : Debug: }
Fri Apr 17 23:10:40 2015 : Debug: literal --> ), AcctSessionTime = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Session-Time
Fri Apr 17 23:10:40 2015 : Debug: literal --> ', AcctInputOctets = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Input-Octets
Fri Apr 17 23:10:40 2015 : Debug: literal --> ', AcctOutputOctets = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Output-Octets
Fri Apr 17 23:10:40 2015 : Debug: literal --> ', AcctInputGigawords = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Input-Gigawords
Fri Apr 17 23:10:40 2015 : Debug: literal --> ', AcctOutputGigawords = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Output-Gigawords
Fri Apr 17 23:10:40 2015 : Debug: literal --> ',  AcctInputPackets64 = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Input-Packets-64
Fri Apr 17 23:10:40 2015 : Debug: literal --> ', AcctOutputPackets64 = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Output-Packets-64
Fri Apr 17 23:10:40 2015 : Debug: literal --> ', AcctInputOctets64 = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Input-Octets-64
Fri Apr 17 23:10:40 2015 : Debug: literal --> ', AcctOutputOctets64 = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Output-Octets-64
Fri Apr 17 23:10:40 2015 : Debug: literal --> ', AcctStatusType = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Status-Type
Fri Apr 17 23:10:40 2015 : Debug: literal --> ' WHERE AcctUniqueSessionId = '
Fri Apr 17 23:10:40 2015 : Debug: attribute --> Acct-Unique-Session-Id
Fri Apr 17 23:10:40 2015 : Debug: literal --> '
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: EXPAND UPDATE radacct SET AcctUpdateTime  = FROM_UNIXTIME(%{integer:Event-Timestamp}), 
AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}', AcctInputGigawords = '%{Acct-Input-
Gigawords}', AcctOutputGigawords = '%{Acct-Output-Gigawords}',  AcctInputPackets64 = '%{Acct-Input-Packets-64}', AcctOutputPackets64 = '%{Acct-Output-Packets-64}', 
AcctInputOctets64 = '%{Acct-Input-Octets-64}', AcctOutputOctets64 = '%{Acct-Output-Octets-64}', AcctStatusType = '%{Acct-Status-Type}' WHERE AcctUniqueSessionId = 
'%{Acct-Unique-Session-Id}'
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl:    --> UPDATE radacct SET AcctUpdateTime  = FROM_UNIXTIME(1429305036), AcctSessionTime = '46801', 
AcctInputOctets = '21485810', AcctOutputOctets = '66723218', AcctInputGigawords = '0', AcctOutputGigawords = '0',  AcctInputPackets64 = '128870', AcctOutputPackets64 = 
'114354', AcctInputOctets64 = '21485810', AcctOutputOctets64 = '66723218', AcctStatusType = 'Interim-Update' WHERE AcctUniqueSessionId = 
'2c50b78d9c67b698fed00c015c76192f'
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: Executing query: UPDATE radacct SET AcctUpdateTime  = FROM_UNIXTIME(1429305036), AcctSessionTime = 
'46801', AcctInputOctets = '21485810', AcctOutputOctets = '66723218', AcctInputGigawords = '0', AcctOutputGigawords = '0',  AcctInputPackets64 = '128870', 
AcctOutputPackets64 = '114354', AcctInputOctets64 = '21485810', AcctOutputOctets64 = '66723218', AcctStatusType = 'Interim-Update' WHERE AcctUniqueSessionId = 
'2c50b78d9c67b698fed00c015c76192f'
Fri Apr 17 23:10:40 2015 : Debug: rlm_sql_mysql: Rows matched: 1  Changed: 1  Warnings: 0
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: SQL query returned: success
Fri Apr 17 23:10:40 2015 : Debug: (19349) sql_instance_dsl: 1 record(s) updated
Fri Apr 17 23:10:40 2015 : Debug: rlm_sql (sql_instance_dsl): Released connection (4)
Fri Apr 17 23:10:40 2015 : Debug: (19349)     modsingle[accounting]: returned from sql_instance_dsl (rlm_sql) for request 19349
Fri Apr 17 23:10:40 2015 : Debug: (19349)     [sql_instance_dsl] = ok
Fri Apr 17 23:10:40 2015 : Debug: (19349)     if (noop) {
Fri Apr 17 23:10:40 2015 : Debug: (19349)     if (noop)  -> FALSE
Fri Apr 17 23:10:40 2015 : Debug: (19349)   } # accounting = ok
Fri Apr 17 23:10:40 2015 : Debug: (19349) Received response for request 19349.  Will read the next packet in 0 seconds
Fri Apr 17 23:10:40 2015 : Debug: (19349) Sent Accounting-Response Id 32 from 127.0.0.0:1024 to 255.255.255.255:1024 length 0
Fri Apr 17 23:10:40 2015 : Debug: (19349) Finished request
Fri Apr 17 23:10:40 2015 : Debug: (19328) <done>: Cleaning up request packet ID 155 with timestamp +160
Fri Apr 17 23:10:40 2015 : Warning: Failed marking detail request as done: Bad file descriptor
Fri Apr 17 23:10:40 2015 : Debug: Detail - unlinking /var/log/freeradius/radacct/detail.dsl/detail.work
Fri Apr 17 23:10:40 2015 : Debug: Polling for detail file /var/log/freeradius/radacct/detail.dsl/detail-*
Fri Apr 17 23:10:40 2015 : Debug: Detail listener /var/log/freeradius/radacct/detail.dsl/detail-* state unopened waiting 5.014879 sec
Fri Apr 17 23:10:40 2015 : Debug: (19329) <done>: Cleaning up request packet ID 233 with timestamp +160
Fri Apr 17 23:10:41 2015 : Debug: (19350) Received Accounting-Request Id 29 from 10.49.37.3:26675 to 10.49.38.3:3813 length 442

No other warning or errors concerning file descriptors in the log... I can check the  v3.0.x branch but it will take some time.

> > Just a short question: where is the information about the las processed
> > packet from the detail file stored?
> 
> IIRC the timestamps in the packet headers are overwritten. If the process
> restarts it checks each header and skips the packet if it's already been
> processed.
> 

Thanks
Regards
Ales


More information about the Freeradius-Users mailing list