Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
On Friday I tried to recreate this issue using iptables (to block all outgoing traffic to 3306) but was still unable to recreate it. After unblocking 3306 the pool would eventually recover and create new connections. So I still do not understand why it was necessary to restart Tomcat to resolve the original problem. Since I cannot recreate the problem the best I can do is adjust some settings to help evaluate it if (when) it happens again in the future. 1. Turn on the 'abanonded' settings per your suggestions so I can see if the app is actually leaking connections. 2. Turn up pool logging to FINE. When a connection attempt times out or fails it logs at this level. 3. Possibly enable connect and TCP read timeouts on the mysql jdbc driver. Per the docs they are 'infinite' by default, but I think lower timeouts would help to detect network/firewall problems more quickly. And I'm writing a script to perform stack traces, heap dumps, lsof for open files, etc., to run on the jvm process before restarting in the event this happens again. Who knows, maybe the problem was 1 open sockets or something. Thank you for your time looking into this. I appreciate it. Regards, Colin Thank you Filip for all your help. On Thu, Mar 22, 2012 at 9:39 PM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Pretty much you're guaranteed to have a network problem at that point. You see Java caches DNS translations forever, and yanking VPN like that may change around IPs but the JVM is not aware of that. Wireshark would tell you that. Now relying in VPN is never a good thing, but maybe it's required. You could try 1. Use IP instead of host name in your jdbc URL 2. Configure the JRE to not cache dns lookups, (network.properties) The error you see tells you that: 1. The pool doesn't have any idle established connections idle=0 2. The pool doesn't have any connections used by other threads busy=0 3. There is currently 1 thread trying to activate a connection size=1. The size is an atomic counter to protect against overuse in a lock free way. Filip Hi Filip, Today I have been trying to recreate the issue by disconnecting from the vpn, as: 1. Start app. Pool creates some connections via the vpn. 2. Test app a bit to execute sql queries. 3. Shut down the vpn 4. Force some more queries. Predictably, connections fail and exceptions show up in the logs. 5. Restore vpn connection 6. Check if pool creates new connections, which it does not. I also upgraded to the latest pool available in maven central: tomcat-jdbc-7.0.26.jar I understand this could still be a connection leak in my application. But the new pool version logs an error I don't understand: ... stack trace ... Caused by: java.sql.SQLException: [scheduler-low-1] Timeout: Pool empty. Unable to fetch a connection in 10 seconds, none available[size:1; busy:0; idle:0; lastwait:1]. ... more trace ... The relevant part of my current pool DataSource configuration: removeAbandonedTimeout=10 removeAbandoned=true logAbandoned=true defaultAutoCommit=false maxActive=1 maxIdle=1 minIdle=1 maxWait=1 testOnBorrow=true validationQuery=SELECT 1 I also have yet to see any abandoned log messages. Should the pool always have at least 1 busy or idle connection? If not would it create another? Thanks, Colin On Thu, Mar 22, 2012 at 11:11 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Ultimately tho I'd still like to see some debug logging from the pool itself. Is there a simple way to turn it on? not to the problem you are looking at. if a connection got taken out of the pool, and it passed validation, then everything is ok. at this point the SQLException you get has all the data, and the problem is probably at the network level the fact that you see that for 2 hours and problem goes away with restart, that can only be the app holding on to the flawed connection, cause there would have been several validations during the 2 hour period :) I think there is a loop somewhere that when it fails it just retries and retries, logAbandoned will show that though. Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Thursday, March 22, 2012 8:06:14 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) Ah, Wireshark. My friend calls it the universal debugger. :) I will set the validation interval to 1 and keep an eye on the network to see what's going on. I may also install MySql locally so I can kill it easily to try and simulation connection timeouts. I won't really feel this is resolved until I can recreate the original issue. Thanks, Colin On Wed, Mar 21, 2012 at 11:20 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: it will take a while to see the abandoned log. I'm
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
-BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Colin, On 3/21/12 12:11 PM, Colin Ingarfield wrote: I added the 3 abandoned settings but I don't see any indication in the tomcat log that connections are being abandoned. I also made the max pool size pretty small.. my application would have failed quickly if all the connections we're being incorrectly held up. In development, I recommend setting your max connection pool size to 1: you'll find potential deadlocks that way, too. http://blog.christopherschultz.net/index.php/2009/03/16/properly-handling-pooled-jdbc-connections/ - -chris -BEGIN PGP SIGNATURE- Version: GnuPG/MacGPG2 v2.0.17 (Darwin) Comment: GPGTools - http://gpgtools.org Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iEYEARECAAYFAk9rHbgACgkQ9CaO5/Lv0PCHaQCgnv5/vPGuULmZDHk2/H4/TNcr 3nkAmgOKjma3jVulg56+UaZIHFquEsgB =8YkY -END PGP SIGNATURE- - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
Chris, On Thu, Mar 22, 2012 at 7:40 AM, Christopher Schultz ch...@christopherschultz.net wrote: -BEGIN PGP SIGNED MESSAGE- Hash: SHA1 Colin, On 3/21/12 12:11 PM, Colin Ingarfield wrote: I added the 3 abandoned settings but I don't see any indication in the tomcat log that connections are being abandoned. I also made the max pool size pretty small.. my application would have failed quickly if all the connections we're being incorrectly held up. In development, I recommend setting your max connection pool size to 1: you'll find potential deadlocks that way, too. http://blog.christopherschultz.net/index.php/2009/03/16/properly-handling-pooled-jdbc-connections/ - -chris -BEGIN PGP SIGNATURE- Version: GnuPG/MacGPG2 v2.0.17 (Darwin) Comment: GPGTools - http://gpgtools.org Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/ iEYEARECAAYFAk9rHbgACgkQ9CaO5/Lv0PCHaQCgnv5/vPGuULmZDHk2/H4/TNcr 3nkAmgOKjma3jVulg56+UaZIHFquEsgB =8YkY -END PGP SIGNATURE- - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org Setting the pool size to 1 for dev is a good idea. I'll try that. Nice blog post re: jdbc. Thankfully I use Spring 3 JDBC and it takes care of all that jdbc grunt work for me. It's possible my code is doing something strange that prevents Spring from cleaning up, but I'm not sure what that would be. Thanks for the suggestions, Colin
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
Ah, Wireshark. My friend calls it the universal debugger. :) I will set the validation interval to 1 and keep an eye on the network to see what's going on. I may also install MySql locally so I can kill it easily to try and simulation connection timeouts. I won't really feel this is resolved until I can recreate the original issue. Ultimately tho I'd still like to see some debug logging from the pool itself. Is there a simple way to turn it on? Thanks, Colin On Wed, Mar 21, 2012 at 11:20 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: it will take a while to see the abandoned log. I'm not implying every request hogs the connection, but that you could have ended up in a scenario where that did happen. otherwise, you would have not seen the problem for 2 hours and to go away when the system was restarted, as it should have failed on validation. You can enable validation every single time by doing validationInterval=1 after that, if it was me, I'd start pulling in something like Wireshark to see what is going on Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Wednesday, March 21, 2012 10:11:43 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) I added the 3 abandoned settings but I don't see any indication in the tomcat log that connections are being abandoned. I also made the max pool size pretty small.. my application would have failed quickly if all the connections we're being incorrectly held up. Anything else I can try? Thanks again for your help. -- Colin On Wed, Mar 21, 2012 at 10:41 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Got it, thank you. The other way this can happen is if the application checks out a connection and then never returns it, and expects it to be used. For this you will want to enable removeAbandonedTimeout=60 removeAbandoned=true logAbandoned=true this should tell you pretty quickly if you got a component that is hogging the connection. So test that first. Now if that is the case, there is a way to fix that: 1. remove the above settings 2. compile and configure the interceptor described in: https://issues.apache.org/bugzilla/show_bug.cgi?id=52024 In this interceptor, when a failure occurs, it automatically reconnects and retries the operation. And that is the only way to get around the problem (assuming my assumption is correct) Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: users@tomcat.apache.org Sent: Wednesday, March 21, 2012 9:30:46 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) My configuration: Resource auth=Container name=jdbc/cdb.mysql defaultAutoCommit=false driverClassName=com.mysql.jdbc.Driver factory=org.apache.tomcat.jdbc.pool.DataSourceFactory url=jdbc:mysql://X.com/_dev?sessionVariables=TRANSACTION ISOLATION LEVEL READ COMMITTED username=X password=X maxActive=100 maxIdle=100 minIdle=10 initialSize=10 maxWait=1 testOnBorrow=true type=javax.sql.DataSource validationQuery=SELECT 1/ I have testOnBorrow and validationQuery set as you suggest, so I do not think that is the issue. Thanks, Colin - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
Ultimately tho I'd still like to see some debug logging from the pool itself. Is there a simple way to turn it on? not to the problem you are looking at. if a connection got taken out of the pool, and it passed validation, then everything is ok. at this point the SQLException you get has all the data, and the problem is probably at the network level the fact that you see that for 2 hours and problem goes away with restart, that can only be the app holding on to the flawed connection, cause there would have been several validations during the 2 hour period :) I think there is a loop somewhere that when it fails it just retries and retries, logAbandoned will show that though. Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Thursday, March 22, 2012 8:06:14 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) Ah, Wireshark. My friend calls it the universal debugger. :) I will set the validation interval to 1 and keep an eye on the network to see what's going on. I may also install MySql locally so I can kill it easily to try and simulation connection timeouts. I won't really feel this is resolved until I can recreate the original issue. Thanks, Colin On Wed, Mar 21, 2012 at 11:20 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: it will take a while to see the abandoned log. I'm not implying every request hogs the connection, but that you could have ended up in a scenario where that did happen. otherwise, you would have not seen the problem for 2 hours and to go away when the system was restarted, as it should have failed on validation. You can enable validation every single time by doing validationInterval=1 after that, if it was me, I'd start pulling in something like Wireshark to see what is going on Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Wednesday, March 21, 2012 10:11:43 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) I added the 3 abandoned settings but I don't see any indication in the tomcat log that connections are being abandoned. I also made the max pool size pretty small.. my application would have failed quickly if all the connections we're being incorrectly held up. Anything else I can try? Thanks again for your help. -- Colin On Wed, Mar 21, 2012 at 10:41 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Got it, thank you. The other way this can happen is if the application checks out a connection and then never returns it, and expects it to be used. For this you will want to enable removeAbandonedTimeout=60 removeAbandoned=true logAbandoned=true this should tell you pretty quickly if you got a component that is hogging the connection. So test that first. Now if that is the case, there is a way to fix that: 1. remove the above settings 2. compile and configure the interceptor described in: https://issues.apache.org/bugzilla/show_bug.cgi?id=52024 In this interceptor, when a failure occurs, it automatically reconnects and retries the operation. And that is the only way to get around the problem (assuming my assumption is correct) Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: users@tomcat.apache.org Sent: Wednesday, March 21, 2012 9:30:46 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) My configuration: Resource auth=Container name=jdbc/cdb.mysql defaultAutoCommit=false driverClassName=com.mysql.jdbc.Driver factory=org.apache.tomcat.jdbc.pool.DataSourceFactory url=jdbc:mysql://X.com/_dev?sessionVariables=TRANSACTION ISOLATION LEVEL READ COMMITTED username=X password=X maxActive=100 maxIdle=100 minIdle=10 initialSize=10 maxWait=1 testOnBorrow=true type=javax.sql.DataSource validationQuery=SELECT 1/ I have testOnBorrow and validationQuery set as you suggest, so I do not think that is the issue. Thanks, Colin - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
Hi Filip, Today I have been trying to recreate the issue by disconnecting from the vpn, as: 1. Start app. Pool creates some connections via the vpn. 2. Test app a bit to execute sql queries. 3. Shut down the vpn 4. Force some more queries. Predictably, connections fail and exceptions show up in the logs. 5. Restore vpn connection 6. Check if pool creates new connections, which it does not. I also upgraded to the latest pool available in maven central: tomcat-jdbc-7.0.26.jar I understand this could still be a connection leak in my application. But the new pool version logs an error I don't understand: ... stack trace ... Caused by: java.sql.SQLException: [scheduler-low-1] Timeout: Pool empty. Unable to fetch a connection in 10 seconds, none available[size:1; busy:0; idle:0; lastwait:1]. ... more trace ... The relevant part of my current pool DataSource configuration: removeAbandonedTimeout=10 removeAbandoned=true logAbandoned=true defaultAutoCommit=false maxActive=1 maxIdle=1 minIdle=1 maxWait=1 testOnBorrow=true validationQuery=SELECT 1 I also have yet to see any abandoned log messages. Should the pool always have at least 1 busy or idle connection? If not would it create another? Thanks, Colin On Thu, Mar 22, 2012 at 11:11 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Ultimately tho I'd still like to see some debug logging from the pool itself. Is there a simple way to turn it on? not to the problem you are looking at. if a connection got taken out of the pool, and it passed validation, then everything is ok. at this point the SQLException you get has all the data, and the problem is probably at the network level the fact that you see that for 2 hours and problem goes away with restart, that can only be the app holding on to the flawed connection, cause there would have been several validations during the 2 hour period :) I think there is a loop somewhere that when it fails it just retries and retries, logAbandoned will show that though. Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Thursday, March 22, 2012 8:06:14 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) Ah, Wireshark. My friend calls it the universal debugger. :) I will set the validation interval to 1 and keep an eye on the network to see what's going on. I may also install MySql locally so I can kill it easily to try and simulation connection timeouts. I won't really feel this is resolved until I can recreate the original issue. Thanks, Colin On Wed, Mar 21, 2012 at 11:20 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: it will take a while to see the abandoned log. I'm not implying every request hogs the connection, but that you could have ended up in a scenario where that did happen. otherwise, you would have not seen the problem for 2 hours and to go away when the system was restarted, as it should have failed on validation. You can enable validation every single time by doing validationInterval=1 after that, if it was me, I'd start pulling in something like Wireshark to see what is going on Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Wednesday, March 21, 2012 10:11:43 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) I added the 3 abandoned settings but I don't see any indication in the tomcat log that connections are being abandoned. I also made the max pool size pretty small.. my application would have failed quickly if all the connections we're being incorrectly held up. Anything else I can try? Thanks again for your help. -- Colin On Wed, Mar 21, 2012 at 10:41 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Got it, thank you. The other way this can happen is if the application checks out a connection and then never returns it, and expects it to be used. For this you will want to enable removeAbandonedTimeout=60 removeAbandoned=true logAbandoned=true this should tell you pretty quickly if you got a component that is hogging the connection. So test that first. Now if that is the case, there is a way to fix that: 1. remove the above settings 2. compile and configure the interceptor described in: https://issues.apache.org/bugzilla/show_bug.cgi?id=52024 In this interceptor, when a failure occurs, it automatically reconnects and retries the operation. And that is the only way to get around the problem (assuming my assumption is correct) Filip - Original Message
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
Pretty much you're guaranteed to have a network problem at that point. You see Java caches DNS translations forever, and yanking VPN like that may change around IPs but the JVM is not aware of that. Wireshark would tell you that. Now relying in VPN is never a good thing, but maybe it's required. You could try 1. Use IP instead of host name in your jdbc URL 2. Configure the JRE to not cache dns lookups, (network.properties) The error you see tells you that: 1. The pool doesn't have any idle established connections idle=0 2. The pool doesn't have any connections used by other threads busy=0 3. There is currently 1 thread trying to activate a connection size=1. The size is an atomic counter to protect against overuse in a lock free way. Filip Hi Filip, Today I have been trying to recreate the issue by disconnecting from the vpn, as: 1. Start app. Pool creates some connections via the vpn. 2. Test app a bit to execute sql queries. 3. Shut down the vpn 4. Force some more queries. Predictably, connections fail and exceptions show up in the logs. 5. Restore vpn connection 6. Check if pool creates new connections, which it does not. I also upgraded to the latest pool available in maven central: tomcat-jdbc-7.0.26.jar I understand this could still be a connection leak in my application. But the new pool version logs an error I don't understand: ... stack trace ... Caused by: java.sql.SQLException: [scheduler-low-1] Timeout: Pool empty. Unable to fetch a connection in 10 seconds, none available[size:1; busy:0; idle:0; lastwait:1]. ... more trace ... The relevant part of my current pool DataSource configuration: removeAbandonedTimeout=10 removeAbandoned=true logAbandoned=true defaultAutoCommit=false maxActive=1 maxIdle=1 minIdle=1 maxWait=1 testOnBorrow=true validationQuery=SELECT 1 I also have yet to see any abandoned log messages. Should the pool always have at least 1 busy or idle connection? If not would it create another? Thanks, Colin On Thu, Mar 22, 2012 at 11:11 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Ultimately tho I'd still like to see some debug logging from the pool itself. Is there a simple way to turn it on? not to the problem you are looking at. if a connection got taken out of the pool, and it passed validation, then everything is ok. at this point the SQLException you get has all the data, and the problem is probably at the network level the fact that you see that for 2 hours and problem goes away with restart, that can only be the app holding on to the flawed connection, cause there would have been several validations during the 2 hour period :) I think there is a loop somewhere that when it fails it just retries and retries, logAbandoned will show that though. Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Thursday, March 22, 2012 8:06:14 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) Ah, Wireshark. My friend calls it the universal debugger. :) I will set the validation interval to 1 and keep an eye on the network to see what's going on. I may also install MySql locally so I can kill it easily to try and simulation connection timeouts. I won't really feel this is resolved until I can recreate the original issue. Thanks, Colin On Wed, Mar 21, 2012 at 11:20 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: it will take a while to see the abandoned log. I'm not implying every request hogs the connection, but that you could have ended up in a scenario where that did happen. otherwise, you would have not seen the problem for 2 hours and to go away when the system was restarted, as it should have failed on validation. You can enable validation every single time by doing validationInterval=1 after that, if it was me, I'd start pulling in something like Wireshark to see what is going on Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Wednesday, March 21, 2012 10:11:43 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) I added the 3 abandoned settings but I don't see any indication in the tomcat log that connections are being abandoned. I also made the max pool size pretty small.. my application would have failed quickly if all the connections we're being incorrectly held up. Anything else I can try? Thanks again for your help. -- Colin On Wed, Mar 21, 2012 at 10:41 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Got it, thank you. The other way this can happen is if the application checks out a connection and then never returns it, and expects
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
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)
Re: 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. Where your 1.1.0.1 comes from? It is not an official release. Released versions of jdbc-pool come with Tomcat 7 and share its version numbers. Best regards, Konstantin Kolinko iirc I copied the version number from the tomcat-jdbc.jar/META-INF/MANIFEST.MF file and renamed the jar myself. (Looking in the manifest now I see Bundle-Version: 1.1.0.1). I prefer to avoid unversioned jar files in my project as it can cause confusion. But I don't recall which version of Tomcat 7 I got the jar from. Is the best policy to always use the tomcat-jdbc jar from the latest version of Tomcat 7? Thank you, Colin
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
That is very easily fixed testOnBorrow=true validationQuery=SELECT 1 Do you have this set? Otherwise, yes, you wont be able to detect if connections time out. send me your config - Original Message - From: Colin Ingarfield colin...@gmail.com To: users@tomcat.apache.org Sent: Wednesday, March 21, 2012 6:23:02 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) 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
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
- Original Message - From: Colin Ingarfield colin...@gmail.com To: users@tomcat.apache.org Sent: Wednesday, March 21, 2012 6:25:54 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) iirc I copied the version number from the tomcat-jdbc.jar/META-INF/MANIFEST.MF file and renamed the jar myself. (Looking in the manifest now I see Bundle-Version: 1.1.0.1). I prefer to avoid unversioned jar files in my project as it can cause confusion. But I don't recall which version of Tomcat 7 I got the jar from. Is the best policy to always use the tomcat-jdbc jar from the latest version of Tomcat 7? yes, as of now it is. As tomcat-jdbc got included in Tomcat 7 it gets published as an individual JAR in the Maven repo as well. Filip Thank you, Colin - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
My configuration: Resource auth=Container name=jdbc/cdb.mysql defaultAutoCommit=false driverClassName=com.mysql.jdbc.Driver factory=org.apache.tomcat.jdbc.pool.DataSourceFactory url=jdbc:mysql://X.com/_dev?sessionVariables=TRANSACTION ISOLATION LEVEL READ COMMITTED username=X password=X maxActive=100 maxIdle=100 minIdle=10 initialSize=10 maxWait=1 testOnBorrow=true type=javax.sql.DataSource validationQuery=SELECT 1/ I have testOnBorrow and validationQuery set as you suggest, so I do not think that is the issue. Thanks, Colin
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
Got it, thank you. The other way this can happen is if the application checks out a connection and then never returns it, and expects it to be used. For this you will want to enable removeAbandonedTimeout=60 removeAbandoned=true logAbandoned=true this should tell you pretty quickly if you got a component that is hogging the connection. So test that first. Now if that is the case, there is a way to fix that: 1. remove the above settings 2. compile and configure the interceptor described in: https://issues.apache.org/bugzilla/show_bug.cgi?id=52024 In this interceptor, when a failure occurs, it automatically reconnects and retries the operation. And that is the only way to get around the problem (assuming my assumption is correct) Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: users@tomcat.apache.org Sent: Wednesday, March 21, 2012 9:30:46 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) My configuration: Resource auth=Container name=jdbc/cdb.mysql defaultAutoCommit=false driverClassName=com.mysql.jdbc.Driver factory=org.apache.tomcat.jdbc.pool.DataSourceFactory url=jdbc:mysql://X.com/_dev?sessionVariables=TRANSACTION ISOLATION LEVEL READ COMMITTED username=X password=X maxActive=100 maxIdle=100 minIdle=10 initialSize=10 maxWait=1 testOnBorrow=true type=javax.sql.DataSource validationQuery=SELECT 1/ I have testOnBorrow and validationQuery set as you suggest, so I do not think that is the issue. Thanks, Colin - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
I added the 3 abandoned settings but I don't see any indication in the tomcat log that connections are being abandoned. I also made the max pool size pretty small.. my application would have failed quickly if all the connections we're being incorrectly held up. Anything else I can try? Thanks again for your help. -- Colin On Wed, Mar 21, 2012 at 10:41 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Got it, thank you. The other way this can happen is if the application checks out a connection and then never returns it, and expects it to be used. For this you will want to enable removeAbandonedTimeout=60 removeAbandoned=true logAbandoned=true this should tell you pretty quickly if you got a component that is hogging the connection. So test that first. Now if that is the case, there is a way to fix that: 1. remove the above settings 2. compile and configure the interceptor described in: https://issues.apache.org/bugzilla/show_bug.cgi?id=52024 In this interceptor, when a failure occurs, it automatically reconnects and retries the operation. And that is the only way to get around the problem (assuming my assumption is correct) Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: users@tomcat.apache.org Sent: Wednesday, March 21, 2012 9:30:46 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) My configuration: Resource auth=Container name=jdbc/cdb.mysql defaultAutoCommit=false driverClassName=com.mysql.jdbc.Driver factory=org.apache.tomcat.jdbc.pool.DataSourceFactory url=jdbc:mysql://X.com/_dev?sessionVariables=TRANSACTION ISOLATION LEVEL READ COMMITTED username=X password=X maxActive=100 maxIdle=100 minIdle=10 initialSize=10 maxWait=1 testOnBorrow=true type=javax.sql.DataSource validationQuery=SELECT 1/ I have testOnBorrow and validationQuery set as you suggest, so I do not think that is the issue. Thanks, Colin - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
it will take a while to see the abandoned log. I'm not implying every request hogs the connection, but that you could have ended up in a scenario where that did happen. otherwise, you would have not seen the problem for 2 hours and to go away when the system was restarted, as it should have failed on validation. You can enable validation every single time by doing validationInterval=1 after that, if it was me, I'd start pulling in something like Wireshark to see what is going on Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Wednesday, March 21, 2012 10:11:43 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) I added the 3 abandoned settings but I don't see any indication in the tomcat log that connections are being abandoned. I also made the max pool size pretty small.. my application would have failed quickly if all the connections we're being incorrectly held up. Anything else I can try? Thanks again for your help. -- Colin On Wed, Mar 21, 2012 at 10:41 AM, Filip Hanik Mailing Lists devli...@hanik.com wrote: Got it, thank you. The other way this can happen is if the application checks out a connection and then never returns it, and expects it to be used. For this you will want to enable removeAbandonedTimeout=60 removeAbandoned=true logAbandoned=true this should tell you pretty quickly if you got a component that is hogging the connection. So test that first. Now if that is the case, there is a way to fix that: 1. remove the above settings 2. compile and configure the interceptor described in: https://issues.apache.org/bugzilla/show_bug.cgi?id=52024 In this interceptor, when a failure occurs, it automatically reconnects and retries the operation. And that is the only way to get around the problem (assuming my assumption is correct) Filip - Original Message - From: Colin Ingarfield colin...@gmail.com To: users@tomcat.apache.org Sent: Wednesday, March 21, 2012 9:30:46 AM Subject: Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32) My configuration: Resource auth=Container name=jdbc/cdb.mysql defaultAutoCommit=false driverClassName=com.mysql.jdbc.Driver factory=org.apache.tomcat.jdbc.pool.DataSourceFactory url=jdbc:mysql://X.com/_dev?sessionVariables=TRANSACTION ISOLATION LEVEL READ COMMITTED username=X password=X maxActive=100 maxIdle=100 minIdle=10 initialSize=10 maxWait=1 testOnBorrow=true type=javax.sql.DataSource validationQuery=SELECT 1/ I have testOnBorrow and validationQuery set as you suggest, so I do not think that is the issue. Thanks, Colin - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
RE: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
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] 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 - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: how to enable debug logging for Tomcat jdbc pool (Tomcat 6.0.32)
2012/3/19 Colin Ingarfield colin...@gmail.com: 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. Where your 1.1.0.1 comes from? It is not an official release. Released versions of jdbc-pool come with Tomcat 7 and share its version numbers. Best regards, Konstantin Kolinko - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
