-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 10 posts ] 
Author Message
 Post subject: Connection closed on the 6th minute of opening the session
PostPosted: Wed Sep 13, 2017 12:15 pm 
Newbie

Joined: Wed Sep 13, 2017 10:21 am
Posts: 7
Hi,

I have a very strange problem after upgrading the hibernate core from version 3.3.2 to 5.0.2 Final and c3p0 from 0.9.1 to 0.9.2.1. We are using also hibernate-c3p0 5.0.3.Final. Here is the case. We are deleting on chunks the entries from a some table with logs. It is possible for our users to define the the chunk size and a sleep time between every chunk. We are opening a session, then for every chunk a transaction begins. There is no problem with the first several transactions, but after the 6th minute of opening the session there is an exception "com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed." when beginning the transaction. I have debugged it and the exception is thrown in org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor in the begin() method when setting auto commit to false. Actually I can go a little bit deeper so I can find that the exception is thrown in com.mchange.v2.c3p0.impl.NewProxyConnection in setAutoCommit(boolean a) method where the value is set, no further. I can reproduce it also when I put a break point before entering the begin transaction, wait for 6 minutes or more and step in. I have tried to check if the session is opened and connected before entering the begin transaction. Even if I wait for 15 minutes, the session is still opened and connected, but a second later the exception is thrown. We have:
hibernate.c3p0.timeout="1800",
hibernate.c3p0.preferredTestQuery="select 1",
hibernate.c3p0.min_size="2",
hibernate.c3p0.max_size="100" set.
I have found out about the 6 minutes because when setting sleep time of 30 seconds, there are 12 transactions executed, on the 13th it fails. Is it possible that we have to set some new property? I did not find such. I have read the change log of c3p0, but I am not sure that I have understood all of the changes. The problem is observed with MySQL and MSSQL, so I do not thing that it is database specific. Here is the code:
Code:
//the session is defined somewhere here
try {
    session = mSessionFactoryManager.getSessionFactory().openSession();
    for (Long toDateMillis : deleteTimes) {
         Transaction tx = session.beginTransaction(); //fails here everytime on the 6th minute
         Query dq = session.createQuery(deleteQuery);
         //doing some stuff

         tx.commit();
         if(sleepTime > 0) {
             try {
                  Thread.sleep(sleepTime);
             } catch (InterruptedException e) {
                  sLogger.debug("Deleting logs ", e);
             }
         }
     }
} finally {
    session.close();
}


I do not know what to do any more. There is no such problem with the older version of our product that uses the old libraries. I am still a beginner with hibernate. If you think that the question is not for this forum, please excuse me and delete the topic. Thank you.

Regards.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Wed Sep 13, 2017 12:55 pm 
Hibernate Team
Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania
The connection got closed as indicated by the logged message:

Code:
No operations allowed after connection closed.


Maybe the DB closes the connection after a given interval (e.g. wait_timeout).

You can also set a high-availability proxy or set autoReconnect at the MySQL Driver level.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Wed Sep 13, 2017 4:21 pm 
Newbie

Joined: Wed Sep 13, 2017 10:21 am
Posts: 7
Thank you about the answer. I doubt that the problem comes from the database. The same databases with the old version of the product works properly. Why when I check if the session is closed or connected with session.isClosed() and session.isConnected() the result is positive. No matter if I wait 6, 10 or 15 minutes when I do these checks before beginTransaction, the result is that everything with the connection is all right. When I step in the beginTansaction() there are also such checks that are evaluated to true, but in the moment when setAutoCommit() in AbstractLogicalConnectionImplementor is executed, the exception is throw. This is something that I am curious about. Something has been changed.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Thu Sep 14, 2017 3:15 am 
Hibernate Team
Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania
Even without the setAutoCommit call, if the underlying Connection gets closed, you won't be able to execute any statement anymore.

You could add a breakpoint in Connection#close and see how it gets called.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Thu Sep 14, 2017 8:46 am 
Newbie

