Very rare failure to expand Foreach-Variable
Once or twice per day - after many tens of thousands of requests have been successfully processed, a single request will not be processed as expected - freeradius doens't crash and there's no sign of memory corruption - further requests continue to be processed as expected. Originally this was seen on v3.0.12, but I have taken one server up to 3.0.x revision 694d088 from git and continue to see this. Running with -t to disable threading has not helped. There's a lot of custom unlang in the configuration. When run with -xx, I observe one line is missing for requests that failed. Here's a snippet from one of the failing requests: -=- radiusd[7451]: (85278) update { radiusd[7451]: (85278) &control:LU-SQL-Bridge-Exploded-Result := &control:LU-SQL-Bridge-Result -> "&request:LU-NE-Id := 2\n&control:LU-SQL-Bridge-Return-Code := noop" radiusd[7451]: (85278) } # update = noop radiusd[7451]: (85278) update { radiusd[7451]: (85278) &control:LU-SQL-Bridge-Return-Code !* ANY radiusd[7451]: (85278) } # update = noop radiusd[7451]: (85278) EXPAND %{explode:control:LU-SQL-Bridge-Exploded-Result } radiusd[7451]: (85278) --> 2 radiusd[7451]: (85278) foreach &control:LU-SQL-Bridge-Exploded-Result radiusd[7451]: (85278) if ("%{map:%{Foreach-Variable-0}}" != 1) { radiusd[7451]: (85278) EXPAND Foreach-Variable-0 radiusd[7451]: (85278) --> &request:LU-NE-Id := 2 radiusd[7451]: (85278) EXPAND %{map:%{Foreach-Variable-0}} radiusd[7451]: (85278) --> radiusd[7451]: (85278) if ("%{map:%{Foreach-Variable-0}}" != 1) -> TRUE radiusd[7451]: (85278) if ("%{map:%{Foreach-Variable-0}}" != 1) { radiusd[7451]: (85278) update { radiusd[7451]: (85278) &request:Module-Failure-Message += 'SQL bridge result contains invalid map fragment' radiusd[7451]: (85278) } # update = noop radiusd[7451]: (85278) [fail] = fail -=- And here is one (with identical inputs) that was processed as expected: -=- radiusd[7451]: (85308) update { radiusd[7451]: (85308) &control:LU-SQL-Bridge-Exploded-Result := &control:LU-SQL-Bridge-Result -> "&request:LU-NE-Id := 2\n&control:LU-SQL-Bridge-Return-Code := noop" radiusd[7451]: (85308) } # update = noop radiusd[7451]: (85308) update { radiusd[7451]: (85308) &control:LU-SQL-Bridge-Return-Code !* ANY radiusd[7451]: (85308) } # update = noop radiusd[7451]: (85308) EXPAND %{explode:control:LU-SQL-Bridge-Exploded-Result } radiusd[7451]: (85308) --> 2 radiusd[7451]: (85308) foreach &control:LU-SQL-Bridge-Exploded-Result radiusd[7451]: (85308) if ("%{map:%{Foreach-Variable-0}}" != 1) { radiusd[7451]: (85308) EXPAND Foreach-Variable-0 radiusd[7451]: (85308) --> &request:LU-NE-Id := 2 radiusd[7451]: (85308) &request:LU-NE-Id := 2 radiusd[7451]: (85308) EXPAND %{map:%{Foreach-Variable-0}} radiusd[7451]: (85308) --> 1 radiusd[7451]: (85308) if ("%{map:%{Foreach-Variable-0}}" != 1) -> FALSE -=- The line missing is '&request:LU-NE-Id := 2' - between "--> &request:LU-NE-Id := 2" and "EXPAND %{map:%{Foreach-Variable-0}}". I infer that the value of "&request:LU-NE-Id := 2" is not being returned from the expansion properly and thus map is being passed an empty string. I've had a glance around tmpl.c and modcall.c but I'm not making much progress working out where the variable value is normally printed. Can somebody more in touch with the unlang processor point me in the right direction? Graham
On Feb 16, 2019, at 5:12 PM, Graham Clinch <g.clinch@lancaster.ac.uk> wrote:
Once or twice per day - after many tens of thousands of requests have been successfully processed, a single request will not be processed as expected - freeradius doens't crash and there's no sign of memory corruption - further requests continue to be processed as expected.
Originally this was seen on v3.0.12, but I have taken one server up to 3.0.x revision 694d088 from git and continue to see this. Running with -t to disable threading has not helped.
There's a lot of custom unlang in the configuration.
That *should* be fine...
The line missing is '&request:LU-NE-Id := 2' - between "--> &request:LU-NE-Id := 2" and "EXPAND %{map:%{Foreach-Variable-0}}".
Where does that line come from? I don't think that the default is to print out bare attribute names to the debug.
I infer that the value of "&request:LU-NE-Id := 2" is not being returned from the expansion properly and thus map is being passed an empty string.
Maybe... you'll have to instrument src/main/xlat.c in order to walk through the various expansions to see both their inputs and outputs. Also, what's "%{map: ..}" doing? Is it your custom module, or is it a standard module?
I've had a glance around tmpl.c and modcall.c but I'm not making much progress working out where the variable value is normally printed. Can somebody more in touch with the unlang processor point me in the right direction?
I don't know where it prints out the attribute name like that. The dynamic expansion code prints out: EXPAND input ---> output So if the output is wrong, it's long after the string expansion. Alan DeKok.
The line missing is '&request:LU-NE-Id := 2' - between "--> &request:LU-NE-Id := 2" and "EXPAND %{map:%{Foreach-Variable-0}}".
Where does that line come from? I don't think that the default is to print out bare attribute names to the debug.
I'm now sure this occasionally missing line is normally output by the map xlat (map_debug_log called by map_to_request called by xlat_map), well after '%{Foreach-Variable-0}' has been expanded.
I infer that the value of "&request:LU-NE-Id := 2" is not being returned from the expansion properly and thus map is being passed an empty string.
Maybe... you'll have to instrument src/main/xlat.c in order to walk through the various expansions to see both their inputs and outputs.> Also, what's "%{map: ..}" doing? Is it your custom module, or is it a standard module?
It's the standard core's map xlat. I'll continue slowly winding my way down the stack. Graham
On Feb 17, 2019, at 5:52 PM, Graham Clinch <g.clinch@lancaster.ac.uk> wrote:
I'm now sure this occasionally missing line is normally output by the map xlat (map_debug_log called by map_to_request called by xlat_map), well after '%{Foreach-Variable-0}' has been expanded.
OK.
It's the standard core's map xlat.
It's been a while since I looked at v3 in any detail, unfortunately.
I'll continue slowly winding my way down the stack.
I pushed a patch to map_debug_log() that shows what it *is* getting. Odds are the the map is somehow being parsed as something other than an attribute or a list, in which case it's ignored. Alan DeKok.
I'll continue slowly winding my way down the stack.
I pushed a patch to map_debug_log() that shows what it *is* getting.
Odds are the the map is somehow being parsed as something other than an attribute or a list, in which case it's ignored.
Thanks - unfortunately it's lead me on quite a journey, and well away from map. My observations of failures caught so far, based on 3.0.x rev 3e6e385: - The breakage happens before xlat_map() gets called. - (we have correct_escapes=yes in the configuration) main/xlat.c:xlat_aprint() calls lib/value.c:value_data_from_str() which returns -1 - causing xlat_aprint to return NULL before it's got to calling node->xlat->func(). Here's the situation with a few new RDEBUGs (although I understand that without my massaged source they're not especially enlightening) - essentially showing that value_data_from_str is returning 18446744073709551615, although child looks reasonable: Rare breakage (value_data_from_str() returns <= 0) -=- Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) foreach &control:LU-SQL-Bridge-Exploded-Result Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) if ("%{map:%{Foreach-Variable-0}}" != 1) { Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) GPC: xlat_aprint XLAT_VIRTUAL Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) EXPAND Foreach-Variable-0 Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) --> &request:LU-NE-Id := 2 Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) GPC: XLAT_MODULE child=&request:LU-NE-Id := 2 Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) GPC: xlat_aprint: cf_new_escape && child: done value_data_from_str slen <= 0 slen=18446744073709551615 child=&request:LU-NE-Id := 2 Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) GPC: tmpl_aexpand: cf_new_escape && !ATTR: pre-vdfs slen=0 out='' Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) GPC: tmpl_aexpand: cf_new_escape && !ATTR: vdfs slen=0 out='' vd='' Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) EXPAND %{map:%{Foreach-Variable-0}} Feb 20 15:04:18 is-kulkea-radius1 radiusd[16633]: (6041) --> -=- Normal working (value_data_from_str() returns > 0): -=- Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) foreach &control:LU-SQL-Bridge-Exploded-Result Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) if ("%{map:%{Foreach-Variable-0}}" != 1) { Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) GPC: xlat_aprint XLAT_VIRTUAL Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) EXPAND Foreach-Variable-0 Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) --> &request:LU-NE-Id := 2 Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) GPC: XLAT_MODULE child=&request:LU-NE-Id := 2 Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) GPC: xlat_aprint: cf_new_escape && child: done value_data_from_str slen=2047, child=&request:LU-NE-Id := 2, data=&request:LU-NE-Id := 2 Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) GPC: Entering xlat_map Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) &request:LU-NE-Id := 2 Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) GPC: xlat_map: about to return ret=0 outlen=2048 Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) GPC: tmpl_aexpand: cf_new_escape && !ATTR: pre-vdfs slen=1 out='1' Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) GPC: tmpl_aexpand: cf_new_escape && !ATTR: vdfs slen=1 out='1' vd='1' Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) EXPAND %{map:%{Foreach-Variable-0}} Feb 20 15:06:31 is-kulkea-radius1 radiusd[16633]: (7091) --> 1 -=- So I want to investigate why lib/value.c:value_data_from_str() is very occasionally returning -1, but I'm hitting a wall as DEBUG statements added to lib/value.c don't seem to cause any visible output - is there a way to debug messages from inside the library? Graham
On Wed, 2019-02-20 at 15:46 +0000, Graham Clinch wrote:
So I want to investigate why lib/value.c:value_data_from_str() is very occasionally returning -1, but I'm hitting a wall as DEBUG statements added to lib/value.c don't seem to cause any visible output - is there a way to debug messages from inside the library?
printf()...? https://rr-project.org/ can be very useful if you're comfortable using gdb. -- Matthew
On Feb 20, 2019, at 10:46 AM, Graham Clinch <g.clinch@lancaster.ac.uk> wrote: My observations of failures caught so far, based on 3.0.x rev 3e6e385: - The breakage happens before xlat_map() gets called. - (we have correct_escapes=yes in the configuration) main/xlat.c:xlat_aprint() calls lib/value.c:value_data_from_str() which returns -1 - causing xlat_aprint to return NULL before it's got to calling node->xlat->func().
How is the input string wrong? That's weird.
So I want to investigate why lib/value.c:value_data_from_str() is very occasionally returning -1, but I'm hitting a wall as DEBUG statements added to lib/value.c don't seem to cause any visible output - is there a way to debug messages from inside the library?
call fr_strerror_printf() to create a message. Then from the calling function, call DEBUG("it failed; %s", fr_strerror(). TBH, in these cases I also use this a lot: fprintf(stderr, "HERE %d\n", __LINE__); fprintf(stderr, ...) is better than printf(). Because the output to stderr is flushed immediately. The output to stdout is buffered, and therefore might not show up for a while. Alan DeKok.
On 20/02/2019 16:03, Alan DeKok wrote:
On Feb 20, 2019, at 10:46 AM, Graham Clinch <g.clinch@lancaster.ac.uk> wrote: My observations of failures caught so far, based on 3.0.x rev 3e6e385: - The breakage happens before xlat_map() gets called. - (we have correct_escapes=yes in the configuration) main/xlat.c:xlat_aprint() calls lib/value.c:value_data_from_str() which returns -1 - causing xlat_aprint to return NULL before it's got to calling node->xlat->func().
How is the input string wrong? That's weird.
Apparently "Invalid escape at end of string"! -=- Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) foreach &control:LU-SQL-Bridge-Exploded-Result Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) if ("%{map:%{Foreach-Variable-0}}" != 1) { Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) GPC: xlat_aprint XLAT_VIRTUAL Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) EXPAND Foreach-Variable-0 Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) --> &request:LU-NE-Id := 1 Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) GPC: XLAT_MODULE child=&request:LU-NE-Id := 1 Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) GPC: xlat_aprint: about to call value_data_from_str child=&request:LU-NE-Id := 1, len=2047 Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) GPC: xlat_aprint: cf_new_escape && child: value_data_from_str slen <= 0 slen=18446744073709551615 child=&request:LU-NE-Id := 1 Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) GPC: xlat_aprint: value_data_from_str error=Invalid escape at end of string len=2047, buff='&request:LU-NE-Id := 1' Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) GPC: tmpl_aexpand: cf_new_escape && !ATTR: pre-vdfs slen=0 out='' Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) GPC: tmpl_aexpand: cf_new_escape && !ATTR: vdfs slen=0 out='' vd='' Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) EXPAND %{map:%{Foreach-Variable-0}} Feb 20 17:02:32 is-kulkea-radius1 radiusd[25734]: (5505) --> -=- I think: - "%{Foreach-Variable-0}" is of type XLAT_VIRTUAL, so it's talloc'd an array of fixed length 2048 (main/xlat.c line 2228) - "%{map:...}" is of type XLAT_MODULE, which calls value_data_from_str with src_len=(talloc_array_length(child)-1) = 2047 (main/xlat.c line 2267) - value_data_from_str loops through every character using the passed src_len of 2047. After sufficient entropy in the process, occasionally the final character is a backslash, which is bad news and so value_data_from_str returns -1. So I believe this can only occur when correct_escapes is on and an XLAT_MODULE is being called with an XLAT_VIRTUAL child (or an XLAT_MODULE is being called with an XLAT_MODULE child, since XLAT_MODULE also allocs a fixed length array) I'm not sure how to move towards a fix here - especially with regard to impact on binary data processing: * xlat_aprint could call value_data_from_str with src_len=strlen() rather than src_len=talloc_array_length() - but then no hope of modules processing binary. * xlat_aprint's XLAT_VIRTUAL processing could talloc_realloc to the correct length, after the virtual handler func has returned (do all the funcs return the correct length?) * ??
So I want to investigate why lib/value.c:value_data_from_str() is very occasionally returning -1, but I'm hitting a wall as DEBUG statements added to lib/value.c don't seem to cause any visible output - is there a way to debug messages from inside the library?
call fr_strerror_printf() to create a message. Then from the calling function, call DEBUG("it failed; %s", fr_strerror().
Thanks - this got me straight to the detail. Graham
On Feb 20, 2019, at 12:52 PM, Graham Clinch <g.clinch@lancaster.ac.uk> wrote:
I think:
- "%{Foreach-Variable-0}" is of type XLAT_VIRTUAL, so it's talloc'd an array of fixed length 2048 (main/xlat.c line 2228) - "%{map:...}" is of type XLAT_MODULE, which calls value_data_from_str with src_len=(talloc_array_length(child)-1) = 2047 (main/xlat.c line 2267)
That's correct for value_data_from_str(). But if the input doesn't contain 2K of data, then value_data_from_str() shouldn't be told it has 2K of data.
- value_data_from_str loops through every character using the passed src_len of 2047. After sufficient entropy in the process, occasionally the final character is a backslash, which is bad news and so value_data_from_str returns -1.
So two issues. One, the field isn't initialized (oops), and second, the wrong length is being passed to value_data_from_str().
So I believe this can only occur when correct_escapes is on and an XLAT_MODULE is being called with an XLAT_VIRTUAL child (or an XLAT_MODULE is being called with an XLAT_MODULE child, since XLAT_MODULE also allocs a fixed length array)
I'm not sure how to move towards a fix here - especially with regard to impact on binary data processing:
I've pushed a fix. :)
* xlat_aprint could call value_data_from_str with src_len=strlen() rather than src_len=talloc_array_length() - but then no hope of modules processing binary. * xlat_aprint's XLAT_VIRTUAL processing could talloc_realloc to the correct length, after the virtual handler func has returned (do all the funcs return the correct length?)
Yes, that's it.
Thanks - this got me straight to the detail.
Good to hear. That's an esoteric bug, and good to have fixed. Thanks a bunch! Alan DeKok.
participants (3)
-
Alan DeKok -
Graham Clinch -
Matthew Newton