3 Replies Latest reply on Dec 3, 2015 8:09 AM by shawkins

    No operations allowed after statement closed while inserting a large number of values in a foreign temporary table

    gadeyne.bram

      Hi,

       

      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>

        • 1. Re: No operations allowed after statement closed while inserting a large number of values in a foreign temporary table
          gadeyne.bram

          Additionaly I had a different problem while executing a new query in the same teiid session. Probably because Teiid was using the same connection.

           

          08:25:08,853 DEBUG [org.teiid.CONNECTOR] (Worker261_QueryProcessorQueue1105289) LZWCF/Urovjt Source-specific command: DELETE FROM rep38_results WHERE rep38_results.vargroup = 'RespiratoryRate'

          08:25:58,195 WARN  [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (Worker261_QueryProcessorQueue1105289) LZWCF/Urovjt IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1587a818[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@1a361cc6 connection handles=1 lastUse=1449041108853 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@8d1b510 pool internal context=SemaphoreArrayListManagedConnectionPool@56f8452d[pool=tmptables] xaResource=LocalXAResourceImpl@2b09de44[connectionListener=1587a818 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.CommunicationsException: Communications link failure

           

           

          The last packet successfully received from the server was 49,342 milliseconds ago.  The last packet sent successfully to the server was 49,341 milliseconds ago.

                  at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.8.0_60]

                  at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) [rt.jar: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.SQLError.createCommunicationsException(SQLError.java:1117)

                  at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3603)

                  at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3492)

                  at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4043)

                  at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2503)

                  at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2664)

                  at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2788)

                  at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1816)

                  at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1730)

                  at org.jboss.jca.adapters.jdbc.WrappedStatement.executeUpdate(WrappedStatement.java:375)

                  at org.teiid.translator.jdbc.JDBCUpdateExecution.executeTranslatedCommand(JDBCUpdateExecution.java:179) [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.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.

                  at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3052)

                  at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3503)

                  ... 28 more

          • 2. Re: No operations allowed after statement closed while inserting a large number of values in a foreign temporary table
            gadeyne.bram

            Ok,

             

            So it seems like this is caused by a failing MySQL Server.

             

            I found this in the logs for MySQL.

             

            InnoDB: Warning: database page corruption or a failed

            InnoDB: file read of space 532 page 82258.

            InnoDB: Trying to recover it from the doublewrite buffer.

             

            And then the server is restarted.

            • 3. Re: No operations allowed after statement closed while inserting a large number of values in a foreign temporary table
              shawkins

              Do you have connection validation configured on the connection pool?  You'd still get an error for a currently executing statement if something fails, but at least you wouldn't get stale connections.