[jira] [Closed] (LOG4J2-3188) Concurrent individual LoggerContext initializations cause severe LogEvent drop or incorrect delivery

["Volkan Yazici (Jira)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/LOG4J2-3188?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Volkan Yazici closed LOG4J2-3188.
---------------------------------
      Assignee: Volkan Yazici
    Resolution: Not A Problem

> Concurrent individual LoggerContext initializations cause severe LogEvent drop or incorrect delivery
> ----------------------------------------------------------------------------------------------------
>
>                 Key: LOG4J2-3188
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-3188
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>            Reporter: Volkan Yazici
>            Assignee: Volkan Yazici
>            Priority: Major
>
> When multiple {{LoggerContext}}'s get initialized concurrently, they affect each other causing severe {{LogEvent}} drop and incorrect delivery. Consider the following test:
> {code:java}
> @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);
>     }
> }
> {code}
> Above test, given a {{letter}}, creates a {{ParallelRunTest-<letter>.log}} file, and writes 999 times that letter to each line (ending with a line-feed character) for 1,000 lines. The eventual file is expected to be of size {{lineLength * lineCount = 1,000 * 1,000 = 1e6}}. These assumptions indeed hold after a run:
> {code}
> 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
> {code}
> Though when {{ExecutionMode.SAME_THREAD}} is replaced with {{ExecutionMode.CONCURRENT}} tests fail due to unexpected {{appenderFileLength}}:
> {code}
> 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
> {code}
> 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.



--
This message was sent by Atlassian Jira
(v8.20.10#820010)