[JBoss JIRA] (TEIID-3582) Add the query requestID to all lines for that query in the logs

Wednesday, 6 April 2016

    [
https://issues.jboss.org/browse/TEIID-3582?page=com.atlassian.jira.plugin...
] 

Jan Stastny edited comment on TEIID-3582 at 4/6/16 1:15 PM:
------------------------------------------------------------

The requestId is not present in the log mentioned in the description.
I get:
{code:plain}
17:33:12,227 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) Source-specific
command: SELECT g_0.`id`, g_0.`name`, g_0.`address` FROM `dballo19`.`customers` AS g_0 
{code}
Logs for whole query processing:
{code:plain}
17:33:12,046 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) Request Thread
GZ80TLU8xKRP.0 with state NEW 
17:33:12,047 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) GZ80TLU8xKRP.0
Command has no cache hint and result set cache mode is not on. 
17:33:12,047 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) GZ80TLU8xKRP.0
executing  SELECT * FROM customers
17:33:12,141 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue0) Initializing the
capabilities for mysql5
17:33:12,142 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue0) Setting the
database version to 5.5.47
17:33:12,164 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) ProcessTree for
GZ80TLU8xKRP.0 AccessNode(0) output=[MySQLSource.dballo19.customers.id,
MySQLSource.dballo19.customers.name, MySQLSource.dballo19.customers.address] SELECT
g_0.id, g_0.name, g_0.address FROM MySQLSource.dballo19.customers AS g_0

17:33:12,165 DEBUG [org.teiid.TXN_LOG] (Worker0_QueryProcessorQueue0) before
getOrCreateTransactionContext:org.teiid.dqp.internal.process.TransactionServerImpl@cdfd35f(GZ80TLU8xKRP)
17:33:12,166 DEBUG [org.teiid.TXN_LOG] (Worker0_QueryProcessorQueue0) after
getOrCreateTransactionContext : GZ80TLU8xKRP NONE ID:NONE
17:33:12,176 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0) Creating
TupleBuffer: 0 [MySQLSource.dballo19.customers.id, MySQLSource.dballo19.customers.name,
MySQLSource.dballo19.customers.address] [class java.lang.Long, class java.lang.String,
class java.lang.String] batch size 512 of type PROCESSOR
17:33:12,183 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue0) GZ80TLU8xKRP.0.0.0
Create State
17:33:12,207 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0)
GZ80TLU8xKRP.0.0.0 Blocking on source query GZ80TLU8xKRP.0.0.0
17:33:12,207 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0) GZ80TLU8xKRP.0
Blocking on source request(s).
17:33:12,207 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) Request Thread
GZ80TLU8xKRP.0 - processor blocked
17:33:12,214 DEBUG [org.teiid.PROCESSOR] (Worker1_QueryProcessorQueue1) Running task for
parent thread Worker0_QueryProcessorQueue0
17:33:12,215 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Processing NEW request: SELECT g_0.id, g_0.name, g_0.address FROM
MySQLSource.dballo19.customers AS g_0 
17:33:12,218 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Obtained execution
17:33:12,227 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) Source-specific
command: SELECT g_0.`id`, g_0.`name`, g_0.`address` FROM `dballo19`.`customers` AS g_0 
17:33:12,571 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Executed command
17:33:12,571 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Processing MORE request
17:33:12,571 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Getting results from connector
17:33:12,573 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Obtained last batch, total row count: 10
17:33:12,574 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) Request Thread
GZ80TLU8xKRP.0 with state PROCESSING
17:33:12,575 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0.0.0
Remove State
17:33:12,575 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0.0.0
Processing Close : SELECT g_0.id, g_0.name, g_0.address FROM
MySQLSource.dballo19.customers AS g_0 
17:33:12,576 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0.0.0
Closed execution
17:33:12,576 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0.0.0
Closed connection
17:33:12,577 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) QueryProcessor:
closing processor
17:33:12,577 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0
Finished Processing
{code}

