<html>
<head>
<base href="https://docs.jboss.org/author">
<link rel="stylesheet" href="/author/s/en/2172/19/5/_/styles/combined.css?spaceKey=TEIID&forWysiwyg=true" type="text/css">
</head>
<body style="background: white;" bgcolor="white" class="email-body">
<div id="pageContent">
<div id="notificationFormat">
<div class="wiki-content">
<div class="email">
<h2><a href="https://docs.jboss.org/author/display/TEIID/Logging">Logging</a></h2>
<h4>Page <b>edited</b> by <a href="https://docs.jboss.org/author/display/~shawkins">Steven Hawkins</a>
</h4>
<br/>
<h4>Changes (2)</h4>
<div id="page-diffs">
<table class="diff" cellpadding="0" cellspacing="0">
<tr><td class="diff-snipped" >...<br></td></tr>
<tr><td class="diff-unchanged" >h1. Command Logging <br> <br></td></tr>
<tr><td class="diff-deleted-lines" style="color:#999;background-color:#fdd;text-decoration:line-through;">Command logging captures executing commands in the Teiid System. This includes user commands (that have been submitted to Teiid), query plan commands (for when the query planning is performed), and data source commands (that are being executed by the connectors) are tracked through command logging. <br></td></tr>
<tr><td class="diff-added-lines" style="background-color: #dfd;">Command logging captures executing commands in the Teiid System. This includes user commands (that have been submitted to Teiid at an INFO level), data source commands (that are being executed by the connectors at a DEBUG level), and query plan commands (for when the query planning is performed at a TRACE level) are tracked through command logging. <br></td></tr>
<tr><td class="diff-unchanged" > <br>The user command, "START USER COMMAND", is logged when Teiid starts working on the query for the first time. This does not include the time the query was waiting in the queue. And a corresponding user command, "END USER COMMAND", is logged when the request is complete (i.e. when statement is closed or all the batches are retrieved). There is only one pair of these for every user query. <br></td></tr>
<tr><td class="diff-snipped" >...<br></td></tr>
</table>
</div> <h4>Full Content</h4>
<div class="notificationGreySide">
<p>The Teiid system provides a wealth of information via logging. To control logging level, contexts, and log locations, you should be familiar with <a href="http://logging.apache.org/log4j/" class="external-link" rel="nofollow">log4j</a> and the container's <em>standalone-teiid.xml</em> or <em>domain-teiid.xml</em> configuration files depending upon the start up mode of JBoss AS.</p>
<p>All the logs produced by Teiid are prefixed by "org.teiid". This makes it extremely easy to control of of Teiid logging from a single context. Note however that changes to the log configuration file manually require a restart to take affect. CLI based log context modifications are possible, however details are beyond the scope of this document.</p>
<div class='panelMacro'><table class='tipMacro'><colgroup><col width='24'><col></colgroup><tr><td valign='top'><img src="/author/images/icons/emoticons/check.gif" width="16" height="16" align="absmiddle" alt="" border="0"></td><td>If you expect a high volume of logging information or use expensive custom audit/command loggers, it is a good idea to use an aynch appender to minimize the performance impact. For example you can use a configuration snippet like the one below to insert an asynch handler in front of the target appender.
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: java; gutter: false" style="font-size:12px; font-family: ConfluenceInstalledFont,monospace;"><periodic-rotating-file-handler name="COMMAND_FILE">
<level name="DEBUG" />
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n" />
</formatter>
<file relative-to="jboss.server.log.dir" path="command.log" />
<suffix value=".yyyy-MM-dd" />
</periodic-rotating-file-handler>
<async-handler name="ASYNC">
<level name="DEBUG"/>
<queue-length value="1024"/>
<overflow-action value="block"/>
<subhandlers>
<handler name="COMMAND"/>
</subhandlers>
</async-handler>
<logger category="org.teiid.COMMAND_LOG">
<level name="DEBUG" />
<handlers>
<handler name="ASYNC" />
</handlers>
</logger>
</pre>
</div></div></td></tr></table></div>
<h1><a name="Logging-LoggingContexts"></a>Logging Contexts</h1>
<p>While all of Teiid's logs are prefixed with <em>"org.teiid"</em>, there are more specific contexts depending on the functional area of the system. Note that logs originating from third-party code, including integrated org.jboss components, will be logged through their respective contexts and not through <em>"org.teiid"</em>. See the table below for information on contexts relevant to Teiid. See the container's <em>standalone-teiid.xml</em> for a more complete listing of logging contexts used in the container.</p>
<div class='table-wrap'>
<table class='confluenceTable'><tbody>
<tr>
<th class='confluenceTh'> Context </th>
<th class='confluenceTh'> Description </th>
</tr>
<tr>
<td class='confluenceTd'> com.arjuna </td>
<td class='confluenceTd'> Third-party transaction manager. This will include information about all transactions, not just those for Teiid. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid </td>
<td class='confluenceTd'> Root context for all Teiid logs. Note: there are potentially other contexts used under org.teiid than are shown in this table. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.PROCESSOR </td>
<td class='confluenceTd'> Query processing logs. See also org.teiid.PLANNER for query planning logs. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.PLANNER </td>
<td class='confluenceTd'> Query planning logs. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.SECURITY </td>
<td class='confluenceTd'> Session/Authentication events - see also AUDIT logging </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.TRANSPORT </td>
<td class='confluenceTd'> Events related to the socket transport. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.RUNTIME </td>
<td class='confluenceTd'> Events related to work management and system start/stop. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.CONNECTOR </td>
<td class='confluenceTd'> Connector logs. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.BUFFER_MGR </td>
<td class='confluenceTd'> Buffer and storage management logs. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.TXN_LOG </td>
<td class='confluenceTd'> Detail log of all transaction operations. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.COMMAND_LOG </td>
<td class='confluenceTd'> See command logging </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.AUDIT_LOG </td>
<td class='confluenceTd'> See audit logging </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.ADMIN_API </td>
<td class='confluenceTd'> Admin API logs. </td>
</tr>
<tr>
<td class='confluenceTd'> org.teiid.ODBC </td>
<td class='confluenceTd'> ODBC logs. </td>
</tr>
</tbody></table>
</div>
<h1><a name="Logging-CommandLogging"></a>Command Logging</h1>
<p>Command logging captures executing commands in the Teiid System. This includes user commands (that have been submitted to Teiid at an INFO level), data source commands (that are being executed by the connectors at a DEBUG level), and query plan commands (for when the query planning is performed at a TRACE level) are tracked through command logging.</p>
<p>The user command, "START USER COMMAND", is logged when Teiid starts working on the query for the first time. This does not include the time the query was waiting in the queue. And a corresponding user command, "END USER COMMAND", is logged when the request is complete (i.e. when statement is closed or all the batches are retrieved). There is only one pair of these for every user query. </p>
<p>The query plan command, "PLAN USER COMMAND", is logged when Teiid finishes the query planning process. There is no corresponding ending log entry.</p>
<p>The data source command, "START DATA SRC COMMAND", is logged when a query is sent to the data source. And a corresponding data source command, "END SRC COMMAND", is logged when the execution is closed (i.e all the rows has been read). There can be one pair for each data source query that has been executed by Teiid, and there can be number of pairs depending upon your query.</p>
<p>With this information being captured, the overall query execution time in Teiid can be calculated. Additionally, each source query execution time can be calculated. If the overall query execution time is showing a performance issue, then look at each data source execution time to see where the issue maybe.</p>
<p>To enable command logging to the default log location, simply enable the DETAIL level of logging for the org.teiid.COMMAND_LOG context.</p>
<div class='panelMacro'><table class='tipMacro'><colgroup><col width='24'><col></colgroup><tr><td valign='top'><img src="/author/images/icons/emoticons/check.gif" width="16" height="16" align="absmiddle" alt="" border="0"></td><td><b>"Want to log to a database?"</b><br />If you would like to log Command log messages to any database, then look at the <a href="https://github.com/teiid/teiid-extensions" class="external-link" rel="nofollow">https://github.com/teiid/teiid-extensions</a> project. The installation zip file is available in Teiid downloads page.</td></tr></table></div>
<p>To enable command logging to an alternative file location, configure a separate file appender for the DETAIL logging of the org.teiid.COMMAND_LOG context. An example of this is shown below and can also be found in the standalone-teiid.xml distributed with Teiid.</p>
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: java; gutter: false" style="font-size:12px; font-family: ConfluenceInstalledFont,monospace;">
<periodic-rotating-file-handler name="COMMAND_FILE">
<level name="DEBUG" />
<formatter>
<pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n" />
</formatter>
<file relative-to="jboss.server.log.dir" path="command.log" />
<suffix value=".yyyy-MM-dd" />
</periodic-rotating-file-handler>
<logger category="org.teiid.COMMAND_LOG">
<level name="DEBUG" />
<handlers>
<handler name="COMMAND_FILE" />
</handlers>
</logger>
</pre>
</div></div>
<p>See the <a href="/author/display/TEIID/Developer%27s+Guide" title="Developer's Guide">Developer's Guide</a> to develop a <a href="/author/display/TEIID/Custom+Logging" title="Custom Logging">custom logging solution</a> if file based logging, or any other built-in Log4j logging, is not sufficient.</p>
<p>The following is an example of a data source command and what one would look like when printed to the command log:</p>
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: java; gutter: false" style="font-size:12px; font-family: ConfluenceInstalledFont,monospace;">
2012-02-22 16:01:53,712 DEBUG [org.teiid.COMMAND_LOG] (Worker1_QueryProcessorQueue11 START DATA SRC COMMAND: startTime=2012-02-22 16:01:53.712
requestID=Ku4/dgtZPYk0.5 sourceCommandID=4 txID=null modelName=DTHCP translatorName=jdbc-simple sessionID=Ku4/dgtZPYk0
principal=user@teiid-security
sql=HCP_ADDR_XREF.HUB_ADDR_ID, CPN_PROMO_HIST.PROMO_STAT_DT FROM CPN_PROMO_HIST, HCP_ADDRESS, HCP_ADDR_XREF
WHERE (HCP_ADDRESS.ADDR_ID = CPN_PROMO_HIST.SENT_ADDR_ID) AND (HCP_ADDRESS.ADDR_ID = HCP_ADDR_XREF.ADDR_ID) AND
(CPN_PROMO_HIST.PROMO_STAT_CD NOT LIKE 'EMAIL%') AND (CPN_PROMO_HIST.PROMO_STAT_CD <> 'SENT_EM') AND
(CPN_PROMO_HIST.PROMO_STAT_DT > {ts'2010-02-22 16:01:52.928'})
</pre>
</div></div>
<p>Note the following pieces of information:</p>
<ul>
<li>modelName: this represents the physical model for the data source that the query is being issued. </li>
<li>translatorName: shows type of translator used to communicate to the data source. </li>
<li>principal: shows the user account who submitted the query</li>
<li>startTime/endTime: the time of the action, which is based on the type command being executed.</li>
<li>sql: is the command submitted to the translator for execution, which is NOT necessarily the final sql command submitted to the actual data source. But it does show what the query engine decided to push down.</li>
</ul>
<p>END DATA SRC events will additionally contain:</p>
<ul>
<li>finalRowCount: the number of rows returned to the engine by the source query.</li>
<li>cpuTime: the number of nanoseconds of cpu time used by the source command. Can be compared to the start/end wall clock times to determine cpu vs. idle time.</li>
</ul>
<h1><a name="Logging-AuditLogging"></a>Audit Logging</h1>
<p>Audit logging captures important security events. This includes the enforcement of permissions, authentication success/failures, etc.</p>
<p>To enable audit logging to the default log location, simply enable the DETAIL level of logging for the org.teiid.AUDIT_LOG context.</p>
<div class='panelMacro'><table class='tipMacro'><colgroup><col width='24'><col></colgroup><tr><td valign='top'><img src="/author/images/icons/emoticons/check.gif" width="16" height="16" align="absmiddle" alt="" border="0"></td><td><b>"Want to log to a database?"</b><br />If you would like to log Audit log messages to any database, then look at the <a href="https://github.com/teiid/teiid-extensions" class="external-link" rel="nofollow">https://github.com/teiid/teiid-extensions</a> project. The installation zip file will be available in Teiid downloads page.</td></tr></table></div>
<p>To enable audit logging to an alternative file location, configure a separate file appender for the DETAIL logging of the org.teiid.AUDIT_LOG context. See the <a href="/author/display/TEIID/Developer%27s+Guide" title="Developer's Guide">Developer's Guide</a> to develop a <a href="/author/display/TEIID/Custom+Logging" title="Custom Logging">custom logging solution</a> if file based, or any other built-in Log4j, logging is not sufficient.</p>
<h1><a name="Logging-AdditionalLoggingInformation"></a>Additional Logging Information</h1>
<p>Once a session has been created, each log made by Teiid will include the session id and vdb name/version in the MDC (mapped diagnostic context) with keys of teiid-session and teiid-vdb respectively. Custom loggers, or format patterns can take advantage of this information to better correlate log entries. See for example Teiid default <em>standalone-teiid.xml</em> that uses a pattern format which includes the session id prior to the message: <div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: java; gutter: false" style="font-size:12px; font-family: ConfluenceInstalledFont,monospace;"><pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %X{teiid-session} %s%E%n"/></pre>
</div></div></p>
</div>
<div id="commentsSection" class="wiki-content pageSection">
<div style="float: right;" class="grey">
<a href="https://docs.jboss.org/author/users/removespacenotification.action?spaceKey=TEIID">Stop watching space</a>
<span style="padding: 0px 5px;">|</span>
<a href="https://docs.jboss.org/author/users/editmyemailsettings.action">Change email notification preferences</a>
</div>
<a href="https://docs.jboss.org/author/display/TEIID/Logging">View Online</a>
|
<a href="https://docs.jboss.org/author/pages/diffpagesbyversion.action?pageId=18646064&revisedVersion=18&originalVersion=17">View Changes</a>
|
<a href="https://docs.jboss.org/author/display/TEIID/Logging?showComments=true&showCommentArea=true#addcomment">Add Comment</a>
</div>
</div>
</div>
</div>
</div>
</body>
</html>