Attachment 927828 Details for Bug 1131020 – Server log after query

Server log after query

server.log (text/plain), 15.97 KB, created by Juraj Duráni on 2014-08-18 11:57:24 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Juraj Duráni

Created: 2014-08-18 11:57:24 UTC

Size: 15.97 KB

patch

obsolete

>11:48:47,545 DEBUG [org.teiid.TRANSPORT] (New I/O worker #2) processing message:MessageHolder: key=0 contents=[B@33e938c1
>11:48:47,553 DEBUG [org.teiid.SECURITY] (New I/O worker #2) authenticateUser jdurani JDBC
>11:48:47,587 DEBUG [org.teiid.SECURITY] (New I/O worker #2) Logon successful for " jdurani "
>11:48:47,589 DEBUG [org.teiid.SECURITY] (New I/O worker #2) Logon successful, created session: sessionid=T3NjeLtt3MnL; userName=jdurani@teiid-security; vdbName=QT_Ingres10_Push; vdbVersion=1; createdTime=Fri Aug 08 11:48:47 CEST 2014; applicationName=JDBC; clientHostName=localhost; clientHardwareAddress=null; IPAddress=127.0.0.1; securityDomain=teiid-security; lastPingTime=Fri Aug 08 11:48:47 CEST 2014
>11:48:47,592 DEBUG [org.teiid.TRANSPORT] (New I/O worker #2) send message: MessageHolder: key=0 contents=[B@7ad2a80c
>11:48:47,633 DEBUG [org.teiid.TRANSPORT] (New I/O worker #2) processing message:MessageHolder: key=1 contents=Invoke interface org.teiid.client.DQP.executeRequest
>11:48:47,640 DEBUG [org.teiid.COMMAND_LOG] (New I/O worker #2) 	START USER COMMAND:	startTime=2014-08-08 11:48:47.64	requestID=T3NjeLtt3MnL.0	txID=null	sessionID=T3NjeLtt3MnL	applicationName=JDBC	principal=jdurani@teiid-security	vdbName=QT_Ingres10_Push	vdbVersion=1	sql=SELECT intkey FROM BQT1.SmallA AS A WHERE stringkey = (SELECT stringkey FROM BQT1.SmallA AS B WHERE b.intnum = a.intnum ) ORDER BY intkey
>11:48:47,642 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) Request Thread T3NjeLtt3MnL.0 with state NEW
>11:48:47,642 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) T3NjeLtt3MnL.0 Non-cachable command.
>11:48:47,642 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) T3NjeLtt3MnL.0 executing prepared SELECT intkey FROM BQT1.SmallA AS A WHERE stringkey = (SELECT stringkey FROM BQT1.SmallA AS B WHERE b.intnum = a.intnum ) ORDER BY intkey
>11:48:47,738 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) ProcessTree for T3NjeLtt3MnL.0 AccessNode(1) output=[smalla__1.intkey AS IntKey] SELECT g_0.intkey AS c_0 FROM Source.smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM Source.smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0
>
>11:48:47,748 DEBUG [org.teiid.TXN_LOG] (Worker0_QueryProcessorQueue0) before getOrCreateTransactionContext:org.teiid.dqp.internal.process.TransactionServerImpl@1837eee6(T3NjeLtt3MnL)
>11:48:47,748 DEBUG [org.teiid.TXN_LOG] (Worker0_QueryProcessorQueue0) after getOrCreateTransactionContext : T3NjeLtt3MnL NONE ID:NONE
>11:48:47,755 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0) Creating TupleBuffer: 0 [A.IntKey] [class java.lang.Integer] batch size 2048 of type PROCESSOR
>11:48:47,758 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue0) T3NjeLtt3MnL.0.1.0 Create State
>11:48:47,770 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0) T3NjeLtt3MnL.0.1.0 Blocking on source query T3NjeLtt3MnL.0.1.0
>11:48:47,771 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0) T3NjeLtt3MnL.0 Blocking on source request(s).
>11:48:47,770 DEBUG [org.teiid.PROCESSOR] (Worker1_QueryProcessorQueue1) Running task for parent thread Worker0_QueryProcessorQueue0
>11:48:47,771 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) Request Thread T3NjeLtt3MnL.0 - processor blocked
>11:48:47,771 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) T3NjeLtt3MnL.0.1.0 Processing NEW request: SELECT g_0.intkey AS c_0 FROM Source.smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM Source.smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0
>11:48:47,771 DEBUG [org.jboss.jca.core.connectionmanager.pool.idle.IdleRemover] (Worker1_QueryProcessorQueue1) Register pool: SemaphoreArrayListManagedConnectionPool@5c6febad[pool=ingres10DS] (interval=1800000)
>11:48:47,771 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Worker1_QueryProcessorQueue1) ingres10DS: getConnection(null, WrappedConnectionRequestInfo@37d9da44[userName=bqt2]) [0/20]
>11:48:47,772 DEBUG [org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory] (Worker1_QueryProcessorQueue1) Driver loaded and instance created:Actian Corporation - JDBC Driver
>11:48:49,981 INFO  [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) IngresExecutionFactory Commit=true;DatabaseProductName=INGRES;DatabaseProductVersion=II 10.1.0 (a64.win/125)GPL;DriverMajorVersion=4;DriverMajorVersion=1;DriverName=Actian Corporation - JDBC Driver;DriverVersion=4.1.4;IsolationLevel=8
>11:48:49,989 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) T3NjeLtt3MnL.0.1.0 Obtained execution
>11:48:49,990 DEBUG [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1) 	START DATA SRC COMMAND:	startTime=2014-08-08 11:48:49.989	requestID=T3NjeLtt3MnL.0	sourceCommandID=1	executionID=0	txID=null	modelName=Source	translatorName=ingres	sessionID=T3NjeLtt3MnL	principal=jdurani@teiid-security	sql=SELECT g_0.intkey AS c_0 FROM Source.smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM Source.smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0
>11:48:49,995 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) Source-specific command: SELECT g_0.intkey AS c_0 FROM smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0
>11:48:50,904 DEBUG [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1) 	ERROR SRC COMMAND:	endTime=2014-08-08 11:48:50.904	requestID=T3NjeLtt3MnL.0	sourceCommandID=1	executionID=0	txID=null	modelName=Source	translatorName=ingres	sessionID=T3NjeLtt3MnL	principal=jdurani@teiid-security	finalRowCount=null
>11:48:50,904 WARN  [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) Connector worker process failed for atomic-request=T3NjeLtt3MnL.0.1.0: org.teiid.translator.jdbc.JDBCExecutionException: 4502 TEIID11008:TEIID11004 Error executing statement(s): [Prepared Values: [] SQL: SELECT g_0.intkey AS c_0 FROM smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0]
>	at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:131)
>	at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.execute(ConnectorWorkItem.java:325) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DataTierTupleSource.getResults(DataTierTupleSource.java:298) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:110) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:107) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_60]
>	at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:58) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:274) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:214) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_60]
>	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_60]
>	at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_60]
>Caused by: java.sql.SQLException: SELECT returned multiple values.
>	at com.ingres.gcf.util.SqlExType.getSqlEx(SqlExType.java:127)
>	at com.ingres.gcf.util.SqlExFactory.get(SqlExFactory.java:96)
>	at com.ingres.gcf.jdbc.DrvObj.readError(DrvObj.java:852)
>	at com.ingres.gcf.jdbc.DrvObj.readResults(DrvObj.java:636)
>	at com.ingres.gcf.jdbc.RsltFtch.preLoad(RsltFtch.java:611)
>	at com.ingres.gcf.jdbc.RsltCurs.preLoad(RsltCurs.java:306)
>	at com.ingres.gcf.jdbc.RsltCurs.<init>(RsltCurs.java:235)
>	at com.ingres.gcf.jdbc.JdbcPrep.exec(JdbcPrep.java:1279)
>	at com.ingres.gcf.jdbc.JdbcPrep.executeQuery(JdbcPrep.java:589)
>	at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:462)
>	at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:123)
>	... 12 more
>
>11:48:50,914 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) Request Thread T3NjeLtt3MnL.0 with state PROCESSING
>11:48:50,915 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) T3NjeLtt3MnL.0.1.0 Remove State
>11:48:50,915 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) T3NjeLtt3MnL.0.1.0 Processing Close : SELECT g_0.intkey AS c_0 FROM Source.smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM Source.smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0
>11:48:50,915 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) T3NjeLtt3MnL.0.1.0 Closed execution
>11:48:50,916 DEBUG [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (Worker0_QueryProcessorQueue2) ingres10DS: returnConnection(a92cef2, false) [0/20]
>11:48:50,916 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) T3NjeLtt3MnL.0.1.0 Closed connection
>11:48:50,917 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) QueryProcessor: closing processor
>11:48:50,917 DEBUG [org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue2) 	ERROR USER COMMAND:	endTime=2014-08-08 11:48:50.917	requestID=T3NjeLtt3MnL.0	txID=null	sessionID=T3NjeLtt3MnL	principal=jdurani@teiid-security	vdbName=QT_Ingres10_Push	vdbVersion=1	finalRowCount=null
>11:48:50,919 WARN  [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) TEIID30020 Processing exception for request T3NjeLtt3MnL.0 'TEIID30504 Source: 4502 TEIID11008:TEIID11004 Error executing statement(s): [Prepared Values: [] SQL: SELECT g_0.intkey AS c_0 FROM smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0]'. Originally TeiidProcessingException 'SELECT returned multiple values.' SqlExType.java:127.: org.teiid.core.TeiidProcessingException: TEIID30504 Source: 4502 TEIID11008:TEIID11004 Error executing statement(s): [Prepared Values: [] SQL: SELECT g_0.intkey AS c_0 FROM smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0]
>	at org.teiid.dqp.internal.process.DataTierTupleSource.exceptionOccurred(DataTierTupleSource.java:381) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DataTierTupleSource.nextTuple(DataTierTupleSource.java:154) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.query.processor.relational.AccessNode.nextBatchDirect(AccessNode.java:369) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.query.processor.relational.RelationalNode.nextBatch(RelationalNode.java:278) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.query.processor.relational.RelationalPlan.nextBatch(RelationalPlan.java:136) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.query.processor.QueryProcessor.nextBatchDirect(QueryProcessor.java:151) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.query.processor.QueryProcessor.nextBatch(QueryProcessor.java:114) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.query.processor.BatchCollector.collectTuples(BatchCollector.java:159) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.query.processor.BatchCollector.collectTuples(BatchCollector.java:141) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.RequestWorkItem.processMore(RequestWorkItem.java:444) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.RequestWorkItem.process(RequestWorkItem.java:326) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.AbstractWorkItem.run(AbstractWorkItem.java:51) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.RequestWorkItem.run(RequestWorkItem.java:254) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DQPWorkContext.runInContext(DQPWorkContext.java:274) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:119) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:214) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_60]
>	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_60]
>	at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_60]
>Caused by: org.teiid.translator.jdbc.JDBCExecutionException: 4502 TEIID11008:TEIID11004 Error executing statement(s): [Prepared Values: [] SQL: SELECT g_0.intkey AS c_0 FROM smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0]
>	at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:131)
>	at org.teiid.dqp.internal.datamgr.ConnectorWorkItem.execute(ConnectorWorkItem.java:325) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DataTierTupleSource.getResults(DataTierTupleSource.java:298) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:110) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at org.teiid.dqp.internal.process.DataTierTupleSource$1.call(DataTierTupleSource.java:107) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_60]
>	at org.teiid.dqp.internal.process.FutureWork.run(FutureWork.java:58) [teiid-engine-8.7.1.redhat-1.jar:8.7.1.redhat-1]
>	... 6 more
>Caused by: java.sql.SQLException: SELECT returned multiple values.
>	at com.ingres.gcf.util.SqlExType.getSqlEx(SqlExType.java:127)
>	at com.ingres.gcf.util.SqlExFactory.get(SqlExFactory.java:96)
>	at com.ingres.gcf.jdbc.DrvObj.readError(DrvObj.java:852)
>	at com.ingres.gcf.jdbc.DrvObj.readResults(DrvObj.java:636)
>	at com.ingres.gcf.jdbc.RsltFtch.preLoad(RsltFtch.java:611)
>	at com.ingres.gcf.jdbc.RsltCurs.preLoad(RsltCurs.java:306)
>	at com.ingres.gcf.jdbc.RsltCurs.<init>(RsltCurs.java:235)
>	at com.ingres.gcf.jdbc.JdbcPrep.exec(JdbcPrep.java:1279)
>	at com.ingres.gcf.jdbc.JdbcPrep.executeQuery(JdbcPrep.java:589)
>	at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:462)
>	at org.teiid.translator.jdbc.JDBCQueryExecution.execute(JDBCQueryExecution.java:123)
>	... 12 more
>
>11:48:50,926 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) Removing tuplesource for the request T3NjeLtt3MnL.0
>11:48:50,926 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue2) Removing TupleBuffer: 0
>11:48:50,927 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) org.teiid.core.TeiidProcessingException: TEIID30504 Source: 4502 TEIID11008:TEIID11004 Error executing statement(s): [Prepared Values: [] SQL: SELECT g_0.intkey AS c_0 FROM smalla AS g_0 WHERE g_0.stringkey = (SELECT g_1.stringkey FROM smalla AS g_1 WHERE g_1.intnum = g_0.intnum) ORDER BY c_0] Sending error to client T3NjeLtt3MnL.0
>11:48:50,929 DEBUG [org.teiid.TRANSPORT] (Worker0_QueryProcessorQueue2) send message: MessageHolder: key=1 contents=ResultsMessage rowCount=0 finalRow=-1
>11:48:50,977 DEBUG [org.teiid.TRANSPORT] (New I/O worker #2) processing message:MessageHolder: key=2 contents=Invoke interface org.teiid.client.security.ILogon.logoff
>11:48:50,977 DEBUG [org.teiid.SECURITY] (New I/O worker #2) closeSession T3NjeLtt3MnL
>11:48:50,978 DEBUG [org.teiid.TXN_LOG] (New I/O worker #2) before cancelTransactions:org.teiid.dqp.internal.process.TransactionServerImpl@1837eee6(T3NjeLtt3MnL,false)
>11:48:50,978 DEBUG [org.teiid.TXN_LOG] (New I/O worker #2) after cancelTransactions : null
>11:48:50,978 DEBUG [org.teiid.TRANSPORT] (New I/O worker #2) send message: MessageHolder: key=2 contents=null
>11:48:51,001 DEBUG [org.teiid.TRANSPORT] (New I/O worker #2) Channel closed

Actions: View

Attachments on bug 1131020: 927826 | 927827 | 927828