Improve update summary usability

[EvaristeGalois11]

Impact

• Bug fix (non-breaking change which fixes expected existing functionality)
• Enhancement/New feature (adds functionality without impacting existing logic)
• Breaking change (fix or feature that would cause existing functionality to change)

Description

Hi, I changed a bit the way the summary logs works because it was a bit ugly the way it rendered in a Spring application for example. I made a few small changes that are somewhat unrelated to this PR so let me know if you prefer to split them on their own proper PR.

This is what I've done:

• Skipped changesets are propagated to the changelog that includes them. I've done this mostly because I wanted to see the skipped changesets summary but couldn't quite understand why it wasn't produced. It seems that changesets included in other changelogs with the include or includeAll directive aren't considered for the summary recap. The fix is very simple this is why I'm including it in this PR, but if you think it isn't necessary or it needs more polishing I can branch it to a separate PR.
• Clean up the summary recap logged. In general it isn't necessary to include new lines in logged string because log aggregators can take care of collecting and presenting logs in the best way possible. This is why I removed the new line from the logged string, but still preserving them in the strings outputted to the standard output where new lines could be necessary.
• Remove the outputted summary recap unless the VERBOSE option is selected. This will partially mitigate Disable console logs for every changeset #2396 (comment) in the sense that by default the summary isn't spammed on the standard output anymore, but one have to opt in with the VERBOSE option. I don't know if it's considered a breaking changes, but this is the reason I selected the breaking checkbox above.
• Add the showSummary parameter to Maven and Spring.

Things to be aware of

I didn't manage to run the tests so I don't know what it's broken and needs to be fixed. I would ask you to help a bit understanding what tests should be changed and if it's necessary to add new ones thanks.

Things to worry about

Additional Context

Sorry if it's a bit messy as a PR but it started with something totally unrelated and I ended up with a somewhat semi functional PR.

[MalloD12]

Hi @EvaristeGalois11, I have seen there are a few command tests failing:

I'll see if I can find out what's wrong with these files not being written. In case you are keen to debug/fix these tests the easiest way I found is by creating a test directory and placing there the update.test.groovy (here are the ones failing), then set the path variable pointing to your test directory on the getCommandTestDefinitions() (CommandTests.groovy).

As you can see on the screenshot posted there are a few tests failing because for some reason command test execution is not writing the command execution result on the expected outputFile file (for example target/test-classes/ignoredChangeset.txt.

Thanks,
Daniel.

[EvaristeGalois11]

Thank you very much @MalloD12 for the help, I'll try to do what you say and fix these tests!

[MalloD12]

Earlier talking with a team member he pointed out this is the piece that is making fail a couple of update tests (update, updateCount and updateToTag) where a showSummary is set with a different value than verbose and this is causing to not make write the command execution result. Could you please take a look at this?

Thanks,
Daniel.

[EvaristeGalois11]

Thank you, I changed the level to verbose to all the failing tests and now they are working!

[MalloD12]

I think fixing the tests this way is alright, but I am still not sure this IF block is totally accurate because we have already seen with the previously failing tests that when showSummary != verbose output won't be written.

[EvaristeGalois11]

It's because the summary logs are being outputted to the "standard" log (I don't how you call it sorry) with Scope.getCurrentScope().getLog(ShowSummaryUtil.class).info() and printed directly to the standard output. The if remove the printing to the standard output, but not to the standard log. The test is set up to redirect the standard output to the file, so unless it is set to verbose it seems to not write anything.

Should I try to redirect the standard log to the file to check if it's logging correctly? Are there already places where it's done so I can copy them?

[EvaristeGalois11]

I'll answer myself: it wasn't at all difficult thanks to the expectedLogs property.

I added to the update.test all the summary and verbose level tests to ensure that they behaves correctly. Does this resolve your doubts @MalloD12? I can update the updateCount.test and updateToTag.test too if you think it's fine.

[MalloD12]

Hi @EvaristeGalois11, thank you for updating these tests. I think it would be nice to update the others as well to keep them consistent, but let me check with somebody else from the team to double-check others are happy with it as well. I'll get back to you soon.

[EvaristeGalois11]

Sorry for taking this long @MalloD12 but I managed to catch a cold in the middle of summer lol.

Anyway after a fierce battle with intellij I successfully fixed the failing tests.

I tried adding a test case for the skipped changesets but I'm not sure if it's the right way to do it.

The Spring and maven test classes are all commented out so I didn't touch them.

[MalloD12]

One more thing, could you please tell/show me how are you using showSummary in Spring? I'm not very familiar with it and when trying to set this like:

spring.liquibase.showSummary=verbose

