connection pool: poisoned connection not being removed from pool

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

connection pool: poisoned connection not being removed from pool

Emmanuel Touzery-2
Hello,

     we are seeing with our TOMEE setup that a connection that was
(potentially uncleanly) closed from the SQL server remains in the pool
for longer periods (instead of being closed+reopened), causing long-term
issues with the application, which we can only fix through a restart.

     A scenario where we see this clearly are failovers: in that case
the currently open connections will become invalid, which the
application should realise quickly enough through the validation
queries, therefore quickly cleaning up the pool (trying to establish a
new connection would work, except in the first few hundreds of
milliseconds of the event). But that's not what we see. We also see
situation where something happens to the SQL server (for instance it's
restarted), or the connection from TOMEE to the SQL server is disrupted,
but the application never recovers until TOMEE is restarted.

     Here is our resource, as defined in the tomee.xml:

     <Resource id="jdbc/generic" type="javax.sql.DataSource">
         jdbcDriver = org.postgresql.Driver
         jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
         userName = xxxxxx
         password = xxxxxx
         maxActive = 140
         maxIdle = 20
         validationQuery = select version();
         testWhileIdle = true
         testOnBorrow = true
         testOnReturn = false
         timeBetweenEvictionRuns = 10000 millisecond
         removeAbandonedTimeout = 4400
         removeAbandoned = true
         maxWaitTime = 30000 millisecond
     </Resource>

     We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
upgraded from 5.2.12 recently, had the issue with that version too).

     Is there anything else we should do to make sure that we properly
recover when something happens to some connections from the pool?

     Thank you!

Emmanuel

PS: Some relevant sections of the stacktraces we're seeing for longer
period of times after the event:

         Caused by: javax.persistence.PersistenceException:
org.hibernate.exception.JDBCConnectionException: could not prepare
statement
                 at
org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)

                 at
org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)

                 at org.hibernate.query.Query.getResultList(Query.java:165)


         Caused by: org.postgresql.util.PSQLException: This connection
has been closed.
                 at
org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
                 at
org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
                 at
org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
                 at
jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
                 at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

                 at
java.base/java.lang.reflect.Method.invoke(Method.java:566)
                 at
org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)

                 at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)

                 at
org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)

                 at
org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)

                 at
org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)

                 at com.sun.proxy.$Proxy257.prepareStatement(Unknown
Source)
                 at
jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
                 at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

                 at
java.base/java.lang.reflect.Method.invoke(Method.java:566)
                 at
org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)

                 at
org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)

                 at com.sun.proxy.$Proxy256.prepareStatement(Unknown
Source)
                 at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)

                 at
org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)

                 ... 88 more

Reply | Threaded
Open this post in threaded view
|

Re: connection pool: poisoned connection not being removed from pool

jgallimore
Sounds like you're using TomEE 8 and Postgres (can you specify the version
of Postgres and the JDBC driver?)

Can we get a bit more detail on the "failover" element - is this a failover
to a secondary database node? Are the database nodes you connect to
specified in the JDBC URI, or do you have a loadbalancer/proxy that is
shifting the connections across?

I'd like to reproduce and find out what's going on.

Jon

On Tue, Jan 19, 2021 at 10:05 AM Emmanuel Touzery <
[hidden email]> wrote:

