奇怪的异常：DEBUG -- CLOSE BY CLIENT STACK TRACE

 

      last modified：2013-10-08 16:34:22

      **********************************************

      今天将测试服务器上测试通过的系统发布到线上，刚开始是出现一个mysql数据连接超时的错误，后来修改一下连接池的配置文件问题解决了，但是重新启动服务器确又报了一个新的错误：

2013-10-08 14:51:58 DEBUG [C3P0PooledConnectionPool.java:468] com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool.destroyResource() - Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@4574aee5
2013-10-08 14:51:58 DEBUG [NewPooledConnection.java:491] com.mchange.v2.c3p0.impl.NewPooledConnection.close() - com.mchange.v2.c3p0.impl.NewPooledConnection@4574aee5 closed by a client.
java.lang.Exception: DEBUG -- CLOSE BY CLIENT STACK TRACE
	at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:491)
	at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:191)
	at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:470)
	at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:964)
	at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:547)

 

 

在网上查了许多资料总结如下：这是一个提示而已，提示数据库连接池里面的连接已经关闭，使用异常形式输出是为了让程序员debug是能看到连接池里连接关闭的效果！如果要屏蔽这个错误，只要将log的输出级别改为info就可以了。

 

网上查的资料具体如下：

 

//跟踪错误代码，发现 是 c3p0 内部的异常输出

//C3p0 相关源码 ：
com.mchange.v2.c3p0.impl. NewPooledConnection

public synchronized void close() throws SQLException{ 
       close( null ); 
}
private void close( Throwable cause ) throws SQLException{ 
    close( cause, false ); 
}

private void close( Throwable cause, boolean forced ) throws SQLException{
//。。。。。。。。。。。。。。。。 
/********************出错位置************************/
            if ( cause == null ){
                this .invalidatingException = NORMAL_CLOSE_PLACEHOLDER ;
                if ( Debug.DEBUG && logger .isLoggable( MLevel.FINEST ) )
                    logger .log( MLevel.FINEST , this + " closed by a client.", new Exception("DEBUG -- CLOSE BY CLIENT STACK TRACE") );
                logCloseExceptions ( null , closeExceptions );
                if (closeExceptions.size() > 0)
                    throw new SQLException("Some resources failed to close properly while closing " + this );
/*********************************************************/
            }else{
                this .invalidatingException = cause;
                if (Debug.TRACE >= Debug.TRACE_MED )
                    logCloseExceptions ( cause, closeExceptions );
                else
                    logCloseExceptions ( cause, null );
            }
        }
    }

 原因：

由于Mysql服务器默认的wait_timeout是8小时，也就是说一个connection空闲超过8个小时，
    Mysql将自动断开该 connection。然而在C3P0 pools中的connections如果空闲超过8小时，
    Mysql将其断开，而C3P0并不知道该connection已经失效，如果这时有 Client请求connection，
    C3P0将该失效的Connection提供给Client，将会造成异常。

 

但是以上的解答不是完全的，后来在百度上看到一篇专门介绍这个bug的文章，感觉比较靠谱：

 

转自：http://hi.baidu.com/xhr8334/item/7e5a6f5326aa02d5d48bacca

由一个DEBUG说开去

    先交代一下背景。昨天晚上一个群友在群里问我一个问题。他当时在给Oracle 10g配置C3P0连接池。

最起初呢，这家伙用的是ojdbc14.jar。写法是标准的Spring的写法，但是就是不行。后来我说，你换个包。

换成classes12.jar看看。顺利执行了。

话说，后来又出了一个问题。他问我说，执行是执行了，但是出现个新的问题。

XXXX(1234567890123456) 19:02:17

新问题又出来了

XXXX(1234567890123456) 19:02:28

NewPooledConnection - closed by a client.

java.lang.Exception: DEBUG -- CLOSE BY CLIENT STACK TRACE

at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:566)

at com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:234)

at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.

destroyResource(C3P0PooledConnectionPool.java:470)

at com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.

java:964)

at com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.

java:547)

C3P0PooledConnectionPool - Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.

NewPool

 

    我看到那个DEBUG,我说，是调试信息，修改一下LOG4J的等级就行了。

    这个群友很不解的问，既然成功了，干嘛还要丢异常出来？

    这里就不得不说到两个商业开发的原则问题了。

        第一，对上家传入数据严加过滤，对传出给下家的数据仔细检查。

        第二，合理使用异常。

    第一点其实很简单的。也就是模块化开发的一个思想问题。对自己的行为负责。前端返回的数据究竟是

什么，需要进行校。不合格的剔除或者是修正。合格的处理完后，在传出之前也要加以校验，是否合格。具

体到这个问题里，就是来自Spring关于数据源的那个配置文件。

 

<bean id="dataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource" destroy-method="close">

//略去数据源相关信息的配置

</bean>

    这个配置文件里，有两个信息是很管用的。一个是class，一个是destroy-method。简单点说，一个是

数据源的实现类，一个是析构方法。Spring在读取这个配置文件以后，需要根据这些信息来实例化一些类，

然后内部再根据中间的那些配置信息来实际构造数据源。比如username啥的。

    可是来了个问题。不能保证这里的ComboPooledDataSource数据源一定是可用的，也不能保证close方法

一定能关闭连接，对吧？Spring本身不能检查这个类是否真实有效，毫无Bug。实际上呢，也检查不了。同样

的，close方法是否有效，也需要进行检查。这就是我刚才说的，对上家数据的严加检查。

    那好吧，怎么检查呢？最简洁的方法莫过于实际构造一下，连接池，获取数据库连接，执行一个测试

语句，然后关闭连接。如果一切都成功，那就OK。关于那个测试语句，配置过WebSphere数据源的同学们还记

得不？有个SQL语句会默认的写在数据源配置里，是 " SELECT 1 FROM TABLE "。嗯，对的，这个就是测试语

句。

    这一套流程能走得通，走的顺，那么就可以在自己能力范围内说这个数据源和连接池是能用的，对吧？

    这里补充一个知识。java.sql.Connection，这玩意不是class，是interface。

    声明是：public interface Connection extends Wrapper 。

    任何一个JDBC数据库连接的实现类都应该实现这个接口的全部方法。比如，close。API里的描述是，

立即释放Connection 对象的数据库和 JDBC 资源，而不是等待它们被自动释放。

    熟悉Java的同学们应该记得一点，在规范里有个要求，就是接口的实现类必须实现接口的所有方法。但是

呢，这句话还有个意思，那就是，你可以在实现所有方法之外，再写几个方法。没人会管你。

    啊哈，那就有疑问了。虽然API规定了close是关闭连接释放资源的。但这只是你接口的一厢情愿。也许人

家实现厂家觉得close方法不够帅，要改成closeConnection。那。。。Spring总不好傻傻的去死扣close方法来

关闭连接吧？虽然这方法必须实现，但是可没说一定要有内容啊。如果是空方法呢？

    所以有了destroy-method这个配置项的出现。Spring说，不碍的，您老人家看哪个爽，告诉我就行。

    现在测试完了。一切都成功了。

    现在来看看第二个问题。合理使用异常。

    又遇到一个问题。既然测试成功了，那总得给用户一点交待吧？难道说，测试成功了，就闷声大发财了？

显然不合适嘛。可以试想一下，你是程序员，然后点了个按钮，测试。结果呢，实际上是测试成功了，但是系

统啥动静都不给你。然后你傻傻的等痴痴的盼，一直等到天荒地老……嗯嗯，扯的有点远。如果你等一个小时

还不见动静，活不见人死不见尸的，你说你会不会骂娘？

    那么怎么通知才能保证一定有效呢？println？这个不见得一定能看到。因为别人也可能在同时输出信息，

一下就刷掉了。那么有同学说了，最好是能暂停一下，我输出以后，就暂停了，不动了。

    嗯，很好。

    大家想想看，输出一大堆东西，然后此程序不动了，不继续执行了，这是啥玩意?

    这不就是异常嘛！

    只有异常能保证程序员一定能看到这个信息，比如，测试成功。这就是为什么Spring要采用这种方式来通

知的原因。

    这里呢，我想更正同学们一个习惯成自然的想法。异常不一定是通知坏消息的。异常就是异常，只要你愿

意，你甚至可以在代码执行成功的时候，throws一个Exception。异常只不过是比较激烈的一种通知方式而已。

无他，仅此而已。

    现在又有个问题来了。既然要测试，而且每次执行到此处的时候都要测试一下。那么……难道都卡在这里

不走了啊？显然更不合适啊。

    熟悉log4J的同学应该看出来了，这是log4J输出的日志。很明显的，这种日志只应当在开发期间存在，不

应该在发布期间存在。因为开发期间数据库变动很大，比如改表啊，改数据库配置啊。所以需要通知用户是否

成功。但是产品一旦开发完毕，正式发布，这种信息就不应再出现，因为商业化运作的应用不允许乱动配置的，

对不？

    所以log4J提供了一种方法。消息级别。INFO的时候，是看不到这个异常的。实现起来也很好办，catch了，

然后不做任何处理，也就是空的catch块。

    具体实现的时候可以在catch里判断一下，如果等级是INFO的话，就不做任何事。如果不是，那就按照规则

去做。

     结合到 “合理使用异常” 这句话来说呢，就是说，需要抛出异常的时候，就抛出。不需要抛出的时候，

就不抛出。对程序员来说，在必要的时候看到一串异常信息，是最合适的事情了。 

      关于异常的使用，这里不展开说了。有兴趣的同学可以参见林锐博士的 高质量Java编程。