Add mdc to update command (DAT-12602) (#3647)

* add MDC interfaces and base classes (DAT-12601) (#3567)

Create the basic APIs for MDC in support of structured logging.

* set log format in log service

* add deprecated annotation

* Revert "set log format in log service"

This reverts commit 096b067.

* use log formatter for JSON logging

* add MDC to structured log output

* fix test

* Include "path" in databasechangelog's description column for all change types with "path" attributes (#3244)

Extends the DESCRIPTION column of the DATABASECHANGELOG for sqlFile by the path specification, for example sqlFile path=IUNT200.sql

Co-authored-by: michaelmatthiaskern <michael.kern@mail.de>
Co-authored-by: Nathan Voxland <nathan@voxland.net>

* #1466: Add ignore:true changeset attribute to Formatted SQL changeLogs (#3377)

Co-authored-by: skrivenko <skrivenko@users.noreply.github.com>
Co-authored-by: filipe lautert <flautert@liquibase.org>

* [DAT-12602] Initial update mdc implementation.

* add configuration option for log format

* [DAT-12602] Adds remaining mdc values. Reworks to use static strings over enum.

* [DAT-12602] Remove unused keys, fixed formatting.

* [DAT-12602] Adds system information to mdc.

* [DAT-12602] Fixes formatting for mdckey.

* [DAT-12602] Simplifies getting mdc for command name.

* updated logFormat description

* warn about invalid values for log format

* [DAT-12602] Add changeset outcome to info log, fix deployment outcome to actually show in info.

* Revert "Merge remote-tracking branch 'origin/DAT-11693' into DAT-12602"

This reverts commit 6e9163d, reversing
changes made to 1ceec55.

* Revert "Merge remote-tracking branch 'origin/DAT-12727' into DAT-12602"

This reverts commit 8554e29, reversing
changes made to 10d540b.

* Revert "Revert "Merge remote-tracking branch 'origin/DAT-11693' into DAT-12602""

This reverts commit 10d540b.

* Revert "Revert "Merge remote-tracking branch 'origin/DAT-12727' into DAT-12602""

This reverts commit 12f6539.

* [DAT-12602] Fix liquibase system information mdc.

* [DAT-12602] Fix logged liquibase version.

* Revert change to build.properties

* safely cast logformat - fixes using the default value

* [DAT-12602] Adds mdc for failed changeset outcome.

Co-authored-by: Steven Massaro <steven.massaro.web@gmail.com>
Co-authored-by: MichaelKern-IVV <102645261+MichaelKern-IVV@users.noreply.github.com>
Co-authored-by: michaelmatthiaskern <michael.kern@mail.de>
Co-authored-by: Nathan Voxland <nathan@voxland.net>
Co-authored-by: skrivenko <72100114+skrivenko@users.noreply.github.com>
Co-authored-by: skrivenko <skrivenko@users.noreply.github.com>
Co-authored-by: filipe lautert <flautert@liquibase.org>

liquibase-cli/src/main/java/liquibase/integration/commandline/LiquibaseCommandLine.java

@@ -18,13 +18,16 @@
 import liquibase.license.LicenseServiceFactory;
 import liquibase.logging.LogService;
 import liquibase.logging.core.JavaLogService;
+import liquibase.logging.mdc.MdcKey;
+import liquibase.logging.mdc.MdcManager;
 import liquibase.resource.*;
 import liquibase.ui.ConsoleUIService;
 import liquibase.ui.UIService;
 import liquibase.util.*;
 import picocli.CommandLine;
 
 import java.io.*;
+import java.net.InetAddress;
 import java.net.MalformedURLException;
 import java.net.URL;
 import java.net.URLClassLoader;
@@ -349,7 +352,14 @@ public int execute(String[] args) {
                     }
 
                     enableMonitoring();
-
+                    MdcManager mdcManager = Scope.getCurrentScope().getMdcManager();
+                    mdcManager.put(MdcKey.LIQUIBASE_VERSION, LiquibaseUtil.getBuildVersion());
+                    mdcManager.put(MdcKey.LIQUIBASE_SYSTEM_USER, System.getProperty("user.name"));
+                    mdcManager.put(MdcKey.LIQUIBASE_SYSTEM_NAME, InetAddress.getLocalHost().getHostName());
+                    Scope.getCurrentScope().getLog(getClass()).info("Starting command execution.");
+                    mdcManager.remove(MdcKey.LIQUIBASE_VERSION);
+                    mdcManager.remove(MdcKey.LIQUIBASE_SYSTEM_NAME);
+                    mdcManager.remove(MdcKey.LIQUIBASE_SYSTEM_USER);
                     int response = commandLine.execute(finalArgs);
 
                     if (!wasHelpOrVersionRequested()) {

liquibase-core/src/main/java/liquibase/Liquibase.java

@@ -33,6 +33,8 @@
 import liquibase.logging.Logger;
 import liquibase.logging.core.BufferedLogService;
 import liquibase.logging.core.CompositeLogService;
+import liquibase.logging.mdc.MdcKey;
+import liquibase.logging.mdc.MdcValue;
 import liquibase.parser.ChangeLogParser;
 import liquibase.parser.ChangeLogParserFactory;
 import liquibase.parser.core.xml.XMLChangeLogSAXParser;
@@ -237,6 +239,8 @@ public void update(Contexts contexts, LabelExpression labelExpression, boolean c
         runInScope(() -> {
             LockService lockService = LockServiceFactory.getInstance().getLockService(database);
             lockService.waitForLock();
+            Scope.getCurrentScope().addMdcValue(MdcKey.OPERATION_TARGET_VALUE, database.getConnection().getURL());
+            Scope.getCurrentScope().addMdcValue(MdcKey.OPERATION_TARGET_TYPE, MdcValue.URL_DATABASE_TARGET);
 
             changeLogParameters.setContexts(contexts);
             changeLogParameters.setLabels(labelExpression);
@@ -254,6 +258,8 @@ public void update(Contexts contexts, LabelExpression labelExpression, boolean c
                 ChangeLogHistoryService changelogService = ChangeLogHistoryServiceFactory.getInstance().getChangeLogService(database);
                 changelogService.generateDeploymentId();
 
+                Scope.getCurrentScope().addMdcValue(MdcKey.DEPLOYMENT_ID, changelogService.getDeploymentId());
+
                 changeLog.validate(database, contexts, labelExpression);
 
                 //
@@ -295,7 +301,13 @@ public void update(Contexts contexts, LabelExpression labelExpression, boolean c
                 // Update Hub with the operation information
                 //
                 hubUpdater.postUpdateHub(updateOperation, bufferLog);
+                Scope.getCurrentScope().getMdcManager().put(MdcKey.DEPLOYMENT_OUTCOME, MdcValue.COMMAND_SUCCESSFUL);
+                Scope.getCurrentScope().getLog(getClass()).info("Update command completed successfully.");
+                Scope.getCurrentScope().getMdcManager().remove(MdcKey.DEPLOYMENT_OUTCOME);
             } catch (Throwable e) {
+                Scope.getCurrentScope().addMdcValue(MdcKey.DEPLOYMENT_OUTCOME, MdcValue.COMMAND_FAILED);
+                Scope.getCurrentScope().getLog(getClass()).info("Update command encountered an exception.");
+                Scope.getCurrentScope().getMdcManager().remove(MdcKey.DEPLOYMENT_OUTCOME);
                 if (hubUpdater != null) {
                     hubUpdater.postUpdateHubExceptionHandling(updateOperation, bufferLog, e.getMessage());
                 }

liquibase-core/src/main/java/liquibase/changelog/ChangeSet.java

@@ -16,6 +16,7 @@
 import liquibase.executor.ExecutorService;
 import liquibase.executor.LoggingExecutor;
 import liquibase.logging.Logger;
+import liquibase.logging.mdc.MdcKey;
 import liquibase.parser.ChangeLogParserConfiguration;
 import liquibase.parser.core.ParsedNode;
 import liquibase.parser.core.ParsedNodeException;
@@ -27,6 +28,7 @@
 import liquibase.sql.visitor.SqlVisitor;
 import liquibase.sql.visitor.SqlVisitorFactory;
 import liquibase.statement.SqlStatement;
+import liquibase.util.ISODateFormat;
 import liquibase.util.StreamUtil;
 import liquibase.util.StringUtil;
 
@@ -569,6 +571,7 @@ public ExecType execute(DatabaseChangeLog databaseChangeLog, ChangeExecListener
         }
 
         long startTime = new Date().getTime();
+        Scope.getCurrentScope().addMdcValue(MdcKey.CHANGESET_OPERATION_START_TIME, new ISODateFormat().format(new Date()));
 
         ExecType execType = null;
 
@@ -697,15 +700,22 @@ public ExecType execute(DatabaseChangeLog databaseChangeLog, ChangeExecListener
                 if (runInTransaction) {
                     database.commit();
                 }
-                log.info("ChangeSet " + toString(false) + " ran successfully in " + (new Date().getTime() - startTime + "ms"));
                 if (execType == null) {
                     execType = ExecType.EXECUTED;
                 }
+                Date stopTime = new Date();
+                Scope.getCurrentScope().addMdcValue(MdcKey.CHANGESET_OPERATION_STOP_TIME, new ISODateFormat().format(stopTime));
+                Scope.getCurrentScope().addMdcValue(MdcKey.CHANGESET_OUTCOME, execType.value.toLowerCase());
+                log.info("ChangeSet " + toString(false) + " ran successfully in " + (stopTime.getTime() - startTime) + "ms");
             } else {
                 log.fine("Skipping ChangeSet: " + toString());
             }
 
         } catch (Exception e) {
+            if (getFailOnError() == null || getFailOnError()) {
+                Scope.getCurrentScope().addMdcValue(MdcKey.CHANGESET_OUTCOME, ExecType.FAILED.value.toLowerCase());
+            }
+            log.info(String.format("ChangeSet %s encountered an exception.", toString(false)));
             try {
                 database.rollback();
             } catch (Exception e1) {

liquibase-core/src/main/java/liquibase/changelog/visitor/UpdateVisitor.java

@@ -13,6 +13,7 @@
 import liquibase.executor.Executor;
 import liquibase.executor.ExecutorService;
 import liquibase.executor.LoggingExecutor;
+import liquibase.logging.mdc.MdcKey;
 
 import java.util.Set;
 
@@ -43,6 +44,10 @@ public Direction getDirection() {
     @Override
     public void visit(ChangeSet changeSet, DatabaseChangeLog databaseChangeLog, Database database,
                       Set<ChangeSetFilterResult> filterResults) throws LiquibaseException {
+        Scope scope = Scope.getCurrentScope();
+        scope.addMdcValue(MdcKey.CHANGESET_ID, changeSet.getId());
+        scope.addMdcValue(MdcKey.CHANGESET_AUTHOR, changeSet.getAuthor());
+        scope.addMdcValue(MdcKey.CHANGESET_FILEPATH, changeSet.getFilePath());
         Executor executor = Scope.getCurrentScope().getSingleton(ExecutorService.class).getExecutor("jdbc", database);
         if (! (executor instanceof LoggingExecutor)) {
             Scope.getCurrentScope().getUI().sendMessage("Running Changeset: " + changeSet);

liquibase-core/src/main/java/liquibase/executor/jvm/JdbcExecutor.java

@@ -11,6 +11,7 @@
 import liquibase.executor.AbstractExecutor;
 import liquibase.listener.SqlListener;
 import liquibase.logging.Logger;
+import liquibase.logging.mdc.MdcKey;
 import liquibase.servicelocator.PrioritizedService;
 import liquibase.sql.CallableSql;
 import liquibase.sql.Sql;
@@ -425,6 +426,7 @@ public Object doInStatement(Statement stmt) throws SQLException, DatabaseExcepti
                         statement = statement.replaceFirst("[\\s\\r\\n]*[^*]/[\\s\\r\\n]*$", "");
                     }
                 }
+                Scope.getCurrentScope().addMdcValue(MdcKey.CHANGESET_SQL, statement);
 
                 for (SqlListener listener : Scope.getCurrentScope().getListeners(SqlListener.class)) {
                     listener.writeSqlWillRun(String.format("%s", statement));

liquibase-core/src/main/java/liquibase/integration/commandline/Main.java

@@ -26,6 +26,7 @@
 import liquibase.logging.LogService;
 import liquibase.logging.Logger;
 import liquibase.logging.core.JavaLogService;
+import liquibase.logging.mdc.MdcKey;
 import liquibase.resource.*;
 import liquibase.ui.ConsoleUIService;
 import liquibase.util.*;
@@ -324,6 +325,7 @@ public Integer run() throws Exception {
                             }
                         }
 
+
                         LicenseService licenseService = Scope.getCurrentScope().getSingleton(LicenseServiceFactory.class).getLicenseService();
                         if (licenseService != null) {
                             if (main.liquibaseProLicenseKey == null) {
@@ -393,9 +395,9 @@ public Integer run() throws Exception {
                         if (!Main.runningFromNewCli) {
                             innerScopeObjects.put(Scope.Attr.resourceAccessor.name(), new ClassLoaderResourceAccessor(main.configureClassLoader()));
                         }
+
                         Scope.child(innerScopeObjects, () -> {
                             main.doMigration();
-
                             if (!Main.runningFromNewCli) {
                                 if (COMMANDS.UPDATE.equals(main.command)) {
                                     Scope.getCurrentScope().getUI().sendMessage(coreBundle.getString("update.successful"));
@@ -1831,7 +1833,9 @@ protected void doMigration() throws Exception {
             }
 
             try {
+                Scope.getCurrentScope().addMdcValue(MdcKey.LIQUIBASE_COMMAND_NAME, command);
                 if (COMMANDS.UPDATE.equalsIgnoreCase(command)) {
+                    Scope.getCurrentScope().addMdcValue(MdcKey.OPERATION_TYPE, COMMANDS.UPDATE);
                     try {
                         liquibase.update(new Contexts(contexts), new LabelExpression(getLabelFilter()));
                     } catch (LiquibaseException updateException) {

liquibase-core/src/main/java/liquibase/logging/mdc/MdcKey.java

@@ -0,0 +1,20 @@
+package liquibase.logging.mdc;
+
+public class MdcKey {
+    public static final String DEPLOYMENT_ID = "deploymentId";
+    public static final String CHANGESET_ID = "changesetId";
+    public static final String CHANGESET_AUTHOR = "changesetAuthor";
+    public static final String CHANGESET_FILEPATH = "changesetFilepath";
+    public static final String CHANGESET_OUTCOME = "changesetOutcome";
+    public static final String OPERATION_TYPE = "liquibaseOperation";
+    public static final String OPERATION_TARGET_TYPE = "liquibaseTargetType";
+    public static final String OPERATION_TARGET_VALUE = "liquibaseTarget";
+    public static final String CHANGESET_OPERATION_START_TIME = "changesetOperationStart";
+    public static final String CHANGESET_OPERATION_STOP_TIME = "changesetOperationStop";
+    public static final String CHANGESET_SQL = "changesetSql";
+    public static final String DEPLOYMENT_OUTCOME = "deploymentOutcome";
+    public static final String LIQUIBASE_COMMAND_NAME = "liquibaseCommandName";
+    public static final String LIQUIBASE_VERSION = "liquibaseVersion";
+    public static final String LIQUIBASE_SYSTEM_NAME = "liquibaseSystemName";
+    public static final String LIQUIBASE_SYSTEM_USER = "liquibaseSystemUser";
+}

liquibase-core/src/main/java/liquibase/logging/mdc/MdcValue.java

@@ -0,0 +1,7 @@
+package liquibase.logging.mdc;
+
+public class MdcValue {
+    public static final String COMMAND_SUCCESSFUL = "success";
+    public static final String COMMAND_FAILED = "fail";
+    public static final String URL_DATABASE_TARGET = "url";
+}