Logging broken for status command

Search first

[X] I searched and no similar issues were found

Description

Trying to use slf4j with log4j logging in java application which uses liquibase. Using jul-to-slf4j for redirecting liquibase logging to slf4j The logging is working fine for other commands and I can see proper logs in the file but output corresponding to status command is missing from the log file which is indicating issue in the status command logging.

Output in console:

2024-07-28 18:09:59,550 +0000 [pool-2-thread-1] INFO  (StatusCheckScheduledExecutorService.java:28) - Executing status check command
2024-07-28 18:09:59,591 +0000 [pool-2-thread-1] INFO  (JavaLogger.java:37) - Set default schema name to public
2024-07-28 18:09:59,657 +0000 [pool-2-thread-1] INFO  (JavaLogger.java:37) - Reading from public.databasechangelog
1 changeset has not been applied to <user>@jdbc:postgresql://<ip:port>/rangerkms
     kms/db/v1/sleep.xml::6_sleep::fateh
2024-07-28 18:09:59,670 +0000 [pool-2-thread-1] INFO  (JavaLogger.java:37) - Command execution complete
2024-07-28 18:09:59,671 +0000 [pool-2-thread-1] INFO  (StatusCheckScheduledExecutorService.java:31) - statusCheckResult={}

Output in log file:

2024-07-28 18:09:59,550 +0000 [pool-2-thread-1] INFO  (StatusCheckScheduledExecutorService.java:28) - Executing status check command
2024-07-28 18:09:59,591 +0000 [pool-2-thread-1] INFO  (JavaLogger.java:37) - Set default schema name to public
2024-07-28 18:09:59,657 +0000 [pool-2-thread-1] INFO  (JavaLogger.java:37) - Reading from public.databasechangelog
2024-07-28 18:09:59,670 +0000 [pool-2-thread-1] INFO  (JavaLogger.java:37) - Command execution complete
2024-07-28 18:09:59,671 +0000 [pool-2-thread-1] INFO  (StatusCheckScheduledExecutorService.java:31) - statusCheckResult={}

The missing log line in the log file:

1 changeset has not been applied to <user>@jdbc:postgresql://<ip:port>/rangerkms
     kms/db/v1/sleep.xml::6_sleep::fateh

Steps To Reproduce

Pom dependencies for logging: `

org.slf4j slf4j-api ${slf4j.version}

    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-slf4j-impl</artifactId>
        <version>${log4j2.version}</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jul-to-slf4j</artifactId>
        <version>${slf4j.version}</version>
    </dependency>

1.7.30</slf4j.version> 2.18.0</log4j2.version>`

Log4j properties file:

# Define the File File Appender
appender.file.type = File
appender.file.name = FileAppender
appender.file.fileName = /logs/database-upgrade-${date:yyyy-MM-dd_HH-mm-ss}.log
appender.file.layout.type = PatternLayout
appender.file.layout.pattern = %d %d{Z} [%t] %-5p (%F:%L) - %m%n

# Define the Console Appender
appender.console.type = Console
appender.console.name = ConsoleAppender
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %d %d{Z} [%t] %-5p (%F:%L) - %m%n

# Define Loggers
loggers = console, file

logger.console.name = ConsoleLogger
logger.console.level = info
logger.console.additivity = false
logger.console.appenderRef.console.ref = ConsoleAppender

logger.file.name = FileLogger
logger.file.level = info
logger.file.additivity = false
logger.file.appenderRef.file.ref = FileAppender

# Define Root Logger
rootLogger.level = info
rootLogger.appenderRefs = console, file
rootLogger.appenderRef.console.ref = ConsoleAppender
rootLogger.appenderRef.file.ref = FileAppender

Rest of the setup is similar to https://github.com/liquibase/liquibase/issues/6009 except that previously I was using System.out.println but now I am trying to use sl4fj logging

static {
    // Liquibase logs to java.util.logging
    // Below statements ensures that the jul-to-slf4j binding works properly

    // Remove existing handlers attached to j.u.l root logger
    SLF4JBridgeHandler.removeHandlersForRootLogger();
    // Bridge j.u.l logging to SLF4J
    SLF4JBridgeHandler.install();
  }

Expected/Desired Behavior