> Hello,
>
>      we are seeing with our TOMEE setup that a connection that was
> (potentially uncleanly) closed from the SQL server remains in the pool
> for longer periods (instead of being closed+reopened), causing long-term
> issues with the application, which we can only fix through a restart.
>
>      A scenario where we see this clearly are failovers: in that case
> the currently open connections will become invalid, which the
> application should realise quickly enough through the validation
> queries, therefore quickly cleaning up the pool (trying to establish a
> new connection would work, except in the first few hundreds of
> milliseconds of the event). But that's not what we see. We also see
> situation where something happens to the SQL server (for instance it's
> restarted), or the connection from TOMEE to the SQL server is disrupted,
> but the application never recovers until TOMEE is restarted.
>
>      Here is our resource, as defined in the tomee.xml:
>
>      <Resource id="jdbc/generic" type="javax.sql.DataSource">
>          jdbcDriver = org.postgresql.Driver
>          jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>          userName = xxxxxx
>          password = xxxxxx
>          maxActive = 140
>          maxIdle = 20
>          validationQuery = select version();
>          testWhileIdle = true
>          testOnBorrow = true
>          testOnReturn = false
>          timeBetweenEvictionRuns = 10000 millisecond
>          removeAbandonedTimeout = 4400
>          removeAbandoned = true
>          maxWaitTime = 30000 millisecond
>      </Resource>
>
>      We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
> upgraded from 5.2.12 recently, had the issue with that version too).
>
>      Is there anything else we should do to make sure that we properly
> recover when something happens to some connections from the pool?
>
>      Thank you!
>
> Emmanuel
>
> PS: Some relevant sections of the stacktraces we're seeing for longer
> period of times after the event:
>
>          Caused by: javax.persistence.PersistenceException:
> org.hibernate.exception.JDBCConnectionException: could not prepare
> statement
>                  at
> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>
>
>                  at
> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>
>
>                  at org.hibernate.query.Query.getResultList(Query.java:165)
>
>
>          Caused by: org.postgresql.util.PSQLException: This connection
> has been closed.
>                  at
> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>                  at
> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>                  at
> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>                  at
> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>                  at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>
>                  at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>                  at
> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>
>
>                  at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>
>
>                  at
> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>
>
>                  at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>
>
>                  at
> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>
>
>                  at com.sun.proxy.$Proxy257.prepareStatement(Unknown
> Source)
>                  at
> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>                  at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>
>                  at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>                  at
> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>
>
>                  at
> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>
>
>                  at com.sun.proxy.$Proxy256.prepareStatement(Unknown
> Source)
>                  at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>
>
>                  at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>
>
>                  ... 88 more
>
>
Reply | Threaded
Open this post in threaded view
|

Re: connection pool: poisoned connection not being removed from pool

Emmanuel Touzery-2
Hello,

     I have to say it's not necessarily about the failover. We can also
see this if there is something wrong with the connection to the server.
I believe including if the SQL server is restarted.

     My understanding is that it's normal that there is an error, but I
would expect TOMEE to recover -- to stop handling to the application a
JDBC connection which is in fact closed and has shown itself in the past
to be invalid. Especially since we configure a validation query.

     This is otherwise Enterprise DB 12. My understanding is that it's
mostly a rebranded Postgresql. We are using the normal postgresql
driver, although an older version (we didn't try a newer version,
assuming that's not related to the issue at hand). We're using the
postgresql jdbc driver version 42.1.4.
     For the failover, we're using EFM:
https://www.enterprisedb.com/edb-docs/d/edb-postgres-failover-manager/user-guides/user-guide/3.7/using_efm_utility.html

     There is a "virtual IP" that we connect to through JDBC, and it
links to one or the other true IP, over 3 EDB nodes.

     We actually don't get an issue at every switchover. Even load
testing the app (with a relatively light load though), we need ~4
failovers to reproduce the issue. Meaning, an OK failover means that we
get JDBC errors during the failover, but then the application recovers.
A bad failover is when we keep getting errors long after the failover
finished. I think it's tied to whether we had a compromised connection
in the pool before the failover.

     Thank you for the answer!

Emmanuel

On 19/01/2021 13:26, Jonathan Gallimore wrote:

> Sounds like you're using TomEE 8 and Postgres (can you specify the version
> of Postgres and the JDBC driver?)
>
> Can we get a bit more detail on the "failover" element - is this a failover
> to a secondary database node? Are the database nodes you connect to
> specified in the JDBC URI, or do you have a loadbalancer/proxy that is
> shifting the connections across?
>
> I'd like to reproduce and find out what's going on.
>
> Jon
>
> On Tue, Jan 19, 2021 at 10:05 AM Emmanuel Touzery <
> [hidden email]> wrote:
>
>> Hello,
>>
>>       we are seeing with our TOMEE setup that a connection that was
>> (potentially uncleanly) closed from the SQL server remains in the pool
>> for longer periods (instead of being closed+reopened), causing long-term
>> issues with the application, which we can only fix through a restart.
>>
>>       A scenario where we see this clearly are failovers: in that case
>> the currently open connections will become invalid, which the
>> application should realise quickly enough through the validation
>> queries, therefore quickly cleaning up the pool (trying to establish a
>> new connection would work, except in the first few hundreds of
>> milliseconds of the event). But that's not what we see. We also see
>> situation where something happens to the SQL server (for instance it's
>> restarted), or the connection from TOMEE to the SQL server is disrupted,
>> but the application never recovers until TOMEE is restarted.
>>
>>       Here is our resource, as defined in the tomee.xml:
>>
>>       <Resource id="jdbc/generic" type="javax.sql.DataSource">
>>           jdbcDriver = org.postgresql.Driver
>>           jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>>           userName = xxxxxx
>>           password = xxxxxx
>>           maxActive = 140
>>           maxIdle = 20
>>           validationQuery = select version();
>>           testWhileIdle = true
>>           testOnBorrow = true
>>           testOnReturn = false
>>           timeBetweenEvictionRuns = 10000 millisecond
>>           removeAbandonedTimeout = 4400
>>           removeAbandoned = true
>>           maxWaitTime = 30000 millisecond
>>       </Resource>
>>
>>       We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
>> upgraded from 5.2.12 recently, had the issue with that version too).
>>
>>       Is there anything else we should do to make sure that we properly
>> recover when something happens to some connections from the pool?
>>
>>       Thank you!
>>
>> Emmanuel
>>
>> PS: Some relevant sections of the stacktraces we're seeing for longer
>> period of times after the event:
>>
>>           Caused by: javax.persistence.PersistenceException:
>> org.hibernate.exception.JDBCConnectionException: could not prepare
>> statement
>>                   at
>> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>>
>>
>>                   at
>> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>>
>>
>>                   at org.hibernate.query.Query.getResultList(Query.java:165)
>>
>>
>>           Caused by: org.postgresql.util.PSQLException: This connection
>> has been closed.
>>                   at
>> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>>                   at
>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>>                   at
>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>>                   at
>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>                   at
>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>
>>
>>                   at
>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>                   at
>> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>>
>>
>>                   at
>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>
>>
>>                   at
>> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>>
>>
>>                   at
>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>
>>
>>                   at
>> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>>
>>
>>                   at com.sun.proxy.$Proxy257.prepareStatement(Unknown
>> Source)
>>                   at
>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>                   at
>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>
>>
>>                   at
>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>                   at
>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>>
>>
>>                   at
>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>>
>>
>>                   at com.sun.proxy.$Proxy256.prepareStatement(Unknown
>> Source)
>>                   at
>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>>
>>
>>                   at
>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>>
>>
>>                   ... 88 more
>>
>>

