Logging improvement

omidtavakoli · omid.tavakoli · web-flow · commit 4a71e507e614 · 2025-10-30T13:57:47.000+01:00
* parameterized logging defined

* execution time logged

* sauron buildID logged

* pipeline service logging and metrics exposing updated

* comments updated

* removed atomic reference

* removed spare variable

---------

Co-authored-by: omid.tavakoli &lt;omid.tavakoli@free-now.com&gt;
diff --git a/sauron-core/src/main/java/com/freenow/sauron/model/DataSet.java b/sauron-core/src/main/java/com/freenow/sauron/model/DataSet.java
@@ -94,6 +94,24 @@ public Map<String, Object> copyAdditionalInformation()
     }
 
 
+    @Override
+    public String toString()
+    {
+        try
+        {
+            return toJson();
+        }
+        catch (JsonProcessingException e)
+        {
+            return "DataSet{" +
+                "serviceName='" + serviceName + '\'' +
+                ", commitId='" + commitId + '\'' +
+                ", additionalInformation=" + additionalInformation +
+                '}';
+        }
+    }
+
+
     public String toJson() throws JsonProcessingException
     {
         ObjectMapper jsonMapper = new ObjectMapper();
diff --git a/sauron-service/src/main/java/com/freenow/sauron/controller/PipelineController.java b/sauron-service/src/main/java/com/freenow/sauron/controller/PipelineController.java
@@ -39,4 +39,4 @@ public ResponseEntity<Void> build(@Valid @RequestBody BuildRequest request)
         pipelineService.publish(request);
         return ResponseEntity.ok().build();
     }
-}
+}
diff --git a/sauron-service/src/main/java/com/freenow/sauron/properties/PipelineConfigurationProperties.java b/sauron-service/src/main/java/com/freenow/sauron/properties/PipelineConfigurationProperties.java
@@ -1,21 +1,30 @@
 package com.freenow.sauron.properties;
 
 import java.util.Collections;
-import java.util.HashMap;
 import java.util.List;
+import java.util.Map;
+import lombok.Getter;
+import lombok.Setter;
 import org.springframework.boot.context.properties.ConfigurationProperties;
 
-@ConfigurationProperties("sauron.pipelines")
-public class PipelineConfigurationProperties extends HashMap<String, List<String>>
+@Getter
+@Setter
+@ConfigurationProperties(prefix = "sauron")
+public class PipelineConfigurationProperties
 {
+    //A map of pipeline names to the list of plugin IDs that comprise them.Spring Boot will bind properties like `sauron.pipelines.default` into this map.
+    private Map<String, List<String>> pipelines = Collections.emptyMap();
+
+    //The ID of the plugin that must be executed at the end of a user-defined pipeline run.
+    private String mandatoryOutputPlugin = "elasticsearch-output";
+
     public List<String> getDefaultPipeline()
     {
         return getPipeline("default");
     }
 
-
     public List<String> getPipeline(String pipeline)
     {
-        return this.getOrDefault(pipeline, Collections.emptyList());
+        return pipelines.getOrDefault(pipeline, Collections.emptyList());
     }
 }
diff --git a/sauron-service/src/main/java/com/freenow/sauron/service/PipelineService.java b/sauron-service/src/main/java/com/freenow/sauron/service/PipelineService.java
@@ -7,6 +7,8 @@
 import com.freenow.sauron.plugins.SauronExtension;
 import com.freenow.sauron.properties.PipelineConfigurationProperties;
 import com.freenow.sauron.properties.PluginsConfigurationProperties;
+import io.micrometer.core.instrument.MeterRegistry;
+import io.micrometer.core.instrument.Timer;
 import java.util.List;
 import lombok.extern.slf4j.Slf4j;
 import org.apache.commons.lang3.StringUtils;
