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