[engine] Implement template location tracking with slf4j MDC tags; disabled by default

git-svn-id: https://svn.apache.org/repos/asf/velocity/engine/trunk@1858687 13f79535-47bb-0310-9956-ffa450edef68

9 files changed, 860 insertions, 615 deletions

diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeConstants.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeConstants.java
index ed8ae1c3..27782632 100644
--- a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeConstants.java
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeConstants.java
@@ -57,9 +57,11 @@ public interface RuntimeConstants extends DeprecatedRuntimeConstants
     /** Logging of invalid method calls. */
     String RUNTIME_LOG_METHOD_CALL_LOG_INVALID = "runtime.log.log_invalid_method_calls";
 
-    /** Whether to use string interning. */
-    String RUNTIME_STRING_INTERNING = "runtime.string_interning";
-
+    /** Whether to populate slf4j's MDC with location in template file
+     *  @since 2.2
+     */
+    String RUNTIME_LOG_TRACK_LOCATION = "runtime.log.track_location";
+    
     /*
      * ----------------------------------------------------------------------
      * D I R E C T I V E  C O N F I G U R A T I O N
@@ -369,6 +371,9 @@ public interface RuntimeConstants extends DeprecatedRuntimeConstants
      * ----------------------------------------------------------------------
      */
 
+    /** Whether to use string interning. */
+    String RUNTIME_STRING_INTERNING = "runtime.string_interning";
+    
     /** Switch for the interpolation facility for string literals. */
     String INTERPOLATE_STRINGLITERALS = "runtime.interpolate_string_literals";
 
diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeInstance.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeInstance.java
index 498d7aaf..c72491a6 100644
--- a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeInstance.java
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeInstance.java
@@ -37,6 +37,7 @@ import org.apache.velocity.runtime.directive.Directive;
 import org.apache.velocity.runtime.directive.Macro;
 import org.apache.velocity.runtime.directive.Scope;
 import org.apache.velocity.runtime.directive.StopCommand;
+import org.apache.velocity.runtime.parser.LogContext;
 import org.apache.velocity.runtime.parser.ParseException;
 import org.apache.velocity.runtime.parser.Parser;
 import org.apache.velocity.runtime.parser.node.Node;
@@ -120,7 +121,7 @@ public class RuntimeInstance implements RuntimeConstants, RuntimeServices
     /**
      * The Runtime parser pool
      */
-    private  ParserPool parserPool;
+    private ParserPool parserPool;
 
     /**
      * Indicate whether the Runtime is in the midst of initialization.
@@ -136,7 +137,7 @@ public class RuntimeInstance implements RuntimeConstants, RuntimeServices
      * These are the properties that are laid down over top
      * of the default properties when requested.
      */
-    private  ExtProperties overridingProperties = null;
+    private ExtProperties overridingProperties = null;
 
     /**
      * This is a hashtable of initialized directives.
@@ -220,6 +221,11 @@ public class RuntimeInstance implements RuntimeConstants, RuntimeServices
     private boolean hyphenAllowedInIdentifiers;
 
     /**
+     * The LogContext object used to track location in templates
+     */
+    private LogContext logContext;
+
+    /**
      * Creates a new RuntimeInstance object.
      */
     public RuntimeInstance()
@@ -952,6 +958,10 @@ public class RuntimeInstance implements RuntimeConstants, RuntimeServices
             }
             /* else keep our default Velocity logger
              */
+
+            /* Initialize LogContext */
+            boolean trackLocation = getBoolean(RUNTIME_LOG_TRACK_LOCATION, false);
+            logContext = new LogContext(trackLocation);
         }
         catch (Exception e)
         {
@@ -1672,6 +1682,16 @@ public class RuntimeInstance implements RuntimeConstants, RuntimeServices
     }
 
     /**
+     * Get the LogContext object used to tack locations in templates.
+     * @return LogContext object
+     * @since 2.2
+     */
+    public LogContext getLogContext()
+    {
+        return logContext;
+    }
+
+    /**
      * String property accessor method with default to hide the
      * configuration implementation.
      *
diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeServices.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeServices.java
index 371267f0..20f63a3a 100644
--- a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeServices.java
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/RuntimeServices.java
@@ -28,6 +28,7 @@ import org.apache.velocity.exception.ResourceNotFoundException;
 import org.apache.velocity.runtime.RuntimeConstants.SpaceGobbling;
 import org.apache.velocity.runtime.directive.Directive;
 import org.apache.velocity.runtime.directive.Macro;
+import org.apache.velocity.runtime.parser.LogContext;
 import org.apache.velocity.runtime.parser.ParseException;
 import org.apache.velocity.runtime.parser.Parser;
 import org.apache.velocity.runtime.parser.node.Node;
@@ -429,7 +430,14 @@ public interface RuntimeServices
      */
     Logger getLog(String childNamespace);
 
-    /**
+   /**
+    * Get the LogContext object used to tack locations in templates.
+    * @return LogContext object
+    * @since 2.2
+    */
+   LogContext getLogContext();
+
+   /**
      * Returns the event handlers for the application.
      * @return The event handlers for the application.
      */
diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/LogContext.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/LogContext.java
new file mode 100644
index 00000000..455f2675
--- /dev/null
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/LogContext.java
@@ -0,0 +1,140 @@
+package org.apache.velocity.runtime.parser;
+
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ */
+
+import org.apache.velocity.util.introspection.Info;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
+
+import java.util.ArrayDeque;
+import java.util.Deque;
+
+/**
+ * <p>Track location in template files during rendering by populating the slf4j MDC tags <code>file</code>, <code>line</code> and <code>column</code>.</p>
+ * <p>An MDC-aware logger can then use this info to display the template location in the message</p>
+ * <p>For instance with webapp-slf4j-logger, it's enough to use <code>%file</code>, <code>%line</code> and <code>%column</code> in the logger format string.</p>
+ * <p>Since this feature can have a performance impact, it has to be enabled in <code>velocity.properties</code> using:</p>
+ * <pre><code>runtime.log.track_location = true</code></pre>
+ * <p>(typically in a development environment)</p>
+ *
+ * @author Claude Brisson
+ * @version $Id:$
+ * @since 2.2
+ */
+
+public class LogContext
+{
+    protected static Logger logger = LoggerFactory.getLogger(LogContext.class);
+
+    public static final String MDC_FILE = "file";
+    public static final String MDC_LINE = "line";
+    public static final String MDC_COLUMN = "column";
+
+    private boolean trackLocation;
+
+    public LogContext(boolean trackLocation)
+    {
+        this.trackLocation = trackLocation;
+    }
+
+    private static ThreadLocal<Deque<StackElement>> contextStack = new ThreadLocal<Deque<StackElement>>()
+    {
+        @Override
+        public Deque<StackElement> initialValue()
+        {
+            return new ArrayDeque<StackElement>();
+        }
+    };
+
+    private static class StackElement
+    {
+        protected StackElement(Object src, Info info)
+        {
+            this.src = src;
+            this.info = info;
+        }
+
+        protected Object src;
+        protected int count = 1;
+        protected Info info;
+    }
+
+    public void pushLogContext(Object src, Info info)
+    {
+        if (!trackLocation)
+        {
+            return;
+        }
+        Deque<StackElement> stack = contextStack.get();
+        StackElement last = stack.peek();
+        if (last != null && last.src == src)
+        {
+            ++last.count;
+        }
+        else
+        {
+            stack.push(new StackElement(src, info));
+            setLogContext(info);
+        }
+    }
+
+    public void popLogContext()
+    {
+        if (!trackLocation)
+        {
+            return;
+        }
+        Deque<StackElement> stack = contextStack.get();
+        StackElement last = stack.peek();
+        if (last == null)
+        {
+            logger.error("log context is already empty");
+            return;
+        }
+        if (--last.count == 0)
+        {
+            stack.pop();
+            last = stack.peek();
+            if (last == null)
+            {
+                clearLogContext();
+            }
+            else
+            {
+                setLogContext(last.info);
+            }
+        }
+    }
+
+    private void setLogContext(Info info)
+    {
+        MDC.put(MDC_FILE, info.getTemplateName());
+        MDC.put(MDC_LINE, String.valueOf(info.getLine()));
+        MDC.put(MDC_COLUMN, String.valueOf(info.getColumn()));
+    }
+
+    private void clearLogContext()
+    {
+        MDC.remove(MDC_FILE);
+        MDC.remove(MDC_LINE);
+        MDC.remove(MDC_COLUMN);
+    }
+}
diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTDirective.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTDirective.java
index 94490a9a..bed5fadc 100644
--- a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTDirective.java
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTDirective.java
@@ -29,10 +29,12 @@ import org.apache.velocity.runtime.RuntimeConstants.SpaceGobbling;
 import org.apache.velocity.runtime.directive.BlockMacro;
 import org.apache.velocity.runtime.directive.Directive;
 import org.apache.velocity.runtime.directive.RuntimeMacro;
