You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Remko Popma (JIRA)" <ji...@apache.org> on 2015/10/22 19:27:28 UTC
[jira] [Issue Comment Deleted] (LOG4J2-493) Problem with
AsyncLogger when web app is deployed/undeployed multiple times
[ https://issues.apache.org/jira/browse/LOG4J2-493?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Remko Popma updated LOG4J2-493:
-------------------------------
Comment: was deleted
(was: {code}
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
index f9e707b..8c2dab5 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContext.java
@@ -35,24 +35,24 @@
public AsyncLoggerContext(final String name) {
super(name);
- helper = new AsyncLoggerHelper();
+ helper = new AsyncLoggerHelper(name);
}
public AsyncLoggerContext(final String name, final Object externalContext) {
super(name, externalContext);
- helper = new AsyncLoggerHelper();
+ helper = new AsyncLoggerHelper(name);
}
public AsyncLoggerContext(final String name, final Object externalContext,
final URI configLocn) {
super(name, externalContext, configLocn);
- helper = new AsyncLoggerHelper();
+ helper = new AsyncLoggerHelper(name);
}
public AsyncLoggerContext(final String name, final Object externalContext,
final String configLocn) {
super(name, externalContext, configLocn);
- helper = new AsyncLoggerHelper();
+ helper = new AsyncLoggerHelper(name);
}
@Override
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelector.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelector.java
index d2ee058..a82f615 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelector.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelector.java
@@ -23,6 +23,7 @@
import java.util.concurrent.ConcurrentMap;
import org.apache.logging.log4j.core.LoggerContext;
+import org.apache.logging.log4j.core.impl.ContextAnchor;
import org.apache.logging.log4j.core.selector.ContextSelector;
import org.apache.logging.log4j.core.util.Constants;
import org.apache.logging.log4j.util.PropertiesUtil;
@@ -47,15 +48,11 @@
@Override
public LoggerContext getContext(final String fqcn, final ClassLoader loader, final boolean currentContext) {
- // LOG4J2-666 ensure unique name across separate instances created by webapp classloaders
- final int hash = loader == null ? getClass().getClassLoader().hashCode() : loader.hashCode();
- final String key = "AsyncLoggerContext@" + Integer.toHexString(hash);
- AsyncLoggerContext result = contexts.get(key);
- if (result == null) {
- result = new AsyncLoggerContext(key);
- return contexts.putIfAbsent(key, result);
- }
- return result;
+ return getContext(fqcn, loader, currentContext, null);
+ }
+
+ private int hash(ClassLoader loader) {
+ return System.identityHashCode(loader);
}
@Override
@@ -66,10 +63,36 @@
@Override
public LoggerContext getContext(final String fqcn, final ClassLoader loader, final boolean currentContext,
final URI configLocation) {
- return getContext(fqcn, loader, currentContext);
+ if (currentContext) {
+ final LoggerContext ctx = ContextAnchor.THREAD_CONTEXT.get();
+ if (ctx != null) {
+ return ctx;
+ }
+ return getDefault(loader);
+ }
+ final String key = createKey(loader);
+ final AsyncLoggerContext existing = contexts.get(key);
+ if (existing != null) {
+ return existing;
+ }
+ final AsyncLoggerContext fresh = new AsyncLoggerContext(key);
+ final AsyncLoggerContext old = contexts.putIfAbsent(key, fresh);
+ return old == null ? fresh : old;
+ }
+
+ private String createKey(final ClassLoader loader) {
+ // LOG4J2-666 ensure unique name across separate instances created by webapp classloaders
+ final int hash = loader == null ? hash(getClass().getClassLoader()) : hash(loader);
+ final String key = "AsyncContext@" + Integer.toHexString(hash);
+ return key;
}
- @Override
+ private LoggerContext getDefault(final ClassLoader loader) {
+ // TODO Auto-generated method stub
+ return null;
+ }
+
+ @Override
public void removeContext(final LoggerContext context) {
contexts.remove(context.getName());
}
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerHelper.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerHelper.java
index 33a34e1..40712d4 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerHelper.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerHelper.java
@@ -54,11 +54,20 @@
private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024;
private static final StatusLogger LOGGER = StatusLogger.getLogger();
+ private final String contextName;
private ExecutorService executor;
private volatile Disruptor<RingBufferLogEvent> disruptor;
private volatile int count = 0;
- Disruptor<RingBufferLogEvent> getDisruptor() {
+ public AsyncLoggerHelper(String contextName) {
+ this.contextName = contextName;
+ }
+
+ public String getContextName() {
+ return contextName;
+ }
+
+ Disruptor<RingBufferLogEvent> getDisruptor() {
return disruptor;
}
@@ -75,13 +84,13 @@
private synchronized void initDisruptor() {
if (disruptor != null) {
- LOGGER.trace("AsyncLoggerHelper not starting new disruptor, using existing object. Ref count is {}.", count);
+ LOGGER.trace("[{}] AsyncLoggerHelper not starting new disruptor, using existing object. Ref count is {}.", contextName, count);
return;
}
- LOGGER.trace("AsyncLoggerHelper creating new disruptor. Ref count is {}.", count);
+ LOGGER.trace("[{}] AsyncLoggerHelper creating new disruptor. Ref count is {}.", contextName, count);
final int ringBufferSize = calculateRingBufferSize();
final WaitStrategy waitStrategy = createWaitStrategy();
- executor = Executors.newSingleThreadExecutor(new DaemonThreadFactory("AsyncLogger-"));
+ executor = Executors.newSingleThreadExecutor(new DaemonThreadFactory(contextName +"-Logger-"));
Info.initExecutorThreadInstance(executor);
disruptor = new Disruptor<>(RingBufferLogEvent.FACTORY, ringBufferSize, executor, ProducerType.MULTI,
@@ -91,7 +100,7 @@
final RingBufferLogEventHandler[] handlers = {new RingBufferLogEventHandler()};
disruptor.handleEventsWith(handlers);
- LOGGER.debug("Starting AsyncLogger disruptor with ringbuffer size {}...", disruptor.getRingBuffer()
+ LOGGER.debug("[{}] Starting AsyncLogger disruptor with ringbuffer size {}...", contextName, disruptor.getRingBuffer()
.getBufferSize());
disruptor.start();
}
@@ -104,19 +113,19 @@
int size = Integer.parseInt(userPreferredRBSize);
if (size < RINGBUFFER_MIN_SIZE) {
size = RINGBUFFER_MIN_SIZE;
- LOGGER.warn("Invalid RingBufferSize {}, using minimum size {}.", userPreferredRBSize,
+ LOGGER.warn("[{}] Invalid RingBufferSize {}, using minimum size {}.", contextName, userPreferredRBSize,
RINGBUFFER_MIN_SIZE);
}
ringBufferSize = size;
} catch (final Exception ex) {
- LOGGER.warn("Invalid RingBufferSize {}, using default size {}.", userPreferredRBSize, ringBufferSize);
+ LOGGER.warn("[{}] Invalid RingBufferSize {}, using default size {}.", contextName, userPreferredRBSize, ringBufferSize);
}
return Integers.ceilingNextPowerOfTwo(ringBufferSize);
}
private WaitStrategy createWaitStrategy() {
final String strategy = PropertiesUtil.getProperties().getStringProperty("AsyncLogger.WaitStrategy");
- LOGGER.debug("property AsyncLogger.WaitStrategy={}", strategy);
+ LOGGER.debug("[{}] property AsyncLogger.WaitStrategy={}", contextName, strategy);
if ("Sleep".equals(strategy)) {
return new SleepingWaitStrategy();
} else if ("Yield".equals(strategy)) {
@@ -124,24 +133,24 @@
} else if ("Block".equals(strategy)) {
return new BlockingWaitStrategy();
}
- LOGGER.debug("disruptor event handler uses BlockingWaitStrategy");
+ LOGGER.debug("[{}] disruptor event handler uses BlockingWaitStrategy", contextName);
return new BlockingWaitStrategy();
}
private ExceptionHandler<RingBufferLogEvent> getExceptionHandler() {
final String cls = PropertiesUtil.getProperties().getStringProperty("AsyncLogger.ExceptionHandler");
if (cls == null) {
- LOGGER.debug("No AsyncLogger.ExceptionHandler specified");
+ LOGGER.debug("[{}] No AsyncLogger.ExceptionHandler specified", contextName);
return null;
}
try {
@SuppressWarnings("unchecked")
final ExceptionHandler<RingBufferLogEvent> result = Loader
.newCheckedInstanceOf(cls, ExceptionHandler.class);
- LOGGER.debug("AsyncLogger.ExceptionHandler={}", result);
+ LOGGER.debug("[{}] AsyncLogger.ExceptionHandler={}", contextName, result);
return result;
} catch (final Exception ignored) {
- LOGGER.debug("AsyncLogger.ExceptionHandler not set: error creating " + cls + ": ", ignored);
+ LOGGER.debug("[{}] AsyncLogger.ExceptionHandler not set: error creating " + cls + ": ", contextName, ignored);
return null;
}
}
@@ -154,7 +163,7 @@
// was shut down, which could cause the publishEvent method to hang and never return.
disruptor.publishEvent(translator);
} catch (final NullPointerException npe) {
- LOGGER.fatal("Ignoring log event after log4j was shut down.");
+ LOGGER.fatal("[{}] Ignoring log event after log4j was shut down.", contextName);
}
}
@@ -174,17 +183,17 @@
*/
synchronized void stop() {
if (--count > 0) {
- LOGGER.trace("AsyncLoggerHelper: not shutting down disruptor: ref count is {}.", count);
+ LOGGER.trace("[{}] AsyncLoggerHelper: not shutting down disruptor: ref count is {}.", contextName, count);
return;
}
final Disruptor<RingBufferLogEvent> temp = getDisruptor();
if (temp == null) {
- LOGGER.trace("AsyncLoggerHelper: disruptor already shut down: ref count is {}. (Resetting to zero.)", count);
+ LOGGER.trace("[{}] AsyncLoggerHelper: disruptor already shut down: ref count is {}. (Resetting to zero.)", contextName, count);
count = 0; // ref count must not be negative or #claim() will not work correctly
return; // disruptor was already shut down by another thread
}
- LOGGER.debug("AsyncLoggerHelper: shutting down disruptor: ref count is {}.", count);
+ LOGGER.debug("[{}] AsyncLoggerHelper: shutting down disruptor: ref count is {}.", contextName, count);
// Must guarantee that publishing to the RingBuffer has stopped
// before we call disruptor.shutdown()
@@ -201,7 +210,7 @@
}
temp.shutdown(); // busy-spins until all events currently in the disruptor have been processed
- LOGGER.trace("AsyncLoggerHelper: shutting down disruptor executor.");
+ LOGGER.trace("[{}] AsyncLoggerHelper: shutting down disruptor executor.", contextName);
executor.shutdown(); // finally, kill the processor thread
executor = null;
// Info.THREADLOCAL.remove(); // LOG4J2-323
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelectorTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelectorTest.java
index 3bae290..46f0d0d 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelectorTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerContextSelectorTest.java
@@ -42,10 +42,17 @@
}
@Test
+ public void testLoggerContextsListInitiallyEmpty() {
+ final AsyncLoggerContextSelector selector = new AsyncLoggerContextSelector();
+ assertTrue(selector.getLoggerContexts().isEmpty());
+ }
+
+ @Test
public void testLoggerContextsReturnsAsyncLoggerContext() {
final AsyncLoggerContextSelector selector = new AsyncLoggerContextSelector();
+ selector.getContext(null, null, false);
+
final List<LoggerContext> list = selector.getLoggerContexts();
-
assertEquals(1, list.size());
assertTrue(list.get(0) instanceof AsyncLoggerContext);
}
@@ -54,7 +61,8 @@
public void testContextNameIsAsyncLoggerContextWithClassHashCode() {
final AsyncLoggerContextSelector selector = new AsyncLoggerContextSelector();
final LoggerContext context = selector.getContext(null, null, false);
- final String expectedContextName = "AsyncLoggerContext@" + Integer.toHexString(AsyncLoggerContext.class.hashCode());
+ final int hash = getClass().getClassLoader().hashCode();
+ final String expectedContextName = "AsyncLoggerContext@" + Integer.toHexString(hash);
assertEquals(expectedContextName, context.getName());
}
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/net/ssl/SslConfigurationTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/net/ssl/SslConfigurationTest.java
index 5283535..cf1f315 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/net/ssl/SslConfigurationTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/net/ssl/SslConfigurationTest.java
@@ -23,6 +23,7 @@
import javax.net.ssl.SSLSocketFactory;
import org.junit.Assert;
+import org.junit.Ignore;
import org.junit.Test;
public class SslConfigurationTest {
@@ -36,6 +37,7 @@
Assert.assertNotNull(factory);
}
+ @Ignore
@Test
public void emptyConfigurationHasDefaultTrustStore() throws IOException {
final SslConfiguration sc = SslConfiguration.createSSLConfiguration(null, null, null);
@@ -45,6 +47,7 @@
Assert.assertNotNull(clientSocket);
}
+ @Ignore
@Test
public void connectionFailsWithoutValidServerCertificate() throws IOException, StoreConfigurationException {
final TrustStoreConfiguration tsc = new TrustStoreConfiguration(TestConstants.TRUSTSTORE_FILE, null, null, null);
diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java
index dc222e7..1c7e1db 100644
--- a/log4j-core/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java
+++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/util/datetime/FixedDateFormatTest.java
@@ -19,6 +19,7 @@
import java.text.SimpleDateFormat;
import java.util.Date;
+import java.util.Locale;
import java.util.concurrent.TimeUnit;
import org.apache.logging.log4j.core.util.datetime.FixedDateFormat.FixedFormat;
@@ -138,7 +139,7 @@
final long start = now - TimeUnit.HOURS.toMillis(25);
final long end = now + TimeUnit.HOURS.toMillis(25);
for (final FixedFormat format : FixedFormat.values()) {
- final SimpleDateFormat simpleDF = new SimpleDateFormat(format.getPattern());
+ final SimpleDateFormat simpleDF = new SimpleDateFormat(format.getPattern(), Locale.getDefault());
final FixedDateFormat customTF = new FixedDateFormat(format);
for (long time = start; time < end; time += 12345) {
final String actual = customTF.format(time);
@@ -154,7 +155,7 @@
final long start = now - TimeUnit.HOURS.toMillis(25);
final long end = now + TimeUnit.HOURS.toMillis(25);
for (final FixedFormat format : FixedFormat.values()) {
- final SimpleDateFormat simpleDF = new SimpleDateFormat(format.getPattern());
+ final SimpleDateFormat simpleDF = new SimpleDateFormat(format.getPattern(), Locale.getDefault());
final FixedDateFormat customTF = new FixedDateFormat(format);
for (long time = end; time > start; time -= 12345) {
final String actual = customTF.format(time);
@@ -171,7 +172,7 @@
final long end = now + TimeUnit.HOURS.toMillis(25);
final char[] buffer = new char[128];
for (final FixedFormat format : FixedFormat.values()) {
- final SimpleDateFormat simpleDF = new SimpleDateFormat(format.getPattern());
+ final SimpleDateFormat simpleDF = new SimpleDateFormat(format.getPattern(), Locale.getDefault());
final FixedDateFormat customTF = new FixedDateFormat(format);
for (long time = start; time < end; time += 12345) {
final int length = customTF.format(time, buffer, 23);
@@ -189,7 +190,7 @@
final long end = now + TimeUnit.HOURS.toMillis(25);
final char[] buffer = new char[128];
for (final FixedFormat format : FixedFormat.values()) {
- final SimpleDateFormat simpleDF = new SimpleDateFormat(format.getPattern());
+ final SimpleDateFormat simpleDF = new SimpleDateFormat(format.getPattern(), Locale.getDefault());
final FixedDateFormat customTF = new FixedDateFormat(format);
for (long time = end; time > start; time -= 12345) {
final int length = customTF.format(time, buffer, 23);
diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ThreadLocalVsConcurrentHashMapBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ThreadLocalVsConcurrentHashMapBenchmark.java
new file mode 100644
index 0000000..9580968
--- /dev/null
+++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ThreadLocalVsConcurrentHashMapBenchmark.java
@@ -0,0 +1,93 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You 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.apache.logging.log4j.perf.jmh;
+
+import java.util.concurrent.ConcurrentHashMap;
+
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.Scope;
+import org.openjdk.jmh.annotations.State;
+
+/**
+ * Compares performance of ThreadLocal, vs ConcurrentHashMap<Thread, Object>.
+ */
+// ============================== HOW TO RUN THIS TEST: ====================================
+// (Quick build: mvn -DskipTests=true clean package -pl log4j-perf -am )
+//
+// single thread:
+// java -jar log4j-perf/target/benchmarks.jar ".*ThreadLocalVsConcurrentHashMap.*" -f 1 -wi 10 -i 20 -tu ns -bm sample
+//
+// four threads:
+// java -jar log4j-perf/target/benchmarks.jar ".*ThreadLocalVsConcurrentHashMap.*" -f 1 -wi 10 -i 20 -tu ns -bm sample -t 4
+//
+// Usage help:
+// java -jar log4j-perf/target/benchmarks.jar -help
+//
+@State(Scope.Benchmark)
+public class ThreadLocalVsConcurrentHashMapBenchmark {
+
+ private static final String VALUE = "value";
+ private static ConcurrentHashMap<Thread, StringBuilder> map = new ConcurrentHashMap<Thread, StringBuilder>();
+ private static ThreadLocal<StringBuilder> threadLocal = new ThreadLocal<>();
+
+ @Benchmark
+ public String newInstance() {
+ StringBuilder sb = getNew();
+ sb.append(VALUE);
+ return sb.toString();
+ }
+
+ @Benchmark
+ public String _stringThreadLocal() {
+ StringBuilder sb = getThreadLocal();
+ sb.append(VALUE);
+ return sb.toString();
+ }
+
+ @Benchmark
+ public String _concurrentHashMap() {
+ StringBuilder sb = getConcurrentMap();
+ sb.append(VALUE);
+ return sb.toString();
+ }
+
+ private StringBuilder getNew() {
+ final StringBuilder buf = new StringBuilder();
+ return buf;
+ }
+
+ private StringBuilder getThreadLocal() {
+ StringBuilder buf = threadLocal.get();
+ if (buf == null) {
+ buf = new StringBuilder();
+ threadLocal.set(buf);
+ }
+ buf.setLength(0);
+ return buf;
+ }
+
+ private StringBuilder getConcurrentMap() {
+ StringBuilder buf = map.get(Thread.currentThread());
+ if (buf == null) {
+ buf = new StringBuilder();
+ map.put(Thread.currentThread(), buf);
+ }
+ buf.setLength(0);
+ return buf;
+ }
+}
{code})
> Problem with AsyncLogger when web app is deployed/undeployed multiple times
> ---------------------------------------------------------------------------
>
> Key: LOG4J2-493
> URL: https://issues.apache.org/jira/browse/LOG4J2-493
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.0-beta9, 2.0-rc1
> Environment: tomcat 7.0.42
> Reporter: Kireet Reddy
> Assignee: Remko Popma
> Labels: Async
> Fix For: 2.5
>
>
> |_This ticket tracks Async Logger issues in Tomcat when making all loggers async with LoggerContextSelector system property. For Tomcat issues with AsyncRoot/AsyncLogger in the configuration file, see LOG4J2-323._|
> When redeploying my application in tomcat multiple times, I get an exception:
> {code}
> Exception in thread "Thread-29" java.lang.NullPointerException
> at org.apache.logging.log4j.core.async.AsyncLogger.stop(AsyncLogger.java:249)
> at org.apache.logging.log4j.core.async.AsyncLoggerContext.stop(AsyncLoggerContext.java:56)
> at org.apache.logging.log4j.core.LoggerContext$ShutdownThread.run(LoggerContext.java:437)
> {code}
> This seems to be due to the fact that some initialization code happens in the class initializer but is undone in the stop() method which is called during webapp undeployment. This causes issues because in this case the log4j jar is loaded by the shared classloader ($catalina.home/lib) rather than the webapp classloader. This means the AsyncLogger class is not re-created during webapp deployment.
> I am using this structure because I have many 3rd party libraries and want to keep redeployments lightweight.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org