diff --git a/src/main/java/org/jboss/logmanager/handlers/DelayedHandler.java b/src/main/java/org/jboss/logmanager/handlers/DelayedHandler.java new file mode 100644 index 00000000..056ad9be --- /dev/null +++ b/src/main/java/org/jboss/logmanager/handlers/DelayedHandler.java @@ -0,0 +1,216 @@ +/* + * JBoss, Home of Professional Open Source. + * + * Copyright 2017 Red Hat, Inc., and individual contributors + * as indicated by the @author tags. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.jboss.logmanager.handlers; + +import java.util.ArrayDeque; +import java.util.Deque; +import java.util.logging.Formatter; +import java.util.logging.Handler; + +import org.jboss.logmanager.ExtHandler; +import org.jboss.logmanager.ExtLogRecord; +import org.jboss.logmanager.StandardOutputStreams; +import org.jboss.logmanager.formatters.PatternFormatter; + +/** + * A handler that queues messages until it's at least one child handler is {@linkplain #addHandler(Handler) added} or + * {@linkplain #setHandlers(Handler[]) set}. If the children handlers are {@linkplain #clearHandlers() cleared} then + * the handler is no longer considered activated and messages will once again be queued. + * + * @author James R. Perkins + */ +@SuppressWarnings({"unused", "WeakerAccess"}) +public class DelayedHandler extends ExtHandler { + + private final Deque logRecords = new ArrayDeque<>(); + + private volatile boolean activated = false; + private volatile boolean callerCalculationRequired = false; + + @Override + protected void doPublish(final ExtLogRecord record) { + // If activated just delegate + if (activated) { + publishToChildren(record); + super.doPublish(record); + } else { + synchronized (this) { + // Check one more time to see if we've been activated before queuing the messages + if (activated) { + publishToChildren(record); + super.doPublish(record); + } else { + // Determine if we need to calculate the caller information before we queue the record + if (isCallerCalculationRequired()) { + // prepare record to move to another thread + record.copyAll(); + } else { + // Disable the caller calculation since it's been determined we won't be using it + record.disableCallerCalculation(); + // Copy the MDC over + record.copyMdc(); + // In case serialization is required by a child handler + record.getFormattedMessage(); + } + logRecords.addLast(record); + } + } + } + } + + @Override + public final void close() throws SecurityException { + checkAccess(this); + synchronized (this) { + if (!logRecords.isEmpty()) { + Formatter formatter = getFormatter(); + if (formatter == null) { + formatter = new PatternFormatter("%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"); + } + StandardOutputStreams.printError("The DelayedHandler was closed before any children handlers were " + + "configured. Messages will be written to stderr."); + // Always attempt to drain the queue + ExtLogRecord record; + while ((record = logRecords.pollFirst()) != null) { + StandardOutputStreams.printError(formatter.format(record)); + } + } + } + activated = false; + super.close(); + } + + /** + * {@inheritDoc} + *

+ * Note that once this is invoked the handler will be activated and the messages will no longer be queued. If more + * than one child handler is required the {@link #setHandlers(Handler[])} should be used. + *

+ * + * @see #setHandlers(Handler[]) + */ + @Override + public void addHandler(final Handler handler) throws SecurityException { + super.addHandler(handler); + activate(); + } + + /** + * {@inheritDoc} + *

+ * Note that once this is invoked the handler will be activated and the messages will no longer be queued. + *

+ */ + @Override + public Handler[] setHandlers(final Handler[] newHandlers) throws SecurityException { + final Handler[] result = super.setHandlers(newHandlers); + activate(); + return result; + } + + /** + * {@inheritDoc} + *

+ * Note that if the last child handler is removed the handler will no longer be activated and the messages will + * again be queued. + *

+ * + * @see #clearHandlers() + */ + @Override + public void removeHandler(final Handler handler) throws SecurityException { + super.removeHandler(handler); + activated = handlers.length != 0; + } + + /** + * {@inheritDoc} + *

+ * Note that once this is invoked the handler will no longer be activated and messages will again be queued. + *

+ * + * @see #removeHandler(Handler) + */ + @Override + public Handler[] clearHandlers() throws SecurityException { + activated = false; + return super.clearHandlers(); + } + + /** + * {@inheritDoc} + *

+ * This can be overridden to always require the caller calculation by setting the + * {@link #setCallerCalculationRequired(boolean)} value to {@code true}. + *

+ * + * @see #setCallerCalculationRequired(boolean) + */ + @Override + public boolean isCallerCalculationRequired() { + return callerCalculationRequired || super.isCallerCalculationRequired(); + } + + /** + * Sets whether or not {@linkplain ExtLogRecord#copyAll() caller information} will be required when formatting + * records. + *

+ * If set to {@code true} the {@linkplain ExtLogRecord#copyAll() caller information} will be calculated for each + * record that is placed in the queue. A value of {@code false} means the + * {@link super#isCallerCalculationRequired()} will be used. + *

+ *

+ * Note that the caller information is only attempted to be calculated when the handler has not been activated. Once + * activated it's up to the {@linkplain #getHandlers() children handlers} to determine how the record is processed. + *

+ * + * @param callerCalculationRequired {@code true} if the {@linkplain ExtLogRecord#copyAll() caller information} + * should always be calculated before the record is being placed in the queue + */ + public void setCallerCalculationRequired(final boolean callerCalculationRequired) { + this.callerCalculationRequired = callerCalculationRequired; + } + + /** + * Indicates whether or not this handler has been activated. + * + * @return {@code true} if the handler has been activated, otherwise {@code false} + */ + public final boolean isActivated() { + return activated; + } + + private synchronized void activate() { + // Always attempt to drain the queue + ExtLogRecord record; + while ((record = logRecords.pollFirst()) != null) { + if (isEnabled() && isLoggable(record)) { + publishToChildren(record); + } + } + activated = true; + } + + private void publishToChildren(final ExtLogRecord record) { + for (Handler handler : handlers) { + handler.publish(record); + } + } +} \ No newline at end of file diff --git a/src/test/java/org/jboss/logmanager/handlers/DelayedHandlerTests.java b/src/test/java/org/jboss/logmanager/handlers/DelayedHandlerTests.java new file mode 100644 index 00000000..33b4e251 --- /dev/null +++ b/src/test/java/org/jboss/logmanager/handlers/DelayedHandlerTests.java @@ -0,0 +1,255 @@ +/* + * JBoss, Home of Professional Open Source. + * + * Copyright 2017 Red Hat, Inc., and individual contributors + * as indicated by the @author tags. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.jboss.logmanager.handlers; + +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; +import java.util.Random; +import java.util.UUID; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.logging.Logger; +import java.util.stream.Collectors; + +import org.jboss.logmanager.ExtHandler; +import org.jboss.logmanager.ExtLogRecord; +import org.jboss.logmanager.LogContext; +import org.jboss.logmanager.config.HandlerConfiguration; +import org.jboss.logmanager.config.LogContextConfiguration; +import org.junit.After; +import org.junit.Assert; +import org.junit.Test; +import org.wildfly.common.cpu.ProcessorInfo; + +/** + * @author James R. Perkins + */ +public class DelayedHandlerTests { + + private static final int ITERATIONS = Integer.parseInt(System.getProperty("org.jboss.bootstrap.test.iterations", "1000")); + + @After + public void cleanup() { + TestHandler.MESSAGES.clear(); + } + + @Test + public void testQueuedMessages() { + final LogContext logContext = LogContext.create(); + + final LogContextConfiguration logContextConfiguration = LogContextConfiguration.Factory.create(logContext); + final HandlerConfiguration delayedHandler = logContextConfiguration.addHandlerConfiguration( + null, DelayedHandler.class.getName(), "delayed-handler"); + logContextConfiguration.addLoggerConfiguration("").addHandlerName(delayedHandler.getName()); + logContextConfiguration.commit(); + + final Logger rootLogger = logContext.getLogger(""); + rootLogger.info("Test message 1"); + rootLogger.fine("Test message 2"); + + final Logger testLogger = logContext.getLogger(DelayedHandlerTests.class.getName()); + testLogger.warning("Test message 3"); + + final Logger randomLogger = logContext.getLogger("org.jboss.logmanager." + UUID.randomUUID()); + randomLogger.severe("Test message 4"); + + // Activate after some messages have been logged + final HandlerConfiguration handlerConfiguration = logContextConfiguration.addHandlerConfiguration( + null, TestHandler.class.getName(), "test-handler"); + delayedHandler.setHandlerNames(handlerConfiguration.getName()); + logContextConfiguration.commit(); + + + rootLogger.info("Test message 5"); + testLogger.severe("Test message 6"); + randomLogger.finest("Test message 7"); + + // The default root logger message is INFO so FINE and FINEST should not be logged + Assert.assertEquals(5, TestHandler.MESSAGES.size()); + + // Test the messages actually logged + Assert.assertEquals("Test message 1", TestHandler.MESSAGES.get(0).getFormattedMessage()); + Assert.assertEquals("Test message 3", TestHandler.MESSAGES.get(1).getFormattedMessage()); + Assert.assertEquals("Test message 4", TestHandler.MESSAGES.get(2).getFormattedMessage()); + Assert.assertEquals("Test message 5", TestHandler.MESSAGES.get(3).getFormattedMessage()); + Assert.assertEquals("Test message 6", TestHandler.MESSAGES.get(4).getFormattedMessage()); + } + + + @Test + public void testAllLoggedAfterActivation() throws Exception { + final ExecutorService service = createExecutor(); + final LogContext logContext = LogContext.create(); + + final DelayedHandler handler = new DelayedHandler(); + final Logger rootLogger = logContext.getLogger(""); + rootLogger.addHandler(handler); + + try { + for (int i = 0; i < ITERATIONS; i++) { + final int current = i; + service.submit(() -> rootLogger.info(Integer.toString(current))); + } + // Wait until all the messages have been logged before + service.shutdown(); + service.awaitTermination(5, TimeUnit.SECONDS); + handler.addHandler(new TestHandler()); + + // Test that all messages have been flushed to the handler + Assert.assertEquals(ITERATIONS, TestHandler.MESSAGES.size()); + + // Test that all messages have been flushed to the handler + final List missing = new ArrayList<>(ITERATIONS); + for (int i = 0; i < ITERATIONS; i++) { + missing.add(i); + } + + final List ints = TestHandler.MESSAGES.stream() + .map(extLogRecord -> Integer.parseInt(extLogRecord.getFormattedMessage())) + .collect(Collectors.toList()); + missing.removeAll(ints); + Collections.sort(missing); + Assert.assertEquals(String.format("Missing the following entries: %s", missing), ITERATIONS, TestHandler.MESSAGES.size()); + + } finally { + Assert.assertTrue(service.shutdownNow().isEmpty()); + } + } + + @Test + public void testAllLoggedMidActivation() throws Exception { + final ExecutorService service = createExecutor(); + final LogContext logContext = LogContext.create(); + + final DelayedHandler handler = new DelayedHandler(); + final Logger rootLogger = logContext.getLogger(""); + rootLogger.addHandler(handler); + final Random r = new Random(); + + try { + for (int i = 0; i < ITERATIONS; i++) { + final int current = i; + service.submit(() -> { + TimeUnit.MILLISECONDS.sleep(r.nextInt(15)); + rootLogger.info(Integer.toString(current)); + return null; + }); + } + // Wait for a short time to make sure some messages are logged before we activate + TimeUnit.MILLISECONDS.sleep(150L); + handler.addHandler(new TestHandler()); + // Wait until all the messages have been logged before + service.shutdown(); + service.awaitTermination(5, TimeUnit.SECONDS); + + // Test that all messages have been flushed to the handler + final List missing = new ArrayList<>(ITERATIONS); + for (int i = 0; i < ITERATIONS; i++) { + missing.add(i); + } + + final List ints = TestHandler.MESSAGES.stream() + .map(extLogRecord -> Integer.parseInt(extLogRecord.getFormattedMessage())) + .collect(Collectors.toList()); + missing.removeAll(ints); + Collections.sort(missing); + Assert.assertEquals(String.format("Missing the following entries: %s", missing), ITERATIONS, TestHandler.MESSAGES.size()); + + } finally { + Assert.assertTrue(service.shutdownNow().isEmpty()); + } + } + + @Test + public void testOrder() throws Exception { + final List expected = new ArrayList<>(ITERATIONS); + final ExecutorService service = createExecutor(); + final LogContext logContext = LogContext.create(); + + final DelayedHandler handler = new DelayedHandler(); + final Logger rootLogger = logContext.getLogger(""); + rootLogger.addHandler(handler); + final Random r = new Random(); + + try { + for (int i = 0; i < ITERATIONS; i++) { + final int current = i; + service.submit(() -> { + TimeUnit.MILLISECONDS.sleep(r.nextInt(15)); + final String msg = Integer.toString(current); + // Need to synchronize to ensure order of the logged messages and the expected messages + synchronized (expected) { + expected.add(msg); + rootLogger.info(msg); + } + return null; + }); + } + // Wait for a short time to make sure some messages are logged before we commit + TimeUnit.MILLISECONDS.sleep(150L); + handler.addHandler(new TestHandler()); + // Wait until all the messages have been logged before + service.shutdown(); + service.awaitTermination(5, TimeUnit.SECONDS); + + // Get the current messages from the handler + final List found = TestHandler.MESSAGES.stream() + .map(ExtLogRecord::getFormattedMessage) + .collect(Collectors.toList()); + final List missing = new ArrayList<>(expected); + missing.removeAll(found); + Assert.assertTrue("Missing the following entries: " + missing, missing.isEmpty()); + + // This shouldn't happen as the above should find it, but it's better to fail here than below. + Assert.assertEquals(expected.size(), TestHandler.MESSAGES.size()); + + // Now we need to test the order of what we have vs what is expected. These should be in the same order + for (int i = 0; i < expected.size(); i++) { + final String expectedMessage = expected.get(i); + final ExtLogRecord record = TestHandler.MESSAGES.get(i); + Assert.assertEquals(expectedMessage, record.getFormattedMessage()); + } + + } finally { + Assert.assertTrue(service.shutdownNow().isEmpty()); + } + } + + private static ExecutorService createExecutor() { + return Executors.newFixedThreadPool(ProcessorInfo.availableProcessors() * 2); + } + + public static class TestHandler extends ExtHandler { + static final List MESSAGES = new ArrayList<>(); + + @Override + protected synchronized void doPublish(final ExtLogRecord record) { + MESSAGES.add(record); + } + + @Override + public void close() throws SecurityException { + MESSAGES.clear(); + super.close(); + } + } +} \ No newline at end of file