Freeradius 3.0.7 and multiple buffered-sql servers - detail file issues
Hello all. I am trying to migrate the freeradius 2.2.5 to 3.0.7. The server is doing just Acounting request processing and is loading requests to MariaDB with radacct table on InnoDB engine allowing row level locking. There are 128 detail files derived from Calling-Station-Id attribute using mod 128: Queue-Number = "%{expr: %{Calling-Station-Id} %% 128 }" detailfile = ${radacctdir}/detail.mobile/queue-${Queue-Number}/detail-%Y%m%d-%H Then there are 128 buffered-sql servers reading these detail files and feeding the radacct table: server buffered-sql-0 { listen { type = detail filename = "${radacctdir}/detail.mobile/queue-0/detail-*" load_factor = 85 track = yes poll_interval = 5 retry_interval = 30 } preacct { acct_unique } accounting { sql if (noop) { ok } } } . . . server buffered-sql-127 { listen { type = detail filename = "${radacctdir}/detail.mobile/queue-127/detail-*" load_factor = 85 track = yes poll_interval = 5 retry_interval = 30 } preacct { acct_unique } accounting { sql if (noop) { ok } } } This setup is working fine with 2.2.5 version and is very fast. I am able to process more that 1.500 Acct req/s realtime. When I try to use 3.0.7, I am facing some issues: 1. Bad file descriptor message. Looks like it is caused by track = yes config option. When switched to no, it dissapears. What is the problem here? Thu Apr 16 15:58:52 2015 : Warning: Failed marking detail request as done: Bad file descriptor Thu Apr 16 15:58:52 2015 : Warning: Failed marking detail request as done: Bad file descriptor Thu Apr 16 15:58:52 2015 : Warning: Failed marking detail request as done: Bad file descriptor 2. When the server is loaded with ~350 req/s, it is ok. When the load is ~1500 req/s, I can see tons of errors in the log file: Thu Apr 16 16:24:38 2015 : ERROR: (585809) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-58/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585810) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-28/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585811) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-122/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585812) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-102/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585813) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-10/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585814) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-118/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585815) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-0/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585816) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-36/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585817) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-0/detail-2015041616: Too many different filenames Thu Apr 16 16:24:38 2015 : ERROR: (585818) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-32/detail-2015041616: Too many different filename The config: sites-enabled/acct_detail server acct.mobile { listen { ipaddr = * port = 2813 type = acct limit { } } preacct { preprocess acct_unique_mobile } accounting { detail.mobile if (noop) { ok } } } sites-enabled/buffered-sql-mobile-0 server buffered-sql-0 { listen { type = detail filename = "${radacctdir}/detail.mobile/queue-0/detail-*" load_factor = 85 track = no poll_interval = 5 retry_interval = 120 } preacct { } accounting { sql_instance_mobile if (noop) { ok } } } mods-enabled/detail.mobile detail detail.mobile { Queue-Number = "%{expr: %{Calling-Station-Id} %% 128 }" filename = ${radacctdir}/detail.mobile/queue-${Queue-Number}/detail-%Y%m%d%H locking = yes } ./mods-available/sql_ar sql sql_instance_mobile { driver = "rlm_sql_mysql" dialect = "mysql" server = "localhost" port = 3306 login = "radius" password = "xxxxxxxxxxxxxxx" radius_db = "gprscalls" acct_table1 = "radacct_test" acct_table2 = "radacct_test" postauth_table = "radpostauth" authcheck_table = "radcheck" groupcheck_table = "radgroupcheck" authreply_table = "radreply" groupreply_table = "radgroupreply" usergroup_table = "radusergroup" delete_stale_sessions = yes logfile = ${logdir}/sqllog_mobile.sql pool { start = 128 min = 128 # max = ${thread[pool].max_servers} max = 128 spare = 5 uses = 0 lifetime = 0 idle_timeout = 60 } client_table = "nas" $INCLUDE ${modconfdir}/${.:name}/main/${dialect}/queries_mobile.conf } radiusd.conf prefix = /usr exec_prefix = /usr sysconfdir = /etc localstatedir = /var sbindir = ${exec_prefix}/sbin logdir = /var/log/freeradius raddbdir = /etc/freeradius radacctdir = ${logdir}/radacct name = freeradius confdir = ${raddbdir} modconfdir = ${confdir}/mods-config certdir = ${confdir}/certs cadir = ${confdir}/certs run_dir = ${localstatedir}/run/${name} db_dir = ${raddbdir} libdir = /usr/lib/freeradius pidfile = ${run_dir}/${name}.pid max_request_time = 10 cleanup_delay = 5 max_requests = 20000 hostname_lookups = no log { destination = files colourise = yes file = ${logdir}/radius.log syslog_facility = daemon stripped_names = no auth = no auth_badpass = no auth_goodpass = no msg_denied = "You are already logged in - access denied" } checkrad = ${sbindir}/checkrad security { user = freerad group = freerad allow_core_dumps = no max_attributes = 200 reject_delay = 1 status_server = yes allow_vulnerable_openssl = 'CVE-2014-0160' } $INCLUDE clients.conf thread pool { start_servers = 512 max_servers = 2000 min_spare_servers = 100 max_spare_servers = 300 max_requests_per_server = 0 auto_limit_acct = no } modules { $INCLUDE mods-enabled/ } instantiate { } policy { $INCLUDE policy.d/ } $INCLUDE sites-enabled/ Thanks With regards Ales
I am trying to migrate the freeradius 2.2.5 to 3.0.7. The server is doing just Acounting request processing and is loading requests to MariaDB with radacct table on InnoDB engine allowing row level locking. There are 128 detail files derived from Calling-Station-Id attribute using mod 128:
Your config has spawned 128 threads, each with their own set of file descriptors to access the detail files, and then two more for communication with the master thread for inserting packets into the packet queue. I assume you also have 128 detail writers so that's another 128. So that's at least 512 file descriptors, which by itself, I guess, isn't a problem. However, on the master thread side of some of those descriptors sits a select() loop, which, with 128 file descriptors, will be a problem. In fact, it'll likely cause a large drop in throughput. I imagine the error is being thrown by the exfiles API, because you have a large number of different files that are open, and you've hit a compiled in limit. Compiled in limits are usually to stop people doing stupid things. Stop doing stupid things and the server will work. The detail file reader is considerably faster in v3.0.7 than 2.2.5, you probably don't need 128 detail queues. One would likely be enough, 10 at most. Also is there a reason why you're not doing direct inserts into the database? buffered sql was intended primarily for buffering SQL data when the database went offline, not for insertion into the normal request flow. It'll always be slower than blocking inserts. You can set the MySQL client library timeout sufficiently low that the module will will trash all its connections, and failover to the detail writer before the server starts dropping packets. Set retry_delay in the sql module pool to something like 60 to stop the server continuously trying to open new connections when a MySQL server does down. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Hello Arran. Thanks for your explanation concerning filedescriptors.
Compiled in limits are usually to stop people doing stupid things. Stop doing stupid things and the server will work.
I try to.
The detail file reader is considerably faster in v3.0.7 than 2.2.5, you probably don't need 128 detail queues. One would likely be enough, 10 at most.
I can confim it. I have tried 12 and it is really fast an uses the DB connections more efficiently.
Also is there a reason why you're not doing direct inserts into the database? buffered sql was intended primarily for buffering SQL data when the database went offline, not for insertion into the normal request flow. It'll always be slower than blocking inserts.
The idea behind was that writing to a file is cheeper than perform a DB transactions and a delayed (asynchronous) write to DB is not an issue for me. My average row lock time is about 40ms in bussy hour. IMHO writing to a file must be faster or am I wrong?
You can set the MySQL client library timeout sufficiently low that the module will will trash all its connections, and failover to the detail writer before the server starts dropping packets.
What config parameter is it? I am affraid that if I lock the raddact table for 3-5 sec or so because of another transaction the server will start to drop requests before it will have a chance to failover to a file...
Set retry_delay in the sql module pool to something like 60 to stop the server continuously trying to open new connections when a MySQL server does down.
Thanks Ales
The idea behind was that writing to a file is cheeper than perform a DB transactions and a delayed (asynchronous) write to DB is not an issue for me. My average row lock time is about 40ms in bussy hour. IMHO writing to a file must be faster or am I wrong?
Yes. The detail reader is not doing multiple inserts per transaction. It does a single insert per transaction, the same as if you'd inserted the row at the time the packet was received. There is no advantage to using a detail/reader writer, unless you want to guarantee inserts happen in serial for some reason, or need to spool requests to disk if the database goes down. If you want to do bulk inserts you use the sql_log and the 'null' driver to record the statements that would have been executed. Then you execute them as a batch job in a single transaction using a shell script and a cron job.
You can set the MySQL client library timeout sufficiently low that the module will will trash all its connections, and failover to the detail writer before the server starts dropping packets.
What config parameter is it? I am affraid that if I lock the raddact table for 3-5 sec or so because of another transaction the server will start to drop requests before it will have a chance to failover to a file...
sql { query_timeout = n } I think the minimum timeout is 2. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On Apr 16, 2015, at 2:44 PM, Rygl Aleš <ales@rygl.net> wrote:
I am trying to migrate the freeradius 2.2.5 to 3.0.7. The server is doing just Acounting request processing and is loading requests to MariaDB with radacct table on InnoDB engine allowing row level locking. There are 128 detail files derived from Calling-Station-Id attribute using mod 128:
Why? There shouldn't be a need to create 128 detail file writers / readers. Version 2 was a little slow reading the detail files. Version 3 is much faster, and more robust.
1. Bad file descriptor message. Looks like it is caused by track = yes config option. When switched to no, it dissapears. What is the problem here?
I'm not sure. The file descriptor should NOT be closed while it's being used. And for v3, you should set "track = yes". It means that server re-starts don't cause re-reads of old accounting packets.
2. When the server is loaded with ~350 req/s, it is ok. When the load is ~1500 req/s, I can see tons of errors in the log file: Thu Apr 16 16:24:38 2015 : ERROR: (585809) detail.mobile: ERROR: Couldn't open file /var/log/freeradius/radacct/detail.mobile/queue-58/detail-2015041616: Too many different filenames
Don't configure 128 queues. There shouldn't be a need to do that. Alan DeKok.
Hello Alan, thanks for your comments. I try to explain it. On Friday 17 of April 2015 17:41:08 Alan DeKok wrote:
On Apr 16, 2015, at 2:44 PM, Rygl Aleš <ales@rygl.net> wrote:
I am trying to migrate the freeradius 2.2.5 to 3.0.7. The server is doing just Acounting request processing and is loading requests to MariaDB with radacct table on InnoDB engine allowing row level locking. There are 128 detail files derived from Calling-Station-Id attribute using mod 128: Why?
The goal is to have server which - responds as fast as possible. - is resilient to occasional peaks in the accounting traffic with magnitude of 10 or more - drops packets as little as possible - utilizes parallel processing on the DB side as much as possible I was not able to reach this with InnoDB engine with just sigle queue. It was pretty fast with MEMORY engine but it suffers from locking on table level (and uses just a single connection to DB). I was affraid that talking to DB directly (without fallback to a file buffer) would had problems in case of peaks. So the idea behind is to rather write to a file which IHMO cheaper that perform a DB transaction where I have to wait for a lock. While testing the performance of 2.2.5 server with multiple queues I have found out that 128 queues was giving the best results from the throughput point of view. The DB could be down for an hour and about 3 GB of data in file were loaded then to DB within 20 mins.
There shouldn't be a need to create 128 detail file writers / readers. Version 2 was a little slow reading the detail files. Version 3 is much faster, and more robust.
I can confirm that it is definitely faster. I have followed Arran's recomendations and reduced the number of queues to 12 and it looks good. I will play with this more.
I'm not sure. The file descriptor should NOT be closed while it's being used.
And for v3, you should set "track = yes". It means that server re-starts don't cause re-reads of old accounting packets.
I will try again. Actually I have two more virtual servers in the config with a single queue processing just couple of packets per second and this error was there too. I will do some debugs here.
Don't configure 128 queues. There shouldn't be a need to do that.
I will try the direct connection to DB with a fallback to file. Thanks Ales
On Apr 17, 2015, at 3:23 PM, Rygl Aleš <ales@rygl.net> wrote:
The goal is to have server which - responds as fast as possible. - is resilient to occasional peaks in the accounting traffic with magnitude of 10 or more - drops packets as little as possible - utilizes parallel processing on the DB side as much as possible
That's usually the goal. :)
I was not able to reach this with InnoDB engine with just sigle queue. It was pretty fast with MEMORY engine but it suffers from locking on table level (and uses just a single connection to DB). I was affraid that talking to DB directly (without fallback to a file buffer) would had problems in case of peaks. So the idea behind is to rather write to a file which IHMO cheaper that perform a DB transaction where I have to wait for a lock.
Hmm... sounds like DB issues, to be honest. Your other message mentioned 3-5s delay writing to the DB. That should *never* happen. A normal DB should be able to handle 200-1000 writes per second.
I can confirm that it is definitely faster. I have followed Arran's recomendations and reduced the number of queues to 12 and it looks good. I will play with this more.
That's good. You should be able to do: accounting { ... redundant { sql detail } ... } And carefully tune the "pool" parameters to the SQL module. If all of the connections are in use, the server will fail-over to using the "detail" module. This process is very quick, so there's no performance issues.
I will try again. Actually I have two more virtual servers in the config with a single queue processing just couple of packets per second and this error was there too. I will do some debugs here.
Maybe try the v3.0.x branch. We'll turn it into 3.0.8 real soon now... Alan DeKok.
Hello Alan. On Friday 17 of April 2015 22:44:56 Alan DeKok wrote:
That's usually the goal. :)
I am really close now :)
Hmm... sounds like DB issues, to be honest. Your other message mentioned 3-5s delay writing to the DB. That should *never* happen. A normal DB should be able to handle 200-1000 writes per second.
Well, this happens just once per night where I check the radacct table for some lost Acct-Stop packets (non-closed sessions). The table has about a milion of records.
That's good. You should be able to do:
accounting { ... redundant { sql detail } ... }
And carefully tune the "pool" parameters to the SQL module. If all of the connections are in use, the server will fail-over to using the "detail" module. This process is very quick, so there's no performance issues.
Thanks, I will try.
I will try again. Actually I have two more virtual servers in the config with a single queue processing just couple of packets per second and this error was there too. I will do some debugs here.
Maybe try the v3.0.x branch. We'll turn it into 3.0.8 real soon now...
I have tried again. I can provide you with full debug if needed. Unfortunately there are not too much details about this error: Fri Apr 17 23:08:10 2015 : Debug: rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0 Fri Apr 17 23:08:10 2015 : Debug: (1005) sql_instance_dsl: SQL query returned: success Fri Apr 17 23:08:10 2015 : Debug: (1005) sql_instance_dsl: 1 record(s) updated Fri Apr 17 23:08:10 2015 : Debug: rlm_sql (sql_instance_dsl): Released connection (0) Fri Apr 17 23:08:10 2015 : Debug: (1005) modsingle[accounting]: returned from sql_instance_dsl (rlm_sql) for request 1005 Fri Apr 17 23:08:10 2015 : Debug: (1005) [sql_instance_dsl] = ok Fri Apr 17 23:08:10 2015 : Debug: (1005) if (noop) { Fri Apr 17 23:08:10 2015 : Debug: (1005) if (noop) -> FALSE Fri Apr 17 23:08:10 2015 : Debug: (1005) } # accounting = ok Fri Apr 17 23:08:10 2015 : Debug: (1005) Received response for request 1005. Will read the next packet in 0 seconds Fri Apr 17 23:08:10 2015 : Debug: (1005) Sent Accounting-Response Id 2 from 127.0.0.0:1024 to 255.255.255.255:1024 length 0 Fri Apr 17 23:08:10 2015 : Debug: (1005) Finished request Fri Apr 17 23:08:10 2015 : Warning: Failed marking detail request as done: Bad file descriptor Fri Apr 17 23:08:10 2015 : Debug: Detail - unlinking /var/log/freeradius/radacct/detail.dsl/detail.work Fri Apr 17 23:08:10 2015 : Debug: Polling for detail file /var/log/freeradius/radacct/detail.dsl/detail-* Fri Apr 17 23:08:10 2015 : Debug: Detail listener /var/log/freeradius/radacct/detail.dsl/detail-* state unopened waiting 5.197627 sec Just a short question: where is the information about the las processed packet from the detail file stored? Thanks Ales
Fri Apr 17 23:08:10 2015 : Debug: rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 0 Fri Apr 17 23:08:10 2015 : Debug: (1005) sql_instance_dsl: SQL query returned: success Fri Apr 17 23:08:10 2015 : Debug: (1005) sql_instance_dsl: 1 record(s) updated Fri Apr 17 23:08:10 2015 : Debug: rlm_sql (sql_instance_dsl): Released connection (0) Fri Apr 17 23:08:10 2015 : Debug: (1005) modsingle[accounting]: returned from sql_instance_dsl (rlm_sql) for request 1005 Fri Apr 17 23:08:10 2015 : Debug: (1005) [sql_instance_dsl] = ok Fri Apr 17 23:08:10 2015 : Debug: (1005) if (noop) { Fri Apr 17 23:08:10 2015 : Debug: (1005) if (noop) -> FALSE Fri Apr 17 23:08:10 2015 : Debug: (1005) } # accounting = ok Fri Apr 17 23:08:10 2015 : Debug: (1005) Received response for request 1005. Will read the next packet in 0 seconds Fri Apr 17 23:08:10 2015 : Debug: (1005) Sent Accounting-Response Id 2 from 127.0.0.0:1024 to 255.255.255.255:1024 length 0 Fri Apr 17 23:08:10 2015 : Debug: (1005) Finished request Fri Apr 17 23:08:10 2015 : Warning: Failed marking detail request as done: Bad file descriptor Fri Apr 17 23:08:10 2015 : Debug: Detail - unlinking /var/log/freeradius/radacct/detail.dsl/detail.work Fri Apr 17 23:08:10 2015 : Debug: Polling for detail file /var/log/freeradius/radacct/detail.dsl/detail-* Fri Apr 17 23:08:10 2015 : Debug: Detail listener /var/log/freeradius/radacct/detail.dsl/detail-* state unopened waiting 5.197627 sec
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.
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. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
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
On 17 Apr 2015, at 23:16, Rygl Aleš <ales@rygl.net> wrote:
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.
It's odd that the next seek operation doesn't fail. I've made the warnings a bit more fine grained. Could you try the latest v3.0.x head? -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17 Apr 2015, at 23:52, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 17 Apr 2015, at 23:16, Rygl Aleš <ales@rygl.net> wrote:
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.
It's odd that the next seek operation doesn't fail.
I've made the warnings a bit more fine grained. Could you try the latest v3.0.x head?
ah.. issue has likely been located. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Hello Arran,
I've made the warnings a bit more fine grained. Could you try the latest v3.0.x head?
ah.. issue has likely been located.
I can confirm that it is fixed now! Debian package built from git version 3.0.8 is o.k. No more Bad file descriptor errors. Amazing! Thanks! Ales
On 18 Apr 2015, at 09:09, Rygl Aleš <ales@rygl.net> wrote:
Hello Arran,
I've made the warnings a bit more fine grained. Could you try the latest v3.0.x head?
ah.. issue has likely been located.
I can confirm that it is fixed now! Debian package built from git version 3.0.8 is o.k. No more Bad file descriptor errors.
Amazing! Thanks!
Great! Thanks for testing. Turns out when the file descriptor was being re-opened as a stream, it was opened read only (the fd is opened r/w), hence the seek/write failed. Do you have the definitions for those additional Ericsson/Redback attributes (214-219)? They look like 32bit counters. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Hello Arran,
Do you have the definitions for those additional Ericsson/Redback attributes (214-219)? They look like 32bit counters.
You caught me with my pants down. They are new even for me. I will try to get the lastest dictionary directly from Ericsson next week and come back to you. Regards Ales
Hello Alan, I am able to run the following setup recommeded by you, thanks. accounting { ... redundant { sql detail } ... } It looks good so far (~1000 req/s). The failover to the detail file is very fast (tested with LOCK - sleep - UNLOCK table). Really cool. I am in test environment and I am trying to tune the pool of sql connections in order to avoid failover now. It would be IMHO useful if the server logs a warning that it is doing failover to a file or another instance in the redundant section. Would it be possible to add something like this? It's just something nice to have. Thanks Ales
On 20 Apr 2015, at 21:16, Rygl Aleš <ales@rygl.net> wrote:
Hello Alan,
I am able to run the following setup recommeded by you, thanks.
accounting { ... redundant { sql detail } ... }
It looks good so far (~1000 req/s). The failover to the detail file is very fast (tested with LOCK - sleep - UNLOCK table). Really cool. I am in test environment and I am trying to tune the pool of sql connections in order to avoid failover now.
It would be IMHO useful if the server logs a warning that it is doing failover to a file or another instance in the redundant section. Would it be possible to add something like this? It's just something nice to have.
redundant { sql group { linelog detail } } -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
So, which is better solution for performance: keep accounting data in details file, then read it and write to db with buffered-sql or write accounting to database directly? In configuration file buffered-sql we can read: #v+ The server can read accounting packets from the detail file much more quickly than those packets an be written to a database. If the database is overloaded, then bad things can happen. #v- 2015-04-21 0:14 GMT+02:00 Arran Cudbard-Bell <a.cudbardb@freeradius.org>:
On 20 Apr 2015, at 21:16, Rygl Aleš <ales@rygl.net> wrote:
Hello Alan,
I am able to run the following setup recommeded by you, thanks.
accounting { ... redundant { sql detail } ... }
It looks good so far (~1000 req/s). The failover to the detail file is very fast (tested with LOCK - sleep - UNLOCK table). Really cool. I am in test environment and I am trying to tune the pool of sql connections in order to avoid failover now.
It would be IMHO useful if the server logs a warning that it is doing failover to a file or another instance in the redundant section. Would it be possible to add something like this? It's just something nice to have.
redundant { sql group { linelog detail } }
-Arran
Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Pozdrawiam Marcin / nicraM
Hello, It's too early to say... I am just trying both. It also depends on the particular setup, database HW, queries to DB and many other aspects. What I can see so far is that the writing to detail file tends to be more resilient to peaks in accounting traffic. I will come back with some results Ales On Tue, 21 Apr 2015 08:35:40 +0200, Marcin wrote:
So, which is better solution for performance: keep accounting data in details file, then read it and write to db with buffered-sql or write accounting to database directly? In configuration file buffered-sql we can read: #v+ The server can read accounting packets from the detail file much more quickly than those packets an be written to a database. If the database is overloaded, then bad things can happen.
#v-
2015-04-21 0:14 GMT+02:00 Arran Cudbard-Bell :
On 20 Apr 2015, at 21:16, Rygl Aleš wrote: Hello Alan, I am able to run the following setup recommeded by you, thanks. accounting { ... redundant { sql detail } ... } It looks good so far (~1000 req/s). The failover to the detail file is very
fast (tested with LOCK - sleep - UNLOCK table). Really cool. I am in test environment and I am trying to tune the pool of sql connections in order to avoid failover now. It would be IMHO useful if the server logs a
:#1010ff 2px solid; margin-left:5px; width:100%">to a file or another instance in the redundant section. W
/blockquote>possible a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC
us.org/list/users.html">http://www.freeradius.org/list/users.ht
Links: ------ [1] mailto:ales@rygl.net [2] mailto:a.cudbardb@freeradius.org
Hello all, On Tue, 21 Apr 2015 09:29:37 +0200, Aleš Rygl wrote:
Hello,
It's too early to say... I am just trying both. It also depends on the particular setup, database HW, queries to DB and many other aspects. What I can see so far is that the writing to detail file tends to be more resilient to peaks in accounting traffic.
I will come back with some results
I am back with some observations. I am runnig the latest 3.0.8. The server is doing just Accounting. It is receiving more or less steady load at up to 1.600 req/s. It is connected to Maria DB 10.0.17. Radacct table is InnoDB type, properly indexed, MariaDB has 10GB buffer_pool. OS is Debian Wheezy, HW 24GB, 2x E5345 @ 2.33GHz (8 cores in total). During the query the records are either simply inserted/updated of there is a procedure call which process the Interims a bit more complexly but everything on indexed columns. The setup: listen { ipaddr = * port = 1813 type = acct limit { } } preacct { preprocess acct_unique_mobile } accounting { redundant { sql_instance_mobile_direct group { linelog detail.mobile } } if (noop) { ok } } } With current setup I can get up to ~ 1.000 req/s without any retransmissions on the NAS side. When going higher I can see a periodical stuttering with interval of 10 minutes, where the NAS sends couple of retransissions. I am currently investigating what can be the cause as the average DB row lock time is about 60ms. I can also see that Radius does a failover to the detailfile about once per 1-2 hours. Ales
On Apr 21, 2015, at 2:35 AM, Marcin <marcin@nicram.net> wrote:
So, which is better solution for performance: keep accounting data in details file, then read it and write to db with buffered-sql or write accounting to database directly?
Typically writing to a database directly is lower latency than writing to the detail file and then to the DB. In v3, the pool configuration helps a lot. Set a "max" number of connections the DB can handle, and fail-over to the detail file. In normal operation, everything goes directly to the DB. If you get a huge spike of traffic, the detail file fills up. And then drains slowly when the spike goes away.
In configuration file buffered-sql we can read: #v+ The server can read accounting packets from the detail file much more quickly than those packets an be written to a database. If the database is overloaded, then bad things can happen.
Yes, which means you can read 100K packets/s from the detail file, and only write 2K packets/s to the DB. This shouldn't be surprising. Alan DeKok.
2015-04-21 15:38 GMT+02:00 Alan DeKok <aland@deployingradius.com>:
On Apr 21, 2015, at 2:35 AM, Marcin <marcin@nicram.net> wrote:
So, which is better solution for performance: keep accounting data in details file, then read it and write to db with buffered-sql or write accounting to database directly?
Typically writing to a database directly is lower latency than writing to the detail file and then to the DB.
Yes, but i don't care about latency. I can have even one minute late write to DB. What is more important to me it's performance and speed of freeradius answers.
In v3, the pool configuration helps a lot. Set a "max" number of connections the DB can handle, and fail-over to the detail file. In normal operation, everything goes directly to the DB. If you get a huge spike of traffic, the detail file fills up. And then drains slowly when the spike goes away.
You say about "fail-over", do you have redundant on your thought? redundant { sql detail } and then start buffered-sql. Is that right?
In configuration file buffered-sql we can read: #v+ The server can read accounting packets from the detail file much more quickly than those packets an be written to a database. If the database is overloaded, then bad things can happen.
Yes, which means you can read 100K packets/s from the detail file, and only write 2K packets/s to the DB. This shouldn't be surprising.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Pozdrawiam Marcin / nicraM
On Apr 21, 2015, at 10:09 AM, Marcin <marcin@nicram.net> wrote:
Yes, but i don't care about latency. I can have even one minute late write to DB. What is more important to me it's performance and speed of freeradius answers.
That's why FreeRADIUS is configurable. To let you customize it for your needs.
You say about "fail-over", do you have redundant on your thought?
Yes. Alan DeKok.
2015-04-21 16:14 GMT+02:00 Alan DeKok <aland@deployingradius.com>:
On Apr 21, 2015, at 10:09 AM, Marcin <marcin@nicram.net> wrote:
Yes, but i don't care about latency. I can have even one minute late write to DB. What is more important to me it's performance and speed of freeradius answers.
That's why FreeRADIUS is configurable. To let you customize it for your needs.
You say about "fail-over", do you have redundant on your thought?
Yes
Ok, thans. So please, tell me, where to keep actual login (simultaneous-use) in case of fail-over. radutmp or sql and use "redundant" option? -- Pozdrawiam Marcin / nicraM
On Apr 21, 2015, at 10:28 AM, Marcin <marcin@nicram.net> wrote:
So please, tell me, where to keep actual login (simultaneous-use) in case of fail-over. radutmp or sql and use "redundant" option?
Use SQL. You can't use "redundant" in the "session" section, because it means that Simultaneous-Use won't be checked. Alan DeKok.
21 kwi 2015 17:07 "Alan DeKok" <aland@deployingradius.com> napisał(a):
On Apr 21, 2015, at 10:28 AM, Marcin <marcin@nicram.net> wrote:
So please, tell me, where to keep actual login (simultaneous-use) in
case
of fail-over. radutmp or sql and use "redundant" option?
Use SQL. You can't use "redundant" in the "session" section, because it means that Simultaneous-Use won't be checked.
Ok. Thanks. What will freeradius answer if sql will failed?
2015-04-21 17:45 GMT+02:00 Alan DeKok <aland@deployingradius.com>:
On Apr 21, 2015, at 11:29 AM, Marcin <marcin@nicram.net> wrote:
Ok. Thanks. What will freeradius answer if sql will failed?
Whatever you tell it to answer.
Sorry, I didn't write what i had in my mind :) Proper question should sound: What FreeRADIUS answer about Simultaneous-Use when sessions are stored in sql and db will be broken? It'll will answer "accept" or "reject"? or should I configure something like that: session { sql if (fail) { ok } } -- Pozdrawiam Marcin / nicraM
Hi,
I can confirm that it is fixed now! Debian package built from git version 3.0.8 is o.k. No more Bad file descriptor errors.
Amazing! Thanks!
I know! :-) you realise how long it takes to get a bug fixed when found in one of the commercial RADIUS platforms? or how long it takes to get a feature added? alan
On Apr 17, 2015, at 5:39 PM, Rygl Aleš <ales@rygl.net> wrote:
Hmm... sounds like DB issues, to be honest. Your other message mentioned 3-5s delay writing to the DB. That should *never* happen. A normal DB should be able to handle 200-1000 writes per second.
Well, this happens just once per night where I check the radacct table for some lost Acct-Stop packets (non-closed sessions). The table has about a milion of records.
That's what indexes are for. You should have an index on acctstoptime. With that, finding records with a non-empty stop time is relatively trivial.
I have tried again. I can provide you with full debug if needed. Unfortunately there are not too much details about this error:
That's unfortunate. Hmm... I'll take a deeper look into it. It might be a platform portability thing. i.e. it works on one platform, but not another. Alan DeKok.
Hello Alan.
That's what indexes are for. You should have an index on acctstoptime. With that, finding records with a non-empty stop time is relatively trivial.
Index is there of course. The issue is you have to check if the the time interval from the last session update (which I store as well) is twice longer than Interim-Update interval (just in case I lost an Interim) and the session has Acct-Status-Type Interim-Update. I will check what explain select says here...
Hmm... I'll take a deeper look into it. It might be a platform portability thing. i.e. it works on one platform, but not another.
Thanks for your effort. Regards Ales
participants (6)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
Aleš Rygl -
Arran Cudbard-Bell -
Marcin -
Rygl Aleš