commons-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Phil Steitz (JIRA)" <j...@apache.org>
Subject [jira] Resolved: (DBCP-201) Statement closing due to unprovoked rollback
Date Sat, 08 Mar 2008 23:45:46 GMT

     [ https://issues.apache.org/jira/browse/DBCP-201?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Phil Steitz resolved DBCP-201.
------------------------------

    Resolution: Fixed

Pool 1.4 has been released.  Please reopen if this issue recurs after upgrading to pool 1.4

> Statement closing due to unprovoked rollback
> --------------------------------------------
>
>                 Key: DBCP-201
>                 URL: https://issues.apache.org/jira/browse/DBCP-201
>             Project: Commons Dbcp
>          Issue Type: Bug
>    Affects Versions: 1.2.1
>         Environment: Linux, Hibernate, Java 5, DBCP
>            Reporter: Theresa Field
>             Fix For: 1.3
>
>
> have seen closed statement errors sporadically occurring and I can't get it under control.
Even when the last execution of the statement is successful in a recursive loop reusing the
statement, I can still see this happen. The stack and code is below. I am very curious how
the rollback is getting called. There are several more places in the code where this is occurring.
It is odd that it only happens sporadically and I have only identified 2 places out of a couple
of dozen that actually causes this to occur.
> **************CONFIG********************
> <?xml version="1.0" encoding="UTF-8"?>
> <!DOCTYPE hibernate-configuration PUBLIC
> "-//Hibernate/Hibernate Configuration DTD 3.0//EN"
> "http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
> <hibernate-configuration>
>     <session-factory>
>         <property name="hibernate.connection.driver_class">org.postgresql.Driver</property>
>         <property name="hibernate.connection.password">password</property>
>         <property name="hibernate.connection.url">jdbc:postgresql://localhost/myDB&lt;/property>
>         <property name="hibernate.connection.username">user</property>
>         <property name="hibernate.dialect">org.hibernate.dialect.PostgreSQLDialect</property>
>         <property name="hibernate.transaction.factory_class ">org.hibernate.transaction.JDBCTransactionFactory</property>
>         <property name="hibernate.current_session_context_class">thread</property>
>         
>         <property name="hibernate.connection.provider_class">org.hibernate.connection.DBCPConnectionProvider</property>
>         <!-- Not specified with 3rd party connection pool <property name="connection.pool_size">20</property>-->
>         <property name="hibernate.dbcp.maxActive">3</property>
>         <property name="hibernate.dbcp.maxIdle">3</property>
>         <property name="hibernate.dbcp.max Wait">60000</property>
> <property name="hibernate.dbcp.whenExhaustedAction">1</property>
> <property name="hibernate.dbcp.ps.maxActive">3</property>
> <property name="hibernate.dbcp.ps.maxIdle">3</property>
> <property name="hibernate.dbcp.ps.maxWait">1000*20</property>
> <property name="hibernate.dbcp.ps.whenExhaustedAction">1</property>
> <property name="hibernate.connection.release_mode">after_transaction</property>
> <property name="hibernate.dbcp.poolPreparedStatements">true</property>
>     </session-factory>
> </hibernate-configuration>
> ********************CODE**************
> private synchronized HashMap<Integer, LeadDeliveryPreferences> queryForPreferences()
throws SQLException{
> // we open a session because this quartz group seems to have an
> // issue retrieving the session on the first job execution
> Session hibSession = HibernateUtil.getSessionFactory().openSession();
> hibSession.beginTransaction();
> Connection conn = hibSession.connection();
> HashMap<Integer, LeadDeliveryPreferences> allMap =
> new HashMap<Integer, LeadDeliveryPreferences>();
> try{
> PreparedStatement stmt = conn.prepareStatement(QUERY_ALL_PREF);
> ResultSet rs = stmt.executeQuery();
> //Query for lead delivery preferences
> while(rs.next()){
> LeadDeliveryPreferences lp = new LeadDeliveryPreferences();
> lp.setCampaignID(rs.getInt(LeadDeliveryPreferences.DB_CAMPAIGN_ID));
> lp.setCronSchedule(rs.getString(LeadDeliveryPreferences.DB_CRON_SCHEDULE));
> lp.setEmail(rs.getString(LeadDeliveryPreferences.DB_EMAIL));
> lp.setDeliveryEnabled(rs.getBoolean(LeadDeliveryPreferences.DB_DELIVERY_ENABLED));
> lp.setDeliveryTransformer(rs.getString(LeadDeliveryPreferences.DB_DELIVERY_TRANSFORMER));
> lp.setReportEnabled(rs.getBoolean(LeadDeliveryPreferences.DB_REPORT_ENABLED));
> lp.setReportType(rs.getString(LeadDeliveryPreferences.DB_REPORT_TYPE));
> lp.setSource(rs.getString(LeadDeliveryPreferences.DB_SOURCE));
> allMap.put(rs.getInt(LeadDeliveryPreferences.DB_CAMPAIGN_ID), lp);
> log_.debug("Picked up schedule for campaign: " + rs.getInt(LeadDeliveryPreferences.DB_CAMPAIGN_ID));
> }
> //prepare statement object for re-use
> //stmt.clearParameters();
> //Query for crosswalk values
> Iterator it = allMap.keySet().iterator();
> ArrayList<Integer> idList = new ArrayList<Integer>();
> while(it.hasNext()){
> idList.add((Integer)it.next());
> }
> PreparedStatement stmt2 = conn.prepareStatement(QUERY_TRANSLATIONS);
> for(int i=0;i<idList.size();i++){
> log_.debug("Getting crosswalk for --> " + idList.get(i));
> stmt2.setInt(1,idList.get(i));
> ResultSet rs2 = stmt2.executeQuery();
> LeadDeliveryPreferences lp = allMap.get(idList.get(i));
> while(rs2.next()){
> LeadCrosswalk lc = new LeadCrosswalk();
> log_.debug("got key --> " + rs2.getString(LeadCrosswalk.DB_NAME_COL_NM));
> lc.setName(rs2.getString(LeadCrosswalk.DB_NAME_COL_NM));
> lc.setIsMethod(rs2.getBoolean(LeadCrosswalk.DB_IS_METHOD_COL_NM));
> lc.setNameTranslation(rs2.getString(LeadCrosswalk.DB_NAME_TRANSLATION_COL_NM));
> lc.setIsRequired(rs2.getBoolean(LeadCrosswalk.DB_IS_REQUIRED_COL_NM));
> lp.addCrosswalk(lc.getName(), lc);
> }
> // prepare statement object for re-use
> stmt2.clearParameters();
> allMap.remove(idList.get(i));
> allMap.put(idList.get(i), lp);
> }
> //Query for phone ranges
> PreparedStatement stmt3 = conn.prepareStatement(QUERY_PHONE_RANGES);
> for(int i=0;i<idList.size();i++){
> stmt3.setInt(1, idList.get(i));
> rs = stmt3.executeQuery();
> LeadDeliveryPreferences lp = allMap.get(idList.get(i));
> while(rs.next()){
> LeadDeliveryClientPhoneRanges phoneRange = new LeadDeliveryClientPhoneRanges();
> phoneRange.setLow(rs.getInt(LeadDeliveryClientPhoneRanges.DB_LOW));
> phoneRange.setHigh(rs.getInt(LeadDeliveryClientPhoneRanges.DB_HIGH));
> phoneRange.setLabel(rs.getString(LeadDeliveryClientPhoneRanges.DB_LABEL));
> log_.debug("Added phone range " + phoneRange.getLabel());
> lp.addPhoneRange(phoneRange);
> }
> allMap.remove(idList.get(i));
> allMap.put(idList.get(i), lp);
> }
> hibSession.getTransaction().commit();
> }
> catch(SQLException se){
> hibSession.getTransaction().rollback();
> log_.error("SQLException occured querying for crosswalk", se);
> RuntimeErrorEmailHelper.addMessage("Error creating cron trigger");
> throw se;
> }
> return allMap;
> }
> ****************STACK******************
> 2006-11-15 13:56:02,892 [DefaultQuartzScheduler_Worker-8] DEBUG leads.delivery.LeadDeliveryPreferencesService
- Getting crosswalk for --> 200
> 2006-11-15 13:56:02,899 [DefaultQuartzScheduler_Worker-8] DEBUG hibernate.transaction.JDBCTransaction
- rollback
> 2006-11-15 13:56:02,912 [DefaultQuartzScheduler_Worker-8] DEBUG hibernate.transaction.JDBCTransaction
- rolled back JDBC Connection
> 2006-11-15 13:56:02,912 [DefaultQuartzScheduler_Worker-8] DEBUG hibernate.jdbc.JDBCContext
- after transaction completion
> 2006-11-15 13:56:02,912 [DefaultQuartzScheduler_Worker-8] DEBUG hibernate.jdbc.ConnectionManager
- aggressively releasing JDBC connection
> 2006-11-15 13:56:02,912 [DefaultQuartzScheduler_Worker-8] DEBUG hibernate.jdbc.ConnectionManager
- releasing JDBC connection [ (open PreparedStatements: 0, globally: 1) (open ResultSets:
0, globally: 0)]
> 2006-11-15 13:56:02,913 [DefaultQuartzScheduler_Worker-8] INFO hibernate.connection.DBCPConnectionProvider
- active: 3 (max: 3) idle: 0(max: 3)
> 2006-11-15 13:56:02,913 [DefaultQuartzScheduler_Worker-8] DEBUG hibernate.impl.SessionImpl
- after transaction completion
> 2006-11-15 13:56:02,915 [DefaultQuartzScheduler_Worker-8] ERROR leads.delivery.LeadDeliveryPreferencesService
- SQLException occured querying for crosswalk
> 2006-11-15 13:56:02,920 [DefaultQuartzScheduler_Worker-8] INFO quartz.core.JobRunShell
- Job LEAD_PREFERENCES.PREFERENCES_UPDATE_JOB threw a JobExecutionException:
> org.quartz.JobExecutionException: org.postgresql.util.PSQLException: This statement has
been closed. [See nested exception: org.postgresql.util.PSQLExcepti
> on: This statement has been closed.]
>         at com.tippit.service.leads.delivery.LeadDeliveryPreferencesService.execute(LeadDeliveryPreferencesService.java:185)
>         at org.quartz.core.JobRunShell.run(JobRunShell.java:195)
>         at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)
> * Nested Exception (Underlying Cause) ---------------
> org.postgresql.util.PSQLException: This statement has been closed.
>         at org.postgresql.jdbc2.AbstractJdbc2Statement.checkClosed(AbstractJdbc2Statement.java:2308)
>         at org.postgresql.jdbc2.AbstractJdbc2Statement.setInt(AbstractJdbc2Statement.java:1070)
>         at org.apache.commons.dbcp.DelegatingPreparedStatement.setInt(DelegatingPreparedStatement.java:116)
>         at org.apache.commons.dbcp.DelegatingPreparedStatement.setInt(DelegatingPreparedStatement.java:116)
>         at com.tippit.service.leads.delivery.LeadDeliveryPreferencesService.queryForPreferences(LeadDeliveryPreferencesService.java:116)
>         at com.tippit.service.leads.delivery.LeadDeliveryPreferencesService.load(LeadDeliveryPreferencesService.java:61)
>         at com.tippit.service.leads.delivery.LeadDeliveryPreferencesService.execute(LeadDeliveryPreferencesService.java:181)
>         at org.quartz.core.JobRunShell.run(JobRunShell.java:195)
>         at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)

> **********WORKAROUND**************************
> I think I kind of resolved the symptom although I still feel there are several issues
in play here.
> 1. No more statement closed exceptions are being thrown. These exceptions were being
thrown because:
>    a. Run out of statements\connections in pool (I think that is what is forcing the
rollback bc it doesn't happen when the pool is not starved).
>    b. Using getCurrentSession() instead of openSession() when using a pool of threads
(Quartz and Mule threads). Good advice at http://opensource.atlassian.com/projects/hibernate/browse/HHH-2243
when using hibernate.current_session_context_class=thread for transaction demarcation with
plain JDBC for applications with thread pools.
> 2. I tried configuring the whenExhaustedAction for connections and statements, even if
I configure 2 to grow the pool for both... these issues still occur when the pool is starved.
> 3. Configuring 20 connection threads and 30 statement threads has resolved the issue
(1a) although I don't understand why #2 above does not work. This causes the application to
be very volatile especially since you can't tell the statement was closed until you try to
set a parameter (not when you prepare the statement)

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message