[java-metadata-aggregator] 02/02: MDA-282 - Add progress logging for CompositeStage and SimplePipeline

Ian Young ian at iay.org.uk
Mon Apr 3 11:09:24 UTC 2023


This is an automated email from the git hooks/post-receive script.

iay pushed a commit to branch main
in repository java-metadata-aggregator.

View the commit online:
http://git.shibboleth.net/view/?p=java-metadata-aggregator.git;a=commit;h=00cddc22fc7a1904935c98892f5b4357bb879ac8

commit 00cddc22fc7a1904935c98892f5b4357bb879ac8
Author: Ian Young <ian at iay.org.uk>
AuthorDate: Mon Apr 3 12:09:11 2023 +0100

    MDA-282 - Add progress logging for CompositeStage and SimplePipeline
    
    https://shibboleth.atlassian.net/browse/MDA-282
---
 .../metadata/pipeline/CompositeStage.java          | 78 ++++++++++++++++++++-
 .../metadata/pipeline/CompositeStageTest.java      | 81 ++++++++++++++++++++++
 2 files changed, 157 insertions(+), 2 deletions(-)

diff --git a/mda-framework/src/main/java/net/shibboleth/metadata/pipeline/CompositeStage.java b/mda-framework/src/main/java/net/shibboleth/metadata/pipeline/CompositeStage.java
index 5845989..f070182 100644
--- a/mda-framework/src/main/java/net/shibboleth/metadata/pipeline/CompositeStage.java
+++ b/mda-framework/src/main/java/net/shibboleth/metadata/pipeline/CompositeStage.java
@@ -17,18 +17,23 @@
 
 package net.shibboleth.metadata.pipeline;
 
+import java.time.Duration;
+import java.time.Instant;
 import java.util.List;
 
 import javax.annotation.Nonnull;
 import javax.annotation.concurrent.GuardedBy;
 import javax.annotation.concurrent.ThreadSafe;
 
+import org.slf4j.Logger;
+
 import net.shibboleth.metadata.Item;
 import net.shibboleth.shared.annotation.constraint.NonnullElements;
 import net.shibboleth.shared.annotation.constraint.Unmodifiable;
 import net.shibboleth.shared.component.ComponentInitializationException;
 import net.shibboleth.shared.primitive.DeprecationSupport;
 import net.shibboleth.shared.primitive.DeprecationSupport.ObjectType;
+import net.shibboleth.shared.primitive.LoggerFactory;
 
 /**
  * A stage that is composed of other stages. This allows a collection of stages to be grouped together and for that
@@ -43,9 +48,39 @@ import net.shibboleth.shared.primitive.DeprecationSupport.ObjectType;
 @ThreadSafe
 public class CompositeStage<T> extends AbstractStage<T> implements Pipeline<T> {
 
+    /**
+     * Class logger.
+     *
+     * @since 0.10.0
+     */
+    private static final @Nonnull Logger LOG = LoggerFactory.getLogger(CompositeStage.class);
+
+    /**
+     * Whether we are logging progress for all instances, regardless of their
+     * {@link #loggingProgress} settings.
+     *
+     * <p>
+     * To enable this feature, define the system property
+     * <code>net.shibboleth.metadata.loggingAllProgress</code>
+     * to the token <code>true</code>.
+     * </p>
+     */
+    private static final boolean LOGGING_ALL_PROGRESS =
+            Boolean.parseBoolean(System.getProperty("net.shibboleth.metadata.loggingAllProgress"));
+
     /** Stages which compose this stage. */
     @Nonnull @NonnullElements @Unmodifiable @GuardedBy("this")
     private List<Stage<T>> composedStages = List.of();