@@ -21,8 +23,6 @@
 @EnableConfigurationProperties({PipelineConfigurationProperties.class, PluginsConfigurationProperties.class})
 public class PipelineService
 {
-    private static final String ELASTICSEARCH_OUTPUT_PLUGIN = "elasticsearch-output";
-
     private final PipelineConfigurationProperties pipelineProperties;
 
     private final PluginsConfigurationProperties pluginsProperties;
@@ -31,18 +31,22 @@ public class PipelineService
 
     private final RequestHandler handler;
 
+    private final MeterRegistry meterRegistry;
+
 
     @Autowired
     public PipelineService(
         PluginManager pluginManager,
         PipelineConfigurationProperties pipelineProperties,
         PluginsConfigurationProperties pluginsProperties,
-        RequestHandler handler)
+        RequestHandler handler,
+        MeterRegistry meterRegistry)
     {
         this.pluginManager = pluginManager;
         this.pipelineProperties = pipelineProperties;
         this.pluginsProperties = pluginsProperties;
         this.handler = handler;
+        this.meterRegistry = meterRegistry;
         handler.setConsumer(this::process);
     }
 
@@ -51,6 +55,7 @@ public void publish(BuildRequest request)
     {
         try
         {
+            log.info("Received request to publish: serviceName={}, commitId={}", request.getServiceName(), request.getCommitId());
             handler.handle(request);
         }
         catch (Exception ex)
@@ -64,68 +69,103 @@ void process(BuildRequest request)
     {
         try
         {
-            final DataSet dataSet = BuildMapper.makeDataSet(request);
+            log.info("Starting processing for request: serviceName={}, commitId={}", request.getServiceName(), request.getCommitId());
+            DataSet dataSet = BuildMapper.makeDataSet(request);
+            log.debug("Initial DataSet created from request: {}", dataSet);
             String plugin = request.getPlugin();
 
             if (StringUtils.isNotBlank(plugin))
             {
                 plugin = StringUtils.lowerCase(request.getPlugin());
                 final List<String> defaultPipeline = pipelineProperties.getDefaultPipeline();
 
-                log.debug("Running user defined pipeline.");
+                log.debug("User-defined plugin specified: {}. Running user defined pipeline. Default pipeline plugins: {}", plugin, defaultPipeline);
 
                 if (defaultPipeline.contains(plugin))
                 {
-                    runDependencies(request, dataSet, plugin, defaultPipeline);
+                    log.debug("User-defined plugin '{}' is part of the default pipeline. Running dependencies first.", plugin);
+                    runDependencies(dataSet, plugin, defaultPipeline);
                 }
 
-                runPlugin(plugin, request, dataSet);
-                runPlugin(ELASTICSEARCH_OUTPUT_PLUGIN, request, dataSet);
+                log.debug("Executing user-defined plugin: {}", plugin);
+                runPlugin(plugin, dataSet);
+
+                String mandatoryOutputPlugin = pipelineProperties.getMandatoryOutputPlugin();
+                if (StringUtils.isNotBlank(mandatoryOutputPlugin)) {
+                    log.debug("Executing mandatory output plugin: {}", mandatoryOutputPlugin);
+                    runPlugin(mandatoryOutputPlugin, dataSet);
+                }
             }
             else
             {
-                log.debug("Running default pipeline.");
-                pipelineProperties.getDefaultPipeline().forEach(pluginId -> runPlugin(pluginId, request, dataSet));
+                log.debug("No user-defined plugin. Running default pipeline. Default pipeline plugins: {}", pipelineProperties.getDefaultPipeline());
+                pipelineProperties.getDefaultPipeline().forEach(pluginId -> runPlugin(pluginId, dataSet));
             }
         }
         catch (final Exception ex)
         {
-            log.error(String.format("Error loading plugins: %s", ex.getMessage()), ex);
+            log.error("Error processing request for serviceName={}, commitId={}", request.getServiceName(), request.getCommitId(), ex);
         }
     }
 
 
     private void runDependencies(
-        final BuildRequest request, final DataSet dataSet,
-        final String plugin, final List<String> defaultPipeline)
+        DataSet dataSet, final String plugin, final List<String> defaultPipeline)
     {
         for (final String defaultPipelinePlugin : defaultPipeline)
         {
             if (StringUtils.equals(plugin, defaultPipelinePlugin))
             {
+                log.debug("Dependency plugin '{}' is the main plugin '{}', skipping further dependencies.", defaultPipelinePlugin, plugin);
                 return;
             }
 
-            runPlugin(defaultPipelinePlugin, request, dataSet);
+            log.debug("Running dependency plugin: {} for main plugin: {}", defaultPipelinePlugin, plugin);
+            runPlugin(defaultPipelinePlugin, dataSet);
         }
     }
 
 
