Skip to content

Timing-Bug when logging once and a possible workaround #8775

@JamesBoon

Description

@JamesBoon

Running any command that contains only one log statement, the output might get lost.
To illustrate this, I'll be using the check command, but it can happen with all commands.

I could not track down the bug, but at least found a workaround, which would require a one-line addition to DefaultLoggingFactory.

Here is a test class I wrote, feel free to use or alter it as you wish:

CheckCommandTest.java
package com.example;

import io.dropwizard.core.Application;
import io.dropwizard.core.Configuration;
import io.dropwizard.core.cli.CheckCommand;
import io.dropwizard.core.cli.Cli;
import io.dropwizard.core.setup.Bootstrap;
import io.dropwizard.core.setup.Environment;
import io.dropwizard.util.JarLocation;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.RepeatedTest;
import org.junit.jupiter.api.io.TempDir;

import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.PrintStream;
import java.nio.file.Files;
import java.nio.file.Path;

import static org.assertj.core.api.Assertions.assertThat;

class CheckCommandTest {

    @TempDir
    private static Path tempDir;
    private static Path confiYml;

    private static class MyApplication extends Application<Configuration> {
        @Override
        public void run(Configuration configuration, Environment environment) throws Exception {
        }
    }

    private final MyApplication application = new MyApplication();
    private final JarLocation location = new JarLocation(MyApplication.class);
    private final CheckCommand<Configuration> command = new CheckCommand<>(application);

    @BeforeAll
    static void beforeAll() throws IOException {
        String config = """
                logging:
                  appenders:
                    - type: console
                      logFormat: "%msg"
                """;

        confiYml = tempDir.resolve("config.yml");
        Files.writeString(confiYml, config);
    }

    @RepeatedTest(100)
    void shouldWriteToStdOut() {
        PrintStream originalOut = System.out;
        ByteArrayOutputStream stdOut = new ByteArrayOutputStream();
        System.setOut(new PrintStream(stdOut));

        Bootstrap<Configuration> bootstrap = new Bootstrap<>(application);
        bootstrap.addCommand(command);

        Cli cli = new Cli(location, bootstrap, stdOut, System.err);
        cli.run("check", confiYml.toAbsolutePath().toString());

        assertThat(stdOut.toString())
                .isEqualTo("Configuration is OK");

        System.setOut(originalOut);
    }

}

Running this, I get around ~60 failed and only 40 passed tests.
I have tested this with the Dropwizard 4, Eclipse Temurin 11 and 17 on Linux (Ubuntu 20).
This might be a Linux problem. Could anyone confirm this on any other platform?

After digging through the Dropwizard code, I found a workaround:
If you add a tiny sleep to DefaultLoggingFactory.flushAppender(...), all tests pass.
Thus, if adding Thread.sleep(10); here, before the while loop starts.

Do you think this workaround might be a valid addition?

Metadata

Metadata

Assignees

No one assigned

    Labels

    staleStale issue or pull request which will be closed soon

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions