From c959ae3da1ad0445412bbe02b5339d1836ddf65f Mon Sep 17 00:00:00 2001 From: Claude Brisson Date: Sun, 5 May 2019 13:52:21 +0000 Subject: [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 --- .../apache/velocity/runtime/RuntimeConstants.java | 11 +- .../apache/velocity/runtime/RuntimeInstance.java | 24 +- .../apache/velocity/runtime/RuntimeServices.java | 10 +- .../apache/velocity/runtime/parser/LogContext.java | 140 ++++ .../velocity/runtime/parser/node/ASTDirective.java | 12 +- .../runtime/parser/node/ASTIdentifier.java | 229 +++--- .../velocity/runtime/parser/node/ASTMethod.java | 184 ++--- .../velocity/runtime/parser/node/ASTReference.java | 803 +++++++++++---------- .../runtime/parser/node/ASTSetDirective.java | 62 +- 9 files changed, 860 insertions(+), 615 deletions(-) create mode 100644 velocity-engine-core/src/main/java/org/apache/velocity/runtime/parser/LogContext.java 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. @@ -219,6 +220,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. */ @@ -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) { @@ -1671,6 +1681,16 @@ public class RuntimeInstance implements RuntimeConstants, RuntimeServices return log; } + /** + * 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; + +/** + *

Track location in template files during rendering by populating the slf4j MDC tags file, line and column.

+ *

An MDC-aware logger can then use this info to display the template location in the message

+ *

For instance with webapp-slf4j-logger, it's enough to use %file, %line and %column in the logger format string.

+ *

Since this feature can have a performance impact, it has to be enabled in velocity.properties using:

+ * 
runtime.log.track_location = true
+ *

(typically in a development environment)

+ * + * @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> contextStack = new ThreadLocal>() + { + @Override + public Deque initialValue() + { + return new ArrayDeque(); + } + }; + + 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 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 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, ), or put(Object, ), or put(Object, 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 * -- cgit v1.2.3