-    void runPlugin(String plugin, BuildRequest request, DataSet dataSet)
+    void runPlugin(String plugin, DataSet dataSet)
     {
-        pluginManager.getExtensions(SauronExtension.class, plugin).forEach(pluginExtension -> {
+        for (SauronExtension pluginExtension : pluginManager.getExtensions(SauronExtension.class, plugin))
+        {
             try
             {
-                log.debug(String.format("Applying pluginId: %s. Processing service %s - %s", plugin, request.getServiceName(), request.getCommitId()));
                 MDC.put("sauron.pluginId", plugin);
-                MDC.put("sauron.serviceName", request.getServiceName());
-                MDC.put("sauron.commitId", request.getCommitId());
-                pluginExtension.apply(pluginsProperties, dataSet);
+                MDC.put("sauron.serviceName", dataSet.getServiceName());
+                MDC.put("sauron.commitId", dataSet.getCommitId());
+                MDC.put("sauron.buildId", dataSet.getBuildId());
+                log.debug("Applying pluginId: {}. Processing service {} - {}. DataSet BEFORE plugin execution: {}", plugin, dataSet.getServiceName(), dataSet.getCommitId(),
+                    dataSet);
+
+                getTimerBuilder("sauron.plugin.execution.time")
+                    .tag("plugin", plugin)
+                    .tag("service", dataSet.getServiceName())
+                    .tag("commit", dataSet.getCommitId())
+                    .register(meterRegistry).record(() -> pluginExtension.apply(pluginsProperties, dataSet));
+
+                meterRegistry.counter("sauron.plugin.executions.total", "plugin", plugin, "result", "success").increment();
+                log.debug("PluginId: {} applied. Processing service {} - {}. DataSet AFTER plugin execution: {}", plugin, dataSet.getServiceName(), dataSet.getCommitId(), dataSet);
             }
             catch (final Exception ex)
             {
-                log.error(String.format("Error processing pipeline: %s:%s. %s", request.getServiceName(), request.getCommitId(), ex.getMessage()), ex);
+                meterRegistry.counter("sauron.plugin.executions.total", "plugin", plugin, "result", "failure").increment();
+                log.error("Error in plugin '{}' for serviceName={}, commitId={}. DataSet at time of failure: {}", plugin, dataSet.getServiceName(), dataSet.getCommitId(), dataSet, ex);
+            }
+            finally
+            {
+                MDC.remove("sauron.pluginId");
+                MDC.remove("sauron.serviceName");
+                MDC.remove("sauron.commitId");
+                MDC.remove("sauron.buildId");
             }
-        });
+        }
+    }
+
+
+    Timer.Builder getTimerBuilder(String name)
+    {
+        return Timer.builder(name);
     }
 }
diff --git a/sauron-service/src/test/java/com/freenow/sauron/service/PipelineServiceTest.java b/sauron-service/src/test/java/com/freenow/sauron/service/PipelineServiceTest.java
diff --git a/sauron-service/src/test/resources/logback-test.xml b/sauron-service/src/test/resources/logback-test.xml

Original file line number	Diff line number	Diff line change
`@@ -39,4 +39,4 @@ public ResponseEntity<Void> build(@Valid @RequestBody BuildRequest request)`
`39`	`39`	`pipelineService.publish(request);`
`40`	`40`	`return ResponseEntity.ok().build();`
`41`	`41`	`}`
`42`		`-}`
	`42`	`+}`
Original file line number	Diff line number	Diff line change
`@@ -1,21 +1,30 @@`
`1`	`1`	`package com.freenow.sauron.properties;`
`2`	`2`
`3`	`3`	`import java.util.Collections;`
`4`		`-import java.util.HashMap;`
`5`	`4`	`import java.util.List;`
	`5`	`+import java.util.Map;`
	`6`	`+import lombok.Getter;`
	`7`	`+import lombok.Setter;`
`6`	`8`	`import org.springframework.boot.context.properties.ConfigurationProperties;`
`7`	`9`
`8`		`-@ConfigurationProperties("sauron.pipelines")`
`9`		`-public class PipelineConfigurationProperties extends HashMap<String, List<String>>`
	`10`	`+@Getter`
	`11`	`+@Setter`
	`12`	`+@ConfigurationProperties(prefix = "sauron")`
	`13`	`+public class PipelineConfigurationProperties`
`10`	`14`	`{`
	`15`	+ //A map of pipeline names to the list of plugin IDs that comprise them.Spring Boot will bind properties like `sauron.pipelines.default` into this map.
	`16`	`+ private Map<String, List<String>> pipelines = Collections.emptyMap();`
	`17`	`+`
	`18`	`+ //The ID of the plugin that must be executed at the end of a user-defined pipeline run.`
	`19`	`+ private String mandatoryOutputPlugin = "elasticsearch-output";`
	`20`	`+`
`11`	`21`	`public List<String> getDefaultPipeline()`
`12`	`22`	`{`
`13`	`23`	`return getPipeline("default");`
`14`	`24`	`}`
`15`	`25`
`16`		`-`
`17`	`26`	`public List<String> getPipeline(String pipeline)`
`18`	`27`	`{`
`19`		`- return this.getOrDefault(pipeline, Collections.emptyList());`
	`28`	`+ return pipelines.getOrDefault(pipeline, Collections.emptyList());`
`20`	`29`	`}`
`21`	`30`	`}`
Original file line number	Diff line number	Diff line change
`@@ -7,6 +7,8 @@`
`7`	`7`	`import com.freenow.sauron.plugins.SauronExtension;`
`8`	`8`	`import com.freenow.sauron.properties.PipelineConfigurationProperties;`
`9`	`9`	`import com.freenow.sauron.properties.PluginsConfigurationProperties;`
	`10`	`+import io.micrometer.core.instrument.MeterRegistry;`
	`11`	`+import io.micrometer.core.instrument.Timer;`
`10`	`12`	`import java.util.List;`
`11`	`13`	`import lombok.extern.slf4j.Slf4j;`
`12`	`14`	`import org.apache.commons.lang3.StringUtils;`
`@@ -21,8 +23,6 @@`
`21`	`23`	`@EnableConfigurationProperties({PipelineConfigurationProperties.class, PluginsConfigurationProperties.class})`
`22`	`24`	`public class PipelineService`
`23`	`25`	`{`
`24`		`- private static final String ELASTICSEARCH_OUTPUT_PLUGIN = "elasticsearch-output";`
`25`		`-`
`26`	`26`	`private final PipelineConfigurationProperties pipelineProperties;`
`27`	`27`
`28`	`28`	`private final PluginsConfigurationProperties pluginsProperties;`
`@@ -31,18 +31,22 @@ public class PipelineService`
`31`	`31`
`32`	`32`	`private final RequestHandler handler;`
`33`	`33`
	`34`	`+ private final MeterRegistry meterRegistry;`
	`35`	`+`
`34`	`36`
`35`	`37`	`@Autowired`
`36`	`38`	`public PipelineService(`
`37`	`39`	`PluginManager pluginManager,`
`38`	`40`	`PipelineConfigurationProperties pipelineProperties,`
`39`	`41`	`PluginsConfigurationProperties pluginsProperties,`
`40`		`- RequestHandler handler)`
	`42`	`+ RequestHandler handler,`
	`43`	`+ MeterRegistry meterRegistry)`
`41`	`44`	`{`
`42`	`45`	`this.pluginManager = pluginManager;`
`43`	`46`	`this.pipelineProperties = pipelineProperties;`
`44`	`47`	`this.pluginsProperties = pluginsProperties;`
`45`	`48`	`this.handler = handler;`
	`49`	`+ this.meterRegistry = meterRegistry;`
`46`	`50`	`handler.setConsumer(this::process);`
`47`	`51`	`}`
`48`	`52`
`@@ -51,6 +55,7 @@ public void publish(BuildRequest request)`
`51`	`55`	`{`
`52`	`56`	`try`
`53`	`57`	`{`
	`58`	`+ log.info("Received request to publish: serviceName={}, commitId={}", request.getServiceName(), request.getCommitId());`