this is the output I'm getting:

Binding to target [Bindable@7bde1f3a type = org.springframework.boot.autoconfigure.liquibase.LiquibaseProperties, value = 'provided', annotations = array<Annotation>[@org.springframework.boot.context.properties.ConfigurationProperties(value=spring.liquibase, prefix=spring.liquibase, ignoreUnknownFields=false, ignoreInvalidFields=false)]] failed:

    Property: spring.liquibase.showsummary
    Value: verbose
    Origin: class path resource [application.properties]:3:30
    Reason: The elements [spring.liquibase.showsummary] were left unbound.

[EvaristeGalois11]

One more thing, could you please tell/show me how are you using showSummary in Spring? I'm not very familiar with it and when trying to set this like:

spring.liquibase.showSummary=verbose

this is the output I'm getting:

Binding to target [Bindable@7bde1f3a type = org.springframework.boot.autoconfigure.liquibase.LiquibaseProperties, value = 'provided', annotations = array<Annotation>[@org.springframework.boot.context.properties.ConfigurationProperties(value=spring.liquibase, prefix=spring.liquibase, ignoreUnknownFields=false, ignoreInvalidFields=false)]] failed:

    Property: spring.liquibase.showsummary
    Value: verbose
    Origin: class path resource [application.properties]:3:30
    Reason: The elements [spring.liquibase.showsummary] were left unbound.

For now you need to manually set it because Spring doesn't know about this property, like this:

@Configuration
public class ShowSummaryConfiguration implements BeanPostProcessor {
    @Override
    public Object postProcessBeforeInitialization(@NonNull Object bean, @NonNull String beanName)
            throws BeansException {
        if (bean instanceof SpringLiquibase springLiquibase) {
            springLiquibase.setShowSummary(UpdateSummaryEnum.VERBOSE);
        }
        return bean;
    }
}

If this PR is accepted I'm planning to try to investigate the issue that is currently blocking Spring from updating the liquibase version #4135, and after that I can submit a PR to spring boot for managing this new property :D

[MalloD12]

Thank you @EvaristeGalois11, I'll do my best to complete my round of Spring testing on Monday, so then we can move forward with this. In the meantime, if you are with that you can do the same updates on the other test files as you did for update.

Thanks,
Daniel.

[MalloD12]

Hi @EvaristeGalois11,

At the moment, I'm performing a bit of testing around these changes and seeing a few things I would like to share with you. When running an update command setting show-summary = verbose I can see below output:

