Enabling logging for Velocity

[Blama]

Hi all,

I'm stuck with some complicated Velocity expression that does not work as expected. Unfortunately I can't get log4j to log Velocity output.

I'm 100% sure Velocity is called as I attached source to velocity-1.6.1.jar and set breakpoints to the log methods in org.apache.velocity.runtime.log.Log. Within the debugger I can see my meaningful log messages, but of course I'd like to see them in the server-log, which does not work here. Do you have an advice?
I'm on v8.2p_2012-04-14/EVAL and this is my log4j.isc.config.xml:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

	<appender name="STDOUT" class="org.apache.log4j.ConsoleAppender">
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="=== %d [%.4t] %-5p %c{1} - %m%n" />
		</layout>
	</appender>

	<appender name="FILE_LOG" class="org.apache.log4j.FileAppender">
		<param name="File" value="/smartClientServerLog.txt" />
		<param name="Append" value="false" />
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="=== %d [%.4t] %-5p %c{1} - %m%n" />
		</layout>
	</appender>

	<!-- This appender is used by the "Server Logs" tab in the Developer Console. -->
	<appender name="SmartClientLog" class="com.isomorphic.log.RevolvingMemoryAppender">
		<param name="maxEntries" value="2000" />
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern" value="=== %d [%.4t] %-5p %c{1} - %m%n" />
		</layout>
	</appender>

	<!-- isomorphic log messages -->
	<!-- The STDOUT appender defined above is set as the default appender for all Isomorphic SmartClient server logging. It 
		should typically be visible in the console from which you started the application server. Some Application Servers redirect 
		stdout output to a file (typically called stdout.log or something like that, so you should be able to find it there. If you 
		can't find the server log, you should be able to use the SmartClientLog (above) which is visible in the Developer Console 
		under "Server Logs" and as a standalone log viewer in /tools/serverLogViewer.jsp. Failing all of the above, you can switch 
		the appender-ref value for the com.isomorphic category to use the FILE_LOG appender which will log to /smartClientServerLog.txt 
		on UNIX and C:\smartClientServerLog.txt on Windows. You can change this by modifying the value of the "File" param in the 
		FILE_LOG definition above. -->
	<category name="com.isomorphic">
		<priority value="DEBUG" />
		<appender-ref ref="STDOUT" />
		<appender-ref ref="SmartClientLog" />
	</category>

	<category name="com.isomorphic.base.Reflection">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.base.ISCInit">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.base.ConfigLoader">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.download.Download">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.sql.ValueSet">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.servlet.RequestContext">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.datasource.DataSource">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.datasource.BasicDataSource">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.validation.Validation">
		<priority value="DEBUG" />
	</category>

	<category name="com.isomorphic.store.DataStructCache">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.assembly.FileAssembler">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.obfuscation.Obfuscator">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.servlet.PreCache">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.timing.Timing">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.resultData.ResultData">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.js.JSSyntaxScannerFilter">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.interfaces.InterfaceProvider">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.compression.Compression">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.servlet.ProxyHttpServletResponse">
		<priority value="INFO" />
	</category>

	<category name="com.isomorphic.naming.JNDI">
		<priority value="WARN" />
	</category>

	<category name="org.hibernate.SQL">
		<priority value="DEBUG" />
	</category>

	<!-- shows values bound to params in SQL query, but produces a lot of output -->
	<!-- <category name="org.hibernate.type"> <priority value="DEBUG" /> <appender-ref ref="STDOUT"/> </category> -->

	<!-- embedded tomcat -->
	<category name="org.apache">
		<priority value="DEBUG" />
		<appender-ref ref="STDOUT" />
		<appender-ref ref="SmartClientLog" />
	</category>

	<category name="org.apache.velocity">
		<priority value="DEBUG" />
		<appender-ref ref="STDOUT" />
		<appender-ref ref="SmartClientLog" />
	</category>

	<!-- hibernate log messages -->
	<category name="org.hibernate">
		<priority value="DEBUG" />
		<appender-ref ref="STDOUT" />
		<appender-ref ref="SmartClientLog" />
	</category>

	<!-- <category name="org.apache.jasper.compiler.JspRuntimeContext"> <priority value="DEBUG" /> <appender-ref ref="STDOUT" 
		/> <appender-ref ref="SmartClientLog" /> </category> -->
</log4j:configuration>

Thanks,
Blama

[Isomorphic]

Not really, that approach works fine for us, although we do not have the appender-ref elements under the Velocity category, but that's just redundant anyway.

Also consider, if a Velocity expression is complex enough that you're doing a deep dive like this, you might just use a DMI instead.

[Blama]

Hi Isomorphic,

I got it: I added source to log4j-1.2.15.jar and traced my logs from Velocity to Log4J.
I hit this method in Hierarchy.java:

  void emitNoAppenderWarning(Category cat) {
    // No appenders in hierarchy, warn user only once.
    if(!this.emittedNoAppenderWarning) {
      LogLog.warn("No appenders could be found for logger (" +
		   cat.getName() + ").");
      LogLog.warn("Please initialize the log4j system properly.");
      this.emittedNoAppenderWarning = true;
    }
  }

As you can see, a missing appender msg is only sent fpr the 1st missing appender. When I start my app in dev mode, I get this warning at the very end in the dev console:

log4j:WARN No appenders could be found for logger (org.apache.jasper.compiler.JspRuntimeContext).
log4j:WARN Please initialize the log4j system properly.

So I can't get more of these, suppressing the warnings for the missing Velocity appender. I then started the app with "-Dlog4j.debug" VM argument and saw these lines right before the JspRuntimeContext-appender warning:

log4j: Trying to find [log4j.xml] using context classloader ContextLoader@null.
log4j: Trying to find [log4j.xml] using sun.misc.Launcher$AppClassLoader@35a16869 class loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader ContextLoader@null.
log4j: Trying to find [log4j.properties] using sun.misc.Launcher$AppClassLoader@35a16869 class loader.
log4j: Trying to find [log4j.properties] using ClassLoader.getSystemResource().
log4j: Could not find resource: [null].

I saved "src/log4j.isc.config.xml" as "src/log4j.xml" and now the JspRuntimeContext-appender warning is gone AND I get my velocity output!
Perhaps this post helps someone in the future.

Best regards,
Blama