`54`	`59`	`handler.handle(request);`
`55`	`60`	`}`
`56`	`61`	`catch (Exception ex)`
`@@ -64,68 +69,103 @@ void process(BuildRequest request)`
`64`	`69`	`{`
`65`	`70`	`try`
`66`	`71`	`{`
`67`		`- final DataSet dataSet = BuildMapper.makeDataSet(request);`
	`72`	`+ log.info("Starting processing for request: serviceName={}, commitId={}", request.getServiceName(), request.getCommitId());`
	`73`	`+ DataSet dataSet = BuildMapper.makeDataSet(request);`
	`74`	`+ log.debug("Initial DataSet created from request: {}", dataSet);`
`68`	`75`	`String plugin = request.getPlugin();`
`69`	`76`
`70`	`77`	`if (StringUtils.isNotBlank(plugin))`
`71`	`78`	`{`
`72`	`79`	`plugin = StringUtils.lowerCase(request.getPlugin());`
`73`	`80`	`final List<String> defaultPipeline = pipelineProperties.getDefaultPipeline();`
`74`	`81`
`75`		`- log.debug("Running user defined pipeline.");`
	`82`	`+ log.debug("User-defined plugin specified: {}. Running user defined pipeline. Default pipeline plugins: {}", plugin, defaultPipeline);`
`76`	`83`
`77`	`84`	`if (defaultPipeline.contains(plugin))`
`78`	`85`	`{`
`79`		`- runDependencies(request, dataSet, plugin, defaultPipeline);`
	`86`	`+ log.debug("User-defined plugin '{}' is part of the default pipeline. Running dependencies first.", plugin);`
	`87`	`+ runDependencies(dataSet, plugin, defaultPipeline);`
`80`	`88`	`}`
`81`	`89`
`82`		`- runPlugin(plugin, request, dataSet);`
`83`		`- runPlugin(ELASTICSEARCH_OUTPUT_PLUGIN, request, dataSet);`
	`90`	`+ log.debug("Executing user-defined plugin: {}", plugin);`
	`91`	`+ runPlugin(plugin, dataSet);`
	`92`	`+`
	`93`	`+ String mandatoryOutputPlugin = pipelineProperties.getMandatoryOutputPlugin();`
	`94`	`+ if (StringUtils.isNotBlank(mandatoryOutputPlugin)) {`
	`95`	`+ log.debug("Executing mandatory output plugin: {}", mandatoryOutputPlugin);`
	`96`	`+ runPlugin(mandatoryOutputPlugin, dataSet);`
	`97`	`+ }`
`84`	`98`	`}`
`85`	`99`	`else`
`86`	`100`	`{`
`87`		`- log.debug("Running default pipeline.");`
`88`		`- pipelineProperties.getDefaultPipeline().forEach(pluginId -> runPlugin(pluginId, request, dataSet));`
	`101`	`+ log.debug("No user-defined plugin. Running default pipeline. Default pipeline plugins: {}", pipelineProperties.getDefaultPipeline());`
	`102`	`+ pipelineProperties.getDefaultPipeline().forEach(pluginId -> runPlugin(pluginId, dataSet));`
`89`	`103`	`}`
`90`	`104`	`}`
`91`	`105`	`catch (final Exception ex)`
`92`	`106`	`{`
`93`		`- log.error(String.format("Error loading plugins: %s", ex.getMessage()), ex);`
	`107`	`+ log.error("Error processing request for serviceName={}, commitId={}", request.getServiceName(), request.getCommitId(), ex);`
`94`	`108`	`}`
`95`	`109`	`}`
`96`	`110`
`97`	`111`
`98`	`112`	`private void runDependencies(`
`99`		`- final BuildRequest request, final DataSet dataSet,`
`100`		`- final String plugin, final List<String> defaultPipeline)`
	`113`	`+ DataSet dataSet, final String plugin, final List<String> defaultPipeline)`
`101`	`114`	`{`
`102`	`115`	`for (final String defaultPipelinePlugin : defaultPipeline)`
`103`	`116`	`{`
`104`	`117`	`if (StringUtils.equals(plugin, defaultPipelinePlugin))`
`105`	`118`	`{`
	`119`	`+ log.debug("Dependency plugin '{}' is the main plugin '{}', skipping further dependencies.", defaultPipelinePlugin, plugin);`
