Resin 3.x的日志切换问题

迈不过友情╰ 2022-06-01 12:08 118阅读 0赞

最近Resin服务器总是在晚上0点宕机，观察日志无反应，少则几分钟多则几十分钟，便会自行恢复。dump出栈信息，发现是resin的rollback日志的问题。

当前resin版本为3.1.1 ，目前服务器上resin.conf的日志配置一般是：

《stdout -[log][] path=”[log][]/stdout.[log][]” timestamp=”\[%Y-%m-%d %H:%M:%S\] ” rollover-size=”200mb” /》  
《stderr -log path=”log/stderr.log” timestamp=”\[%Y-%m-%d %H:%M:%S\] ” rollover-size=”200mb” /》  
《access -log path=”logs/access.log” rollover-period=”1D” rollover-size=”200mb”/》

在这种情况下，日志始终是先输出到logs/access.log这样的固定文件里，待文件大小满200M的时候，resin先锁住所有写日志操作，将文件的内容复制到文件名带时间戳的文件里，再清空当前日志文件的内容。既多增加了磁盘io操作，也因为锁机制导致线程容易满，以至resin被webapp监控重启。以前出现该问题的时候，只简单的通过关闭access-log绕了过去，而最近web网站的resin也出现了重启。

具体分析如下：

共发现14个线程日志，其中13个为BLOCKED状态，其中一个如下：

"http-twap-t2-jsp-8001-909$602672722" daemon prio=10 tid=0x00002aab45092c00 nid=0x2cf6 waiting for monitor entry \[0x00000000495e8000..0x00000000495e8d10\]  
java.lang.Thread.State: BLOCKED (on object monitor)  
at org.apache.log4j.Category.callAppenders(Category.java:204)  
\- waiting to lock <0x00002aaac0cc6348> (a org.apache.log4j.spi.RootLogger)  
at org.apache.log4j.Category.forcedLog(Category.java:391)  
at org.apache.log4j.Category.log(Category.java:856)  
at org.apache.commons.logging.impl.Log4JLogger.info(Log4JLogger.java:133)  
at com.sohu.twap.filter.AdapterFilter.doFilterInternal(AdapterFilter.java:67)

如果BLOCKED的话，肯定有一个占有锁0x00002aaac0cc6348，向下查看，有一个状态是TIMED\_WAITING ，如下：

"http-twap-t2-jsp-8001-714$1598579590" daemon prio=10 tid=0x00002aab4428dc00 nid=0x2c7a in Object.wait() \[0x00000000488a0000..0x00000000488a1b10\]  
 java.lang.Thread.State: TIMED\_WAITING (on object monitor)  
 at java.lang.Object.wait(Native Method)  
 at com.caucho.util.ThreadPool.schedule(ThreadPool.java:529)  
 \- locked <0x00002aaabfc45a28> (a java.lang.Object)  
 at com.caucho.util.ThreadPool.startPriority(ThreadPool.java:418)  
 at com.caucho.log.AbstractRolloverLog.rolloverLog(AbstractRolloverLog.java:457)  
 at com.caucho.log.AbstractRolloverLog.rollover(AbstractRolloverLog.java:346)  
 at com.caucho.log.RotateStream.write(RotateStream.java:243)  
 at com.caucho.vfs.WriteStream.flush(WriteStream.java:355)  
 at com.caucho.log.EnvironmentStream.flush(EnvironmentStream.java:170)  
 \- locked <0x00002aaac02baef8> (a com.caucho.vfs.WriteStream)  
 at com.caucho.vfs.WriteStream.flush(WriteStream.java:360)  
 at java.io.PrintStream.write(PrintStream.java:432)  
 \- locked <0x00002aaabfc2eb10> (a java.io.PrintStream)  
 at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)  
 at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272)  
 at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276)  
 at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)  
 \- locked <0x00002aaac0cc5c88> (a java.io.OutputStreamWriter)  
 at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)  
 at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)  
 at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)  
 at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)  
 at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)  
 \- locked <0x00002aaac0cef9a0> (a org.apache.log4j.ConsoleAppender)  
 at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)  
 at org.apache.log4j.Category.callAppenders(Category.java:206)

分析代码，问题出在Resin 的ThreadPool.schedule。当日志切换的时候发现线程池没有新的线程来完成日志切换所以就导致resin宕机了。。查看resin的升级日志：

## 4.0.6 - April 6, 2010 ##

*  class-loader: changed override order to match config order (\#3773, rep by cyttesen)
 *  servlet: add cookie-domain-regexp to <session-config> (\#3865, rep by Matt Sporleder)
 *  watchdog: add <jvm-arg-line> as shortcut for <jvm-arg> (\#3940, rep by Bill Au)
 *  log: print timestamp only for first item for multiline (\#3229, rep by Jamison Novak)
 *  log: remove excess synchronization for log period calculation (\#3814, rep by zenant)
 *  log: change date calculating to use TimeZone.getOffset(time) (\#3853, rep by Jamison Novak)

## 4.0.2 - Nov 24, 2009 ##

*  config: add $\{server.address\} and $\{server.port\} (\#3671, rep by Ken Roach)
 *  jsp: StaticMethodExpr needs serialization fix (\#3677, rep by boris\_kovalenko)
 *  jsp: jsp:attribute in tag file (\#3228, rep by jens)
 *  log: update AbstractRolloverLog to eliminate long archive block (\#3650, rep by Patrik Stymne)清除了大文档的阻断问题。

“两个bug在4.0.2以上版本已修复。结论就是stdout和stderr文件不能太大，要不然在高并发下很容易出现问题（这个bug不是肯定出现，所以头疼）。至于3.1.9或者3.1.11可能都有此问题。只不过通过按日切分的规则规避了文件太大的bug。"引用自： [http://fastwei.i.sohu.com/blog/view/187818773.htm][http_fastwei.i.sohu.com_blog_view_187818773.htm]

查看resin的bug记录 [http://bugs.caucho.com/view.php?id=3509][http_bugs.caucho.com_view.php_id_3509] [http://bugs.caucho.com/view.php?id=4821][http_bugs.caucho.com_view.php_id_4821] 同样表明，在4.0版本修正了。

![Image 1][]

参考：

[http://618119.com/archives/2009/02/18/135.html][http_618119.com_archives_2009_02_18_135.html]

[http://fastwei.i.sohu.com/blog/view/187818773.htm][http_fastwei.i.sohu.com_blog_view_187818773.htm]

[http://fastwei.i.sohu.com/blog/view/188613558.htm][http_fastwei.i.sohu.com_blog_view_188613558.htm]

[log]: http://618119.com/tag/log
[http_fastwei.i.sohu.com_blog_view_187818773.htm]: http://fastwei.i.sohu.com/blog/view/187818773.htm
[http_bugs.caucho.com_view.php_id_3509]: http://bugs.caucho.com/view.php?id=3509
[http_bugs.caucho.com_view.php_id_4821]: http://bugs.caucho.com/view.php?id=4821%E7%AD%89%E3%80%82
[Image 1]: 
[http_618119.com_archives_2009_02_18_135.html]: http://618119.com/archives/2009/02/18/135.html
[http_fastwei.i.sohu.com_blog_view_188613558.htm]: http://fastwei.i.sohu.com/blog/view/188613558.htm