I have created LOG4J2-3188 <https://issues.apache.org/jira/browse/LOG4J2-3188> for this issue.
On Fri, Nov 12, 2021 at 2:46 PM Volkan Yazıcı <[email protected]> wrote: > *[Note that the shared `ParallelRunTest` is a self-sufficient code, that > is, one can simply copy-paste it into a Log4j test and run it.]* > > When `ExecutionMode.SAME_THREAD` is used, everything works as expected: > > wc -l /tmp/ParallelRunTest-* > 1000 /tmp/ParallelRunTest-A.log > 1000 /tmp/ParallelRunTest-B.log > 1000 /tmp/ParallelRunTest-C.log > 1000 /tmp/ParallelRunTest-D.log > 4000 total > > for log_file in /tmp/ParallelRunTest-*; do > echo "file: $log_file" > echo "line lengths:" > awk "{print length}" $log_file | sort | uniq > echo "distinct lines:" > sort $log_file | uniq > echo > done > > file: /tmp/ParallelRunTest-A.log > line lengths: > 999 > distinct lines: > AAA...A > > file: /tmp/ParallelRunTest-B.log > line lengths: > 999 > distinct lines: > BBB...B > > file: /tmp/ParallelRunTest-C.log > line lengths: > 999 > distinct lines: > CCC...C > > file: /tmp/ParallelRunTest-D.log > line lengths: > 999 > distinct lines: > DDD...D > > When `ExecutionMode.CONCURRENT` is used, tests fail due to unexpected > `appenderFileLength`: > > wc -l /tmp/ParallelRunTest-* > 96 /tmp/ParallelRunTest-A.log > 1 /tmp/ParallelRunTest-B.log > 96 /tmp/ParallelRunTest-C.log > 3577 /tmp/ParallelRunTest-D.log > 3770 total > > for log_file in /tmp/ParallelRunTest-*; do > echo "file: $log_file" > echo "line lengths:" > awk "{print length}" $log_file | sort | uniq > echo "distinct lines:" > sort $log_file | uniq > echo > done > > file: /tmp/ParallelRunTest-A.log > line lengths: > 999 > distinct lines: > AAA...A > BBB...B > CCC...C > > file: /tmp/ParallelRunTest-B.log > line lengths: > 999 > distinct lines: > BBB...B > > file: /tmp/ParallelRunTest-C.log > line lengths: > 999 > distinct lines: > BBB...B > CCC...C > > file: /tmp/ParallelRunTest-D.log > line lengths: > 999 > distinct lines: > AAA...A > BBB...B > CCC...C > DDD...D > > Note that `AAA...A`, `BBB...B`, etc. snippets shared above are truncated > for display purposes, otherwise each line has 999 *_unscrambled_* > characters. > > Given 1) the total number of logged lines is less than 4000, 2) letters > are scattered between files, and 3) lines are not scrambled, I have the > feeling that produced `LogEvent`s either got lost or sent to wrong > appenders. > > On Fri, Nov 12, 2021 at 7:49 AM Remko Popma <[email protected]> wrote: > >> What do the generated files look like? >> Is the output that is generated in concurrent mode longer or shorter than >> the expected length? >> Also, does it contain one entry (one log message) per line, or is it >> scrambled? Are entries ordered by time? >> >> On Fri, Nov 12, 2021 at 12:34 AM Ralph Goers <[email protected]> >> wrote: >> >> > How does it fail? >> > >> > Ralph >> > >> > > On Nov 11, 2021, at 1:42 AM, Volkan Yazıcı <[email protected]> wrote: >> > > >> > > They sort of do exist, see JsonTemplateLayoutConcurrentEncodeTest >> > > < >> > >> https://github.com/apache/logging-log4j2/blob/release-2.x/log4j-layout-template-json/src/test/java/org/apache/logging/log4j/layout/template/json/JsonTemplateLayoutConcurrentEncodeTest.java#L58 >> > > >> > > . >> > > But I can add a dedicated test too. >> > > Nevertheless, I still wonder what the problem is. >> > > >> > > On Wed, Nov 10, 2021 at 9:15 PM Gary Gregory <[email protected]> >> > wrote: >> > > >> > >> Should this test be added to the repo with a TODO comment? >> > >> >> > >> Gary >> > >> >> > >> On Mon, Nov 8, 2021, 07:09 Volkan Yazıcı <[email protected]> >> > wrote: >> > >> >> > >>> Hello! Does anybody have an idea why the following test fails for >> > >>> CONCURRENT execution mode, whereas it works for SAME_THREAD? >> > >>> >> > >>> import org.apache.logging.log4j.Level; >> > >>> import org.apache.logging.log4j.Logger; >> > >>> import org.apache.logging.log4j.core.LoggerContext; >> > >>> import org.apache.logging.log4j.core.config.Configuration; >> > >>> import org.apache.logging.log4j.core.config.Configurator; >> > >>> import >> > >>> >> org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilder; >> > >>> import >> > >>> >> > >> >> > >> org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilderFactory; >> > >>> import org.apache.logging.log4j.util.Strings; >> > >>> import org.junit.jupiter.api.parallel.Execution; >> > >>> import org.junit.jupiter.api.parallel.ExecutionMode; >> > >>> import org.junit.jupiter.params.ParameterizedTest; >> > >>> import org.junit.jupiter.params.provider.ValueSource; >> > >>> >> > >>> import java.io.File; >> > >>> import java.nio.file.Paths; >> > >>> >> > >>> import static org.assertj.core.api.Assertions.assertThat; >> > >>> >> > >>> @Execution(ExecutionMode.SAME_THREAD) >> > >>> class ParallelRunTest { >> > >>> >> > >>> @ParameterizedTest >> > >>> @ValueSource(chars = {'A', 'B', 'C', 'D'}) >> > >>> void test(final char letter) { >> > >>> >> > >>> // Create the configuration builder. >> > >>> final ConfigurationBuilder<?> configBuilder = >> > >>> ConfigurationBuilderFactory >> > >>> .newConfigurationBuilder() >> > >>> .setStatusLevel(Level.ERROR) >> > >>> .setConfigurationName("Letter-" + letter); >> > >>> >> > >>> // Create the configuration. >> > >>> final String appenderName = "File"; >> > >>> final String appenderFilepath = Paths >> > >>> .get( >> > >>> System.getProperty("java.io.tmpdir"), >> > >>> "ParallelRunTest-" + letter + ".log") >> > >>> .toAbsolutePath() >> > >>> .toString(); >> > >>> final Configuration config = configBuilder >> > >>> .add(configBuilder >> > >>> .newAppender(appenderName, "File") >> > >>> .addAttribute("fileName", appenderFilepath) >> > >>> .addAttribute("append", false) >> > >>> .addAttribute("immediateFlush", false) >> > >>> .addAttribute("ignoreExceptions", false) >> > >>> .add(configBuilder >> > >>> .newLayout("PatternLayout") >> > >>> .addAttribute("pattern", "%m\n"))) >> > >>> .add(configBuilder >> > >>> .newRootLogger(Level.ALL) >> > >>> >> > .add(configBuilder.newAppenderRef(appenderName))) >> > >>> .build(false); >> > >>> >> > >>> // Initialize the configuration. >> > >>> try (final LoggerContext loggerContext = >> > >>> Configurator.initialize(config)) { >> > >>> final Logger logger = >> > >>> loggerContext.getLogger(ParallelRunTest.class); >> > >>> >> > >>> // Write logs. >> > >>> final String message = >> > Strings.repeat(String.valueOf(letter), >> > >>> 999); >> > >>> for (int i = 0; i < 1_000; i++) { >> > >>> logger.info(message); >> > >>> } >> > >>> >> > >>> } >> > >>> >> > >>> // Verify the file content. >> > >>> final long appenderFileLength = new >> > >>> File(appenderFilepath).length(); >> > >>> assertThat(appenderFileLength).isEqualTo(1_000_000L); >> > >>> >> > >>> } >> > >>> >> > >>> } >> > >>> >> > >> >> > >> > >> > >> >