`106`	`120`	`return;`
`107`	`121`	`}`
`108`	`122`
`109`		`- runPlugin(defaultPipelinePlugin, request, dataSet);`
	`123`	`+ log.debug("Running dependency plugin: {} for main plugin: {}", defaultPipelinePlugin, plugin);`
	`124`	`+ runPlugin(defaultPipelinePlugin, dataSet);`
`110`	`125`	`}`
`111`	`126`	`}`
`112`	`127`
`113`	`128`
`114`		`- void runPlugin(String plugin, BuildRequest request, DataSet dataSet)`
	`129`	`+ void runPlugin(String plugin, DataSet dataSet)`
`115`	`130`	`{`
`116`		`- pluginManager.getExtensions(SauronExtension.class, plugin).forEach(pluginExtension -> {`
	`131`	`+ for (SauronExtension pluginExtension : pluginManager.getExtensions(SauronExtension.class, plugin))`
	`132`	`+ {`
`117`	`133`	`try`
`118`	`134`	`{`
`119`		`- log.debug(String.format("Applying pluginId: %s. Processing service %s - %s", plugin, request.getServiceName(), request.getCommitId()));`
`120`	`135`	`MDC.put("sauron.pluginId", plugin);`
`121`		`- MDC.put("sauron.serviceName", request.getServiceName());`
`122`		`- MDC.put("sauron.commitId", request.getCommitId());`
`123`		`- pluginExtension.apply(pluginsProperties, dataSet);`
	`136`	`+ MDC.put("sauron.serviceName", dataSet.getServiceName());`
	`137`	`+ MDC.put("sauron.commitId", dataSet.getCommitId());`
	`138`	`+ MDC.put("sauron.buildId", dataSet.getBuildId());`
	`139`	`+ log.debug("Applying pluginId: {}. Processing service {} - {}. DataSet BEFORE plugin execution: {}", plugin, dataSet.getServiceName(), dataSet.getCommitId(),`
	`140`	`+ dataSet);`
	`141`	`+`
	`142`	`+ getTimerBuilder("sauron.plugin.execution.time")`
	`143`	`+ .tag("plugin", plugin)`
	`144`	`+ .tag("service", dataSet.getServiceName())`
	`145`	`+ .tag("commit", dataSet.getCommitId())`
	`146`	`+ .register(meterRegistry).record(() -> pluginExtension.apply(pluginsProperties, dataSet));`
	`147`	`+`
	`148`	`+ meterRegistry.counter("sauron.plugin.executions.total", "plugin", plugin, "result", "success").increment();`
	`149`	`+ log.debug("PluginId: {} applied. Processing service {} - {}. DataSet AFTER plugin execution: {}", plugin, dataSet.getServiceName(), dataSet.getCommitId(), dataSet);`
`124`	`150`	`}`
`125`	`151`	`catch (final Exception ex)`
`126`	`152`	`{`
`127`		`- log.error(String.format("Error processing pipeline: %s:%s. %s", request.getServiceName(), request.getCommitId(), ex.getMessage()), ex);`
	`153`	`+ meterRegistry.counter("sauron.plugin.executions.total", "plugin", plugin, "result", "failure").increment();`
	`154`	`+ log.error("Error in plugin '{}' for serviceName={}, commitId={}. DataSet at time of failure: {}", plugin, dataSet.getServiceName(), dataSet.getCommitId(), dataSet, ex);`
	`155`	`+ }`
	`156`	`+ finally`
	`157`	`+ {`
	`158`	`+ MDC.remove("sauron.pluginId");`
	`159`	`+ MDC.remove("sauron.serviceName");`
	`160`	`+ MDC.remove("sauron.commitId");`
	`161`	`+ MDC.remove("sauron.buildId");`
`128`	`162`	`}`
`129`		`- });`
	`163`	`+ }`
	`164`	`+ }`
	`165`	`+`
	`166`	`+`
	`167`	`+ Timer.Builder getTimerBuilder(String name)`
	`168`	`+ {`
	`169`	`+ return Timer.builder(name);`
`130`	`170`	`}`
`131`	`171`	`}`