Reply | Threaded
Open this post in threaded view
|

Re: connection pool: poisoned connection not being removed from pool

kerickson
In reply to this post by Emmanuel Touzery-2
Hi Emmanual, I believe that is how connections that were discarded due to
removeAbandoned = true. In an ideal setup you shouldnt need that flag or
its timeout, becaise the transactions should be too fast to go that long

Also some versions before tomee 8.0.5 have a memory leak in the version of
bval that is used. Not sure if 8.0.1 has that problem version but try
updatng tomee to 8.0.5

On Tue, Jan 19, 2021, 2:05 AM Emmanuel Touzery <
[hidden email]> wrote:

> Hello,
>
>      we are seeing with our TOMEE setup that a connection that was
> (potentially uncleanly) closed from the SQL server remains in the pool
> for longer periods (instead of being closed+reopened), causing long-term
> issues with the application, which we can only fix through a restart.
>
>      A scenario where we see this clearly are failovers: in that case
> the currently open connections will become invalid, which the
> application should realise quickly enough through the validation
> queries, therefore quickly cleaning up the pool (trying to establish a
> new connection would work, except in the first few hundreds of
> milliseconds of the event). But that's not what we see. We also see
> situation where something happens to the SQL server (for instance it's
> restarted), or the connection from TOMEE to the SQL server is disrupted,
> but the application never recovers until TOMEE is restarted.
>
>      Here is our resource, as defined in the tomee.xml:
>
>      <Resource id="jdbc/generic" type="javax.sql.DataSource">
>          jdbcDriver = org.postgresql.Driver
>          jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>          userName = xxxxxx
>          password = xxxxxx
>          maxActive = 140
>          maxIdle = 20
>          validationQuery = select version();
>          testWhileIdle = true
>          testOnBorrow = true
>          testOnReturn = false
>          timeBetweenEvictionRuns = 10000 millisecond
>          removeAbandonedTimeout = 4400
>          removeAbandoned = true
>          maxWaitTime = 30000 millisecond
>      </Resource>
>
>      We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
> upgraded from 5.2.12 recently, had the issue with that version too).
>
>      Is there anything else we should do to make sure that we properly
> recover when something happens to some connections from the pool?
>
>      Thank you!
>
> Emmanuel
>
> PS: Some relevant sections of the stacktraces we're seeing for longer
> period of times after the event:
>
>          Caused by: javax.persistence.PersistenceException:
> org.hibernate.exception.JDBCConnectionException: could not prepare
> statement
>                  at
> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>
>
>                  at
> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>
>
>                  at org.hibernate.query.Query.getResultList(Query.java:165)
>
>
>          Caused by: org.postgresql.util.PSQLException: This connection
> has been closed.
>                  at
> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>                  at
> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>                  at
> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>                  at
> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>                  at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>
>                  at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>                  at
> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>
>
>                  at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>
>
>                  at
> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>
>
>                  at
> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>
>
>                  at
> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>
>
>                  at com.sun.proxy.$Proxy257.prepareStatement(Unknown
> Source)
>                  at
> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>                  at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>
>
>                  at
> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>                  at
> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>
>
>                  at
> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>
>
>                  at com.sun.proxy.$Proxy256.prepareStatement(Unknown
> Source)
>                  at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>
>
>                  at
> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>
>
>                  ... 88 more
>
>
Reply | Threaded
Open this post in threaded view
|

