小毛的胡思乱想

凡走过,必留痕迹.

Log4j源码心得

| Comments

log4j是一个非常流行的日志框架,最近研究了一下log4j的源代码,这里记录一下心得体会。

Logger、Appender、Layout之间的结构关系?

这是log4j的基本数据结构,之间的关系还是很好理解的。首先,一个Logger都要一个名字(通常是类名或包名),它是有父子结构的,相关的实现是Hierarchy。
一个Logger会对应多个Appender,表示可以日志输出的地方。
Appender的输出格式是通过Layout来实现的,Logger在输出的时候是包装一个LogEvent对象,有Layout来格式化成一个字符串。

简单点:

1
Logger 1--* Appender 1--* Layout

加载log4j的配置文件

先考虑加载的是log4j.xml, 然后才是log4j.properties。我平时主要使用log4j.properties.

log4j果然是年代久远

以前都说log4j在jdk1.1版本就存在了,现在从源码的细节上看,的确是这样的。例如:

  1. 加载配置文件的时候,使用context class loader,它不是用标准的api,而是采用反射。
  2. 处理FileAppender的时候,针对父级目录不存在的时候需要创建目录,如果是我就直接使用mkdirs,它确是手工处理。
  3. Logger的名字是通过CategoryKey作为key存储到HashTable的,按理说用String作为key就可以了,估计是很早之前String的hashcode是不带缓存实现的吧。

其他细节

没有配置文件的时候,如何优雅处理?

正常的时候,会在static初始化的时候得到LogRepositorySelector,如果失败的话,这个值就是空的。
然后就生成一个repositorySelector = new DefaultRepositorySelector(new NOPLoggerRepository());,这个处理方式就是进行空输出。

log4j配置中的占位符处理

log4j配置中的占位符处理是在OptionConverter的substVars方法处理。优先使用系统变量,然后才是properties配置的定义 log4j.threshold用来配置log level的阀值,就是最低级别。默认是不设置。

log4j在重复加载文件时的处理

log4j在重复加载的时候,有个做法可以学习一下。这个做法和commons-logging的方式是一样的。

