ConcurrentLoggingWithJsonLayoutTest is failing for me. I don’t understand why.
2017-01-09 21:41:06,174 main DEBUG Starting
LoggerContext[name=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest]
from configuration at log4j2-json-layout.xml
2017-01-09 21:41:06,176 main DEBUG Starting
LoggerContext[name=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest,
org.apache.logging.log4j.core.LoggerContext@14acaea5] with configuration
XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml]...
2017-01-09 21:41:06,177 main DEBUG Shutdown hook enabled. Registering a new one.
2017-01-09 21:41:06,187 main DEBUG Initializing configuration
XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml]
2017-01-09 21:41:06,193 main DEBUG Installed script engines
2017-01-09 21:41:06,208 main DEBUG Groovy Scripting Engine Version: 2.0,
Language: Groovy, Threading: MULTITHREADED, Compile: true, Names: {groovy,
Groovy}
2017-01-09 21:41:06,499 main DEBUG Oracle Nashorn Version: 1.8.0_65, Language:
ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn,
Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
2017-01-09 21:41:06,538 main DEBUG BeanShell Engine Version: 1.0, Language:
BeanShell, Threading: MULTITHREADED, Compile: true, Names: {beanshell, bsh,
java}
2017-01-09 21:41:06,539 main DEBUG PluginManager 'Core' found 121 plugins
2017-01-09 21:41:06,539 main DEBUG PluginManager 'Level' found 1 plugins
2017-01-09 21:41:06,543 main DEBUG PluginManager 'Lookup' found 13 plugins
2017-01-09 21:41:06,545 main DEBUG Building Plugin[name=layout,
class=org.apache.logging.log4j.core.layout.JsonLayout].
2017-01-09 21:41:06,556 main DEBUG PluginManager 'TypeConverter' found 26
plugins
2017-01-09 21:41:06,575 main DEBUG JsonLayout$Builder(locationInfo="null",
properties="null", propertiesAsList="null", includeStacktrace="null",
eventEol="true", compact="true", complete="null", charset="null",
footerSerializer=null, headerSerializer=null,
Configuration(/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml),
footer="null", header="null")
2017-01-09 21:41:06,710 main DEBUG PluginManager 'Converter' found 41 plugins
2017-01-09 21:41:06,710 main DEBUG Building Plugin[name=appender,
class=org.apache.logging.log4j.core.appender.FileAppender].
2017-01-09 21:41:06,718 main DEBUG
FileAppender$Builder(fileName="target/test-json-layout.log", append="false",
locking="null", advertise="null", advertiseUri="null", createOnDemand="null",
bufferedIo="null", bufferSize="null", immediateFlush="null",
ignoreExceptions="false",
JsonLayout(org.apache.logging.log4j.core.layout.JsonLayout@37654521),
name="stdout",
Configuration(/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml),
Filter=null)
2017-01-09 21:41:06,719 main DEBUG Starting FileManager
target/test-json-layout.log
2017-01-09 21:41:06,720 main DEBUG Building Plugin[name=appenders,
class=org.apache.logging.log4j.core.config.AppendersPlugin].
2017-01-09 21:41:06,721 main DEBUG createAppenders(={stdout})
2017-01-09 21:41:06,722 main DEBUG Building Plugin[name=AppenderRef,
class=org.apache.logging.log4j.core.config.AppenderRef].
2017-01-09 21:41:06,725 main DEBUG createAppenderRef(ref="stdout",
level="null", Filter=null)
2017-01-09 21:41:06,726 main DEBUG Building Plugin[name=root,
class=org.apache.logging.log4j.core.config.LoggerConfig$RootLogger].
2017-01-09 21:41:06,727 main DEBUG createLogger(additivity="null",
level="INFO", includeLocation="null", ={stdout}, ={},
Configuration(/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml),
Filter=null)
2017-01-09 21:41:06,729 main DEBUG Building Plugin[name=loggers,
class=org.apache.logging.log4j.core.config.LoggersPlugin].
2017-01-09 21:41:06,729 main DEBUG createLoggers(={root})
2017-01-09 21:41:06,730 main DEBUG Configuration
XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml]
initialized
2017-01-09 21:41:06,730 main DEBUG Starting configuration
XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml]
2017-01-09 21:41:06,731 main DEBUG Started configuration
XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml]
OK.
2017-01-09 21:41:06,732 main DEBUG Shutting down OutputStreamManager
SYSTEM_OUT.false.false-1
2017-01-09 21:41:06,732 main DEBUG Shut down OutputStreamManager
SYSTEM_OUT.false.false-1, all resources released: true
2017-01-09 21:41:06,732 main DEBUG Stopped
org.apache.logging.log4j.core.config.DefaultConfiguration@66d2e7d9 OK
2017-01-09 21:41:06,784 main DEBUG Registering MBean
org.apache.logging.log4j2:type=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest
2017-01-09 21:41:06,786 main DEBUG Registering MBean
org.apache.logging.log4j2:type=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest,component=StatusLogger
2017-01-09 21:41:06,787 main DEBUG Registering MBean
org.apache.logging.log4j2:type=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest,component=ContextSelector
2017-01-09 21:41:06,789 main DEBUG Registering MBean
org.apache.logging.log4j2:type=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest,component=Loggers,name=
2017-01-09 21:41:06,790 main DEBUG Registering MBean
org.apache.logging.log4j2:type=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest,component=Appenders,name=stdout
2017-01-09 21:41:06,791 main DEBUG
LoggerContext[name=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest,
org.apache.logging.log4j.core.LoggerContext@14acaea5] started OK with
configuration
XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml].
Running org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest
2017-01-09 21:41:06,976 main DEBUG Stopping
LoggerContext[name=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest,
org.apache.logging.log4j.core.LoggerContext@14acaea5]...
2017-01-09 21:41:06,978 main DEBUG Shutting down FileManager
target/test-json-layout.log
2017-01-09 21:41:06,980 main DEBUG Shut down FileManager
target/test-json-layout.log, all resources released: true
2017-01-09 21:41:06,980 main DEBUG Stopped
XmlConfiguration[location=/Users/rgoers/projects/apache/logging/log4j/log4j2/current/log4j-core/target/test-classes/log4j2-json-layout.xml]
OK
2017-01-09 21:41:06,981 main DEBUG Stopped
LoggerContext[name=org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest,
org.apache.logging.log4j.core.LoggerContext@14acaea5]...
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 0.187 sec <<<
FAILURE! - in
org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest
testConcurrentLogging(org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest)
Time elapsed: 0.182 sec <<< ERROR!
java.nio.file.NoSuchFileException: target/test-json-layout.log
at
org.apache.logging.log4j.core.layout.ConcurrentLoggingWithJsonLayoutTest.testConcurrentLogging(ConcurrentLoggingWithJsonLayoutTest.java:86)
Results :
Tests in error:
ConcurrentLoggingWithJsonLayoutTest.testConcurrentLogging:86 » NoSuchFile
targ...
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0
Ralph
> On Jan 7, 2017, at 6:51 AM, rpo...@apache.org wrote:
>
> Repository: logging-log4j2
> Updated Branches:
> refs/heads/master 9397da66f -> 34a41236f
>
>
> Fixed concurrency issue affecting all layouts except PatternLayout and
> GelfLayout, which caused scrambled output and exceptions when logging
> synchronously from multiple threads.
>
>
> Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
> Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/2f8b6651
> Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/2f8b6651
> Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/2f8b6651
>
> Branch: refs/heads/master
> Commit: 2f8b66510747a1d485cfd3597ea34c9071e1384a
> Parents: 0bca4ca
> Author: rpopma <rpo...@apache.org>
> Authored: Sat Jan 7 22:51:24 2017 +0900
> Committer: rpopma <rpo...@apache.org>
> Committed: Sat Jan 7 22:51:24 2017 +0900
>
> ----------------------------------------------------------------------
> .../log4j/core/layout/AbstractLayout.java | 24 ++--
> .../ConcurrentLoggingWithJsonLayoutTest.java | 115 +++++++++++++++++++
> src/changes/changes.xml | 3 +
> 3 files changed, 131 insertions(+), 11 deletions(-)
> ----------------------------------------------------------------------
>
>
> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/2f8b6651/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/AbstractLayout.java
> ----------------------------------------------------------------------
> diff --git
> a/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/AbstractLayout.java
>
> b/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/AbstractLayout.java
> index e1e419d..393f8c1 100644
> ---
> a/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/AbstractLayout.java
> +++
> b/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/AbstractLayout.java
> @@ -49,7 +49,7 @@ public abstract class AbstractLayout<T extends
> Serializable> implements Layout<T
>
> @PluginBuilderAttribute
> private byte[] footer;
> -
> +
> @PluginBuilderAttribute
> private byte[] header;
>
> @@ -222,15 +222,17 @@ public abstract class AbstractLayout<T extends
> Serializable> implements Layout<T
> */
> public static void writeTo(final byte[] data, int offset, int length,
> final ByteBufferDestination destination) {
> int chunk = 0;
> - ByteBuffer buffer = destination.getByteBuffer();
> - do {
> - if (length > buffer.remaining()) {
> - buffer = destination.drain(buffer);
> - }
> - chunk = Math.min(length, buffer.remaining());
> - buffer.put(data, offset, chunk);
> - offset += chunk;
> - length -= chunk;
> - } while (length > 0);
> + synchronized (destination) {
> + ByteBuffer buffer = destination.getByteBuffer();
> + do {
> + if (length > buffer.remaining()) {
> + buffer = destination.drain(buffer);
> + }
> + chunk = Math.min(length, buffer.remaining());
> + buffer.put(data, offset, chunk);
> + offset += chunk;
> + length -= chunk;
> + } while (length > 0);
> + }
> }
> }
>
> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/2f8b6651/log4j-core/src/test/java/org/apache/logging/log4j/core/layout/ConcurrentLoggingWithJsonLayoutTest.java
> ----------------------------------------------------------------------
> diff --git
> a/log4j-core/src/test/java/org/apache/logging/log4j/core/layout/ConcurrentLoggingWithJsonLayoutTest.java
>
> b/log4j-core/src/test/java/org/apache/logging/log4j/core/layout/ConcurrentLoggingWithJsonLayoutTest.java
> new file mode 100644
> index 0000000..7b4bb4c
> --- /dev/null
> +++
> b/log4j-core/src/test/java/org/apache/logging/log4j/core/layout/ConcurrentLoggingWithJsonLayoutTest.java
> @@ -0,0 +1,115 @@
> +/*
> + * 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.core.layout;
> +
> +import java.io.File;
> +import java.nio.charset.Charset;
> +import java.nio.file.Files;
> +import java.nio.file.Paths;
> +import java.util.ArrayList;
> +import java.util.Collections;
> +import java.util.HashSet;
> +import java.util.List;
> +import java.util.Set;
> +
> +import org.apache.logging.log4j.Logger;
> +import org.apache.logging.log4j.junit.LoggerContextRule;
> +import org.junit.Before;
> +import org.junit.ClassRule;
> +import org.junit.Test;
> +
> +import static org.hamcrest.CoreMatchers.*;
> +
> +import static org.junit.Assert.*;
> +
> +/**
> + * Test for LOG4J2-1769.
> + *
> + * @since 2.8
> + */
> +public class ConcurrentLoggingWithJsonLayoutTest {
> + @ClassRule
> + public static LoggerContextRule context = new
> LoggerContextRule("log4j2-json-layout.xml");
> + private static final String PATH = "target/test-json-layout.log";
> +
> + @Before
> + public void before() {
> + new File(PATH).delete();
> + }
> +
> + @Test
> + public void testConcurrentLogging() throws Throwable {
> + final Logger log =
> context.getLogger(ConcurrentLoggingWithJsonLayoutTest.class);
> + final Set<Thread> threads = Collections.synchronizedSet(new
> HashSet<Thread>());
> + final List<Throwable> thrown = Collections.synchronizedList(new
> ArrayList<Throwable>());
> +
> + for (int x = 0; x < Runtime.getRuntime().availableProcessors() * 2;
> x++) {
> + final Thread t = new LoggingThread(threads, log);
> + threads.add(t);
> +
> + // Appender is configured with ignoreExceptions="false";
> + // any exceptions are propagated to the caller, so we can catch
> them here.
> + t.setUncaughtExceptionHandler(new
> Thread.UncaughtExceptionHandler() {
> + @Override
> + public void uncaughtException(final Thread t, final
> Throwable e) {
> + thrown.add(e);
> + }
> + });
> + t.start();
> + }
> +
> + while (!threads.isEmpty()) {
> + log.info("not done going to sleep...");
> + Thread.sleep(10);
> + }
> +
> + // if any error occurred, fail this test
> + if (!thrown.isEmpty()) {
> + throw thrown.get(0);
> + }
> +
> + // simple test to ensure content is not corrupted
> + final List<String> lines = Files.readAllLines(Paths.get(PATH),
> Charset.defaultCharset());
> + for (final String line : lines) {
> + assertThat(line, startsWith("{\"timeMillis\":"));
> + assertThat(line, endsWith("\"threadPriority\":5}"));
> + }
> + }
> +
> + private class LoggingThread extends Thread {
> + private final Set<Thread> threads;
> + private final Logger log;
> +
> + LoggingThread(final Set<Thread> threads, final Logger log) {
> + this.threads = threads;
> + this.log = log;
> + }
> +
> + @Override
> + public void run() {
> + log.info(threads.size());
> + try {
> + for (int i = 0; i < 64; i++) {
> + log.info("First message.");
> + log.info("Second message.");
> + }
> + } finally {
> + threads.remove(this);
> + }
> + }
> + }
> +}
>
> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/2f8b6651/src/changes/changes.xml
> ----------------------------------------------------------------------
> diff --git a/src/changes/changes.xml b/src/changes/changes.xml
> index bfefc24..789882c 100644
> --- a/src/changes/changes.xml
> +++ b/src/changes/changes.xml
> @@ -24,6 +24,9 @@
> </properties>
> <body>
> <release version="2.8" date="2017-MM-DD" description="GA Release 2.8">
> + <action issue="LOG4J2-1769" dev="rpopma" type="fix" due-to="Brandon
> Goodin">
> + Fixed concurrency issue affecting all layouts except PatternLayout
> and GelfLayout, which caused scrambled output and exceptions when logging
> synchronously from multiple threads.
> + </action>
> <action issue="LOG4J2-1724" dev="mikes" type="fix" due-to="Alexander K">
> Using variables in GelfLayout's additional fields at runtime.
> </action>
>
>
