Author: shawkins Date: 2011-06-03 16:17:30 -0400 (Fri, 03 Jun 2011) New Revision: 3216 Modified: branches/7.4.x/api/src/main/java/org/teiid/logging/LogManager.java branches/7.4.x/api/src/test/java/org/teiid/logging/TestLogManager.java branches/7.4.x/documentation/developer-guide/src/main/docbook/en-US/content/logging.xml branches/7.4.x/engine/src/main/java/org/teiid/common/buffer/BlockedException.java branches/7.4.x/engine/src/main/java/org/teiid/common/buffer/TupleBuffer.java branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/AuthorizationValidationVisitor.java branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/DataTierTupleSource.java branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/AccessNode.java branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/ProjectIntoNode.java branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/UnionAllNode.java branches/7.4.x/engine/src/main/java/org/teiid/query/util/CommandContext.java Log: TEIID-1612 logging cleanup, command/audit messages will now be top level message objects and we'll have better logging of blocked exceptions Modified: branches/7.4.x/api/src/main/java/org/teiid/logging/LogManager.java =================================================================== --- branches/7.4.x/api/src/main/java/org/teiid/logging/LogManager.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/api/src/main/java/org/teiid/logging/LogManager.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -351,6 +351,9 @@ if (!isMessageToBeRecorded(context, msgLevel)) { return; } + if (message != null && message.getClass().isArray()) { + message = new LogMessage((Object[]) message); + } logListener.log(msgLevel, context, e, message); } @@ -383,7 +386,7 @@ if (msgParts == null || msgParts.length == 0 || !isMessageToBeRecorded(context, level)) { return; } - logListener.log(level, context, new LogMessage(msgParts)); + logListener.log(level, context, msgParts.length == 1? msgParts[0] : new LogMessage(msgParts)); } Modified: branches/7.4.x/api/src/test/java/org/teiid/logging/TestLogManager.java =================================================================== --- branches/7.4.x/api/src/test/java/org/teiid/logging/TestLogManager.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/api/src/test/java/org/teiid/logging/TestLogManager.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -41,7 +41,7 @@ */ public class TestLogManager extends TestCase { - String context = "SomeContext"; //$NON-NLS-1$ + private static final String CONTEXT = "SomeContext"; //$NON-NLS-1$ /** * Constructor for TestLogManager. @@ -54,7 +54,7 @@ @Override protected void setUp() throws Exception { ListLogger logger = new ListLogger(); - logger.setLogLevel(context, MessageLevel.DETAIL); + logger.setLogLevel(CONTEXT, MessageLevel.DETAIL); LogManager.logListener = logger; } @@ -66,11 +66,11 @@ * Test for boolean isMessageToBeRecorded(String, int) */ public void testIsMessageToBeRecordedString() { - assertTrue(LogManager.isMessageToBeRecorded(context, MessageLevel.CRITICAL) ); + assertTrue(LogManager.isMessageToBeRecorded(CONTEXT, MessageLevel.CRITICAL) ); ListLogger cfg = (ListLogger)LogManager.logListener; - cfg.setLogLevel(context, MessageLevel.NONE); - assertFalse(LogManager.isMessageToBeRecorded(context, MessageLevel.CRITICAL) ); + cfg.setLogLevel(CONTEXT, MessageLevel.NONE); + assertFalse(LogManager.isMessageToBeRecorded(CONTEXT, MessageLevel.CRITICAL) ); } /** @@ -78,7 +78,7 @@ */ public void testLogMessage() throws Exception { ListLogger cfg = (ListLogger)LogManager.logListener; - cfg.setLogLevel(context, MessageLevel.INFO ); + cfg.setLogLevel(CONTEXT, MessageLevel.INFO ); List<String> sentMsgList = new ArrayList<String>(); sentMsgList.add("A message 1"); //$NON-NLS-1$ @@ -88,12 +88,12 @@ sentMsgList.add("A message 5"); //$NON-NLS-1$ sentMsgList.add("A message 6"); //$NON-NLS-1$ - for (Iterator iter = sentMsgList.iterator(); iter.hasNext();) { - String msg = (String) iter.next(); - LogManager.logInfo(context, msg); + for (Iterator<String> iter = sentMsgList.iterator(); iter.hasNext();) { + String msg = iter.next(); + LogManager.logInfo(CONTEXT, msg); } - List recevedMsgList = cfg.getLoggedMessages(); + List<String> recevedMsgList = cfg.getLoggedMessages(); assertEquals(sentMsgList.size(), recevedMsgList.size()); assertEquals(sentMsgList, recevedMsgList); } @@ -129,7 +129,7 @@ return this.messages.size(); } - public List getLoggedMessages() { + public List<String> getLoggedMessages() { return this.messages; } Modified: branches/7.4.x/documentation/developer-guide/src/main/docbook/en-US/content/logging.xml =================================================================== --- branches/7.4.x/documentation/developer-guide/src/main/docbook/en-US/content/logging.xml 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/documentation/developer-guide/src/main/docbook/en-US/content/logging.xml 2011-06-03 20:17:30 UTC (rev 3216) @@ -33,8 +33,8 @@ <title>Command Logging API</title> <para> If you want to build a custom appender for command logging that will have access to - log4j "LoggingEvents" to the "COMMAND_LOG" contextthe appender will receive a message that is an instance of - <code>org.teiid.logging.CommandLogMessage</code> wrapped in a <code>org.teiid.logging.LogMessage</code>. The relevant Teiid classes are defined in the <code>teiid-api-&versionNumber;.jar</code>. + log4j "LoggingEvents" to the "COMMAND_LOG" context, the appender will receive a message that is an instance of + <code>org.teiid.logging.CommandLogMessage</code>. The relevant Teiid classes are defined in the <code>teiid-api-&versionNumber;.jar</code>. The CommmdLogMessage includes information about vdb, session, command sql, etc. CommandLogMessages are logged at the DEBUG level. </para> <example> @@ -48,14 +48,11 @@ { protected void append(LoggingEvent event) { - if (event.getMessage() instanceof LogMessage) { - LogMessage logMessage = (LogMessage)event.getMessage(); - if (logMessage.getMessageParts()[0] instanceof CommandLogMessage) { - CommandLogMessage clMessage = (CommandLogMessage)logMessage.getMessageParts()[0]; - String sql = clMessage.getSql(); - ... - //log to a database, trigger an email, etc. - } + if (event.getMessage() instanceof CommandLogMessage) { + CommandLogMessage clMessage = (CommandLogMessage)event.getMessage(); + String sql = clMessage.getSql(); + ... + //log to a database, trigger an email, etc. } ... } @@ -70,7 +67,7 @@ <title>Audit Logging API</title> <para>If you want to build a custom appender for command logging that will have access to log4j "LoggingEvents" to the "org.teiid.AUDIT_LOG" context, the appender will receive a message that is an instance of - <code>org.teiid.logging.AuditMessage</code> wrapped in a <code>org.teiid.logging.LogMessage</code>. The relevant Teiid classes are defined in the <code>teiid-api-&versionNumber;.jar</code>. The <code>AuditMessage</code> includes information about user, the action, and the + <code>org.teiid.logging.AuditMessage</code>. The relevant Teiid classes are defined in the <code>teiid-api-&versionNumber;.jar</code>. The <code>AuditMessage</code> includes information about user, the action, and the target(s) of the action. AuditMessages are logged at the DEBUG level. </para> <example> @@ -84,14 +81,11 @@ { protected void append(LoggingEvent event) { - if (event.getMessage() instanceof LogMessage) { - LogMessage logMessage = (LogMessage)event.getMessage(); - if (logMessage.getMessageParts()[0] instanceof AuditMessage) { - AuditMessage auditMessage = (AuditMessage)logMessage.getMessageParts()[0]; - String activity = auditMessage.getActivity(); - ... - //log to a database, trigger an email, etc. - } + if (event.getMessage() instanceof AuditMessage) { + AuditMessage auditMessage = (AuditMessage)event.getMessage(); + String activity = auditMessage.getActivity(); + ... + //log to a database, trigger an email, etc. } ... } Modified: branches/7.4.x/engine/src/main/java/org/teiid/common/buffer/BlockedException.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/common/buffer/BlockedException.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/common/buffer/BlockedException.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -23,6 +23,9 @@ package org.teiid.common.buffer; import org.teiid.core.TeiidComponentException; +import org.teiid.logging.LogConstants; +import org.teiid.logging.LogManager; +import org.teiid.logging.MessageLevel; /** * This exception is thrown if the buffer manager blocks waiting on input during @@ -40,4 +43,11 @@ super(); } + public static BlockedException block(Object... msg) { + if (LogManager.isMessageToBeRecorded(LogConstants.CTX_BUFFER_MGR, MessageLevel.DETAIL)) { + LogManager.logDetail(LogConstants.CTX_BUFFER_MGR, msg); + } + return INSTANCE; + } + } Modified: branches/7.4.x/engine/src/main/java/org/teiid/common/buffer/TupleBuffer.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/common/buffer/TupleBuffer.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/common/buffer/TupleBuffer.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -318,7 +318,7 @@ if(isFinal) { return null; } - throw BlockedException.INSTANCE; + throw BlockedException.block("Blocking on non-final TupleBuffer", tupleSourceID); //$NON-NLS-1$ } @Override Modified: branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/AuthorizationValidationVisitor.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/AuthorizationValidationVisitor.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/AuthorizationValidationVisitor.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -36,7 +36,6 @@ import org.teiid.CommandContext; import org.teiid.adminapi.DataPolicy; -import org.teiid.adminapi.Session; import org.teiid.adminapi.DataPolicy.PermissionType; import org.teiid.adminapi.impl.DataPolicyMetadata; import org.teiid.api.exception.query.QueryMetadataException; Modified: branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/DataTierTupleSource.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/DataTierTupleSource.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/DataTierTupleSource.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -57,6 +57,8 @@ import org.teiid.dqp.message.AtomicRequestMessage; import org.teiid.dqp.message.AtomicResultsMessage; import org.teiid.events.EventDistributor; +import org.teiid.logging.LogConstants; +import org.teiid.logging.LogManager; import org.teiid.metadata.Table; import org.teiid.query.function.source.XMLSystemFunctions; import org.teiid.query.processor.relational.RelationalNodeUtil; @@ -244,7 +246,7 @@ workItem.moreWork(); } }, 10, e.getRetryDelay()); - throw BlockedException.INSTANCE; + throw BlockedException.block(aqr.getAtomicRequestID(), "Blocking on DataNotAvailableException"); //$NON-NLS-1$ } receiveResults(results); } @@ -295,7 +297,7 @@ addWork(); } if (!futureResult.isDone()) { - throw BlockedException.INSTANCE; + throw BlockedException.block(aqr.getAtomicRequestID(), "Blocking on source query"); //$NON-NLS-1$ } FutureWork<AtomicResultsMessage> currentResults = futureResult; futureResult = null; Modified: branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/dqp/internal/process/RequestWorkItem.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -450,7 +450,7 @@ && !batch.getTerminationFlag() && this.getTupleBuffer().getManagedRowCount() >= 20 * this.getTupleBuffer().getBatchSize()) { //requestMore will trigger more processing - throw BlockedException.INSTANCE; + throw BlockedException.block(requestID, "Blocking due to full results buffer."); //$NON-NLS-1$ } } } Modified: branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/AccessNode.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/AccessNode.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/AccessNode.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -306,7 +306,7 @@ } if (!this.tupleSources.isEmpty()) { - throw BlockedException.INSTANCE; + throw BlockedException.block(getContext().getRequestId(), "Blocking on source request(s)."); //$NON-NLS-1$ } } Modified: branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/ProjectIntoNode.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/ProjectIntoNode.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/ProjectIntoNode.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -222,7 +222,7 @@ } // RESPONSE_PROCESSING: process tuple sources if (tupleSourcesProcessed < requestsRegistered) { - throw BlockedException.INSTANCE; + throw BlockedException.block(getContext().getRequestId(), "Blocking on insert update count"); //$NON-NLS-1$ } } Modified: branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/UnionAllNode.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/UnionAllNode.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/query/processor/relational/UnionAllNode.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -129,7 +129,7 @@ } else if(activeSources > 0) { // Didn't get a batch but there are active sources so we are blocked - throw BlockedException.INSTANCE; + throw BlockedException.block(getContext().getRequestId(), "Blocking on union source."); //$NON-NLS-1$ } else { // No batch and no active sources - return empty termination batch (should never happen but just in case) outputBatch = new TupleBatch(outputRow, Collections.EMPTY_LIST); Modified: branches/7.4.x/engine/src/main/java/org/teiid/query/util/CommandContext.java =================================================================== --- branches/7.4.x/engine/src/main/java/org/teiid/query/util/CommandContext.java 2011-06-03 20:16:00 UTC (rev 3215) +++ branches/7.4.x/engine/src/main/java/org/teiid/query/util/CommandContext.java 2011-06-03 20:17:30 UTC (rev 3216) @@ -584,7 +584,7 @@ @Override public String getRequestId() { - return this.globalState.requestId.toString(); + return this.globalState.requestId != null ? this.globalState.requestId.toString() : null; } public void setRequestId(RequestID requestId) {