Ouch! Thank you!
On Wed, Jan 11, 2017 at 12:16 AM, Apache <ralph.go...@dslextreme.com> wrote:
> Yes, it passes on your Windows machine.
>
> The test was creating the LoggerContext and configuration before the
> @Before code is run. The before method attempts to delete the file. On
> Windows that will fail because the file is open. On unix the file’s
> directory entry will be deleted but the file output stream continues to be
> valid and can be written to but there is no way to access it.
>
> I changed the @Before method to be an @AfterClass method and the problem
> is resolved.
>
> Ralph
>
> On Jan 9, 2017, at 11:37 PM, Remko Popma <remko.po...@gmail.com> wrote:
>
> Sorry. I haven't been able to fix this.
> It passes on my Windows machine.
>
> It has something to do with the path of the log file, I don't understand
> why target/test-json-layout.log can't be found on unix systems...
> I'm thinking to just comment out that part of the test...
>
> Sent from my iPhone
>
> On Jan 10, 2017, at 13:42, Apache <ralph.go...@dslextreme.com> wrote:
>
> 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.ConcurrentLoggingWithJsonLayou
> tTest.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>
>
>
>
>
>
