Memory leak parsing/relaying from detail files?
Hi, I am working through debugging a memory leak I am hitting, and I think I have found the culprit. The trigger appears to be a malformed NAS-IPv6-Address attribute coming from a Cisco ASR9000, and I will certainly contact the vendor, however it occurs to me that we should work to solve this in FreeRADIUS as well. We use reliable proxied accounting with the detail file reader, however we write everything to a file and read from that file rather than writing only if the backend server pool has no reachable members. We are running 3.0.11, based on the 3.0.4 Redhat RPMs which we have forward ported. The ASR9000 sends a NAS-IPv6-Address attribute as follows: 0000 5f 16 1a 10 97 8c 00 00 00 00 00 00 00 00 00 00 _............... 0010 00 00 00 00 00 00 …… This has a length field of 0x16, while the standard defines this as always 0x12 - an IPv6 address is 16 bytes, plus two bytes for the type/len. I’m not sure what the ASR9000 thinks is going on.. but I guess that’s not in scope for this memory leak per se. FreeRADIUS interprets this as being not a valid NAS-IPv6-Address, so internally treats it as Attr-95 rather than NAS-IPv6-Address, which is the behaviour I’d expect. This gets written to a detail file, and some time later the detail file reader calls through to dict_unknown_afrom_fields, which allocates some memory that seems to never get freed. Running in valgrind, once for 5 mins, once for 25 mins, we note that the following call stack shows up as much larger after 25 mins. Here it is after about 5 mins: ==31363== 1,379,332 bytes in 5,653 blocks are definitely lost in loss record 1,935 of 1,937 ==31363== at 0x4C29BFD: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so) ==31363== by 0x5B0CA20: __talloc_with_prefix (talloc.c:615) ==31363== by 0x5B0CA20: __talloc (talloc.c:655) ==31363== by 0x5B0CA20: _talloc_named_const (talloc.c:812) ==31363== by 0x5B0CA20: _talloc_zero (talloc.c:2206) ==31363== by 0x50786DE: dict_unknown_afrom_fields (dict.c:2826) ==31363== by 0x508573F: data2vp (radius.c:3794) ==31363== by 0x507F1B1: fr_pair_from_unkown (pair.c:1267) ==31363== by 0x507F1B1: fr_pair_make_unknown (pair.c:1365) ==31363== by 0x507F1B1: fr_pair_make (pair.c:1439) ==31363== by 0x507F807: fr_pair_list_afrom_str (pair.c:1865) ==31363== by 0x146B18: detail_poll (detail.c:735) ==31363== by 0x147028: detail_handler_thread (detail.c:1085) ==31363== by 0x67BBDF4: start_thread (pthread_create.c:308) ==31363== by 0x6F431AC: clone (clone.S:113) Again after about 25 mins: ==10362== 7,163,840 bytes in 29,360 blocks are definitely lost in loss record 1,943 of 1,944 ==10362== at 0x4C29BFD: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so) ==10362== by 0x5B0CA20: __talloc_with_prefix (talloc.c:615) ==10362== by 0x5B0CA20: __talloc (talloc.c:655) ==10362== by 0x5B0CA20: _talloc_named_const (talloc.c:812) ==10362== by 0x5B0CA20: _talloc_zero (talloc.c:2206) ==10362== by 0x50786DE: dict_unknown_afrom_fields (dict.c:2826) ==10362== by 0x508573F: data2vp (radius.c:3794) ==10362== by 0x507F1B1: fr_pair_from_unkown (pair.c:1267) ==10362== by 0x507F1B1: fr_pair_make_unknown (pair.c:1365) ==10362== by 0x507F1B1: fr_pair_make (pair.c:1439) ==10362== by 0x507F807: fr_pair_list_afrom_str (pair.c:1865) ==10362== by 0x146B18: detail_poll (detail.c:735) ==10362== by 0x147028: detail_handler_thread (detail.c:1085) ==10362== by 0x67BBDF4: start_thread (pthread_create.c:308) ==10362== by 0x6F431AC: clone (clone.S:113) I have set up GDB to print out a backtrace whenever dict_unknown_afrom_fields is called with fr_pair_from_unkown 2 frames up the stack. We get this: #0 dict_unknown_afrom_fields (ctx=ctx@entry=0x0, attr=95, vendor=0) at src/lib/dict.c:2822 #1 0x00007fee4f416740 in data2vp (ctx=ctx@entry=0x0, packet=packet@entry=0x0, original=original@entry=0x0, secret=secret@entry=0x0, da=<optimized out>, start=<optimized out>, attrlen=20, packetlen=20, pvp=pvp@entry=0x7fee42bec848) at src/lib/radius.c:3794 #2 0x00007fee4f4101b2 in fr_pair_from_unkown (da=<optimized out>, vp=0x7fee340e3690) at src/lib/pair.c:1267 #3 fr_pair_make_unknown (op=<optimized out>, value=0x7fee42bec9d0 "Attr-95", attribute=0x7fee42bec9d0 "Attr-95", ctx=0x7fee5079c3f0) at src/lib/pair.c:1365 #4 fr_pair_make (ctx=ctx@entry=0x7fee5079c3f0, vps=vps@entry=0x0, attribute=attribute@entry=0x7fee42bec9d0 "Attr-95", value=value@entry=0x7fee42becad0 "0x1a108834", '0' <repeats 32 times>, op=<optimized out>) at src/lib/pair.c:1439 #5 0x00007fee4f410808 in fr_pair_list_afrom_str (ctx=ctx@entry=0x7fee5079c3f0, buffer=buffer@entry=0x7fee42bed570 "\tAttr-95 = 0x1a108834", '0' <repeats 32 times>, "\n", list=list@entry=0x7fee42becf48) at src/lib/pair.c:1865 #6 0x00007fee4facdb19 in detail_poll (listener=listener@entry=0x7fee5079c2a0) at src/main/detail.c:735 #7 0x00007fee4face029 in detail_handler_thread (arg=0x7fee5079c2a0) at src/main/detail.c:1085 #8 0x00007fee4dcd7df5 in start_thread (arg=0x7fee42bee700) at pthread_create.c:308 #9 0x00007fee4d5881ad in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 Note Attr-95 - this is in every one of these backtraces that I looked at. I have attempted to filter out both Attr-95 and NAS-IPv6-Address at the start of my accounting section before it is written to the detail file - we don’t use this attribute so don’t care. I do this with the following: if (Attr-95) { update request { Attr-95 !* ANY } } But if (Attr-95) always returns false. I tried the same logic with NAS-IPv6-Address and get the same result, same trying this in preacct. Preacct has had no configuration changed from the standard “default” site config. Here is a trimmed output - let me know if you want the full thing, and I will get some test circuits set up which don’t have customer data: (469) Tue Mar 8 15:33:39 2016: Debug: Received Accounting-Request Id 141 from 103.241.56.176:51487 to 10.55.86.12:1813 length 1100 .. trimmed .. (469) Tue Mar 8 15:33:39 2016: Debug: Attr-95 = 0x1a10983400000000000000000000000000000000 .. trimmed .. (469) Tue Mar 8 15:33:39 2016: Debug: # Executing section preacct from file /etc/raddb/sites-enabled/trustpower-frontend .. trimmed .. (469) Tue Mar 8 15:33:40 2016: Debug: # Executing section accounting from file /etc/raddb/sites-enabled/trustpower-frontend (469) Tue Mar 8 15:33:40 2016: Debug: accounting { (469) Tue Mar 8 15:33:40 2016: Debug: if (Attr-95) { (469) Tue Mar 8 15:33:40 2016: Debug: if (Attr-95) -> FALSE I have two questions: 1) Can I filter this out in some way that I am unaware of as a short term fix? 2) I would like to figure out this memory leak myself and submit a patch, but I’m not sure how this part of the code works. I *think* that this should be freed after being proxied to the backend server - so, perhaps in process.c somewhere after a packet is sent, it should have any vp das that have is_unknown set to true freed? I’m not clear to me what impact that would have on other bits of code. -- Nathan Ward
On 8 Mar 2016, at 00:10, Nathan Ward <lists+freeradius@daork.net> wrote:
Hi,
I am working through debugging a memory leak I am hitting, and I think I have found the culprit.
Yeah looks broken in v3.1.x too, good catch/sleuthing.
The trigger appears to be a malformed NAS-IPv6-Address attribute coming from a Cisco ASR9000, and I will certainly contact the vendor, however it occurs to me that we should work to solve this in FreeRADIUS as well.
Yes.
I have two questions: 1) Can I filter this out in some way that I am unaware of as a short term fix?
Not in this case no. This particular type of unknown (malformed) attribute is invisible to the policy language. You might have some success with the attr_filter module, but you'd need to list all the attributes you wanted to keep.
2) I would like to figure out this memory leak myself and submit a patch, but I’m not sure how this part of the code works. I *think* that this should be freed after being proxied to the backend server - so, perhaps in process.c somewhere after a packet is sent, it should have any vp das that have is_unknown set to true freed? I’m not clear to me what impact that would have on other bits of code.
The lifetime of the unknown attribute should be tied to the VALUE_PAIR it was created for and that's not being done. I'm not sure those functions are correctly structured. Will review tomorrow unless Alan D gets there first. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On Mar 8, 2016, at 12:10 AM, Nathan Ward <lists+freeradius@daork.net> wrote:
I am working through debugging a memory leak I am hitting, and I think I have found the culprit.
The trigger appears to be a malformed NAS-IPv6-Address attribute coming from a Cisco ASR9000, and I will certainly contact the vendor, however it occurs to me that we should work to solve this in FreeRADIUS as well.
I've pushed a fix to v3.0.x. I'll push a fix to v3.1.x later today. The backtrace and gdb output was exactly what I needed to fix it. Alan DeKok.
On 9/03/2016, at 03:10, Alan DeKok <aland@deployingradius.com> wrote:
On Mar 8, 2016, at 12:10 AM, Nathan Ward <lists+freeradius@daork.net> wrote:
I am working through debugging a memory leak I am hitting, and I think I have found the culprit.
The trigger appears to be a malformed NAS-IPv6-Address attribute coming from a Cisco ASR9000, and I will certainly contact the vendor, however it occurs to me that we should work to solve this in FreeRADIUS as well.
I've pushed a fix to v3.0.x. I'll push a fix to v3.1.x later today.
The backtrace and gdb output was exactly what I needed to fix it.
Hi Alan, Thanks for that, that’s awesome. I have applied your patch, presuming that the only changes in this area are in commit 6b8457f0cfaaf23ee3660d658a8bfa3d7c2b6a2b. I note that there are no other changes to pair.c around that time. If there are changes I’ve missed, please let me know. I am curious whether commit 296eeeb103cac714a58ae64a8130664b527495eb is related, but, I’m not certain. I noted immediately that the memory leak no longer shows in valgrind, which is good! However, I have since noted that the memory usage on the process still increases over time, at the same rate as before. I think what is happening is that now the that the talloc context is set, valgrind no longer recognises it as a leak as it doesn’t consider memory that talloc is managing to be a leak, however we are still allocating memory for something that is never used again (the Attr-95 attribute name) and expanding that talloc context (I don’t know much about talloc, can you tell? :-). What did you think of my prior suggestion in question 2 of my original email: 2) I would like to figure out this memory leak myself and submit a patch, but I’m not sure how this part of the code works. I *think* that this should be freed after being proxied to the backend server - so, perhaps in process.c somewhere after a packet is sent, it should have any vp das that have is_unknown set to true freed? I’m not clear what impact that would have on other bits of code. Of course, happy to write the code, but some guidance on whether this is appropriate or likely to harm other processes would be helpful. Another option that I have considered is whether it would be good to just prevent the detail reader from reading unknown attributes. I imagine that might have some impact on people who rely on sending data which FreeRADIUS doesn’t have dictionaries for, however. I have managed to filter out the bad attribute, temporarily, by re-defining NAS-IPv6-Address in the dictionary to be “octets” type so that it is visible to unlang and can strip it out before it’s written to the file. I do not have any NASes relying on this attribute, so things are working OK. I also had to remove it from the Acct-Unique-Session-Id generation in the acct_unique policy, so that it would not impact existing sessions while I implemented this change. I would, of course, like to find a long term solution for this. I can relax somewhat though, which is helpful. Naturally, I’m progressing this with the vendor for a fix on their end, too. -- Nathan Ward
On Apr 14, 2016, at 8:43 PM, Nathan Ward <lists+freeradius@daork.net> wrote:
I have applied your patch, presuming that the only changes in this area are in commit 6b8457f0cfaaf23ee3660d658a8bfa3d7c2b6a2b. I note that there are no other changes to pair.c around that time. If there are changes I’ve missed, please let me know.
That's it.
I am curious whether commit 296eeeb103cac714a58ae64a8130664b527495eb is related, but, I’m not certain.
It's not related.
I noted immediately that the memory leak no longer shows in valgrind, which is good!
Good..
However, I have since noted that the memory usage on the process still increases over time, at the same rate as before. I think what is happening is that now the that the talloc context is set, valgrind no longer recognises it as a leak as it doesn’t consider memory that talloc is managing to be a leak, however we are still allocating memory for something that is never used again (the Attr-95 attribute name) and expanding that talloc context (I don’t know much about talloc, can you tell? :-).
Are you sure it's the same issue? i.e. if you update the dictionary to have NAS-IPv6-Address be of type "octets", does the same file now *not* leak memory?
What did you think of my prior suggestion in question 2 of my original email: 2) I would like to figure out this memory leak myself and submit a patch, but I’m not sure how this part of the code works. I *think* that this should be freed after being proxied to the backend server - so, perhaps in process.c somewhere after a packet is sent, it should have any vp das that have is_unknown set to true freed? I’m not clear what impact that would have on other bits of code.
The memory should be freed automatically. I've pushed some changes which may help. The issue is that we have a talloc context. When the context gets freed, everything in it gets freed. The context includes a VALUE_PAIR, usually 'vp', and the VALUE_PAIR includes a DICT_ATTR, vp->da. The da (if unknown) SHOULD be parented from the vp. So when the vp is freed, so is the da.
Of course, happy to write the code, but some guidance on whether this is appropriate or likely to harm other processes would be helpful.
The key is to ensure that the da has the correct parent. It will then be automatically freed as necessary.
Another option that I have considered is whether it would be good to just prevent the detail reader from reading unknown attributes. I imagine that might have some impact on people who rely on sending data which FreeRADIUS doesn’t have dictionaries for, however.
Yes.
I have managed to filter out the bad attribute, temporarily, by re-defining NAS-IPv6-Address in the dictionary to be “octets” type so that it is visible to unlang and can strip it out before it’s written to the file. I do not have any NASes relying on this attribute, so things are working OK. I also had to remove it from the Acct-Unique-Session-Id generation in the acct_unique policy, so that it would not impact existing sessions while I implemented this change. I would, of course, like to find a long term solution for this. I can relax somewhat though, which is helpful.
OK.
Naturally, I’m progressing this with the vendor for a fix on their end, too.
That would be good. I'll see if there are fixes to the detail file reader which may help. But the patches I pushed today might fix it... Alan DeKok.
On 16/04/2016, at 03:55, Alan DeKok <aland@deployingradius.com> wrote:
On Apr 14, 2016, at 8:43 PM, Nathan Ward <lists+freeradius@daork.net> wrote:
However, I have since noted that the memory usage on the process still increases over time, at the same rate as before. I think what is happening is that now the that the talloc context is set, valgrind no longer recognises it as a leak as it doesn’t consider memory that talloc is managing to be a leak, however we are still allocating memory for something that is never used again (the Attr-95 attribute name) and expanding that talloc context (I don’t know much about talloc, can you tell? :-).
Are you sure it's the same issue?
i.e. if you update the dictionary to have NAS-IPv6-Address be of type "octets", does the same file now *not* leak memory?
I’ll do some further testing shortly, but so far I have set NAS-IPv6-Address to octets *and* removed it before writing to the file which does not leak memory. I will try it without removing it, but I don’t expect it will make a difference - let’s find out.
What did you think of my prior suggestion in question 2 of my original email: 2) I would like to figure out this memory leak myself and submit a patch, but I’m not sure how this part of the code works. I *think* that this should be freed after being proxied to the backend server - so, perhaps in process.c somewhere after a packet is sent, it should have any vp das that have is_unknown set to true freed? I’m not clear what impact that would have on other bits of code.
The memory should be freed automatically.
I've pushed some changes which may help. The issue is that we have a talloc context. When the context gets freed, everything in it gets freed. The context includes a VALUE_PAIR, usually 'vp', and the VALUE_PAIR includes a DICT_ATTR, vp->da. The da (if unknown) SHOULD be parented from the vp. So when the vp is freed, so is the da.
OK, I’ll go read some code and try understand this some more.
Of course, happy to write the code, but some guidance on whether this is appropriate or likely to harm other processes would be helpful.
The key is to ensure that the da has the correct parent. It will then be automatically freed as necessary.
Got it.
Naturally, I’m progressing this with the vendor for a fix on their end, too.
That would be good.
I'll see if there are fixes to the detail file reader which may help. But the patches I pushed today might fix it...
Thanks. I’ll do the above test, and have a look at the recent patches and see if they help, and then report back. -- Nathan Ward
participants (3)
-
Alan DeKok -
Arran Cudbard-Bell -
Nathan Ward