No operations allowed after statement closed while inserting a large number of values in a foreign temporary table
gadeyne.bram Dec 2, 2015 2:55 AMHi,
I'm using teiid 8.11.3
I'm not sure if this is a Teiid specific issue or wether or not Teiid should be able to catch such an exception.
I had a long running (about 3 hours untill the exception) SQL query that inserted about 7 milion rows to a foreign temporary table. During this process the following error occured.
19:24:19,602 WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (Worker235_QueryProcessorQueue1104440) LZWCF/Urovjt IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@66d9627a[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@67830de1 connection handles=1 lastUse=1448992819738 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@8d1b510 pool internal context=SemaphoreArrayListManagedConnectionPool@56f8452d[pool=tmptables] xaResource=LocalXAResourceImpl@1586438c[connectionListener=66d9627a connectionManager=6a15a8d8 warned=false currentXid=null productName=MySQL productVersion=5.6.27-0ubuntu0.14.04.1 jndiName=java:/tmptables] txSync=null]: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
at sun.reflect.GeneratedConstructorAccessor109.newInstance(Unknown Source) [:1.8.0_60]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.8.0_60]
at java.lang.reflect.Constructor.newInstance(Constructor.java:422) [rt.jar:1.8.0_60]
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.Util.getInstance(Util.java:386)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1014)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:988)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:974)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:919)
at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:466)
at com.mysql.jdbc.PreparedStatement.clearBatch(PreparedStatement.java:1143)
at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1471)
at org.jboss.jca.adapters.jdbc.WrappedStatement.executeBatch(WrappedStatement.java:1077)
at org.teiid.translator.jdbc.JDBCUpdateExecution.executeTranslatedCommand(JDBCUpdateExecution.java:212) [translator-jdbc-8.11.3.jar:8.11.3]
at org.teiid.translator.jdbc.JDBCUpdateExecution.execute(JDBCUpdateExecution.java:80) [translator-jdbc-8.11.3.jar:8.11.3]
at org.teiid.dqp.internal.datamgr.ConnectorWorkItem$1.execute(ConnectorWorkItem.java:377)
at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.execute(ConnectorWorkItem.java:341)
at sun.reflect.GeneratedMethodAccessor105.invoke(Unknown Source) [:1.8.0_60]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
at org.teiid.dqp.internal.datamgr.ConnectorManager$1.invoke(ConnectorManager.java:211)
at com.sun.proxy.$Proxy47.execute(Unknown Source)
at org.teiid.dqp.internal.process.DataTierTupleSource.getResults(DataTierTupleSource.java:298)
at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:110)
at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:107)
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_60]
at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:58)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:276)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_60]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_60]
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_60]
19:24:19,615 WARN [org.teiid.CONNECTOR] (Worker235_QueryProcessorQueue1104440) LZWCF/Urovjt Connector worker process failed for atomic-request=LZWCF/Urovjt.37.0.396684: org.teiid.translator.jdbc.JDBCExecutionException: 0 TEIID11016:TEIID11004 Error executing statement(s): [Prepared Values: [?, ?, ?, ?, ?, ?, ?, ?, ?] SQL: INSERT INTO rep38_results (admissionid, vargroup, vartype, vartime, varenttime, varstrvalue, vardoublevalue, vartimevalue, validated) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)]
at org.teiid.translator.jdbc.JDBCUpdateExecution.restoreAutoCommit(JDBCUpdateExecution.java:298) [translator-jdbc-8.11.3.jar:8.11.3]
at org.teiid.translator.jdbc.JDBCUpdateExecution.executeTranslatedCommand(JDBCUpdateExecution.java:255) [translator-jdbc-8.11.3.jar:8.11.3]
at org.teiid.translator.jdbc.JDBCUpdateExecution.execute(JDBCUpdateExecution.java:80) [translator-jdbc-8.11.3.jar:8.11.3]
at org.teiid.dqp.internal.datamgr.ConnectorWorkItem$1.execute(ConnectorWorkItem.java:377)
at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.execute(ConnectorWorkItem.java:341)
at sun.reflect.GeneratedMethodAccessor105.invoke(Unknown Source) [:1.8.0_60]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_60]
at java.lang.reflect.Method.invoke(Method.java:497) [rt.jar:1.8.0_60]
at org.teiid.dqp.internal.datamgr.ConnectorManager$1.invoke(ConnectorManager.java:211)
at com.sun.proxy.$Proxy47.execute(Unknown Source)
at org.teiid.dqp.internal.process.DataTierTupleSource.getResults(DataTierTupleSource.java:298)
at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:110)
at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:107)
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_60]
at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:58)
at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:276)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119)
at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:210)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_60]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_60]
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_60]
Caused by: java.sql.SQLException: Connection is not associated with a managed connection.org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@51761784
at org.jboss.jca.adapters.jdbc.WrappedConnection.lock(WrappedConnection.java:155)
at org.jboss.jca.adapters.jdbc.WrappedConnection.setAutoCommit(WrappedConnection.java:707)
at org.teiid.translator.jdbc.JDBCUpdateExecution.restoreAutoCommit(JDBCUpdateExecution.java:296) [translator-jdbc-8.11.3.jar:8.11.3]
... 20 more
19:24:19,623 DEBUG [org.teiid.CONNECTOR] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt LZWCF/Urovjt.37.0.396684 Processing CANCEL request
19:24:19,623 DEBUG [org.teiid.COMMAND_LOG] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt CANCEL SRC COMMAND: endTime=2015-12-01 19:24:19.623 requestID=LZWCF/Urovjt.37 sourceCommandID=0 executionID=396684 txID=null modelName=tmptables translatorName=mysql5 sessionID=LZWCF/Urovjt principal=bram@teiid-security finalRowCount=-1
19:24:19,623 DEBUG [org.teiid.CONNECTOR] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt The atomic request LZWCF/Urovjt.37.0.396684 has been canceled.
19:24:19,623 DEBUG [org.teiid.CONNECTOR] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt LZWCF/Urovjt.37.0.396684 Remove State
19:24:19,623 DEBUG [org.teiid.CONNECTOR] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt LZWCF/Urovjt.37.0.396684 Processing Close : INSERT INTO rep38_results (admissionid, vargroup, vartype, vartime, varenttime, varstrvalue, vardoublevalue, vartimevalue, validated) VALUES (...)
19:24:19,624 DEBUG [org.teiid.CONNECTOR] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt LZWCF/Urovjt.37.0.396684 Closed execution
19:24:19,624 DEBUG [org.teiid.CONNECTOR] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt LZWCF/Urovjt.37.0.396684 Closed connection
19:24:19,633 DEBUG [org.teiid.COMMAND_LOG] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt ERROR USER COMMAND: endTime=2015-12-01 19:24:19.633 requestID=LZWCF/Urovjt.37 txID=null sessionID=LZWCF/Urovjt principal=bram@teiid-security vdbName=vdb3 vdbVersion=8 finalRowCount=null
19:24:19,634 WARN [org.teiid.PROCESSOR] (Worker237_QueryProcessorQueue1104442) LZWCF/Urovjt TEIID30020 Processing exception for request LZWCF/Urovjt.37 'TEIID30504 tmptables: 0 TEIID11016:TEIID11004 Error executing statement(s): [Prepared Values: [?, ?, ?, ?, ?, ?, ?, ?, ?] SQL: INSERT INTO rep38_results (admissionid, vargroup, vartype, vartime, varenttime, varstrvalue, vardoublevalue, vartimevalue, validated) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)]'. Originally TeiidProcessingException 'Connection is not associated with a managed connection.org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@51761784' WrappedConnection.java:155. Enable more detailed logging to see the entire stacktrace.
The specific connection is configured as follows:
<datasource jndi-name="java:/tmptables" pool-name="tmptables" enabled="true">
<connection-url>jdbc:mysql://vwodan:3306/tmptables?zeroDateTimeBehavior=convertToNull</connection-url>
<connection-property name="tinyInt1isBit">
false
</connection-property>
<driver>mysql-connector-java-5.1.23-bin.jar</driver>
<pool>
<min-pool-size>10</min-pool-size>
<max-pool-size>30</max-pool-size>
</pool>
<security>
<user-name>xxxxxx</user-name>
<password>xxxxxx</password>
</security>
<validation>
<valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.mysql.MySQLValidConnectionChecker"/>
<validate-on-match>true</validate-on-match>
<exception-sorter class-name="org.jboss.jca.adapters.jdbc.extensions.mysql.MySQLExceptionSorter"/>
</validation>
</datasource>