+    
+    /**
+     * Whether we are logging progress through the stages.
+     *
+     * <p>Default value: <code>false</code></p>
+     *
+     * @since 0.10.0
+     */
+    @GuardedBy("this")
+    private boolean loggingProgress;
 
     /**
      * Gets an unmodifiable list of the stages that compose this stage.
@@ -102,11 +137,50 @@ public class CompositeStage<T> extends AbstractStage<T> implements Pipeline<T> {
         setStages(stages);
     }
 
+    /**
+     * Returns whether we are logging progress.
+     *
+     * @return <code>true</code> if we are logging progress
+     *
+     * @since 0.10.0
+     */
+    public final synchronized boolean isLoggingProgress() {
+        return loggingProgress;
+    }
+
+    /**
+     * Sets whether we are logging progress.
+     *
+     * @param log <code>true</code> to log progress
+     *
+     * @since 0.10.0
+     */
+    public final synchronized void setLoggingProgress(final boolean log) {
+        checkSetterPreconditions();
+        loggingProgress = log;
+    }
+
     @Override
     protected void doExecute(@Nonnull @NonnullElements final List<Item<T>> items)
             throws StageProcessingException {
-        for (final Stage<T> stage : getStages()) {
-            stage.execute(items);
+        if (LOGGING_ALL_PROGRESS || isLoggingProgress()) {            
+            final var id = getId();
+            final var start = Instant.now();
+            for (final Stage<T> stage : getStages()) {
+                final var stageId = stage.getId();
+                final var stageStart = Instant.now();
+                LOG.info("{} >>> {}, count={}", id, stageId, items.size());
+                stage.execute(items);
+                final var stageEnd = Instant.now();
+                final var stageTime = Duration.between(stageStart, stageEnd);
+                LOG.info("{} <<< {}, count={}, duration={}", id, stageId,
+                        items.size(), stageTime);
+            }
+            LOG.info("{} completed, duration={}", id, Duration.between(start, Instant.now()));
+        } else {
+            for (final Stage<T> stage : getStages()) {
+                stage.execute(items);
+            }
         }
     }
 
diff --git a/mda-framework/src/test/java/net/shibboleth/metadata/pipeline/CompositeStageTest.java b/mda-framework/src/test/java/net/shibboleth/metadata/pipeline/CompositeStageTest.java
index 7f8be95..6f6c0c0 100644
--- a/mda-framework/src/test/java/net/shibboleth/metadata/pipeline/CompositeStageTest.java
+++ b/mda-framework/src/test/java/net/shibboleth/metadata/pipeline/CompositeStageTest.java
@@ -3,15 +3,44 @@ package net.shibboleth.metadata.pipeline;
 
 import java.util.List;
 
+import org.slf4j.LoggerFactory;
 import org.testng.Assert;
+import org.testng.annotations.AfterMethod;
+import org.testng.annotations.BeforeMethod;
 import org.testng.annotations.Test;
 
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
 import net.shibboleth.metadata.Item;
 import net.shibboleth.metadata.MockItem;
 import net.shibboleth.metadata.TestMarker;
 
 public class CompositeStageTest {
 
+    private Logger logger;
+    private ListAppender<ILoggingEvent> listAppender;
+
+    @BeforeMethod
+    private void initializeLogger() {
+        // Find the (logback) logger for the class under test
+        logger = (Logger)LoggerFactory.getLogger(CompositeStage.class);
+
+        // Create and start a ListAppender
+        listAppender = new ListAppender<>();
+        listAppender.start();
+
+        // Add the appender to the logger.
+        logger.addAppender(listAppender);
+    }
+    
+    @AfterMethod
+    private void terminateLogger() {
+        logger.detachAppender(listAppender);
+        listAppender.stop();
+    }
+
     @Test
     public void doExecute0Test() throws Exception {
         final var stage = new CompositeStage<String>();
@@ -72,6 +101,58 @@ public class CompositeStageTest {
         stage.destroy();
     }
 
+    @Test
+    public void testNotLogging() throws Exception {
+    	final var marker = new MarkerStage<String>();
+    	marker.setId("marker");
+        marker.initialize();
+
+        final var stage = new CompositeStage<String>();
+        stage.setId("test");
+        stage.setStages(List.of(marker, marker));
+        stage.initialize();
+        Assert.assertFalse(stage.isLoggingProgress());
+        Assert.assertEquals(stage.getStages().size(), 2);
+
+        final var items = List.<Item<String>>of(new MockItem("hello"));
+        stage.execute(items);
+        stage.destroy();
+        
+        marker.destroy();
+
+        // No logging has been performed
+        final var logsList = listAppender.list;
+        Assert.assertEquals(logsList.size(), 0);
+    }
+
+    @Test
+    public void testLogging() throws Exception {
+    	final var marker = new MarkerStage<String>();
+    	marker.setId("marker");
+        marker.initialize();
+
+        final var stage = new CompositeStage<String>();
+        stage.setId("test");
+        stage.setStages(List.of(marker, marker));
+        stage.setLoggingProgress(true);
+        stage.initialize();
+        Assert.assertTrue(stage.isLoggingProgress());
+        Assert.assertEquals(stage.getStages().size(), 2);
+
+        final var items = List.<Item<String>>of(new MockItem("hello"));
+        stage.execute(items);
+        stage.destroy();
+        
+        marker.destroy();
+
+        // Two log lines from each stage, plus one from the composite.
+        final var logsList = listAppender.list;
+        Assert.assertEquals(logsList.size(), 5);
+        for (final var line : logsList) {
+        	Assert.assertEquals(line.getLevel(), Level.INFO);
+        }
+    }
+
     @Test
     public void testDeprecatedMethods() throws Exception {
         final var marker = new MarkerStage<String>();

-- 
To stop receiving notification emails like this one, please contact
the administrator of this repository.


More information about the commits mailing list