[teiid-issues] [JBoss JIRA] (TEIID-3596) Command logging: last command's log is not ended

[Jan Stastny (JIRA)]

Jan Stastny created TEIID-3596:
----------------------------------

             Summary: Command logging: last command's log is not ended
                 Key: TEIID-3596
                 URL: https://issues.jboss.org/browse/TEIID-3596
             Project: Teiid
          Issue Type: Bug
          Components: Query Engine
    Affects Versions: 8.7.1.6_2
            Reporter: Jan Stastny
            Assignee: Steven Hawkins


There are incomplete entries when performing queries on some vdb and examining the org.teiid.COMMAND_LOG entries in server.log.
>From the logs it seems, that the closing entry for a user command is not logged until either another command is performed or the server is shut down.

The following logs appears right after the command is performed:
{code:plain}
[org.teiid.COMMAND_LOG] (New I/O worker #64)         START USER COMMAND:     startTime=2015-07-28 13:43:18.441       requestID=rfFDiTxhxLGL.0        txID=null       sessionID=rfFDiTxhxLGL  applicationName=JDBC    principal=user at teiid-security   vdbName=Portfolio       vdbVersion=1    sql=select * from product
[org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue1)       START DATA SRC COMMAND: startTime=2015-07-28 13:43:18.54        requestID=rfFDiTxhxLGL.0        sourceCommandID=0       executionID=0   txID=null       modelName=Accounts      translatorName=translator-h2    sessionID=rfFDiTxhxLGL  principal=user at teiid-security   sql=SELECT g_0.ID, g_0.SYMBOL, g_0.COMPANY_NAME FROM Accounts.PRODUCT AS g_0
[org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue2)       END SRC COMMAND:        endTime=2015-07-28 13:43:18.548 requestID=rfFDiTxhxLGL.0        sourceCommandID=0       executionID=0   txID=null       modelName=Accounts      translatorName=translator-h2    sessionID=rfFDiTxhxLGL  principal=user at teiid-security   finalRowCount=25
{code}

while the following appers only when the server is shut down (notice the time difference between this one and preceding ones):
{code:plain}
[org.teiid.COMMAND_LOG] (New I/O worker #64)         CANCEL USER COMMAND:    endTime=2015-07-28 13:43:29.152 requestID=rfFDiTxhxLGL.0        txID=null       sessionID=rfFDiTxhxLGL  principal=user at teiid-security   vdbName=Portfolio       vdbVersion=1    finalRowCount=null
{code}
If there is another command following, the previous command log entry is completed (but it can take even minutes):
{code:plain}
[org.teiid.COMMAND_LOG] (Worker0_QueryProcessorQueue3)       END USER COMMAND:       endTime=2015-07-28 14:18:59.511 requestID=q97k+Z4gwV64.0        txID=null       sessionID=q97k+Z4gwV64  principal=user at teiid-security   vdbName=Portfolio       vdbVersion=1    finalRowCount=25
{code}

Also the ending log entry of one command and opening entry of another appear in any order.




--
This message was sent by Atlassian JIRA
(v6.3.15#6346)