java.io.IOException: Stream closed
	at java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:170)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:336)
	at java.io.FilterInputStream.read(FilterInputStream.java:107)
	at liquibase.change.core.ExecuteShellCommandChange$StreamGobbler.copy(ExecuteShellCommandChange.java:424)
	at liquibase.change.core.ExecuteShellCommandChange$StreamGobbler.finish(ExecuteShellCommandChange.java:414)
	at liquibase.change.core.ExecuteShellCommandChange.executeCommand(ExecuteShellCommandChange.java:203)
	at liquibase.change.core.ExecuteShellCommandChange$1.generate(ExecuteShellCommandChange.java:144)
	at liquibase.sqlgenerator.core.RuntimeGenerator.generateSql(RuntimeGenerator.java:18)
	at liquibase.sqlgenerator.core.RuntimeGenerator.generateSql(RuntimeGenerator.java:9)
	at liquibase.sqlgenerator.SqlGeneratorChain.generateSql(SqlGeneratorChain.java:32)
	at liquibase.sqlgenerator.SqlGeneratorFactory.generateSql(SqlGeneratorFactory.java:224)
	at liquibase.executor.AbstractExecutor.applyVisitors(AbstractExecutor.java:104)
	at liquibase.executor.jvm.JdbcExecutor.access$400(JdbcExecutor.java:39)
	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:440)
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:76)
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:179)
	at liquibase.database.AbstractJdbcDatabase.execute(AbstractJdbcDatabase.java:1291)
	at liquibase.database.AbstractJdbcDatabase.executeStatements(AbstractJdbcDatabase.java:1273)
	at liquibase.changelog.ChangeSet.execute(ChangeSet.java:725)
	at liquibase.changelog.visitor.UpdateVisitor.executeAcceptedChange(UpdateVisitor.java:121)
	at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:70)
	at liquibase.changelog.ChangeLogIterator$2.lambda$run$0(ChangeLogIterator.java:110)
	at liquibase.Scope.lambda$child$0(Scope.java:197)
	at liquibase.Scope.child(Scope.java:206)
	at liquibase.Scope.child(Scope.java:196)
	at liquibase.Scope.child(Scope.java:175)
	at liquibase.Scope.child(Scope.java:263)
	at liquibase.changelog.ChangeLogIterator$2.run(ChangeLogIterator.java:100)
	at liquibase.Scope.lambda$child$0(Scope.java:197)
	at liquibase.Scope.child(Scope.java:206)
	at liquibase.Scope.child(Scope.java:196)
	at liquibase.Scope.child(Scope.java:175)
	at liquibase.Scope.child(Scope.java:263)
	at liquibase.Scope.child(Scope.java:267)
	at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:74)
	at liquibase.command.core.AbstractUpdateCommandStep.lambda$run$0(AbstractUpdateCommandStep.java:84)
	at liquibase.Scope.lambda$child$0(Scope.java:197)
	at liquibase.Scope.child(Scope.java:206)
	at liquibase.Scope.child(Scope.java:196)
	at liquibase.Scope.child(Scope.java:175)
	at liquibase.command.core.AbstractUpdateCommandStep.run(AbstractUpdateCommandStep.java:83)
	at liquibase.command.core.UpdateCommandStep.run(UpdateCommandStep.java:98)
	at liquibase.command.CommandScope.execute(CommandScope.java:213)
	at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:55)
	at liquibase.integration.commandline.CommandRunner.call(CommandRunner.java:24)
	at picocli.CommandLine.executeUserObject(CommandLine.java:2041)
	at picocli.CommandLine.access$1500(CommandLine.java:148)
	at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2461)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2453)
	at picocli.CommandLine$RunLast.handle(CommandLine.java:2415)
	at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2273)
	at picocli.CommandLine$RunLast.execute(CommandLine.java:2417)
	at picocli.CommandLine.execute(CommandLine.java:2170)
	at liquibase.integration.commandline.LiquibaseCommandLine.lambda$execute$2(LiquibaseCommandLine.java:381)
	at liquibase.Scope.child(Scope.java:206)
	at liquibase.Scope.child(Scope.java:182)
	at liquibase.integration.commandline.LiquibaseCommandLine.lambda$execute$3(LiquibaseCommandLine.java:356)
	at liquibase.Scope.child(Scope.java:206)
	at liquibase.Scope.child(Scope.java:182)
	at liquibase.integration.commandline.LiquibaseCommandLine.execute(LiquibaseCommandLine.java:354)
	at liquibase.integration.commandline.LiquibaseCommandLine.main(LiquibaseCommandLine.java:94)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at liquibase.integration.commandline.LiquibaseLauncher.main(LiquibaseLauncher.java:107)
Running Changeset: changelog/changelog-1.xml::drop_all_foreign_keys::abuschka
Running Changeset: changelog/changelog-1.xml::output messages::nvoxland
Message using default target
Message using default target
Message using stderr target
Message using stderr target
Running Changeset: changelog/changelog-1.xml::fkexists-without-table-setup::example
Message using stdout target
Message using stdout target
Running Changeset: changelog/changelog-1.xml::example::view-if-exists

UPDATE SUMMARY
Run:                         62
Previously run:               0
Filtered out:                 3
-------------------------------
Total change sets:           65


FILTERED CHANGE SETS SUMMARY
DBMS mismatch:                3

+-----------------------------------------------------------+------------------------------------------+
| Changeset Info                                            | Reason Skipped                           |
+-----------------------------------------------------------+------------------------------------------+
| changelog/changelog-1.xml::CORE-381::ssantoro             | mismatched DBMS value of 'msql'          |
+-----------------------------------------------------------+------------------------------------------+
| changelog/changelog-1.xml::modifySqlWithContext::nvoxland | mismatched DBMS value of 'h2, mysql'     |
+-----------------------------------------------------------+------------------------------------------+
| changelog/changelog-1.xml::nvarchartest::nvoxland         | mismatched DBMS value of 'oracle, mssql' |
+-----------------------------------------------------------+------------------------------------------+
Liquibase: Update has been successful.
Liquibase command 'update' was executed successfully.

Having set show-summary = summary there is not details of the update command about how many changesets have been executed, filtered, etc. See below screenshot:

I think it's good to stop displaying duplicate data on logs, but I don't think only verbose mode should displays update command details because if that is the case I think having a summary option wouldn't make any sense.

Can you please look at this?

Thanks,
Daniel.

[EvaristeGalois11]

Could you @MalloD12 share a minimal project of what you're doing to receive that exception? I actually only use liquibase through the Spring integration so it would be really helpful if you can show me how you're testing it to reproduce that problem thanks.