Re: connection pool: poisoned connection not being removed from pool

Emmanuel Touzery-2
Hello,

     if I understand you correctly, you're suggesting to remove these
settings:

  removeAbandoned = true
  removeAbandonedTimeout = 4400

     I did that now, we don't really need them. Unfortunately I can
still reproduce the issue even after removing both settings.

     We are aware of the memory leak yes, we stumbled on it before a
released version of tomee fixed it, so we disabled bean validation.
We'll reenable it when we upgrade TOMEE.

     So that means for now we're still unsure what's causing this issue
for us :-(

     Thank you!

Emmanuel

On 19/01/2021 19:18, Kean Erickson wrote:

> Hi Emmanual, I believe that is how connections that were discarded due to
> removeAbandoned = true. In an ideal setup you shouldnt need that flag or
> its timeout, becaise the transactions should be too fast to go that long
>
> Also some versions before tomee 8.0.5 have a memory leak in the version of
> bval that is used. Not sure if 8.0.1 has that problem version but try
> updatng tomee to 8.0.5
>
> On Tue, Jan 19, 2021, 2:05 AM Emmanuel Touzery <
> [hidden email]> wrote:
>
>> Hello,
>>
>>       we are seeing with our TOMEE setup that a connection that was
>> (potentially uncleanly) closed from the SQL server remains in the pool
>> for longer periods (instead of being closed+reopened), causing long-term
>> issues with the application, which we can only fix through a restart.
>>
>>       A scenario where we see this clearly are failovers: in that case
>> the currently open connections will become invalid, which the
>> application should realise quickly enough through the validation
>> queries, therefore quickly cleaning up the pool (trying to establish a
>> new connection would work, except in the first few hundreds of
>> milliseconds of the event). But that's not what we see. We also see
>> situation where something happens to the SQL server (for instance it's
>> restarted), or the connection from TOMEE to the SQL server is disrupted,
>> but the application never recovers until TOMEE is restarted.
>>
>>       Here is our resource, as defined in the tomee.xml:
>>
>>       <Resource id="jdbc/generic" type="javax.sql.DataSource">
>>           jdbcDriver = org.postgresql.Driver
>>           jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>>           userName = xxxxxx
>>           password = xxxxxx
>>           maxActive = 140
>>           maxIdle = 20
>>           validationQuery = select version();
>>           testWhileIdle = true
>>           testOnBorrow = true
>>           testOnReturn = false
>>           timeBetweenEvictionRuns = 10000 millisecond
>>           removeAbandonedTimeout = 4400
>>           removeAbandoned = true
>>           maxWaitTime = 30000 millisecond
>>       </Resource>
>>
>>       We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
>> upgraded from 5.2.12 recently, had the issue with that version too).
>>
>>       Is there anything else we should do to make sure that we properly
>> recover when something happens to some connections from the pool?
>>
>>       Thank you!
>>
>> Emmanuel
>>
>> PS: Some relevant sections of the stacktraces we're seeing for longer
>> period of times after the event:
>>
>>           Caused by: javax.persistence.PersistenceException:
>> org.hibernate.exception.JDBCConnectionException: could not prepare
>> statement
>>                   at
>> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>>
>>
>>                   at
>> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>>
>>
>>                   at org.hibernate.query.Query.getResultList(Query.java:165)
>>
>>
>>           Caused by: org.postgresql.util.PSQLException: This connection
>> has been closed.
>>                   at
>> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>>                   at
>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>>                   at
>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>>                   at
>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>                   at
>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>
>>
>>                   at
>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>                   at
>> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>>
>>
>>                   at
>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>
>>
>>                   at
>> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>>
>>
>>                   at
>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>
>>
>>                   at
>> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>>
>>
>>                   at com.sun.proxy.$Proxy257.prepareStatement(Unknown
>> Source)
>>                   at
>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>                   at
>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>
>>
>>                   at
>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>                   at
>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>>
>>
>>                   at
>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>>
>>
>>                   at com.sun.proxy.$Proxy256.prepareStatement(Unknown
>> Source)
>>                   at
>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>>
>>
>>                   at
>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>>
>>
>>                   ... 88 more
>>
>>

