Uploaded image for project: 'Teiid'
  1. Teiid
  2. TEIID-3596

Command logging: last command's log is not ended

    XMLWordPrintable

Details

    • Bug
    • Resolution: Won't Do
    • Major
    • None
    • 8.7.1.6_2
    • Query Engine
    • None
    • Hide
      1. start server with some vdb deployed
      2. run a command
      3. examine log for org.teiid.COMMAND_LOG entries, there is not the "END USER COMMAND"
      4. run another command
      5. examine logs for "END USER COMMAND" of the first command and logs for the second (again without its "END USER COMMAND")
      6. shut down the server
      7. examine the logs for "CANCEL USER COMMAND" for the last command
      Show
      start server with some vdb deployed run a command examine log for org.teiid.COMMAND_LOG entries, there is not the "END USER COMMAND" run another command examine logs for "END USER COMMAND" of the first command and logs for the second (again without its "END USER COMMAND") shut down the server examine the logs for "CANCEL USER COMMAND" for the last command

    Description

      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:

      Unable to find source-code formatter for language: plain. Available languages are: actionscript, ada, applescript, bash, c, c#, c++, cpp, css, erlang, go, groovy, haskell, html, java, javascript, js, json, lua, none, nyan, objc, perl, php, python, r, rainbow, ruby, scala, sh, sql, swift, visualbasic, xml, yaml
      [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
      

      while the following appers only when the server is shut down (notice the time difference between this one and preceding ones):

      Unable to find source-code formatter for language: plain. Available languages are: actionscript, ada, applescript, bash, c, c#, c++, cpp, css, erlang, go, groovy, haskell, html, java, javascript, js, json, lua, none, nyan, objc, perl, php, python, r, rainbow, ruby, scala, sh, sql, swift, visualbasic, xml, yaml
      [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
      

      If there is another command following, the previous command log entry is completed (but it can take even minutes):

      Unable to find source-code formatter for language: plain. Available languages are: actionscript, ada, applescript, bash, c, c#, c++, cpp, css, erlang, go, groovy, haskell, html, java, javascript, js, json, lua, none, nyan, objc, perl, php, python, r, rainbow, ruby, scala, sh, sql, swift, visualbasic, xml, yaml
      [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
      

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

      Attachments

        Activity

          People

            rhn-engineering-shawkins Steven Hawkins
            jstastny@redhat.com Jan Stastny
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: