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

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@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@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@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@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@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.