Hi, This could be related to a similar problem reported a couple of weeks ago. We have a FreeRADIUS 2.1.6 installation running on 64bit CentOS 5.3. The radiusd process is allocating more and more memory with time (around 0.5GB a day). There are only around 5-6 requests/s and other than chewing all memory the server doesn't seem to be doing much work. This radius instance has only one sql module (rlm_sql_mysql) in the authorize section and another one - sql_log (writing to a local file) in the post-auth section. The detail module is listed in accounting{} section but it's not used on this box (nothing is set to send accounting information to this server) All other sections in the default site are empty (the box only does auth) I've followed the advise from the previous thread and run radiusd under valgrind for around 10-15 minutes with some generated traffic and the output is: valgrind --tool=memcheck --leak-check=full /usr/sbin/radiusd -f [..] ==11730== LEAK SUMMARY: ==11730== definitely lost: 8,705,168 bytes in 27,890 blocks. ==11730== indirectly lost: 8,351,440 bytes in 26,598 blocks. ==11730== possibly lost: 17,072 bytes in 56 blocks. ==11730== still reachable: 118,598 bytes in 2,467 blocks. ==11730== suppressed: 0 bytes in 0 blocks. ==11730== Reachable blocks (those to which a pointer was found) are not shown. Is there anything else I can do to track it down and possibly fix the problem? Would setting up max_request_per_server to something else than 0 be a good workaround for it in the meantime? -- szymon roczniak simon@dischaos.com
Szymon Roczniak wrote:
I've followed the advise from the previous thread and run radiusd under valgrind for around 10-15 minutes with some generated traffic and the output is:
valgrind --tool=memcheck --leak-check=full /usr/sbin/radiusd -f
You should add "-m" to the radiusd command line, so that it will try to clean up as much memory as possible before exiting.
[..] ==11730== LEAK SUMMARY: ==11730== definitely lost: 8,705,168 bytes in 27,890 blocks. ==11730== indirectly lost: 8,351,440 bytes in 26,598 blocks. ==11730== possibly lost: 17,072 bytes in 56 blocks. ==11730== still reachable: 118,598 bytes in 2,467 blocks. ==11730== suppressed: 0 bytes in 0 blocks. ==11730== Reachable blocks (those to which a pointer was found) are not shown.
Is there anything else I can do to track it down and possibly fix the problem?
$ valgrind --tool=massif /usr/sbin/radiusd -fm ... (make it exit cleanly) $ ms_print massif* > radiusd.txt That will print out where it *allocates* memory. This helps to catch cases where the memory isn't leaked, but also isn't being free'd.
Would setting up max_request_per_server to something else than 0 be a good workaround for it in the meantime?
No. Alan DeKok.
On Thu, Sep 03, 2009 at 03:02:23PM +0200, Alan DeKok wrote:
You should add "-m" to the radiusd command line, so that it will try to clean up as much memory as possible before exiting.
Output with "-m" and some more debugging information: 34,944 bytes in 112 blocks are definitely lost in loss record 38 of 44 at 0x4C20809: malloc (vg_replace_malloc.c:149) by 0x4E38DCE: pairalloc (in /usr/lib64/freeradius/libfreeradius-radius-2.1.6.so) by 0x4E39160: pairmake (in /usr/lib64/freeradius/libfreeradius-radius-2.1.6.so) by 0x6A393E1: sql_userparse (in /usr/lib64/freeradius/rlm_sql-2.1.6.so) by 0x6A395D4: sql_getvpdata (in /usr/lib64/freeradius/rlm_sql-2.1.6.so) by 0x6A37741: (within /usr/lib64/freeradius/rlm_sql-2.1.6.so) by 0x419B2B: modcall (modcall.c:286) by 0x417040: indexed_modcall (modules.c:631) by 0x40853A: rad_authenticate (auth.c:554) by 0x423D87: radius_handle_request (event.c:3646) by 0x41C7C7: request_handler_thread (threads.c:492) by 0x5478366: start_thread (in /lib64/libpthread-2.5.so) LEAK SUMMARY: definitely lost: 34,944 bytes in 112 blocks. possibly lost: 3,040 bytes in 10 blocks. still reachable: 3,752,939 bytes in 21,575 blocks. suppressed: 0 bytes in 0 blocks. I think the problem is somewhere in our configuration for the sql module as it only affects one particular radius setup we have and not others (all running 2.1.6). In fact one of our servers has two different sql modules called depending on realm. It shows high memory usage when radius uses one of them (the one tested with the above valgrind output) and it doesn't when the other module is used. I'm trying to find out what exactly makes the difference in memory usage between these modules.
$ valgrind --tool=massif /usr/sbin/radiusd -fm That will print out where it *allocates* memory. This helps to catch cases where the memory isn't leaked, but also isn't being free'd.
Output is available here: http://dischaos.com/radius/massif.out -- szymon roczniak simon@dischaos.com
Szymon Roczniak wrote:
Output with "-m" and some more debugging information:
OK, that helps...
34,944 bytes in 112 blocks are definitely lost in loss record 38 of 44 at 0x4C20809: malloc (vg_replace_malloc.c:149) by 0x4E38DCE: pairalloc (in /usr/lib64/freeradius/libfreeradius-radius-2.1.6.so) by 0x4E39160: pairmake (in /usr/lib64/freeradius/libfreeradius-radius-2.1.6.so) by 0x6A393E1: sql_userparse (in /usr/lib64/freeradius/rlm_sql-2.1.6.so) by 0x6A395D4: sql_getvpdata (in /usr/lib64/freeradius/rlm_sql-2.1.6.so) by 0x6A37741: (within /usr/lib64/freeradius/rlm_sql-2.1.6.so)
Ugh. That line doesn't help. It would be nice to know WHICH function had the problem. Can you re-build the rlm_sql module with debugging symbols? (-g, and DELETE any -O2 flags you find). That way, it will print out line numbers like the following:
by 0x419B2B: modcall (modcall.c:286) by 0x417040: indexed_modcall (modules.c:631)
Here we know exactly which line is being used...
I think the problem is somewhere in our configuration for the sql module as it only affects one particular radius setup we have and not others (all running 2.1.6).
What are the attributes in the DB for the one that leaks memory?
In fact one of our servers has two different sql modules called depending on realm. It shows high memory usage when radius uses one of them (the one tested with the above valgrind output) and it doesn't when the other module is used.
So... the content of the DB is what matters here. Alan DeKok.
On Fri, Sep 04, 2009 at 02:27:13PM +0200, Alan DeKok wrote:
Can you re-build the rlm_sql module with debugging symbols? (-g, and DELETE any -O2 flags you find). That way, it will print out line numbers like the following:
I can't make valgrind print file lines from modules for some reason. I've build radius and all modules with -g and can see all debugging information in gdb but not valgrind (at least not with memcheck, it works fine and prints line numbers with callgrind...)
What are the attributes in the DB for the one that leaks memory?
The one that uses leaking memory returns "Auth-Type : Accept" from authorize_check_query on realm match. Authorize_reply_query returns Context-Name and 1-10 groups of Tunnel-Type, Tunnel-Password, Tunnel-Preference and Tunnel-Server-Endpoint. the Auth query is: authorize_check_query = "SELECT 1,'notused','Auth-Type','Accept',':' FROM ${authcheck_table} WHERE Realm = substring_index('%{SQL-User-Name} ','@',-1)" and sample output from reply_query: Tunnel-Type:0 += L2TP Tunnel-Password:0 += "xxx" Tunnel-Preference:0 += 10 Tunnel-Server-Endpoint:0 += "1.2.3.4" Context-Name := "local" Tunnel-Type:1 += L2TP Tunnel-Password:1 += "xxx" Tunnel-Preference:1 += 10 Tunnel-Server-Endpoint:1 += "1.2.3.5" Tunnel-Type:2 += L2TP Tunnel-Password:2 += "xxx" Tunnel-Preference:2 += 10 Tunnel-Server-Endpoint:2 += "1.2.3.6" This works fine, but I guess it's probably not the best way of doing it... -- szymon roczniak simon@dischaos.com
Szymon Roczniak wrote:
The one that uses leaking memory returns "Auth-Type : Accept" from
":" ? What's that?
authorize_check_query = "SELECT 1,'notused','Auth-Type','Accept',':' FROM
That's the issue. The operator is wrong. Use ":=", not ":" It shouldn't leak memory, so that still needs to be fixed. I'm not sure why it leaks, either. All of the code paths *appear* to clean up after themselves. But the rlm_sql code is rather too complicated for its own good. Alan DeKok.
On Tue, Sep 08, 2009 at 01:59:05PM +0200, Alan DeKok wrote:
Szymon Roczniak wrote:
authorize_check_query = "SELECT 1,'notused','Auth-Type','Accept',':' FROM
That's the issue. The operator is wrong. Use ":=", not ":"
That's an error, the production configuration has ':=' in the operator field. It's odd, but it looks like it doesn't matter what operator is used in this place. In fact it still works even without one (I've just tested it with some random 'operators' and with the operator field set to ""). The output at the end of auth group is: Found Auth-Type = Accept Auth-Type = Accept, accepting the user
I'm not sure why it leaks, either. All of the code paths *appear* to
I'll see if I can provide more debugging information to track it down.
clean up after themselves. But the rlm_sql code is rather too
There are some code paths (in rlm_sql.c/rlm_sql_authorize()) where only one of the temporary pair lists (check_tmp) is freed before returning from the function and in other cases both check_tmp and reply_tmp are cleaned with pairfree(). I'm not sure it's a problem at all. And it's certainly not relevant in this case, as the execution goes past these checks and gets to the point where both temp lists are released. -- szymon roczniak simon@dischaos.com
Szymon Roczniak wrote:
It's odd, but it looks like it doesn't matter what operator is used in this place. In fact it still works even without one (I've just tested it with some random 'operators' and with the operator field set to "").
Yes... I saw that, and just fixed it.
There are some code paths (in rlm_sql.c/rlm_sql_authorize()) where only one of the temporary pair lists (check_tmp) is freed before returning from the function and in other cases both check_tmp and reply_tmp are cleaned with pairfree(). I'm not sure it's a problem at all. And it's certainly not relevant in this case, as the execution goes past these checks and gets to the point where both temp lists are released.
Yes... so I'd really like to know what else is going on. From the valgrind log you posted, the leaks are full VALUE_PAIR structures... so there's only a limited number of places where that can happen. Oh well. I think it's time to release 2.1.7, despite these issues. Alan DeKok.
participants (2)
-
Alan DeKok -
Szymon Roczniak