Very rare failure to expand Foreach-Variable

[Graham Clinch]

On 20/02/2019 16:03, Alan DeKok wrote:
> 
>> On Feb 20, 2019, at 10:46 AM, Graham Clinch <g.clinch at 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