was (Author: jstastny):
The requestId is not present in the log mentioned in description:
{code:plain}
17:33:12,046 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) Request Thread
GZ80TLU8xKRP.0 with state NEW 
17:33:12,047 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) GZ80TLU8xKRP.0
Command has no cache hint and result set cache mode is not on. 
17:33:12,047 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) GZ80TLU8xKRP.0
executing  SELECT * FROM customers
17:33:12,141 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue0) Initializing the
capabilities for mysql5
17:33:12,142 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue0) Setting the
database version to 5.5.47
17:33:12,164 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) ProcessTree for
GZ80TLU8xKRP.0 AccessNode(0) output=[MySQLSource.dballo19.customers.id,
MySQLSource.dballo19.customers.name, MySQLSource.dballo19.customers.address] SELECT
g_0.id, g_0.name, g_0.address FROM MySQLSource.dballo19.customers AS g_0

17:33:12,165 DEBUG [org.teiid.TXN_LOG] (Worker0_QueryProcessorQueue0) before
getOrCreateTransactionContext:org.teiid.dqp.internal.process.TransactionServerImpl@cdfd35f(GZ80TLU8xKRP)
17:33:12,166 DEBUG [org.teiid.TXN_LOG] (Worker0_QueryProcessorQueue0) after
getOrCreateTransactionContext : GZ80TLU8xKRP NONE ID:NONE
17:33:12,176 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0) Creating
TupleBuffer: 0 [MySQLSource.dballo19.customers.id, MySQLSource.dballo19.customers.name,
MySQLSource.dballo19.customers.address] [class java.lang.Long, class java.lang.String,
class java.lang.String] batch size 512 of type PROCESSOR
17:33:12,183 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue0) GZ80TLU8xKRP.0.0.0
Create State
17:33:12,207 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0)
GZ80TLU8xKRP.0.0.0 Blocking on source query GZ80TLU8xKRP.0.0.0
17:33:12,207 DEBUG [org.teiid.BUFFER_MGR] (Worker0_QueryProcessorQueue0) GZ80TLU8xKRP.0
Blocking on source request(s).
17:33:12,207 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue0) Request Thread
GZ80TLU8xKRP.0 - processor blocked
17:33:12,214 DEBUG [org.teiid.PROCESSOR] (Worker1_QueryProcessorQueue1) Running task for
parent thread Worker0_QueryProcessorQueue0
17:33:12,215 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Processing NEW request: SELECT g_0.id, g_0.name, g_0.address FROM
MySQLSource.dballo19.customers AS g_0 
17:33:12,218 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Obtained execution
17:33:12,227 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) Source-specific
command: SELECT g_0.`id`, g_0.`name`, g_0.`address` FROM `dballo19`.`customers` AS g_0 
17:33:12,571 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Executed command
17:33:12,571 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Processing MORE request
17:33:12,571 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Getting results from connector
17:33:12,573 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue1) GZ80TLU8xKRP.0.0.0
Obtained last batch, total row count: 10
17:33:12,574 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) Request Thread
GZ80TLU8xKRP.0 with state PROCESSING
17:33:12,575 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0.0.0
Remove State
17:33:12,575 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0.0.0
Processing Close : SELECT g_0.id, g_0.name, g_0.address FROM
MySQLSource.dballo19.customers AS g_0 
17:33:12,576 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0.0.0
Closed execution
17:33:12,576 DEBUG [org.teiid.CONNECTOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0.0.0
Closed connection
17:33:12,577 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) QueryProcessor:
closing processor
17:33:12,577 DEBUG [org.teiid.PROCESSOR] (Worker0_QueryProcessorQueue2) GZ80TLU8xKRP.0
Finished Processing
{code}

...
 Add the query requestID to all lines for that query in the logs
 ---------------------------------------------------------------

                 Key: TEIID-3582
                 URL: https://issues.jboss.org/browse/TEIID-3582
             Project: Teiid
          Issue Type: Enhancement
          Components: Server
    Affects Versions: 8.12.5
            Reporter: Van Halbert
             Fix For: 8.12.2, 8.13

 Currently when running a query, the logs show the requestId on most of the lines but not
all, especially CONNECTOR.
 for example, the following line doesn't have it:
 14:13:34,071 DEBUG [org.teiid.CONNECTOR] (Worker1_QueryProcessorQueue13) Source-specific
command: ....
 That's the problem. When lots of queries are running, user wants to grep through the
log for that requestid and get just that one query's stuff. 

--
This message was sent by Atlassian JIRA
(v6.4.11#64026)

2026

2025

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009