On to the duplicate logs issue, the current implementation is reporting the update summary both on the log and on the output stream. I understand that your case is of a project that doesn't make use of the standard logger, but just reading the standard output (correct me if I'm wrong of course). This way at summary level nothing is being shown which is basically equivalent to a none level. The problem is that if I add the summary recap to the output stream, the problem complained in #2396 (comment) won't be addressed because of the double logging.

Maybe we should add a new setting to let the user choose which one they prefer? Because otherwise I can't think of any other way to resolve this redundant log: only logging with the standard logger wil make the people that don't use a logger not happy not seeing anything, but using the output stream directly will make the people that use a custom logger not happy because it will mess up their console. Something like showSummaryOutput=[LOG|CONSOLE|BOTH(default to preserve backwards compatibility)]? (I'm terrible with naming sorry lol)

ETA: Or we could just use the ConsoleUIService to log instead of this standard log and output stream like the Running changeset: ... messages are doing for example. By default it will output everything on stout, but it isn't hard to configure a proper logger with Scope.enter(). What do you think @MalloD12 ? Could this be a viable option?

[MalloD12]

I could reproduce the same output from a spring demo project I'm using and also from liquibase project (master branch). I'm attaching here the spring log (see VerboseOutput.txt) I got from this execution, plus the changelog (see
changelog.txt
) I'm using so you can try the same if you wish.

Regarding the duplicated log issue, let me check and discuss it with another team member and I'll get back to you once I get an answer.

Thanks,
Daniel.

[EvaristeGalois11]

I'm afraid I can't seem to be able to reproduce that java.io.IOException: Stream closed, for me everything works fine but maybe it's because I'm missing something. This is the project that I'm using liquibase-exception.zip

Judging from the stack trace only, could it be a bug in the ExecuteShellCommandChange?

[MalloD12]

Hi @EvaristeGalois11,

I've been discussing these changes with some other team members and we think we should revert the below change from the ShowSummaryUtil class:

if (verbose) {
            try {
                Writer writer = createOutputWriter(outputStream);
                writer.append(builder.toString());
                writer.flush();
            } catch (IOException ioe) {
                throw new LiquibaseException(ioe);
            }
}

Because of this as we were discussing previously it changes the current behaviour of the different show-summary configurations we have at the moment (OFF, SUMMARY, and VERBOSE). I think what you mentioned yesterday about adding a new configuration (showSummaryOutput) to select what we want to use for outputting update execution results. I think adding that new configuration would help us to solve the duplicate logging issue in a more generic way. Would you be happy to implement that?

Thanks,
Daniel.

[EvaristeGalois11]

I'm more than happy to work on the new configuration. I will probably need a bit of time to understand how the whole flow works, but I'll try my best to do it asap.

Do you @MalloD12 prefer to open a new PR for this new configuration or can i keep working on this one?

[MalloD12]

I think it would be preferable to create a separate PR for it. As I understand it would help us to solve issue #2396. I also think it would be good to test this PR having those changes so we can see how content output behaves for the different show-summary configurations. Would you mind putting this one on hold until we have that?

Thank you for all the work you are doing here!! 🙇‍♂️

Regards,
Daniel.

[EvaristeGalois11]

Hi @MalloD12,
I finally found the time to implement the showSummaryOutput parameter and I opened a new PR like you said #4574.
I hope you can follow me there too, I really appreciate all the support you're giving me :D

Regarding this PR instead, I completely reverted every change to the ShowSummaryUtil class to avoid making a messy merge with the new PR. I updated the description accordingly.

[MalloD12]

Hi @MalloD12, I finally found the time to implement the showSummaryOutput parameter and I opened a new PR like you said #4574. I hope you can follow me there too, I really appreciate all the support you're giving me :D

Regarding this PR instead, I completely reverted every change to the ShowSummaryUtil class to avoid making a messy merge with the new PR. I updated the description accordingly.

Hi @EvaristeGalois11,

Thanks so much for all your hard work to improve this feature. I'll start looking into this today. Any questions I might have I'll keep you posted.

Daniel.

[MalloD12]

Approved.

Review and testing results:

This PR is adding support for show-summary for Spring extension, plus some usability improvements. Part of the original scope of this PR has been updated as @EvaristeGalois11 kindly created another PR to improve show-summary usability (see #4574 ).

Code changes look good to me. Build and all tests have been successfully executed cloning this PR in a separate branch.

Again, thank you @EvaristeGalois11 for all your support with these changes.

Thanks,
Daniel.

Things to be aware of:

• None

Things to worry about:

• None

[EvaristeGalois11]

Thank you @MalloD12 for your kind words and everybody involved with these two PRs for merging them. I'm really proud of my newly acquired contributor badge! Looking forward to the next release 🚀