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