Very rare failure to expand Foreach-Variable

[Graham Clinch]

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