Joined: Wed Sep 13, 2017 10:21 am
Posts: 7
Thank you. If that was an occasional loss of connection, it would not have been reproducible under the same conditions every time. I am trying to find out what is the cause. I have set a break point in the close method in the com.mchange.v2.c3p0.impl.NewProxyConnection, but it was not called at all. I have added checks if the session is connected and opened in the finally block so when the exception is thrown to check the state of the session. The session is opened and connected before I close it. On the other hand the exception is about the connection, not the session. I am not sure how to check the connection. We have a connection pool and a connection is retrieved from the pool when needed than released. In AbstractLogicalConnectionImplementor from hiberanate-core we have:
Code:
   public void begin() {
      try {
         log.trace( "Preparing to begin transaction via JDBC Connection.setAutoCommit(false)" );
         getConnectionForTransactionManagement().setAutoCommit( false );
         status = TransactionStatus.ACTIVE;
         log.trace( "Transaction begun via JDBC Connection.setAutoCommit(false)" );
      }
      catch( SQLException e ) {
         throw new TransactionException( "JDBC begin transaction failed: ", e );
      }
   }

As I can see the connection is resolved before setting AutoCommit. In getConnectionForTransactionManagement() there is a check if it is closed. Than in com.mchange.v2.c3p0.impl.NewProxyConnection we have:
Code:
public synchronized void setAutoCommit(boolean a) throws SQLException {
        try {
            this.txn_known_resolved = true;
            this.inner.setAutoCommit(a);   //it FAILS here
        } catch (NullPointerException var3) {
            if(this.isDetached()) {
                throw SqlUtils.toSQLException("You can't operate on a closed Connection!!!", var3);
            } else {
                throw var3;
            }
        } catch (Exception var4) {
            if(!this.isDetached()) {
                throw this.parentPooledConnection.handleThrowable(var4); //here the exceprion is rethrown
            } else {
                throw SqlUtils.toSQLException(var4);
            }
        }
    }


What can be the reason everything to be ok when this.inner.setAutoCommit(a) is called before the 6th minute, but after that a failure. Am I right that a new connection wiil be used from the pool with every transaction and released after that. I have tried to catch the exception just after beginTransaction and swallow it, so I can continue to the next iteration and try to retrieve a new connection, but it is just the same. Thank you.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Thu Sep 14, 2017 9:11 am 
Hibernate Team
Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania
When you migrated, did you update the JDBC Driver as well?

Maybe you are running on some old JDBC Driver that doesn't work with later c3p0 or Hibernate versions.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Thu Sep 14, 2017 10:00 am 
Newbie

Joined: Wed Sep 13, 2017 10:21 am
Posts: 7
It was updated, yes. We are using mysql-jdbc driver version 5.1.35 and mssql-jdbc4 version 16.2-b04. Now I have just upgraded the mysql jdbc to the latest version and there is no change.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Thu Sep 14, 2017 10:48 am 
Hibernate Team
Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania
Ok, so let it running in debug mode and add a breakpoint in the c3p0 Connection Proxy object for the close method and see who calls it and when.

There's no other way to figure it out since it works just fine in our tests and for all other users using Hibernate 5.x.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Fri Sep 15, 2017 6:57 am 
Newbie

Joined: Wed Sep 13, 2017 10:21 am
Posts: 7
Thank you. I have done what you advised me. I thing I found out the problem. This is a method from c3p0's BasicResourcePool:
Code:
private boolean shouldExpire( Object resc )
    {
        assert Thread.holdsLock( this );

        boolean expired = false;

        PunchCard pc = (PunchCard) managed.get( resc );

        // the resource has already been removed
        // we return true, because removing twice does no harm
        // (false should work as well, but true seems safer.
        //  we certainly don't want to do anything else with
        //  this resource.)
        if (pc == null)
        {
            if ( logger.isLoggable( MLevel.FINE ) )
                logger.fine( "Resource " + resc + " was being tested for expiration, but has already been removed from the pool.");
            return true;
        }

        long now = System.currentTimeMillis();

        if (pc.checkout_time < 0) //resource is not checked out
        {
            NOT OUR CASE
        }
        else //resource is checked out
        {
            long checkout_age = now - pc.checkout_time;
            expired = checkout_age > destroy_unreturned_resc_time;
        }

        return expired;
}


The value of destroy_unreturned_resc_time is 300000(not exactly 6 min, my fault), and the connection is marked as expired when the checkout age is greater than this. Actually this is unreturnedConnectionTimeout. I have to apologize for blaming the library update, actually someone had added it in our code. hibernate.c3p0.unreturnedConnectionTimeout is what I am looking for. Thank you.


Top
 Profile  
 
 Post subject: Re: Connection closed on the 6th minute of opening the session
PostPosted: Fri Sep 15, 2017 1:28 pm 
Hibernate Team
Hibernate Team

Joined: Thu Sep 11, 2014 2:50 am
Posts: 1628
Location: Romania
You're welcome.


Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 10 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.