1
2
3
4
5
6
7
8
9
10
11
  void doConfigure(java.net.URL configURL, LoggerRepository hierarchy) {
    Properties props = new Properties();
    LogLog.debug("Reading configuration from URL " + configURL);
    InputStream istream = null;
    URLConnection uConn = null;
    try {
      uConn = configURL.openConnection();
      uConn.setUseCaches(false);
      istream = uConn.getInputStream();
      props.load(istream);
    }

layout或者appender的参数设置

log4j配置中的有时候组成一个layout或者appender,都是可以设置参数的,这些是怎么对应到类中的变量的? 实现在

1
 PropertySetter.setProperties(layout, props, layoutPrefix + ".");

通常还需要实现OptionHandler来做一些后续的初始化动作.

appender filter如何排序?

log4j的appender filter是可以配置多个的,处理顺序是按照对应的key的排序来的

1
2
3
// sort filters by IDs, insantiate filters, set filter options,
// add filters to the appender
Enumeration g = new SortedKeyEnumeration(filters);

但是它为什么不使用内置的Arrays sort或者Collections sort呢?

1
2
3
4
5
6
7
8
9
10
11
12
13
  public SortedKeyEnumeration(Hashtable ht) {
    Enumeration f = ht.keys();
    Vector keys = new Vector(ht.size());
    for (int i, last = 0; f.hasMoreElements(); ++last) {
      String key = (String) f.nextElement();
      for (i = 0; i < last; ++i) {
        String s = (String) keys.get(i);
        if (key.compareTo(s) <= 0) break;
      }
      keys.add(i, key);
    }
    e = keys.elements();
  }

输出编码没有设置会有什么问题?

如果默认编码不支持中文,可能就乱码。其他不会乱码,只是写的文件是不同编码。编码这块参考WriterAppender

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
  protected
  OutputStreamWriter createWriter(OutputStream os) {
    OutputStreamWriter retval = null;

    String enc = getEncoding();
    if(enc != null) {
      try {
  retval = new OutputStreamWriter(os, enc);
      } catch(IOException e) {
          if (e instanceof InterruptedIOException) {
              Thread.currentThread().interrupt();
          }
        LogLog.warn("Error initializing output writer.");
        LogLog.warn("Unsupported encoding?");
      }
    }
    if(retval == null) {
      retval = new OutputStreamWriter(os);
    }
    return retval;
  }

bufferedIO和bufferSize、immediateFlush有什么关联?

bufferSize只有在bufferIO开启的时候才生效,对应的是BufferedWriter对象。
如果开启了bufferIO那么immediateFlush就会重置成false。

RollingFileAppender多进程写的情况?

RollingFileAppender存在一个rollOver的操作,如果文件大小超过限制,就会进行切换。
如果存在多个进程写的时候,就很可能出现文件大小明显超过限制的情况。
原因在于RollingFileAppender初始化的时候就记录当前文件的大小,每次比较的依据是文件大小+曾经写入的文件大小。

1
2
3
4
5
6
7
8
9
10
  protected
  void subAppend(LoggingEvent event) {
    super.subAppend(event);
    if(fileName != null && qw != null) {
        long size = ((CountingQuietWriter) qw).getCount();
        if (size >= maxFileSize && size >= nextRollover) {
            rollOver();
        }
    }
   }

另外,这里的文件大小限制是字节,但统计大小的时候,用的是字符串的长度,两者是有些区别的。

1
2
3
4
5
6
7
8
9
10
  public
  void write(String string) {
    try {
      out.write(string);
      count += string.length();
    }
    catch(IOException e) {
      errorHandler.error("Write failure.", e, ErrorCode.WRITE_FAILURE);
    }
  }

DailyRollingFileAppender切换

基于一种时间窗口的算法。
首先,如何知道是按分钟、小时还是天数来切换呢?就是靠猜,例如猜测是否是小时,那么就是给一个时间去格式化,再加上一小时去格式化。 如果两个格式化的字符串一样,那么说明不是。按时间间隔,从小到大判断就可以做到。
接下来,根据日期格式,就可以计算下次切换的时间点(文件名)。
最后,判断切换的时候,根据当前时间去格式化,看看是不是不一样了,如果是,那么就开始切换了。

不过,如果多个进程写的话,就很容易出现问题。因为下面的renameTo很容易失败,然后就会继续写到原来的文件。

1
2
3
4
5
6
7
File file = new File(fileName);
boolean result = file.renameTo(target);
if(result) {
  LogLog.debug(fileName +" -> "+ scheduledFilename);
} else {
  LogLog.error("Failed to rename ["+fileName+"] to ["+scheduledFilename+"].");
}

避免对象未知状态

| Comments

今天在使用一个库的时候就遇到一个很纠结的问题。

通常我们应该避免对象new的时候出错,一种常见的设计方案是采用初始化方法。不过也有new出异常的情况,这种情况应该确保对象占用的资源能够被释放。

不过今天遇到的这个情况,是一个链接短信网关的库,假设是Proxy对象,它在初始化的时候,生成2个线程,一个是心跳线程,一个是接受消息的线程。 在链接不上的情况下,初始化会抛出异常,但是仍然会尝试重连。

1
2
3
4
5
6
7
8
9
10
11
12
public class MyProxy extends SMProxy {
    private final RecvMsgHandler handler;
    public MyProxy(Map props, RecvMsgHandler handler){
        super(props);
  this.handler = handler;
    }

    @override
    public void onRecvMsg(Message msg){
        handler.recvMsg(msg);
    }
}

上面是我想实现的构造方法,打算给他注入一个回调方法,让它在特定事件可以通知到我。 由于可能出异常,导致这个对象只是构造了一部分,一旦出现回调的时候,会存在指针异常。

另外一个问题是,本来我想管控一下所有的链接,这样可以随时控制数量。 不过由于出异常的时候,我没法拿到这个对象,所以管控不到这个可能重连的对象,相当于漏掉了这个连接。

这2个问题,特别是第二个,还真的没有什么好的解决方案。

总而言之,这个SMProxy的设计缺陷太明显,看来要绕过这个类的实现才行。

Commons-logging源码学习

| Comments

commons-logging是一个流行的logging统一接口,代码非常简单,具体的logging可以使用不同的实现,如log4j,jdk log等,即使没有这些,它还是能在控制台上输出,它可以帮你选择一种合适的logging实现。

commons-logging有LogFactory和Log两个主要接口,LogFactory实现了如何找到合适的Log,而Log是一个标准的logging接口。

LogFactory是一个抽象类,它的具体实现通过以下顺序确定:

  1. 系统属性org.apache.commons.logging.LogFactory
  2. META-INF/services/org.apache.commons.logging.LogFactory
  3. commons-logging.properties的org.apache.commons.logging.LogFactory
  4. org.apache.commons.logging.impl.LogFactoryImpl

基本上,都会是LogFactoryImpl这个实现。

另外,commons-logging可以采用SPI指定LogFactory实现,不过commons-logging并没有使用标准的ServiceLoader来处理,可能是由于commons-logging要兼容老的java版本吧。

还有,commons-logging.properties是支持重新加载的,按道理classpath加载资源是有缓存的, 见LogFactory中的getProperties,它不是直接使用getResourceAsStream,而是采用getResources/getResource,对得到的URL进行openConnection得到URLConnection对象,对它设置setUseCache为false,这的确是个小技巧。

对于Log实现,如果没有通过commons-logging.properties的的org.apache.commons.logging.Log这个key指定的话,是按照下面的方式尝试获取的:

  1. org.apache.commons.logging.impl.Log4JLogger
  2. org.apache.commons.logging.impl.Jdk14Logger
  3. org.apache.commons.logging.impl.Jdk13LumberjackLogger
  4. org.apache.commons.logging.impl.SimpleLog

很明显,只要有log4j的jar包就会选择log4j,否则就会选择jdk logging或者System.err。

所以正常情况下,不需要设置这个commons-logging.properties里边的org.apache.commons.logging.Log对应的属性值(其实这个配置文件都是不需要的)。

曾经就有项目,依赖一个自己写的jar包,就把commons-logging.properties打包进去,里边配置成SimpleLog,导致很多框架的日志不能输出到log4j指定的文件中去。

Svn报文转发出现handshake_failure的问题

| Comments

问题描述

昨天svn报文转发xx程序突然出现连不上svn的情况,报错信息如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
org.tmatesoft.svn.core.SVNException: svn: E175002: Connection has been shutdown: javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure
svn: E175002: OPTIONS request failed on '/XXXX'
  at org.tmatesoft.svn.core.internal.wc.SVNErrorManager.error(SVNErrorManager.java:106)
  at org.tmatesoft.svn.core.internal.wc.SVNErrorManager.error(SVNErrorManager.java:90)
  at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:798)
  at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:398)
  at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:386)
  at org.tmatesoft.svn.core.internal.io.dav.DAVConnection.performHttpRequest(DAVConnection.java:863)
  at org.tmatesoft.svn.core.internal.io.dav.DAVConnection.exchangeCapabilities(DAVConnection.java:699)
  at org.tmatesoft.svn.core.internal.io.dav.DAVConnection.open(DAVConnection.java:118)
  at org.tmatesoft.svn.core.internal.io.dav.DAVRepository.openConnection(DAVRepository.java:1049)
  at org.tmatesoft.svn.core.internal.io.dav.DAVRepository.testConnection(DAVRepository.java:100)
  ...
  at java.lang.Thread.run(Thread.java:744)