+import org.apache.velocity.runtime.parser.LogContext;
 import org.apache.velocity.runtime.parser.ParseException;
 import org.apache.velocity.runtime.parser.Parser;
 import org.apache.velocity.runtime.parser.ParserConstants;
 import org.apache.velocity.runtime.parser.Token;
+import org.apache.velocity.util.introspection.Info;
 
 import java.io.IOException;
 import java.io.Writer;
@@ -292,7 +294,15 @@ public class ASTDirective extends SimpleNode
 
             writer.write(morePrefix);
 
-            directive.render(context, writer, this);
+            try
+            {
+                rsvc.getLogContext().pushLogContext(this, new Info(getTemplateName(), getLine(), getColumn()));
+                directive.render(context, writer, this);
+            }
+            finally
+            {
+                rsvc.getLogContext().popLogContext();
+            }
 
             if (morePrefix.length() > 0 || spaceGobbling == SpaceGobbling.NONE)
             {
diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTIdentifier.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTIdentifier.java
index a2900dcf..37eaf19e 100644
--- a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTIdentifier.java
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTIdentifier.java
@@ -25,6 +25,7 @@ import org.apache.velocity.exception.MethodInvocationException;
 import org.apache.velocity.exception.TemplateInitException;
 import org.apache.velocity.exception.VelocityException;
 import org.apache.velocity.runtime.RuntimeConstants;
+import org.apache.velocity.runtime.parser.LogContext;
 import org.apache.velocity.runtime.parser.Parser;
 import org.apache.velocity.util.introspection.Info;
 import org.apache.velocity.util.introspection.IntrospectionCacheData;
@@ -127,152 +128,160 @@ public class ASTIdentifier extends SimpleNode
     public Object execute(Object o, InternalContextAdapter context)
         throws MethodInvocationException
     {
-
-        VelPropertyGet vg = null;
-
         try
         {
-            /*
-             *  first, see if we have this information cached.
-             */
+            rsvc.getLogContext().pushLogContext(this, uberInfo);
 
-            IntrospectionCacheData icd = context.icacheGet(this);
-            Class clazz = o instanceof Class ? (Class)o : o.getClass();
-
-            /*
-             * if we have the cache data and the class of the object we are
-             * invoked with is the same as that in the cache, then we must
-             * be all right.  The last 'variable' is the method name, and
-             * that is fixed in the template :)
-             */
+            VelPropertyGet vg = null;
 
-            if ( icd != null && (o != null) && (icd.contextData == clazz) )
-            {
-                vg = (VelPropertyGet) icd.thingy;
-            }
-            else
+            try
             {
                 /*
-                 *  otherwise, do the introspection, and cache it.  Use the
-                 *  uberspector
+                 *  first, see if we have this information cached.
                  */
 
-                vg = rsvc.getUberspect().getPropertyGet(o, identifier, uberInfo);
+                IntrospectionCacheData icd = context.icacheGet(this);
+                Class clazz = o instanceof Class ? (Class)o : o.getClass();
 
-                if (vg != null && vg.isCacheable() && (o != null))
+                /*
+                 * if we have the cache data and the class of the object we are
+                 * invoked with is the same as that in the cache, then we must
+                 * be all right.  The last 'variable' is the method name, and
+                 * that is fixed in the template :)
+                 */
+
+                if ( icd != null && (o != null) && (icd.contextData == clazz) )
+                {
+                    vg = (VelPropertyGet) icd.thingy;
+                }
+                else
                 {
-                    icd = new IntrospectionCacheData();
-                    icd.contextData = clazz;
-                    icd.thingy = vg;
-                    context.icachePut(this,icd);
+                    /*
+                     *  otherwise, do the introspection, and cache it.  Use the
+                     *  uberspector
+                     */
+
+                    vg = rsvc.getUberspect().getPropertyGet(o, identifier, uberInfo);
+
+                    if (vg != null && vg.isCacheable() && (o != null))
+                    {
+                        icd = new IntrospectionCacheData();
+                        icd.contextData = clazz;
+                        icd.thingy = vg;
+                        context.icachePut(this,icd);
+                    }
                 }
             }
-        }
-
-        /**
-         * pass through application level runtime exceptions
-         */
-        catch( RuntimeException e )
-        {
-            throw e;
-        }
-        catch(Exception e)
-        {
-            String msg = "ASTIdentifier.execute() : identifier = "+identifier;
-            log.error(msg, e);
-            throw new VelocityException(msg, e);
-        }
-
-        /*
-         *  we have no getter... punt...
-         */
 
-        if (vg == null)
-        {
-            if (strictRef)
+            /**
+             * pass through application level runtime exceptions
+             */
+            catch( RuntimeException e )
             {
-                throw new MethodInvocationException("Object '" + o.getClass().getName() +
-                    "' does not contain property '" + identifier + "'", null, identifier,
-                    uberInfo.getTemplateName(), uberInfo.getLine(), uberInfo.getColumn());
+                throw e;
             }
-            else
+            catch(Exception e)
             {
-                return null;
+                String msg = "ASTIdentifier.execute() : identifier = "+identifier;
+                log.error(msg, e);
+                throw new VelocityException(msg, e);
             }
-        }
 
-        /*
-         *  now try and execute.  If we get a MIE, throw that
-         *  as the app wants to get these.  If not, log and punt.
-         */
-        try
-        {
-            return vg.invoke(o);
-        }
-        catch(InvocationTargetException ite)
-        {
             /*
-             *  if we have an event cartridge, see if it wants to veto
-             *  also, let non-Exception Throwables go...
+             *  we have no getter... punt...
              */
 
-            Throwable t = ite.getTargetException();
-            if (t instanceof Exception)
+            if (vg == null)
             {
-                try
+                if (strictRef)
                 {
-                    return EventHandlerUtil.methodException(rsvc, context, o.getClass(), vg.getMethodName(),
-                            (Exception) t, uberInfo);
+                    throw new MethodInvocationException("Object '" + o.getClass().getName() +
+                        "' does not contain property '" + identifier + "'", null, identifier,
+                        uberInfo.getTemplateName(), uberInfo.getLine(), uberInfo.getColumn());
                 }
-
-                /**
-                 * If the event handler throws an exception, then wrap it
-                 * in a MethodInvocationException.
-                 */
-                catch( Exception e )
+                else
                 {
-                    throw new MethodInvocationException(
-                      "Invocation of method '" + vg.getMethodName() + "'"
-                      + " in  " + o.getClass()
-                      + " threw exception "
-                      + ite.getTargetException().toString(),
-                      ite.getTargetException(), vg.getMethodName(), getTemplateName(), this.getLine(), this.getColumn());
+                    return null;
                 }
             }
-            else
+
+            /*
+             *  now try and execute.  If we get a MIE, throw that
+             *  as the app wants to get these.  If not, log and punt.
+             */
+            try
+            {
+                return vg.invoke(o);
+            }
+            catch(InvocationTargetException ite)
             {
                 /*
-                 * no event cartridge to override. Just throw
+                 *  if we have an event cartridge, see if it wants to veto
+                 *  also, let non-Exception Throwables go...
                  */
 
-                throw  new MethodInvocationException(
-                "Invocation of method '" + vg.getMethodName() + "'"
-                + " in  " + o.getClass()
-                + " threw exception "
-                + ite.getTargetException().toString(),
-                ite.getTargetException(), vg.getMethodName(), getTemplateName(), this.getLine(), this.getColumn());
+                Throwable t = ite.getTargetException();
+                if (t instanceof Exception)
+                {
+                    try
+                    {
+                        return EventHandlerUtil.methodException(rsvc, context, o.getClass(), vg.getMethodName(),
+                                (Exception) t, uberInfo);
+                    }
+
+                    /**
+                     * If the event handler throws an exception, then wrap it
+                     * in a MethodInvocationException.
+                     */
+                    catch( Exception e )
+                    {
+                        throw new MethodInvocationException(
+                          "Invocation of method '" + vg.getMethodName() + "'"
+                          + " in  " + o.getClass()
+                          + " threw exception "
+                          + ite.getTargetException().toString(),
+                          ite.getTargetException(), vg.getMethodName(), getTemplateName(), this.getLine(), this.getColumn());
+                    }
+                }
+                else
+                {
+                    /*
+                     * no event cartridge to override. Just throw
+                     */
+
+                    throw  new MethodInvocationException(
+                    "Invocation of method '" + vg.getMethodName() + "'"
+                    + " in  " + o.getClass()
+                    + " threw exception "
+                    + ite.getTargetException().toString(),
+                    ite.getTargetException(), vg.getMethodName(), getTemplateName(), this.getLine(), this.getColumn());
 
 
+                }
+            }
+            catch(IllegalArgumentException iae)
+            {
+                return null;
+            }
+            /**
+             * pass through application level runtime exceptions
+             */
+            catch( RuntimeException e )
+            {
+                throw e;
+            }
+            catch(Exception e)
+            {
+                String msg = "ASTIdentifier() : exception invoking method "
+                            + "for identifier '" + identifier + "' in "
+                            + o.getClass();
+                log.error(msg, e);
+                throw new VelocityException(msg, e);
             }
         }
-        catch(IllegalArgumentException iae)
-        {
-            return null;
-        }
-        /**
-         * pass through application level runtime exceptions
-         */
-        catch( RuntimeException e )
-        {
-            throw e;
-        }
-        catch(Exception e)
+        finally
         {
-            String msg = "ASTIdentifier() : exception invoking method "
-                        + "for identifier '" + identifier + "' in "
-                        + o.getClass();
-            log.error(msg, e);
-            throw new VelocityException(msg, e);
+            rsvc.getLogContext().popLogContext();
         }
     }
 }
diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTMethod.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTMethod.java
index 8f953b65..3d38bcf2 100644
--- a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTMethod.java
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTMethod.java
@@ -27,6 +27,7 @@ import org.apache.velocity.exception.TemplateInitException;
 import org.apache.velocity.exception.VelocityException;
 import org.apache.velocity.runtime.RuntimeConstants;
 import org.apache.velocity.runtime.directive.StopCommand;
+import org.apache.velocity.runtime.parser.LogContext;
 import org.apache.velocity.runtime.parser.Parser;
 import org.apache.velocity.util.ClassUtils;
 import org.apache.velocity.util.introspection.Info;
@@ -140,113 +141,122 @@ public class ASTMethod extends SimpleNode
     public Object execute(Object o, InternalContextAdapter context)
         throws MethodInvocationException
     {
-        /*
-         *  new strategy (strategery!) for introspection. Since we want
-         *  to be thread- as well as context-safe, we *must* do it now,
-         *  at execution time.  There can be no in-node caching,
-         *  but if we are careful, we can do it in the context.
-         */
-        Object [] params = new Object[paramCount];
-
-          /*
-           * sadly, we do need recalc the values of the args, as this can
-           * change from visit to visit
-           */
-        final Class[] paramClasses =
-            paramCount > 0 ? new Class[paramCount] : EMPTY_CLASS_ARRAY;
-
-        for (int j = 0; j < paramCount; j++)
+        try
         {
-            params[j] = jjtGetChild(j + 1).value(context);
-            if (params[j] != null)
-            {
-                paramClasses[j] = params[j].getClass();
-            }
-        }
+            rsvc.getLogContext().pushLogContext(this, uberInfo);
 
-        VelMethod method = ClassUtils.getMethod(methodName, params, paramClasses,
-            o, context, this, strictRef);
+            /*
+             *  new strategy (strategery!) for introspection. Since we want
+             *  to be thread- as well as context-safe, we *must* do it now,
+             *  at execution time.  There can be no in-node caching,
+             *  but if we are careful, we can do it in the context.
+             */
+            Object [] params = new Object[paramCount];
 
-        // warn if method wasn't found (if strictRef is true, then ClassUtils did throw an exception)
-        if (o != null && method == null && logOnInvalid)
-        {
-            StringBuilder plist = new StringBuilder();
-            for (int i = 0; i < params.length; i++)
+              /*
+               * sadly, we do need recalc the values of the args, as this can
+               * change from visit to visit
+               */
+            final Class[] paramClasses =
+                paramCount > 0 ? new Class[paramCount] : EMPTY_CLASS_ARRAY;
+
+            for (int j = 0; j < paramCount; j++)
             {
-                Class param = paramClasses[i];
-                plist.append(param == null ? "null" : param.getName());
-                if (i < params.length - 1)
-                    plist.append(", ");
+                params[j] = jjtGetChild(j + 1).value(context);
+                if (params[j] != null)
+                {
+                    paramClasses[j] = params[j].getClass();
+                }
             }
-            log.debug("Object '{}' does not contain method {}({}) at {}[line {}, column {}]", o.getClass().getName(), methodName, plist, getTemplateName(), getLine(), getColumn());
-        }
 
-        /*
-         * The parent class (typically ASTReference) uses the icache entry
-         * under 'this' key to distinguish a valid null result from a non-existent method.
-         * So update this dummy cache value if necessary.
-         */
-        IntrospectionCacheData prevICD = context.icacheGet(this);
-        if (method == null)
-        {
-            if (prevICD != null)
+            VelMethod method = ClassUtils.getMethod(methodName, params, paramClasses,
+                o, context, this, strictRef);
+
+            // warn if method wasn't found (if strictRef is true, then ClassUtils did throw an exception)
+            if (o != null && method == null && logOnInvalid)
             {
-                context.icachePut(this, null);
+                StringBuilder plist = new StringBuilder();
+                for (int i = 0; i < params.length; i++)
+                {
+                    Class param = paramClasses[i];
+                    plist.append(param == null ? "null" : param.getName());
+                    if (i < params.length - 1)
+                        plist.append(", ");
+                }
+                log.debug("Object '{}' does not contain method {}({}) at {}[line {}, column {}]", o.getClass().getName(), methodName, plist, getTemplateName(), getLine(), getColumn());
             }
-            return null;
-        }
-        else if (prevICD == null)
-        {
-            context.icachePut(this, new IntrospectionCacheData()); // no need to fill in its members
-        }
 
-        try
-        {
             /*
-             *  get the returned object.  It may be null, and that is
-             *  valid for something declared with a void return type.
-             *  Since the caller is expecting something to be returned,
-             *  as long as things are peachy, we can return an empty
-             *  String so ASTReference() correctly figures out that
-             *  all is well.
+             * The parent class (typically ASTReference) uses the icache entry
+             * under 'this' key to distinguish a valid null result from a non-existent method.
+             * So update this dummy cache value if necessary.
              */
-
-            Object obj = method.invoke(o, params);
-
-            if (obj == null)
+            IntrospectionCacheData prevICD = context.icacheGet(this);
+            if (method == null)
             {
-                if( method.getReturnType() == Void.TYPE)
+                if (prevICD != null)
                 {
-                    return "";
+                    context.icachePut(this, null);
                 }
+                return null;
+            }
+            else if (prevICD == null)
+            {
+                context.icachePut(this, new IntrospectionCacheData()); // no need to fill in its members
             }
 
-            return obj;
-        }
-        catch( InvocationTargetException ite )
-        {
-            return handleInvocationException(o, context, ite.getTargetException());
-        }
+            try
+            {
+                /*
+                 *  get the returned object.  It may be null, and that is
+                 *  valid for something declared with a void return type.
+                 *  Since the caller is expecting something to be returned,
+                 *  as long as things are peachy, we can return an empty
+                 *  String so ASTReference() correctly figures out that
+                 *  all is well.
+                 */
+
+                Object obj = method.invoke(o, params);
+
+                if (obj == null)
+                {
+                    if( method.getReturnType() == Void.TYPE)
+                    {
+                        return "";
+                    }
+                }
 
-        /** Can also be thrown by method invocation **/
-        catch( IllegalArgumentException t )
-        {
-            return handleInvocationException(o, context, t);
-        }
+                return obj;
+            }
+            catch( InvocationTargetException ite )
+            {
+                return handleInvocationException(o, context, ite.getTargetException());
+            }
 
-        /**
-         * pass through application level runtime exceptions
-         */
-        catch( RuntimeException e )
-        {
-            throw e;
+            /** Can also be thrown by method invocation **/
+            catch( IllegalArgumentException t )
+            {
+                return handleInvocationException(o, context, t);
+            }
+
+            /**
+             * pass through application level runtime exceptions
+             */
+            catch( RuntimeException e )
+            {
+                throw e;
+            }
+            catch( Exception e )
+            {
+                String msg = "ASTMethod.execute() : exception invoking method '"
+                             + methodName + "' in " + o.getClass();
+                log.error(msg, e);
+                throw new VelocityException(msg, e);
+            }
         }
-        catch( Exception e )
+        finally
         {
-            String msg = "ASTMethod.execute() : exception invoking method '"
-                         + methodName + "' in " + o.getClass();
-            log.error(msg, e);
-            throw new VelocityException(msg, e);
+            rsvc.getLogContext().popLogContext();
         }
     }
 
diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTReference.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTReference.java
index 5727acbe..058dff39 100644
--- a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTReference.java
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTReference.java
@@ -28,6 +28,7 @@ import org.apache.velocity.io.Filter;
 import org.apache.velocity.runtime.Renderable;
 import org.apache.velocity.runtime.RuntimeConstants;
 import org.apache.velocity.runtime.directive.Block.Reference;
+import org.apache.velocity.runtime.parser.LogContext;
 import org.apache.velocity.runtime.parser.Parser;
 import org.apache.velocity.runtime.parser.Token;
 import org.apache.velocity.util.ClassUtils;
@@ -249,157 +250,166 @@ public class ASTReference extends SimpleNode
     public Object execute(Object o, InternalContextAdapter context)
         throws MethodInvocationException
     {
-        /*
-         *  The only case where 'o' is not null is when this method is called by evaluate().
-         *  Its value is not used, but it is a convention meant to allow statements like
-         *  #if($invalidReference) *not* to trigger an invalid reference event.
-         *  Statements like #if($invalidReference.prop) should *still* trigger an invalid reference event.
-         *  Statements like #if($validReference.invalidProp) should not.
-         */
-        boolean onlyTestingReference = (o != null);
-
-        if (referenceType == RUNT)
-            return null;
+        try
+        {
+            rsvc.getLogContext().pushLogContext(this, uberInfo);
 
-        /*
-         *  get the root object from the context
-         */
+            /*
+             *  The only case where 'o' is not null is when this method is called by evaluate().
+             *  Its value is not used, but it is a convention meant to allow statements like
+             *  #if($invalidReference) *not* to trigger an invalid reference event.
+             *  Statements like #if($invalidReference.prop) should *still* trigger an invalid reference event.
+             *  Statements like #if($validReference.invalidProp) should not.
+             */
+            boolean onlyTestingReference = (o != null);
 
-        Object result = getRootVariableValue(context);
+            if (referenceType == RUNT)
+                return null;
 
-        if (result == null && !strictRef)
-        {
             /*
-             * do not trigger an invalid reference if the reference is present, but with a null value
-             * don't either for a quiet reference or inside an #if/#elseif evaluation context
+             *  get the root object from the context
              */
-            if (referenceType != QUIET_REFERENCE  &&
-                    (numChildren > 0 ||
-                            !context.containsKey(rootString) && !onlyTestingReference))
-            {
-                result = EventHandlerUtil.invalidGetMethod(rsvc, context,
-                        "$" + rootString, null, null, uberInfo);
-            }
-
-            if (result == null && astAlternateValue != null)
-            {
-                result = astAlternateValue.value(context);
-            }
 
-            return result;
-        }
+            Object result = getRootVariableValue(context);
 
-        /*
-         * Iteratively work 'down' (it's flat...) the reference
-         * to get the value, but check to make sure that
-         * every result along the path is valid. For example:
-         *
-         * $hashtable.Customer.Name
-         *
-         * The $hashtable may be valid, but there is no key
-         * 'Customer' in the hashtable so we want to stop
-         * when we find a null value and return the null
-         * so the error gets logged.
-         */
-
-        try
-        {
-            Object previousResult = result;
-            int failedChild = -1;
-            for (int i = 0; i < numChildren; i++)
+            if (result == null && !strictRef)
             {
-                if (strictRef && result == null)
+                /*
+                 * do not trigger an invalid reference if the reference is present, but with a null value
+                 * don't either for a quiet reference or inside an #if/#elseif evaluation context
+                 */
+                if (referenceType != QUIET_REFERENCE  &&
+                        (numChildren > 0 ||
+                                !context.containsKey(rootString) && !onlyTestingReference))
                 {
-                    /**
-                     * At this point we know that an attempt is about to be made
-                     * to call a method or property on a null value.
-                     */
-                    String name = jjtGetChild(i).getFirstTokenImage();
-                    throw new VelocityException("Attempted to access '"
-                        + name + "' on a null value at "
-                        + StringUtils.formatFileString(uberInfo.getTemplateName(),
-                        + jjtGetChild(i).getLine(), jjtGetChild(i).getColumn()));
+                    result = EventHandlerUtil.invalidGetMethod(rsvc, context,
+                            "$" + rootString, null, null, uberInfo);
                 }
-                previousResult = result;
-                result = jjtGetChild(i).execute(result,context);
-                if (result == null && !strictRef)  // If strict and null then well catch this
-                                                   // next time through the loop
+
+                if (result == null && astAlternateValue != null)
                 {
-                    failedChild = i;
-                    break;
+                    result = astAlternateValue.value(context);
                 }
+
+                return result;
             }
 
-            if (result == null)
+            /*
+             * Iteratively work 'down' (it's flat...) the reference
+             * to get the value, but check to make sure that
+             * every result along the path is valid. For example:
+             *
+             * $hashtable.Customer.Name
+             *
+             * The $hashtable may be valid, but there is no key
+             * 'Customer' in the hashtable so we want to stop
+             * when we find a null value and return the null
+             * so the error gets logged.
+             */
+
+            try
             {
-                if (failedChild == -1)
+                Object previousResult = result;
+                int failedChild = -1;
+                for (int i = 0; i < numChildren; i++)
                 {
-                    /*
-                     * do not trigger an invalid reference if the reference is present, but with a null value
-                     * don't either for a quiet reference,
-                     * or inside an #if/#elseif evaluation context when there's no child
-                     */
-                    if (!context.containsKey(rootString) && referenceType != QUIET_REFERENCE && (!onlyTestingReference || numChildren > 0))
+                    if (strictRef && result == null)
+                    {
+                        /**
+                         * At this point we know that an attempt is about to be made
+                         * to call a method or property on a null value.
+                         */
+                        String name = jjtGetChild(i).getFirstTokenImage();
+                        throw new VelocityException("Attempted to access '"
+                            + name + "' on a null value at "
+                            + StringUtils.formatFileString(uberInfo.getTemplateName(),
+                            + jjtGetChild(i).getLine(), jjtGetChild(i).getColumn()));
+                    }
+                    previousResult = result;
+                    result = jjtGetChild(i).execute(result,context);
+                    if (result == null && !strictRef)  // If strict and null then well catch this
+                                                       // next time through the loop
                     {
-                        result = EventHandlerUtil.invalidGetMethod(rsvc, context,
-                                "$" + rootString, previousResult, null, uberInfo);
+                        failedChild = i;
+                        break;
                     }
                 }
-                else
+
+                if (result == null)
                 {
-                    Node child = jjtGetChild(failedChild);
-                    // do not call bad reference handler if the getter is present
-                    // (it means the getter has been called and returned null)
-                    // do not either for a quiet reference or if the *last* child failed while testing the reference
-                    Object getter = context.icacheGet(child);
-                    if (getter == null &&
-                        referenceType != QUIET_REFERENCE  &&
-                        (!onlyTestingReference || failedChild < numChildren - 1))
+                    if (failedChild == -1)
+                    {
+                        /*
+                         * do not trigger an invalid reference if the reference is present, but with a null value
+                         * don't either for a quiet reference,
+                         * or inside an #if/#elseif evaluation context when there's no child
+                         */
+                        if (!context.containsKey(rootString) && referenceType != QUIET_REFERENCE && (!onlyTestingReference || numChildren > 0))
+                        {
+                            result = EventHandlerUtil.invalidGetMethod(rsvc, context,
+                                    "$" + rootString, previousResult, null, uberInfo);
+                        }
+                    }
+                    else
                     {
-                        StringBuilder name = new StringBuilder("$").append(rootString);
-                        for (int i = 0; i <= failedChild; i++)
+                        Node child = jjtGetChild(failedChild);
+                        // do not call bad reference handler if the getter is present
+                        // (it means the getter has been called and returned null)
+                        // do not either for a quiet reference or if the *last* child failed while testing the reference
+                        Object getter = context.icacheGet(child);
+                        if (getter == null &&
+                            referenceType != QUIET_REFERENCE  &&
+                            (!onlyTestingReference || failedChild < numChildren - 1))
                         {
-                            Node node = jjtGetChild(i);
-                            if (node instanceof ASTMethod)
+                            StringBuilder name = new StringBuilder("$").append(rootString);
+                            for (int i = 0; i <= failedChild; i++)
+                            {
+                                Node node = jjtGetChild(i);
+                                if (node instanceof ASTMethod)
+                                {
+                                    name.append(".").append(((ASTMethod) node).getMethodName()).append("()");
+                                }
+                                else
+                                {
+                                    name.append(".").append(node.getFirstTokenImage());
+                                }
+                            }
+
+                            if (child instanceof ASTMethod)
                             {
-                                name.append(".").append(((ASTMethod) node).getMethodName()).append("()");
+                                String methodName = ((ASTMethod) jjtGetChild(failedChild)).getMethodName();
+                                result = EventHandlerUtil.invalidMethod(rsvc, context,
+                                    name.toString(), previousResult, methodName, uberInfo);
                             }
                             else
                             {
-                                name.append(".").append(node.getFirstTokenImage());
+                                String property = jjtGetChild(failedChild).getFirstTokenImage();
+                                result = EventHandlerUtil.invalidGetMethod(rsvc, context,
+                                    name.toString(), previousResult, property, uberInfo);
                             }
                         }
-
-                        if (child instanceof ASTMethod)
-                        {
-                            String methodName = ((ASTMethod) jjtGetChild(failedChild)).getMethodName();
-                            result = EventHandlerUtil.invalidMethod(rsvc, context,
-                                name.toString(), previousResult, methodName, uberInfo);
-                        }
-                        else
-                        {
-                            String property = jjtGetChild(failedChild).getFirstTokenImage();
-                            result = EventHandlerUtil.invalidGetMethod(rsvc, context,
-                                name.toString(), previousResult, property, uberInfo);
-                        }
                     }
                 }
-            }
 
-            /*
-             * Time to try the alternate value if needed
-             */
-            if (astAlternateValue != null && (result == null || !DuckType.asBoolean(result, checkEmpty)))
+                /*
+                 * Time to try the alternate value if needed
+                 */
+                if (astAlternateValue != null && (result == null || !DuckType.asBoolean(result, checkEmpty)))
+                {
+                    result = astAlternateValue.value(context);
+                }
+
+                return result;
+            }
+            catch(MethodInvocationException mie)
             {
-                result = astAlternateValue.value(context);
+                mie.setReferenceName(rootString);
+                throw mie;
             }
-
-            return result;
         }
-        catch(MethodInvocationException mie)
+        finally
         {
-            mie.setReferenceName(rootString);
-            throw mie;
+            rsvc.getLogContext().popLogContext();
         }
     }
 
