Hello Filip,
Over the weekend my application appears to have lost connectivity to its
MySQL server. At that point in my logs I see these errors:
2012-03-16 18:25:18,248 ERROR [pool-3-thread-201]
c.l.c.s.e.EventServiceImpl failed to store event
[com.lim.cd.service.event.beans.SubscribeEvent@730c434d]
org.springframework.dao.RecoverableDataAccessException:
PreparedStatementCallback; SQL [insert into sessions (session_id,
username, uuid, created) values (?, ?, ?, ?)]; Communications link failure
The last packet sent successfully to the server was 0 milliseconds ago.
The driver has not received any packets from the server.; nested
exception is com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:
Communications link failure
(... a lot omitted ...)
Caused by: java.net.ConnectException: Connection timed out
(the whole stack trace is long, I'll post it at the end.)
This error appeared over and over again for 2 hours and every MySQL
request failed. After restarting Tomcat the app was able to connect to
MySQL and functioned normally. This is the first and only time I've
seen this happen.
Assuming this was a brief network or MySQL outage (the sys admins
haven't said either way), I would expect the connection pool to handle
the situation by destroying these dead connections and creating new ones
automatically once database connectivity was restored. That never
happened (until we restarted Tomcat.)
So my thought was to turn up the logging on the connection pool and try
to see what's going on. I couldn't find any log output from the pool in
my logs or in the Tomcat logs directory.
My application uses Spring JDBC and Spring's @Transaction annotations so
my code does not directly interact with the DataSource or the jdbc
Connections.
I suspect a misconfiguration on my part but I need to know what is
actually failing before I can figure out what's wrong.
Any advice greatly appreciated.
Thanks,
Colin
full stack trace:
2012-03-16 18:25:18,248 ERROR [pool-3-thread-201]
c.l.c.s.e.EventServiceImpl failed to store event
[com.lim.cd.service.event.beans.SubscribeEvent@730c434d]
org.springframework.dao.RecoverableDataAccessException:
PreparedStatementCallback; SQL [insert into sessions (session_id,
username, uuid, created) values (?, ?, ?, ?)]; Communications link failure
The last packet sent successfully to the server was 0 milliseconds ago.
The driver has not received any packets from the server.; nested
exception is com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:
Communications link failure
The last packet sent successfully to the server was 0 milliseconds ago.
The driver has not received any packets from the server.
at
org.springframework.jdbc.support.SQLExceptionSubclassTranslator.doTranslate(SQLExceptionSubclassTranslator.java:98)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:602)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:811)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:867)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:875)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
com.lim.cd.service.event.dao.MySqlEventDao.createSession(MySqlEventDao.java:201)
~[MySqlEventDao.class:na]
at
com.lim.cd.service.event.dao.MySqlEventDao.createOrUpdateSession(MySqlEventDao.java:191)
~[MySqlEventDao.class:na]
at sun.reflect.GeneratedMethodAccessor62.invoke(Unknown Source)
~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
~[na:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_29]
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
~[spring-aop-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
~[spring-aop-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
~[spring-aop-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
~[spring-tx-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
~[spring-aop-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
~[spring-aop-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at $Proxy26.createOrUpdateSession(Unknown Source) ~[na:na]
at
com.lim.cd.service.event.EventServiceImpl$1.run(EventServiceImpl.java:94)
~[EventServiceImpl$1.class:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
[na:1.6.0_29]
at
java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
[na:1.6.0_29]
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
[na:1.6.0_29]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[na:1.6.0_29]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[na:1.6.0_29]
at java.lang.Thread.run(Thread.java:662) [na:1.6.0_29]
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:
Communications link failure
The last packet sent successfully to the server was 0 milliseconds ago.
The driver has not received any packets from the server.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native
Method) ~[na:1.6.0_29]
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
~[na:1.6.0_29]
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
~[na:1.6.0_29]
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
~[na:1.6.0_29]
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
~[mysql-connector-java-5.1.17-bin.jar:na]
at
com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
~[mysql-connector-java-5.1.17-bin.jar:na]
at com.mysql.jdbc.MysqlIO.<init>(MysqlIO.java:344)
~[mysql-connector-java-5.1.17-bin.jar:na]
at
com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2333)
~[mysql-connector-java-5.1.17-bin.jar:na]
at
com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2370)
~[mysql-connector-java-5.1.17-bin.jar:na]
at
com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2154)
~[mysql-connector-java-5.1.17-bin.jar:na]
at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:792)
~[mysql-connector-java-5.1.17-bin.jar:na]
at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
~[mysql-connector-java-5.1.17-bin.jar:na]
at sun.reflect.GeneratedConstructorAccessor101.newInstance(Unknown
Source) ~[na:na]
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
~[na:1.6.0_29]
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
~[na:1.6.0_29]
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
~[mysql-connector-java-5.1.17-bin.jar:na]
at
com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:381)
~[mysql-connector-java-5.1.17-bin.jar:na]
at
com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:305)
~[mysql-connector-java-5.1.17-bin.jar:na]
at
org.apache.tomcat.jdbc.pool.PooledConnection.connectUsingDriver(PooledConnection.java:267)
~[tomcat-jdbc-1.1.0.1.jar:na]
at
org.apache.tomcat.jdbc.pool.PooledConnection.connect(PooledConnection.java:176)
~[tomcat-jdbc-1.1.0.1.jar:na]
at
org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:653)
~[tomcat-jdbc-1.1.0.1.jar:na]
at
org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:595)
~[tomcat-jdbc-1.1.0.1.jar:na]
at
org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:174)
~[tomcat-jdbc-1.1.0.1.jar:na]
at
org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:111)
~[tomcat-jdbc-1.1.0.1.jar:na]
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
~[na:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_29]
at net.bull.javamelody.JdbcWrapper$4.invoke(JdbcWrapper.java:660)
~[javamelody-core-1.34.0.jar:1.34.0]
at
net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:232)
~[javamelody-core-1.34.0.jar:1.34.0]
at $Proxy4.getConnection(Unknown Source) ~[na:na]
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
~[na:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_29]
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
~[spring-aop-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:196)
~[spring-aop-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at $Proxy13.getConnection(Unknown Source) ~[na:na]
at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
~[na:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_29]
at net.bull.javamelody.JdbcWrapper$4.invoke(JdbcWrapper.java:660)
~[javamelody-core-1.34.0.jar:1.34.0]
at
net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:232)
~[javamelody-core-1.34.0.jar:1.34.0]
at $Proxy21.getConnection(Unknown Source) ~[na:na]
at
org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy$LazyConnectionInvocationHandler.getTargetConnection(LazyConnectionDataSourceProxy.java:403)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.jdbc.datasource.LazyConnectionDataSourceProxy$LazyConnectionInvocationHandler.invoke(LazyConnectionDataSourceProxy.java:376)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at $Proxy28.prepareStatement(Unknown Source) ~[na:na]
at sun.reflect.GeneratedMethodAccessor28.invoke(Unknown Source)
~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
~[na:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_29]
at
net.bull.javamelody.JdbcWrapper$ConnectionInvocationHandler.invoke(JdbcWrapper.java:176)
~[javamelody-core-1.34.0.jar:1.34.0]
at
net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:232)
~[javamelody-core-1.34.0.jar:1.34.0]
at $Proxy29.prepareStatement(Unknown Source) ~[na:na]
at
org.springframework.jdbc.core.JdbcTemplate$SimplePreparedStatementCreator.createPreparedStatement(JdbcTemplate.java:1375)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
at
org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:580)
~[spring-jdbc-3.0.5.RELEASE.jar:3.0.5.RELEASE]
... 22 common frames omitted
Caused by: java.net.ConnectException: Connection timed out
at java.net.PlainSocketImpl.socketConnect(Native Method) ~[na:1.6.0_29]
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
~[na:1.6.0_29]
at
java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
~[na:1.6.0_29]
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
~[na:1.6.0_29]
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
~[na:1.6.0_29]
at java.net.Socket.connect(Socket.java:529) ~[na:1.6.0_29]
at java.net.Socket.connect(Socket.java:478) ~[na:1.6.0_29]
at java.net.Socket.<init>(Socket.java:375) ~[na:1.6.0_29]
at java.net.Socket.<init>(Socket.java:218) ~[na:1.6.0_29]
at
com.mysql.jdbc.StandardSocketFactory.connect(StandardSocketFactory.java:257)
~[mysql-connector-java-5.1.17-bin.jar:na]
at com.mysql.jdbc.MysqlIO.<init>(MysqlIO.java:294)
~[mysql-connector-java-5.1.17-bin.jar:na]
... 68 common frames omitted
On 03/20/2012 10:29 AM, Filip Hanik (mailing lists) wrote:
Define "connection timeouts" so that we can understand your problem to
suggest for how to trace it down.
What are you trying to search for. Errors would be logged as errors, and
should show up with the standard configuration
Filip
-----Original Message-----
From: Colin Ingarfield [mailto:colin...@gmail.com <colin...@gmail.com>]
Sent: Monday, March 19, 2012 1:51 PM
To: users@tomcat.apache.org
Subject: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
Hello,
I'm using the new Tomcat jdbc pool (1.1.0.1) with Tomcat 6.0.32, Ubuntu
x86_64. I would like to increase the logging from the pool to try and
chase down connection timeouts.
I added the following line to $CATALINA_BASE/conf/logging.properties:
org.apache.tomcat.jdbc.pool.level=FINE
(the rest of the logging.properties file is unchanged.)
But I don't see any pool debug logging output on the console. I thought
this setting would enable debug logging for all classes in that package.
Is there something else I need to do?
Thank you,
Colin
