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 > <mailto: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.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 <mailto: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 >>> <http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo> >>> Commit: >>> http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/2f8b6651 >>> <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 >>> <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 >>> <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 <mailto:rpo...@apache.org>> >>> Authored: Sat Jan 7 22:51:24 2017 +0900 >>> Committer: rpopma <rpo...@apache.org <mailto: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 >>> >>> <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 >>> >>> <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 >>> <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 <http://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 <http://log.info/>(threads.size()); >>> + try { >>> + for (int i = 0; i < 64; i++) { >>> + log.info <http://log.info/>("First message."); >>> + log.info <http://log.info/>("Second message."); >>> + } >>> + } finally { >>> + threads.remove(this); >>> + } >>> + } >>> + } >>> +} >>> >>> http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/2f8b6651/src/changes/changes.xml >>> >>> <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> >>> >>> >>