@@ -416,161 +426,170 @@ public class ASTReference extends SimpleNode
     public boolean render(InternalContextAdapter context, Writer writer) throws IOException,
             MethodInvocationException
     {
-        if (referenceType == RUNT)
-        {
-            writer.write(literal);
-            return true;
-        }
-
-        Object value = null;
-        if (escaped && strictEscape)
-        {
-          /**
-           * If we are in strict mode and the variable is escaped, then don't bother to
-           * retrieve the value since we won't use it. And if the var is not defined
-           * it will throw an exception.  Set value to TRUE to fall through below with
-           * simply printing $foo, and not \$foo
-           */
-          value = Boolean.TRUE;
-        }
-        else
+        try
         {
-          value = execute(null, context);
-        }
-
-        String localNullString = null;
+            rsvc.getLogContext().pushLogContext(this, uberInfo);
 
-        /*
-         * if this reference is escaped (\$foo) then we want to do one of two things: 1) if this is
-         * a reference in the context, then we want to print $foo 2) if not, then \$foo (its
-         * considered schmoo, not VTL)
-         */
-
-        if (escaped)
-        {
-            localNullString = getNullString(context);
+            if (referenceType == RUNT)
+            {
+                writer.write(literal);
+                return true;
+            }
 
-            if (value == null)
+            Object value = null;
+            if (escaped && strictEscape)
             {
-                writer.write(escPrefix);
-                writer.write("\\");
-                writer.write(localNullString);
+              /**
+               * If we are in strict mode and the variable is escaped, then don't bother to
+               * retrieve the value since we won't use it. And if the var is not defined
+               * it will throw an exception.  Set value to TRUE to fall through below with
+               * simply printing $foo, and not \$foo
+               */
+              value = Boolean.TRUE;
             }
             else
             {
-                writer.write(escPrefix);
-                writer.write(localNullString);
+              value = execute(null, context);
             }
-            return true;
-        }
 
-        /*
-         * the normal processing
-         *
-         * if we have an event cartridge, get a new value object
-         */
+            String localNullString = null;
 
-        value = EventHandlerUtil.referenceInsert(rsvc, context, literal, value);
+            /*
+             * if this reference is escaped (\$foo) then we want to do one of two things: 1) if this is
+             * a reference in the context, then we want to print $foo 2) if not, then \$foo (its
+             * considered schmoo, not VTL)
+             */
 
-        String toString = null;
-        if (value != null)
-        {
-            if (value instanceof Renderable)
+            if (escaped)
             {
-                Renderable renderable = (Renderable)value;
-                try
+                localNullString = getNullString(context);
+
+                if (value == null)
                 {
                     writer.write(escPrefix);
-                    writer.write(morePrefix);
-                    if (renderable.render(context,writer))
-                    {
-                      return true;
-                    }
+                    writer.write("\\");
+                    writer.write(localNullString);
                 }
-                catch(RuntimeException e)
+                else
                 {
-                    // We commonly get here when an error occurs within a block reference.
-                    // We want to log where the reference is at so that a developer can easily
-                    // know where the offending call is located.  This can be seen
-                    // as another element of the error stack we report to log.
-                    log.error("Exception rendering "
-                        + ((renderable instanceof Reference)? "block ":"Renderable ")
-                        + rootString + " at " + StringUtils.formatFileString(this));
-                    throw e;
+                    writer.write(escPrefix);
+                    writer.write(localNullString);
                 }
+                return true;
             }
 
-            toString = DuckType.asString(value);
-        }
+            /*
+             * the normal processing
+             *
+             * if we have an event cartridge, get a new value object
+             */
 
-        if (value == null || toString == null)
-        {
-            if (strictRef)
+            value = EventHandlerUtil.referenceInsert(rsvc, context, literal, value);
+
+            String toString = null;
+            if (value != null)
             {
-                if (referenceType != QUIET_REFERENCE)
+                if (value instanceof Renderable)
                 {
-                  log.error("Prepend the reference with '$!' e.g., $!{}" +
-                            " if you want Velocity to ignore the reference when it evaluates to null",
-                            literal().substring(1));
-                  if (value == null)
-                  {
-                    throw new VelocityException("Reference " + literal()
-                        + " evaluated to null when attempting to render at "
-                        + StringUtils.formatFileString(this));
-                  }
-                  else  // toString == null
-                  {
-                    // This will probably rarely happen, but when it does we want to
-                    // inform the user that toString == null so they don't pull there
-                    // hair out wondering why Velocity thinks the value is null.
-                    throw new VelocityException("Reference " + literal()
-                        + " evaluated to object " + value.getClass().getName()
-                        + " whose toString() method returned null at "
-                        + StringUtils.formatFileString(this));
-                  }
+                    Renderable renderable = (Renderable)value;
+                    try
+                    {
+                        writer.write(escPrefix);
+                        writer.write(morePrefix);
+                        if (renderable.render(context,writer))
+                        {
+                          return true;
+                        }
+                    }
+                    catch(RuntimeException e)
+                    {
+                        // We commonly get here when an error occurs within a block reference.
+                        // We want to log where the reference is at so that a developer can easily
+                        // know where the offending call is located.  This can be seen
+                        // as another element of the error stack we report to log.
+                        log.error("Exception rendering "
+                            + ((renderable instanceof Reference)? "block ":"Renderable ")
+                            + rootString + " at " + StringUtils.formatFileString(this));
+                        throw e;
+                    }
                 }
-                return true;
+
+                toString = DuckType.asString(value);
             }
 
-            /*
-             * write prefix twice, because it's schmoo, so the \ don't escape each
-             * other...
-             */
-            localNullString = getNullString(context);
-            if (!strictEscape)
+            if (value == null || toString == null)
             {
-                // If in strict escape mode then we only print escape once.
-                // Yea, I know.. brittle stuff
+                if (strictRef)
+                {
+                    if (referenceType != QUIET_REFERENCE)
+                    {
+                      log.error("Prepend the reference with '$!' e.g., $!{}" +
+                                " if you want Velocity to ignore the reference when it evaluates to null",
+                                literal().substring(1));
+                      if (value == null)
+                      {
+                        throw new VelocityException("Reference " + literal()
+                            + " evaluated to null when attempting to render at "
+                            + StringUtils.formatFileString(this));
+                      }
+                      else  // toString == null
+                      {
+                        // This will probably rarely happen, but when it does we want to
+                        // inform the user that toString == null so they don't pull there
+                        // hair out wondering why Velocity thinks the value is null.
+                        throw new VelocityException("Reference " + literal()
+                            + " evaluated to object " + value.getClass().getName()
+                            + " whose toString() method returned null at "
+                            + StringUtils.formatFileString(this));
+                      }
+                    }
+                    return true;
+                }
+
+                /*
+                 * write prefix twice, because it's schmoo, so the \ don't escape each
+                 * other...
+                 */
+                localNullString = getNullString(context);
+                if (!strictEscape)
+                {
+                    // If in strict escape mode then we only print escape once.
+                    // Yea, I know.. brittle stuff
+                    writer.write(escPrefix);
+                }
                 writer.write(escPrefix);
-            }
-            writer.write(escPrefix);
-            writer.write(morePrefix);
-            writer.write(localNullString);
+                writer.write(morePrefix);
+                writer.write(localNullString);
 
-            if (logOnNull && referenceType != QUIET_REFERENCE)
-            {
-                log.debug("Null reference [template '{}', line {}, column {}]: {} cannot be resolved.",
-                          getTemplateName(), this.getLine(), this.getColumn(), this.literal());
-            }
-            return true;
-        }
-        else
-        {
-            /*
-             * non-null processing
-             */
-            writer.write(escPrefix);
-            writer.write(morePrefix);
-            if (writer instanceof Filter)
-            {
-                ((Filter)writer).writeReference(toString);
+                if (logOnNull && referenceType != QUIET_REFERENCE)
+                {
+                    log.debug("Null reference [template '{}', line {}, column {}]: {} cannot be resolved.",
+                              getTemplateName(), this.getLine(), this.getColumn(), this.literal());
+                }
+                return true;
             }
             else
             {
-                writer.write(toString);
-            }
+                /*
+                 * non-null processing
+                 */
+                writer.write(escPrefix);
+                writer.write(morePrefix);
+                if (writer instanceof Filter)
+                {
+                    ((Filter)writer).writeReference(toString);
+                }
+                else
+                {
+                    writer.write(toString);
+                }
 
-            return true;
+                return true;
+            }
+        }
+        finally
+        {
+            rsvc.getLogContext().popLogContext();
         }
     }
 
