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