纠结的velocity log那些事(出现Permission denied)

背景　　

　　最近开始使用jetty做为我们的应用web容器，在迁移过程中发现一个比较隐晦的问题，原本在jboss容器跑的好好的应用，换到jetty容器上，直接不可用。出现一些莫名奇妙的错误。

 

现象

说明：我们应用中有代码使用了velocity处理一些业务，比如模板输出，自定义渲染引擎等。

 

使用例子：

RuntimeInstance  ri    = new RuntimeInstance();

.....
ri.parse(new StringReader(script), name);　//进行渲染脚本处理

 

换成jetty后，会莫名的出现一个异常信息，截取了一个异常描述：

caused by: java.lang.RuntimeException: Error configuring Log4JLogChute : 
    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
    at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
    at org.apache.velocity.util.ExceptionUtils.createWithCause(ExceptionUtils.java:67)
    at org.apache.velocity.util.ExceptionUtils.createRuntimeException(ExceptionUtils.java:45)
    at org.apache.velocity.runtime.log.Log4JLogChute.initAppender(Log4JLogChute.java:133)
    at org.apache.velocity.runtime.log.Log4JLogChute.init(Log4JLogChute.java:85)
    at org.apache.velocity.runtime.log.LogManager.createLogChute(LogManager.java:157)
    ... 33 more
Caused by: java.io.FileNotFoundException: velocity.log (Permission denied)
    at java.io.FileOutputStream.openAppend(Native Method)
    at java.io.FileOutputStream.(FileOutputStream.java:177)
    at java.io.FileOutputStream.(FileOutputStream.java:102)
    at org.apache.log4j.FileAppender.setFile(FileAppender.java:290)
    at org.apache.log4j.RollingFileAppender.setFile(RollingFileAppender.java:194)
    at org.apache.log4j.FileAppender.(FileAppender.java:109)
    at org.apache.log4j.RollingFileAppender.(RollingFileAppender.java:72)
    at org.apache.velocity.runtime.log.Log4JLogChute.initAppender(Log4JLogChute.java:118)
    ... 35 more

 

换回jboss容器后，一切正常，没有出现任何异常。

 

分析

   查找问题最好的利器就是debug，我也不例外。开启remote debug，一步步跟踪代码，发现最后的问题出在RuntimeInstance.init()调用initializeLog()方法上，说白了就是velocity日志处理上。

 

展开分析之前，先大致了解下velocity的日志处理。

 

velocity的３个关于日志记录的参数：

• runtime.log.logsystem　      (对应的logsystem实例)
• runtime.log.logsystem.class (对应的logsystem实现类)
• runtime.log  (日志文件名称)

备注：　logsystem是velocity 1.5版本以前早期的log一套实现接口，现在1.5以后建议都使用logchute，而且早的logsystem一套也不建议被使用，@deprecated Use LogChute instead!

 

类图：

Log :  对LogChute的一个delegate，提供一些遍历的方法，比如info(),warn()不同级别的日志记录方法。

LogChute:  velocity中定义的日志处理接口，目前支持各种类型的Log三方包，同时支持System.out，NullLog等特殊类型。

LogMananger : velocity管理Log对象的入口，里面有个方法updateLog(Log log, RuntimeServices rsvc)，就是本次出问题的点。

 

针对每种LogChute实现，都有自己一些特殊的配置项, (大家都知道velocity配置项可以是通过velocity.properties进行配置)

 

比如log4j的配置项，代码：Log4JLogChute

• runtime.log.logsystem.log4j.logger (对应于log4j.xml配置中的Logger name，如果没有就使用class获取Logger，同时获取runtime.log属性作为日志输出的文件)
• runtime.log.logsystem.log4j.logger.level　(转化log4j的level到velocity log中，可覆盖Logger)

 

再来理一下，velocity整个初始化日志过程：

1. new RuntimeInstance()，属性Log log = new Log()，　默认创建一个HoldingLogChute()做为LogChute，(该LogChute临时记录日志到内存对象上)
2. RuntimeInstance.init() 进行velocity系统初始化
3. 顺序调用initializeProperties()， 读取velocity.properties默认配置，合并自定义的properties。
4. 顺序调用initializeLog() ，调用LogManager.updateLog()，进行Log初始化
5. LogManager.createLogChute()会首先读取runtime.log.logsystem配置，看看是否有存在自定义的LogChute实例对象，如果有则直接使用，并返回
6. 在没有对应的LogChute实例对象配置，继续读取runtime.log.logsystem.class，看看似乎否有logsystem的配置，就是前面类图中的一对LogChute,LogSystem的实现类。
   

   runtime.log.logsystem.class = org.apache.velocity.runtime.log.AvalonLogChute,org.apache.velocity.runtime.log.Log4JLogChute,org.apache.velocity.runtime.log.CommonsLogLogChute,org.apache.velocity.runtime.log.ServletLogChute,org.apache.velocity.runtime.log.JdkLogChute

    按照顺序，逐一加载LogChute实现类，如果class装载成功，则进行初始化，并返回
7. LogManager，针对createLogChute，将系统初始时HoldingLogChute记录的内容，输出到新的LogChute上，最后完成了log的初始化

---

 

了解了velocity的整套log机制后，再来看该问题：　