@@ -619,6 +638,7 @@ public class ASTReference extends SimpleNode
         }
         try
         {
+            rsvc.getLogContext().pushLogContext(this, uberInfo);
             return DuckType.asBoolean(value, checkEmpty);
         }
         catch(Exception e)
@@ -626,6 +646,10 @@ public class ASTReference extends SimpleNode
             throw new VelocityException("Reference evaluation threw an exception at "
                 + StringUtils.formatFileString(this), e);
         }
+        finally
+        {
+            rsvc.getLogContext().popLogContext();
+        }
     }
 
     /**
@@ -663,187 +687,196 @@ public class ASTReference extends SimpleNode
     public boolean setValue(InternalContextAdapter context, Object value)
       throws MethodInvocationException
     {
-        if (astAlternateValue != null)
-        {
-            log.error("reference set cannot have a default value {}",
-                StringUtils.formatFileString(uberInfo));
-            return false;
-        }
-
-        if (numChildren == 0)
+        try
         {
-            context.put(rootString, value);
-            return true;
-        }
-
-        /*
-         *  The rootOfIntrospection is the object we will
-         *  retrieve from the Context. This is the base
-         *  object we will apply reflection to.
-         */
+            rsvc.getLogContext().pushLogContext(this, uberInfo);
 
-        Object result = getRootVariableValue(context);
+            if (astAlternateValue != null)
+            {
+                log.error("reference set cannot have a default value {}",
+                    StringUtils.formatFileString(uberInfo));
+                return false;
+            }
 
