Very rare failure to expand Foreach-Variable

[Graham Clinch]

>> 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