As one can see in the log file output that JUL are properly redirected to slf4j and many liquibase logs can be seen being redirected properly so the setup seems to be proper. The issue seems to be only in case of status command whose output is not re-directed to slf4j / log4j properly. I would expect logging to be consistent for all commands

Liquibase Version

4.26.0

Database Vendor & Version

No response

Liquibase Integration

Java application (mvn)

Liquibase Extensions

No response

OS and/or Infrastructure Type/Provider

No response

Additional Context

No response

Are you willing to submit a PR?

[ ] I'm willing to submit a PR (Thank you!)

Hi @fateh288,

Could you please specify how you are executing status command? Are you doing it through Liquibase API?

Thanks, Daniel.

Hi @MalloD12 Thanks for your response I am using Liquibase CommandScope Java API for running status command For additional details you can review the setup I used in https://github.com/liquibase/liquibase/issues/6009 - previously here I was using System.out.println, now I am using proper logging

Following is a part of the driver code used to run status command I am pasting here for easy reference

  public static CommandResults executeLiquibaseCommand(
      String commandName,
      String url,
      String username,
      String password,
      String driver,
      HashMap<String,Object> commandSpecificArguments
  ) throws CommandExecutionException {
    CommandScope commandScope = new CommandScope(commandName);
    commandScope.addArgumentValue("url", url);
    commandScope.addArgumentValue("username", username);
    commandScope.addArgumentValue("password", password);
    commandScope.addArgumentValue("driver", driver);
    for (String argumentName : commandSpecificArguments.keySet()){
      commandScope.addArgumentValue(argumentName, commandSpecificArguments.get(argumentName));
    }
    return commandScope.execute();
  }

  public void startStatusChecks() {
    stopStatusChecks();
    HashMap<String, Object> statusParams = new HashMap<>();
    statusParams.put("changelogFile", changelogFilename);
    final Runnable liquibaseStatusCommand = () -> {
      System.out.println("Executing status check command");
      try {
        CommandResults statusCheckResult =
            executeLiquibaseCommand("status", url, username, password,
                driver, statusParams);
            System.out.println("statusCheckResult=" + statusCheckResult.getResults());
      } catch (Exception e) {
        stopStatusChecks();
        throw new RuntimeException(e);
      }
    };
    System.out.println("Starting status check scheduler");
    statusHandler = scheduler.scheduleWithFixedDelay(liquibaseStatusCommand, 0, 30, SECONDS);
  }

Hey @fateh288,

What's missing here is that for status command if you want to print command output using a logger you need to save the output command in a stream and then print this with your logger. Below a similar example than yours:

private static OutputStream output = new ByteArrayOutputStream();
    public static CommandResults executeLiquibaseCommand(
            String commandName,
            String url,
            String username,
            String password,
            String driver,
            HashMap<String,Object> commandSpecificArguments
    ) throws CommandExecutionException {
        CommandScope commandScope = new CommandScope(commandName);
        commandScope.addArgumentValue("url", url);
        commandScope.addArgumentValue("username", username);
        commandScope.addArgumentValue("password", password);
        commandScope.addArgumentValue("driver", driver);
        commandScope.setOutput(output);
        for (String argumentName : commandSpecificArguments.keySet()){
            commandScope.addArgumentValue(argumentName, commandSpecificArguments.get(argumentName));
        }
        return commandScope.execute();
    }

    public static void main(String[] args) {
        HashMap<String, Object> statusParams = new HashMap<>();
        statusParams.put("changelogFile", "no-tagDatabase-changelog.xml");
        System.out.println("Executing status check command");
        try {
            CommandResults statusCheckResult =
                    executeLiquibaseCommand("status", "jdbc:postgresql://localhost:5438/lbcat", <DB_USER>, <DB_PASSWORD>,
                            "org.postgresql.Driver", statusParams);
            System.out.println("statusCheckResult=" + output);
        } catch (Exception e) {
            throw new RuntimeException(e);
        }
    }

And this will log your output in this way:

statusCheckResult=2 changesets have not been applied to postgres@jdbc:postgresql://localhost:5438/lbcat
     no-tagDatabase-changelog.xml::1::nvoxland
     no-tagDatabase-changelog.xml::2::nvoxland

I hope it helps, if it doesn't please let us know.

cc: @tati-qalified

Thanks, Daniel.

Probably related to #6191

liquibase / liquibase