-        if (result == null)
-        {
-            log.error("reference set is not a valid reference at {}",
-                      StringUtils.formatFileString(uberInfo));
-            return false;
-        }
+            if (numChildren == 0)
+            {
+                context.put(rootString, value);
+                return true;
+            }
 
-        /*
-         * How many child nodes do we have?
-         */
+            /*
+             *  The rootOfIntrospection is the object we will
+             *  retrieve from the Context. This is the base
+             *  object we will apply reflection to.
+             */
 
-        for (int i = 0; i < numChildren - 1; i++)
-        {
-            result = jjtGetChild(i).execute(result, context);
+            Object result = getRootVariableValue(context);
 
             if (result == null)
             {
-                if (strictRef)
-                {
-                    String name = jjtGetChild(i+1).getFirstTokenImage();
-                    throw new MethodInvocationException("Attempted to access '"
-                        + name + "' on a null value", null, name, uberInfo.getTemplateName(),
-                        jjtGetChild(i+1).getLine(), jjtGetChild(i+1).getColumn());
-                }
-
                 log.error("reference set is not a valid reference at {}",
                           StringUtils.formatFileString(uberInfo));
                 return false;
             }
-        }
 
-        if (astIndex != null)
-        {
-            // If astIndex is not null then we are actually setting an index reference,
-            // something of the form $foo[1] =, or in general any reference that ends with
-            // the brackets.  This means that we need to call a more general method
-            // of the form set(Integer, <something>), or put(Object, <something), where
-            // the first parameter is the index value and the second is the LHS of the set.
-
-            Object argument = astIndex.jjtGetChild(0).value(context);
-            // If negative, turn -1 into (size - 1)
-            argument = ASTIndex.adjMinusIndexArg(argument, result, context, astIndex);
-            Object [] params = {argument, value};
-            Class[] paramClasses = {params[0] == null ? null : params[0].getClass(),
-                                    params[1] == null ? null : params[1].getClass()};
-
-            String methodName = "set";
-            VelMethod method = ClassUtils.getMethod(methodName, params, paramClasses,
-                result, context, astIndex, false);
-
-            if (method == null)
-            {
-                // If we can't find a 'set' method, lets try 'put',  This warrents a little
-                // investigation performance wise... if the user is using the hash
-                // form $foo["blaa"], then it may be expensive to first try and fail on 'set'
-                // then go to 'put'?  The problem is that getMethod will try the cache, then
-                // perform introspection on 'result' for 'set'
-                methodName = "put";
-                method = ClassUtils.getMethod(methodName, params, paramClasses,
-                      result, context, astIndex, false);
-            }
+            /*
+             * How many child nodes do we have?
+             */
 
-            if (method == null)
+            for (int i = 0; i < numChildren - 1; i++)
             {
-                // couldn't find set or put method, so bail
-                if (strictRef)
+                result = jjtGetChild(i).execute(result, context);
+
+                if (result == null)
                 {
-                    throw new VelocityException(
-                        "Found neither a 'set' or 'put' method with param types '("
-                        + printClass(paramClasses[0]) + "," + printClass(paramClasses[1])
-                        + ")' on class '" + result.getClass().getName()
-                        + "' at " + StringUtils.formatFileString(astIndex));
+                    if (strictRef)
+                    {
+                        String name = jjtGetChild(i+1).getFirstTokenImage();
+                        throw new MethodInvocationException("Attempted to access '"
+                            + name + "' on a null value", null, name, uberInfo.getTemplateName(),
+                            jjtGetChild(i+1).getLine(), jjtGetChild(i+1).getColumn());
+                    }
+
+                    log.error("reference set is not a valid reference at {}",
+                              StringUtils.formatFileString(uberInfo));
+                    return false;
                 }
-                return false;
             }
 
-            try
-            {
-                method.invoke(result, params);
-            }
-            catch(RuntimeException e)
-            {
-                // Kludge since invoke throws Exception, pass up Runtimes
-                throw e;
-            }
-            catch(Exception e)
+            if (astIndex != null)
             {
-                throw new MethodInvocationException(
-                  "Exception calling method '"
-                  + methodName + "("
-                  + printClass(paramClasses[0]) + "," + printClass(paramClasses[1])
-                  + ")' in  " + result.getClass(),
-                  e.getCause(), identifier, astIndex.getTemplateName(), astIndex.getLine(),
-                    astIndex.getColumn());
-            }
+                // If astIndex is not null then we are actually setting an index reference,
+                // something of the form $foo[1] =, or in general any reference that ends with
+                // the brackets.  This means that we need to call a more general method
+                // of the form set(Integer, <something>), or put(Object, <something), where
+                // the first parameter is the index value and the second is the LHS of the set.
+
+                Object argument = astIndex.jjtGetChild(0).value(context);
+                // If negative, turn -1 into (size - 1)
+                argument = ASTIndex.adjMinusIndexArg(argument, result, context, astIndex);
+                Object [] params = {argument, value};
+                Class[] paramClasses = {params[0] == null ? null : params[0].getClass(),
+                                        params[1] == null ? null : params[1].getClass()};
+
+                String methodName = "set";
+                VelMethod method = ClassUtils.getMethod(methodName, params, paramClasses,
+                    result, context, astIndex, false);
+
+                if (method == null)
+                {
+                    // If we can't find a 'set' method, lets try 'put',  This warrents a little
+                    // investigation performance wise... if the user is using the hash
+                    // form $foo["blaa"], then it may be expensive to first try and fail on 'set'
+                    // then go to 'put'?  The problem is that getMethod will try the cache, then
+                    // perform introspection on 'result' for 'set'
+                    methodName = "put";
+                    method = ClassUtils.getMethod(methodName, params, paramClasses,
+                          result, context, astIndex, false);
+                }
 
-            return true;
-        }
+                if (method == null)
+                {
+                    // couldn't find set or put method, so bail
+                    if (strictRef)
+                    {
+                        throw new VelocityException(
+                            "Found neither a 'set' or 'put' method with param types '("
+                            + printClass(paramClasses[0]) + "," + printClass(paramClasses[1])
+                            + ")' on class '" + result.getClass().getName()
+                            + "' at " + StringUtils.formatFileString(astIndex));
+                    }
+                    return false;
+                }
 