Reply | Threaded
Open this post in threaded view
|

Re: connection pool: poisoned connection not being removed from pool

Emmanuel Touzery-2
Hello,

Note that also setting:

removeAbandoned = true
removeAbandonedTimeout = 60

does not help. Even 6 minutes after the the disconnection, we keep
getting "PooledConnection has already been closed." exceptions.

Regards,

Emmanuel

On 22/01/2021 09:48, Emmanuel Touzery wrote:

> Hello,
>
>     if I understand you correctly, you're suggesting to remove these
> settings:
>
>  removeAbandoned = true
>  removeAbandonedTimeout = 4400
>
>     I did that now, we don't really need them. Unfortunately I can
> still reproduce the issue even after removing both settings.
>
>     We are aware of the memory leak yes, we stumbled on it before a
> released version of tomee fixed it, so we disabled bean validation.
> We'll reenable it when we upgrade TOMEE.
>
>     So that means for now we're still unsure what's causing this issue
> for us :-(
>
>     Thank you!
>
> Emmanuel
>
> On 19/01/2021 19:18, Kean Erickson wrote:
>> Hi Emmanual, I believe that is how connections that were discarded
>> due to
>> removeAbandoned = true. In an ideal setup you shouldnt need that flag or
>> its timeout, becaise the transactions should be too fast to go that long
>>
>> Also some versions before tomee 8.0.5 have a memory leak in the
>> version of
>> bval that is used. Not sure if 8.0.1 has that problem version but try
>> updatng tomee to 8.0.5
>>
>> On Tue, Jan 19, 2021, 2:05 AM Emmanuel Touzery <
>> [hidden email]> wrote:
>>
>>> Hello,
>>>
>>>       we are seeing with our TOMEE setup that a connection that was
>>> (potentially uncleanly) closed from the SQL server remains in the pool
>>> for longer periods (instead of being closed+reopened), causing
>>> long-term
>>> issues with the application, which we can only fix through a restart.
>>>
>>>       A scenario where we see this clearly are failovers: in that case
>>> the currently open connections will become invalid, which the
>>> application should realise quickly enough through the validation
>>> queries, therefore quickly cleaning up the pool (trying to establish a
>>> new connection would work, except in the first few hundreds of
>>> milliseconds of the event). But that's not what we see. We also see
>>> situation where something happens to the SQL server (for instance it's
>>> restarted), or the connection from TOMEE to the SQL server is
>>> disrupted,
>>> but the application never recovers until TOMEE is restarted.
>>>
>>>       Here is our resource, as defined in the tomee.xml:
>>>
>>>       <Resource id="jdbc/generic" type="javax.sql.DataSource">
>>>           jdbcDriver = org.postgresql.Driver
>>>           jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>>>           userName = xxxxxx
>>>           password = xxxxxx
>>>           maxActive = 140
>>>           maxIdle = 20
>>>           validationQuery = select version();
>>>           testWhileIdle = true
>>>           testOnBorrow = true
>>>           testOnReturn = false
>>>           timeBetweenEvictionRuns = 10000 millisecond
>>>           removeAbandonedTimeout = 4400
>>>           removeAbandoned = true
>>>           maxWaitTime = 30000 millisecond
>>>       </Resource>
>>>
>>>       We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27 (we
>>> upgraded from 5.2.12 recently, had the issue with that version too).
>>>
>>>       Is there anything else we should do to make sure that we properly
>>> recover when something happens to some connections from the pool?
>>>
>>>       Thank you!
>>>
>>> Emmanuel
>>>
>>> PS: Some relevant sections of the stacktraces we're seeing for longer
>>> period of times after the event:
>>>
>>>           Caused by: javax.persistence.PersistenceException:
>>> org.hibernate.exception.JDBCConnectionException: could not prepare
>>> statement
>>>                   at
>>> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>>>
>>>
>>>
>>>                   at
>>> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>>>
>>>
>>>
>>>                   at
>>> org.hibernate.query.Query.getResultList(Query.java:165)
>>>
>>>
>>>           Caused by: org.postgresql.util.PSQLException: This connection
>>> has been closed.
>>>                   at
>>> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>>>                   at
>>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>>>
>>>                   at
>>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>>>
>>>                   at
>>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>>                   at
>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>>
>>>
>>>
>>>                   at
>>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>>                   at
>>> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>>>
>>>
>>>
>>>                   at
>>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>>
>>>
>>>
>>>                   at
>>> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>>>
>>>
>>>
>>>                   at
>>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>>
>>>
>>>
>>>                   at
>>> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>>>
>>>
>>>
>>>                   at com.sun.proxy.$Proxy257.prepareStatement(Unknown
>>> Source)
>>>                   at
>>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>>                   at
>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>>
>>>
>>>
>>>                   at
>>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>>                   at
>>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>>>
>>>
>>>
>>>                   at
>>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>>>
>>>
>>>
>>>                   at com.sun.proxy.$Proxy256.prepareStatement(Unknown
>>> Source)
>>>                   at
>>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>>>
>>>
>>>
>>>                   at
>>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>>>
>>>
>>>
>>>                   ... 88 more
>>>
>>>
>

Reply | Threaded
Open this post in threaded view
|

Re: connection pool: poisoned connection not being removed from pool

Emmanuel Touzery-2
Hello,

     I have enabled also "logAbandoned" and I see some connections are
getting abandoned:

22-Jan-2021 10:55:34.306 WARNING [Tomcat JDBC Pool
Cleaner[54495403:1611312334268]]
org.apache.tomcat.jdbc.pool.ConnectionPool.abandon Connection has been
abandoned
PooledConnection[org.postgresql.jdbc.PgConnection@28094e6f]:java.lang.Exception

     However right now I triggered the issue and no connections are
getting abandoned even after 12 minutes, and I can see that the
application won't recover until it's restarted.

     Any suggestion?

     Thank you,

Emmanuel

PS: the way i'm reading the "removeAbandoned" documentation, shouldn't
this setting be named "removeLongRunningConnections"?

On 22/01/2021 11:28, Emmanuel Touzery wrote:

> Hello,
>
> Note that also setting:
>
> removeAbandoned = true
> removeAbandonedTimeout = 60
>
> does not help. Even 6 minutes after the the disconnection, we keep
> getting "PooledConnection has already been closed." exceptions.
>
> Regards,
>
> Emmanuel
>
> On 22/01/2021 09:48, Emmanuel Touzery wrote:
>> Hello,
>>
>>     if I understand you correctly, you're suggesting to remove these
>> settings:
>>
>>  removeAbandoned = true
>>  removeAbandonedTimeout = 4400
>>
>>     I did that now, we don't really need them. Unfortunately I can
>> still reproduce the issue even after removing both settings.
>>
>>     We are aware of the memory leak yes, we stumbled on it before a
>> released version of tomee fixed it, so we disabled bean validation.
>> We'll reenable it when we upgrade TOMEE.
>>
>>     So that means for now we're still unsure what's causing this
>> issue for us :-(
>>
>>     Thank you!
>>
>> Emmanuel
>>
>> On 19/01/2021 19:18, Kean Erickson wrote:
>>> Hi Emmanual, I believe that is how connections that were discarded
>>> due to
>>> removeAbandoned = true. In an ideal setup you shouldnt need that
>>> flag or
>>> its timeout, becaise the transactions should be too fast to go that
>>> long
>>>
>>> Also some versions before tomee 8.0.5 have a memory leak in the
>>> version of
>>> bval that is used. Not sure if 8.0.1 has that problem version but try
>>> updatng tomee to 8.0.5
>>>
>>> On Tue, Jan 19, 2021, 2:05 AM Emmanuel Touzery <
>>> [hidden email]> wrote:
>>>
>>>> Hello,
>>>>
>>>>       we are seeing with our TOMEE setup that a connection that was
>>>> (potentially uncleanly) closed from the SQL server remains in the pool
>>>> for longer periods (instead of being closed+reopened), causing
>>>> long-term
>>>> issues with the application, which we can only fix through a restart.
>>>>
>>>>       A scenario where we see this clearly are failovers: in that case
>>>> the currently open connections will become invalid, which the
>>>> application should realise quickly enough through the validation
>>>> queries, therefore quickly cleaning up the pool (trying to establish a
>>>> new connection would work, except in the first few hundreds of
>>>> milliseconds of the event). But that's not what we see. We also see
>>>> situation where something happens to the SQL server (for instance it's
>>>> restarted), or the connection from TOMEE to the SQL server is
>>>> disrupted,
>>>> but the application never recovers until TOMEE is restarted.
>>>>
>>>>       Here is our resource, as defined in the tomee.xml:
>>>>
>>>>       <Resource id="jdbc/generic" type="javax.sql.DataSource">
>>>>           jdbcDriver = org.postgresql.Driver
>>>>           jdbcUrl = jdbc:postgresql://x.x.x.x/dbname
>>>>           userName = xxxxxx
>>>>           password = xxxxxx
>>>>           maxActive = 140
>>>>           maxIdle = 20
>>>>           validationQuery = select version();
>>>>           testWhileIdle = true
>>>>           testOnBorrow = true
>>>>           testOnReturn = false
>>>>           timeBetweenEvictionRuns = 10000 millisecond
>>>>           removeAbandonedTimeout = 4400
>>>>           removeAbandoned = true
>>>>           maxWaitTime = 30000 millisecond
>>>>       </Resource>
>>>>
>>>>       We are using hibernate. This is tomee 8.0.1, hibernate 5.4.27
>>>> (we
>>>> upgraded from 5.2.12 recently, had the issue with that version too).
>>>>
>>>>       Is there anything else we should do to make sure that we
>>>> properly
>>>> recover when something happens to some connections from the pool?
>>>>
>>>>       Thank you!
>>>>
>>>> Emmanuel
>>>>
>>>> PS: Some relevant sections of the stacktraces we're seeing for longer
>>>> period of times after the event:
>>>>
>>>>           Caused by: javax.persistence.PersistenceException:
>>>> org.hibernate.exception.JDBCConnectionException: could not prepare
>>>> statement
>>>>                   at
>>>> org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:154)
>>>>
>>>>
>>>>
>>>>                   at
>>>> org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1602)
>>>>
>>>>
>>>>
>>>>                   at
>>>> org.hibernate.query.Query.getResultList(Query.java:165)
>>>>
>>>>
>>>>           Caused by: org.postgresql.util.PSQLException: This
>>>> connection
>>>> has been closed.
>>>>                   at
>>>> org.postgresql.jdbc.PgConnection.checkClosed(PgConnection.java:766)
>>>>                   at
>>>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:1582)
>>>>
>>>>                   at
>>>> org.postgresql.jdbc.PgConnection.prepareStatement(PgConnection.java:372)
>>>>
>>>>                   at
>>>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>>>                   at
>>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>>>
>>>>
>>>>
>>>>                   at
>>>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>>>                   at
>>>> org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
>>>>
>>>>
>>>>
>>>>                   at
>>>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>>>
>>>>
>>>>
>>>>                   at
>>>> org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:75)
>>>>
>>>>
>>>>
>>>>                   at
>>>> org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
>>>>
>>>>
>>>>
>>>>                   at
>>>> org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
>>>>
>>>>
>>>>
>>>>                   at com.sun.proxy.$Proxy257.prepareStatement(Unknown
>>>> Source)
>>>>                   at
>>>> jdk.internal.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
>>>>                   at
>>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>>>>
>>>>
>>>>
>>>>                   at
>>>> java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>>>                   at
>>>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invokeUnderTransaction(ManagedConnection.java:277)
>>>>
>>>>
>>>>
>>>>                   at
>>>> org.apache.openejb.resource.jdbc.managed.local.ManagedConnection.invoke(ManagedConnection.java:132)
>>>>
>>>>
>>>>
>>>>                   at com.sun.proxy.$Proxy256.prepareStatement(Unknown
>>>> Source)
>>>>                   at
>>>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:149)
>>>>
>>>>
>>>>
>>>>                   at
>>>> org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:176)
>>>>
>>>>
>>>>
>>>>                   ... 88 more
>>>>
>>>>
>>
>