Caused by: javax.net.ssl.SSLException: Connection has been shutdown: javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure
  at sun.security.ssl.SSLSocketImpl.checkEOF(SSLSocketImpl.java:1476)
  at sun.security.ssl.SSLSocketImpl.checkWrite(SSLSocketImpl.java:1488)
  at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:70)
  at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
  at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
  at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.sendData(HTTPConnection.java:340)
  at org.tmatesoft.svn.core.internal.io.dav.http.HTTPRequest.dispatch(HTTPRequest.java:170)
  at org.tmatesoft.svn.core.internal.io.dav.http.HTTPConnection.request(HTTPConnection.java:497)
  ... 14 more

初步检查

  • 检查了svn用户名密码是正常的
  • 检查了代码也没有变化,java版本也没有变更
  • 初步怀疑是svn服务器做了配置更新,禁用了某些东西,由于是https,尝试开启debug信息看看

调试过程

通过设置vm参数javax.net.debug=all开启网络相关的全部调试信息,可以看到:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
*** ClientHello, SSLv3
RandomCookie:  GMT: 1460716796 bytes = { 214, 15, 157, 159, 83, 144, 248, 115, 164, 210, 12, 247, 143, 96, 117, 244, 202, 251, 111, 187, 109, 171, 81, 216, 101, 89, 33, 240 }
Session ID:  {}
Cipher Suites: [TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_RC4_128_SHA, TLS_ECDHE_RSA_WITH_RC4_128_SHA, SSL_RSA_WITH_RC4_128_SHA, TLS_ECDH_ECDSA_WITH_RC4_128_SHA, TLS_ECDH_RSA_WITH_RC4_128_SHA, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_RC4_128_MD5, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
Compression Methods:  { 0 }
Extension elliptic_curves, curve names: {secp256r1, sect163k1, sect163r2, secp192r1, secp224r1, sect233k1, sect233r1, sect283k1, sect283r1, secp384r1, sect409k1, sect409r1, secp521r1, sect571k1, sect571r1, secp160k1, secp160r1, secp160r2, sect163r1, secp192k1, sect193r1, sect193r2, secp224k1, sect239k1, secp256k1}
Extension ec_point_formats, formats: [uncompressed]
***
[write] MD5 and SHA1 hashes:  len = 149
0000: 01 00 00 91 03 00 57 11   C5 FC D6 0F 9D 9F 53 90  ......W.......S.
0010: F8 73 A4 D2 0C F7 8F 60   75 F4 CA FB 6F BB 6D AB  .s.....`u...o.m.
0020: 51 D8 65 59 21 F0 00 00   2A C0 09 C0 13 00 2F C0  Q.eY!...*...../.
0030: 04 C0 0E 00 33 00 32 C0   07 C0 11 00 05 C0 02 C0  ....3.2.........
0040: 0C C0 08 C0 12 00 0A C0   03 C0 0D 00 16 00 13 00  ................
0050: 04 00 FF 01 00 00 3E 00   0A 00 34 00 32 00 17 00  ......>...4.2...
0060: 01 00 03 00 13 00 15 00   06 00 07 00 09 00 0A 00  ................
0070: 18 00 0B 00 0C 00 19 00   0D 00 0E 00 0F 00 10 00  ................
0080: 11 00 02 00 12 00 04 00   05 00 14 00 08 00 16 00  ................
0090: 0B 00 02 01 00                                     .....
Thread-0, WRITE: SSLv3 Handshake, length = 149
[Raw write]: length = 154
0000: 16 03 00 00 95 01 00 00   91 03 00 57 11 C5 FC D6  ...........W....
0010: 0F 9D 9F 53 90 F8 73 A4   D2 0C F7 8F 60 75 F4 CA  ...S..s.....`u..
0020: FB 6F BB 6D AB 51 D8 65   59 21 F0 00 00 2A C0 09  .o.m.Q.eY!...*..
0030: C0 13 00 2F C0 04 C0 0E   00 33 00 32 C0 07 C0 11  .../.....3.2....
0040: 00 05 C0 02 C0 0C C0 08   C0 12 00 0A C0 03 C0 0D  ................
0050: 00 16 00 13 00 04 00 FF   01 00 00 3E 00 0A 00 34  ...........>...4
0060: 00 32 00 17 00 01 00 03   00 13 00 15 00 06 00 07  .2..............
0070: 00 09 00 0A 00 18 00 0B   00 0C 00 19 00 0D 00 0E  ................
0080: 00 0F 00 10 00 11 00 02   00 12 00 04 00 05 00 14  ................
0090: 00 08 00 16 00 0B 00 02   01 00                    ..........
[Raw read]: length = 5
0000: 15 03 00 00 02                                     .....
[Raw read]: length = 2
0000: 02 28                                              .(
Thread-0, READ: SSLv3 Alert, length = 2
Thread-0, RECV TLSv1 ALERT:  fatal, handshake_failure

和提示信息描述的一样,是在SSL握手阶段就失败了,采用的协议是SSLv3。估计是这个协议被svn服务器禁用了。
尝试配置成TLSv1,发现可以正常访问。

最终处理方式

由于原来的协议配置是在代码写死的,现在调整代码修改成在配置文件形式,见xxx.properties, 修改部分如下所示。
和原来一样,如果需要修改,可以在xxx-user.properties进行覆盖。

1
2
3
4
5
6
# 系统属性,通过System.setProperty设置,不清楚具体含义请不要随意修改
# 调试时可以设置为all,否则设置为none
javax.net.debug=none
https.protocols=SSLv2Hello,SSLv3,TLSv1
svnkit.http.sslProtocols=SSLv2Hello,SSLv3,TLSv1
jsse.enableSNIExtension=false

或许以后用得着的内容:

  • 调试网络信息,可以考虑javax.net.debug这个参数,它的值有很多选择,可以查阅相关材料
  • svnkit的协议配置是通过svnkit.http.sslProtocols这个参数指定的
  • 有空了解一下HTTPS/SSL的基本原理和过程

Heapdump分析简单总结

| Comments

  • 详细的材料可以查看IBM的HeapAnalyzer胶片
  • 本文只是自己的一些简单总结(废话比较多),重点还是大家基于实际dump文件去积累经验
  • 就一个工具,大家都掌握好了就可以有更多时间研究其他东西。

heapdump是什么

  • 通常的名字类似heapdump.20150919.162323.43385076.0055.phd,参考ppt的第12页
  • java堆内存快照(不包括jni,不是c/c++通常说的那个堆)
  • 用来分析oom的原因

heapdump如何生成

  • 参考ppt的第8~12页,通常维护/CMO都知道
  • 需要注意的是,大型中间件的dump是挺大的,需要有足够的硬盘空间,否则频繁的dump会导致空间不足引发其他问题。(频繁dump在生产上是可能的事情)

heapdump分析用什么工具

  • 使用IBM HeapAnalyzer(目前最新ha456.jar, 比之前的版本有更多视图,性能更好)
  • 启动方式: java -jar -Xms512m -Xmx3g ha456.jar
  • 通常要文件大小5倍+的内存, 而websphere之类的dump多在500m以上,所以需要64位的大内存机器,用64位的jdk,堆内存开2g以上
  • 工具需要界面,如果大内存64位机器如果只能找到服务器,可以采用远程运行(但受网速影响)。参考”export DISPLAY=192.168.88.71:0.0”设置xmanager的远程界面显示

ha概念要点

  • 本质上是根据对象引用关系生成一个树结构(可以结合gc的原理加深理解),参考ppt的第14页
  • 结合图例说明

图例说明

ha关注要点

  • 关注Leak Suspect,这是检测出来的可能的问题点,有时候非常方便。参考ppt的第34~37页
  • 关注内存占用比例较大的对象,ha支持按TotalSize大小顺序排列(如上图)
  • 关注节点数众多的情况,而且基本上是挂靠在容器上的(不大可能一个对象有n多内部变量),常见的有map,array,list
  • 关注自己的类,com.huawei开头的。ha支持查询,参考ppt的第54~59页。
  • 有多种维度的视图,多摸索,例如Type List就可以根据特定类型的对象数量进行排序,或许可以找到一些小的内存问题。
  • 如果能够拿到javacore,可以进行对比,定位是哪个功能引起的(单靠类名不一定能够识别哪个业务)。

常见的原因

常见的问题原因如下(有交集,并没有严格分类):

  • 内存设置太低,不过这个几率比较小。一般的web应用内存分配2G还不够,调大也不是办法。
  • 大量的线程泄露(或者某种原因阻塞),java的线程是系统线程,占用的资源还是可观的,相关的可以看Xss参数。生产一般看到的websphere也就300左右。
  • 查询/导出大量数据, 常见于SQL查询结果没有限制数量、或者在内存中集中写出。
  • 远程调用传输大量数据,常见于cics返回大量数据(其实和上面差不多是一个道理)
  • 上传并处理数据,没有分批分段处理或延后处理。
  • 数据没能及时释放,可能是处理较多的数据或较长的处理流程,不过需要显式释放对象引用的情况是比较少见的。

不过,需要注意的是:

  • 像dbc这样的jni实现可能和这个没什么关系,原因在于64位机器进程空间很大。
  • 像数据库,远程调用等响应慢,是不一定会出现dump问题的。但它会导致线程数增多(同步),数据(占用内存)未及时处理,从而导致dump。