• 使用时没有设置velocity log的任何参数，因为系统中存在Log4j的包，所以会使用Log4jChute做为Log记录的对象返回。
• 在初始化Log4jChute时，没有设置logger.name，初始化Logger时，会使用默认的velocity.log做为文件输出路径
• File file = new File("velocity.log")，大家知道这样的文件创建，是基于当前jvm的current work，也就是user.dir属性。(可以通过jinfo $pid | grep user.dir进行查看)

ok，现在的问题已经很明了，异常中提示velocity.log无权限，只需要check一下当前jvm进程的user.dir属性。

最后检查结果：

• jboss作为web容器时，user.dir=/home/ljh/web-deploy/bin  (当前的启动脚本所在目录)
• jetty作为web容器时，user.dir = /usr/local/program/jetty-7.2.0 (所指定的jetty.home变量路径)

刚好我用的是linux系统，软件安装路径的权限都是root用户，运行web应用的都是普通用户，所以也让我撞上了这个问题。

 

 

说明：jboss和jetty我都是通过调用自带的run.sh和jetty.sh进行启动，存在这样的差异也是让我很无语的，几点建议。

• 大家尽量在写代码时做到容器无关性
• 尽量避免使用相对目录

---

解决

深入了解了velocity log机制后，解决方案就有很多种了

 

方案一：暴力型，啥都不输出

RuntimeInstance       ri            = new RuntimeInstance();
.......
if (!ri.isInitialized()) {
            // 设置空的log，避免使用velocity默认的veloicyt.log
           ri.setProperty(RuntimeConstants.RUNTIME_LOG_LOGSYSTEM, new NullLogChute());
           ri.init();
 }

 
说明：针对应用中的渲染引擎，可以直接使用NullLogChute()，不做任何的日志输出。

 

方案二：统一型，融合到现有的log框架

RuntimeInstance       ri            = new RuntimeInstance();
......
if (!ri.isInitialized()) {
	    .......
            // 自定义LogChute，代理到应用的Log对象上，统一使用Log4j.xml进行管理
            ri.setProperty(RuntimeConstants.RUNTIME_LOG_LOGSYSTEM, new LogChute() {
            public void init(RuntimeServices runtimeServices) {
            }

            public void log(int level, String message) {
                log(level, message, null);
            }

            public void log(int level, String message, Throwable t) {
                switch (level) {
                    case TRACE_ID:
                        getLogger().trace(message, t);
                        break;

                    case DEBUG_ID:
                        getLogger().debug(message, t);
                        break;

                    case INFO_ID:
                        getLogger().info(message, t);
                        break;

                    case WARN_ID:
                        getLogger().warn(message, t);
                        break;

                    case ERROR_ID:
                        getLogger().error(message, t);
                        break;

                    default:
                }
            }

            public boolean isLevelEnabled(int level) {
                switch (level) {
                    case TRACE_ID:
                        return getLogger().isTraceEnabled();

                    case DEBUG_ID:
                        return getLogger().isDebugEnabled();

                    case INFO_ID:
                        return getLogger().isInfoEnabled();

                    case WARN_ID:
                        return getLogger().isWarnEnabled();

                    case ERROR_ID:
                        return getLogger().isErrorEnabled();

                    default:
                        return false;
                }
            }
        });

        ri.init();
 }

 

说明：使用内部匿名类，将LogChute代理到当前class类的getLogger对象上，这样实现和当前web容器的整合，可以统一使用log4j.xml进行管理，只需要设置好Velocity 包装class的logger即可。

 

---

 

现在还有比较流行Slf4jLog，同样可以写一个Slf4jLogChute。一个小建议：对WARN以下level不记录异常的详细stack详情 ── 避免Velocity在找不到资源时会打印异常，直接打印e.getMessage()

 

异常的stack打印还是比较消耗性能的，具体可以看下我同事的一篇分析文章，使用异常耗性能到底耗在哪一块http://www.blogjava.net/stone2083/archive/2010/07/09/325649.html。

评论

4 楼 56553655 2011-09-14  

分析的很好，学习了

3 楼 agapple 2010-11-19  

wlhok 写道

有个问题，为什么jetty的run.sh执行的jvm，其user.dir会是jetty的路径？

很简单，打开jetty.sh一看，你就发现了，它有这么一段脚本

##################################################
# No JETTY_HOME yet? We're out of luck!
##################################################
if [ -z "$JETTY_HOME" ]; then
  echo "** ERROR: JETTY_HOME not set, you need to set it or install in a standard location" 
  exit 1
fi

cd "$JETTY_HOME"
JETTY_HOME=$PWD

执行了一次cd动作，真当是 

还有jetty.sh脚本，选择jetty.sh start会被强制使用--daemon，jetty.sh run则是当前进程执行。一些潜规则挺多的。

2 楼 wlhok 2010-11-19  

有个问题，为什么jetty的run.sh执行的jvm，其user.dir会是jetty的路径？

1 楼 agapple 2010-11-19  

网上查了下，java.io.FileNotFoundException: velocity.log (Permission denied)

这样的问题还不少stackoverflow上也有人提问，http://stackoverflow.com/questions/849710/error-in-velocity-and-log4j

看来j2se和j2ee模式下的确会出现一些问题，普通jar运行好好的代码，在运行于容器中就会出现一些莫名的问题

单元测试很重要，集成测试也还是很有必要，这次就犯了这么个错误，改完提测被退回