+                try
+                {
+                    method.invoke(result, params);
+                }
+                catch(RuntimeException e)
+                {
+                    // Kludge since invoke throws Exception, pass up Runtimes
+                    throw e;
+                }
+                catch(Exception e)
+                {
+                    throw new MethodInvocationException(
+                      "Exception calling method '"
+                      + methodName + "("
+                      + printClass(paramClasses[0]) + "," + printClass(paramClasses[1])
+                      + ")' in  " + result.getClass(),
+                      e.getCause(), identifier, astIndex.getTemplateName(), astIndex.getLine(),
+                        astIndex.getColumn());
+                }
 
-        /*
-         *  We support two ways of setting the value in a #set($ref.foo = $value ):
-         *  1) ref.setFoo( value )
-         *  2) ref,put("foo", value ) to parallel the get() map introspection
-         */
+                return true;
+            }
 
-        try
-        {
-            VelPropertySet vs =
-                    rsvc.getUberspect().getPropertySet(result, identifier,
-                            value, uberInfo);
 
-            if (vs == null)
+            /*
+             *  We support two ways of setting the value in a #set($ref.foo = $value ):
+             *  1) ref.setFoo( value )
+             *  2) ref,put("foo", value ) to parallel the get() map introspection
+             */
+
+            try
             {
-                if (strictRef)
-                {
-                    throw new MethodInvocationException("Object '" + result.getClass().getName() +
-                       "' does not contain property '" + identifier + "'", null, identifier,
-                       uberInfo.getTemplateName(), uberInfo.getLine(), uberInfo.getColumn());
-                }
-                else
+                VelPropertySet vs =
+                        rsvc.getUberspect().getPropertySet(result, identifier,
+                                value, uberInfo);
+
+                if (vs == null)
                 {
-                  return false;
+                    if (strictRef)
+                    {
+                        throw new MethodInvocationException("Object '" + result.getClass().getName() +
+                           "' does not contain property '" + identifier + "'", null, identifier,
+                           uberInfo.getTemplateName(), uberInfo.getLine(), uberInfo.getColumn());
+                    }
+                    else
+                    {
+                      return false;
+                    }
                 }
+
+                vs.invoke(result, value);
             }
+            catch(InvocationTargetException ite)
+            {
+                /*
+                 *  this is possible
+                 */
 
-            vs.invoke(result, value);
-        }
-        catch(InvocationTargetException ite)
-        {
-            /*
-             *  this is possible
+                throw  new MethodInvocationException(
+                    "ASTReference: Invocation of method '"
+                    + identifier + "' in  " + result.getClass()
+                    + " threw exception "
+                    + ite.getTargetException().toString(),
+                   ite.getTargetException(), identifier, getTemplateName(), this.getLine(), this.getColumn());
+            }
+            /**
+             * pass through application level runtime exceptions
              */
+            catch( RuntimeException e )
+            {
+                throw e;
+            }
+            catch(Exception e)
+            {
+                /*
+                 *  maybe a security exception?
+                 */
+                String msg = "ASTReference setValue(): exception: " + e
+                              + " template at " + StringUtils.formatFileString(uberInfo);
+                log.error(msg, e);
+                throw new VelocityException(msg, e);
+            }
 
-            throw  new MethodInvocationException(
-                "ASTReference: Invocation of method '"
-                + identifier + "' in  " + result.getClass()
-                + " threw exception "
-                + ite.getTargetException().toString(),
-               ite.getTargetException(), identifier, getTemplateName(), this.getLine(), this.getColumn());
+            return true;
         }
-        /**
-         * pass through application level runtime exceptions
-         */
-        catch( RuntimeException e )
+        finally
         {
-            throw e;
+            rsvc.getLogContext().popLogContext();
         }
-        catch(Exception e)
-        {
-            /*
-             *  maybe a security exception?
-             */
-            String msg = "ASTReference setValue(): exception: " + e
-                          + " template at " + StringUtils.formatFileString(uberInfo);
-            log.error(msg, e);
-            throw new VelocityException(msg, e);
-         }
-
-        return true;
     }
 
     private String getRoot()
diff --git a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTSetDirective.java b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTSetDirective.java
index f639e9c1..438e7c6e 100644
--- a/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTSetDirective.java
+++ b/velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/node/ASTSetDirective.java
@@ -25,6 +25,7 @@ import org.apache.velocity.exception.MethodInvocationException;
 import org.apache.velocity.exception.TemplateInitException;
 import org.apache.velocity.runtime.RuntimeConstants;
 import org.apache.velocity.runtime.RuntimeConstants.SpaceGobbling;
+import org.apache.velocity.runtime.parser.LogContext;
 import org.apache.velocity.runtime.parser.Parser;
 import org.apache.velocity.runtime.parser.Token;
 import org.apache.velocity.util.introspection.Info;
@@ -214,45 +215,54 @@ public class ASTSetDirective extends SimpleNode
     public boolean render( InternalContextAdapter context, Writer writer)
         throws IOException, MethodInvocationException
     {
-        SpaceGobbling spaceGobbling = rsvc.getSpaceGobbling();
+        try
+        {
+            rsvc.getLogContext().pushLogContext(this, uberInfo);
 
-        /* Velocity 1.x space gobbling for #set is rather wacky:
-           prefix is eaten *only* if previous token is not a text node.
-           We handle this by appropriately emptying the prefix in BC mode.
-         */
+            SpaceGobbling spaceGobbling = rsvc.getSpaceGobbling();
 
-        if (morePrefix.length() > 0 || spaceGobbling.compareTo(SpaceGobbling.LINES) < 0)
-        {
-            writer.write(prefix);
-        }
+            /* Velocity 1.x space gobbling for #set is rather wacky:
+               prefix is eaten *only* if previous token is not a text node.
+               We handle this by appropriately emptying the prefix in BC mode.
+             */
+
+            if (morePrefix.length() > 0 || spaceGobbling.compareTo(SpaceGobbling.LINES) < 0)
+            {
+                writer.write(prefix);
+            }
 
-        writer.write(morePrefix);
+            writer.write(morePrefix);
 
-        /*
-         *  get the RHS node, and its value
-         */
+            /*
+             *  get the RHS node, and its value
+             */
 
-        Object value = right.value(context);
+            Object value = right.value(context);
 
-        if ( value == null && !strictRef)
-        {
-            String rightReference = null;
-            if (right instanceof ASTExpression)
+            if ( value == null && !strictRef)
             {
-                rightReference = ((ASTExpression) right).lastImage;
+                String rightReference = null;
+                if (right instanceof ASTExpression)
+                {
+                    rightReference = ((ASTExpression) right).lastImage;
+                }
+                EventHandlerUtil.invalidSetMethod(rsvc, context, leftReference, rightReference, uberInfo);
             }
-            EventHandlerUtil.invalidSetMethod(rsvc, context, leftReference, rightReference, uberInfo);
-        }
 
-        if (morePrefix.length() > 0 || spaceGobbling == SpaceGobbling.NONE)
+            if (morePrefix.length() > 0 || spaceGobbling == SpaceGobbling.NONE)
+            {
+                writer.write(postfix);
+            }
+
+            return left.setValue(context, value);
+        }
+        finally
         {
-            writer.write(postfix);
+            rsvc.getLogContext().popLogContext();
+            StringBuilder builder;
         }
-
-        return left.setValue(context, value);
     }
 
-
     /**
      *  returns the ASTReference that is the LHS of the set statement
      *