Add base logging to composite readers

Change-Id: I6340787f39b9f88fff99190271f74e991b5a7888
Signed-off-by: Maros Marsalek <mmarsale@cisco.com>

4 files changed, 64 insertions, 23 deletions

diff --git a/v3po/impl/pom.xml b/v3po/impl/pom.xml
index 778d81484..1498d82f8 100644
--- a/v3po/impl/pom.xml
+++ b/v3po/impl/pom.xml
@@ -71,5 +71,11 @@
       <version>1.5.6</version>
       <scope>test</scope>
     </dependency>
+    <dependency>
+      <groupId>org.skinny-framework</groupId>
+      <artifactId>skinny-logback</artifactId>
+      <version>1.0.8</version>
+      <scope>test</scope>
+    </dependency>
   </dependencies>
 </project>
diff --git a/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/impl/AbstractCompositeVppReader.java b/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/impl/AbstractCompositeVppReader.java
index 82a365a42..456737f37 100644
--- a/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/impl/AbstractCompositeVppReader.java
+++ b/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/impl/AbstractCompositeVppReader.java
@@ -38,11 +38,13 @@ import org.opendaylight.yangtools.yang.binding.ChildOf;
 import org.opendaylight.yangtools.yang.binding.DataObject;
 import org.opendaylight.yangtools.yang.binding.Identifier;
 import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 @Beta
 abstract class AbstractCompositeVppReader<D extends DataObject, B extends Builder<D>> implements VppReader<D> {
 
-    // TODO add debug + trace logs here and there
+    private static final Logger LOG = LoggerFactory.getLogger(AbstractCompositeVppReader.class);
 
     private final Map<Class<? extends DataObject>, ChildVppReader<? extends ChildOf<D>>> childReaders;
     private final Map<Class<? extends DataObject>, ChildVppReader<? extends Augmentation<D>>> augReaders;
@@ -66,33 +68,40 @@ abstract class AbstractCompositeVppReader<D extends DataObject, B extends Builde
      * @param id {@link InstanceIdentifier} pointing to current node. In case of keyed list, key must be present.
      */
     protected List<D> readCurrent(final InstanceIdentifier<D> id) {
+        LOG.debug("{}: Reading current: {}", this, id);
         final B builder = getBuilder(id);
         // Cache empty value to determine if anything has changed later TODO cache in a field
         final D emptyValue = builder.build();
 
+        LOG.trace("{}: Reading current attributes", this);
         readCurrentAttributes(id, builder);
 
         // TODO expect exceptions from reader
         for (ChildVppReader<? extends ChildOf<D>> child : childReaders.values()) {
+            LOG.debug("{}: Reading child from: {}", this, child);
             child.read(id, builder);
         }
 
         for (ChildVppReader<? extends Augmentation<D>> child : augReaders.values()) {
+            LOG.debug("{}: Reading augment from: {}", this, child);
             child.read(id, builder);
         }
 
         // Need to check whether anything was filled in to determine if data is present or not.
         final D built = builder.build();
-        return built.equals(emptyValue) ? Collections.<D>emptyList() : Collections.singletonList(built);
+        final List<D> read = built.equals(emptyValue)
+            ? Collections.<D>emptyList()
+            : Collections.singletonList(built);
+
+        LOG.debug("{}: Current node read successfully. Result: {}", this, read);
+        return read;
     }
 
     @Nonnull
     @Override
     @SuppressWarnings("unchecked")
     public List<? extends DataObject> read(@Nonnull final InstanceIdentifier<? extends DataObject> id) {
-        // This is read for one of children, we need to read and then filter, not parent)
-
-        // If this is target, just read
+        LOG.trace("{}: Reading : {}", this, id);
         if (id.getTargetType().equals(getManagedDataObjectType().getTargetType())) {
             return readCurrent((InstanceIdentifier<D>) id);
         } else {
@@ -101,18 +110,25 @@ abstract class AbstractCompositeVppReader<D extends DataObject, B extends Builde
     }
 
     private List<? extends DataObject> readSubtree(final InstanceIdentifier<? extends DataObject> id) {
-        // Read only specific subtree
+        LOG.debug("{}: Reading subtree: {}", this, id);
         final Class<? extends DataObject> next = VppRWUtils.getNextId(id, getManagedDataObjectType()).getType();
         final ChildVppReader<? extends ChildOf<D>> vppReader = childReaders.get(next);
 
         if (vppReader != null) {
+            LOG.debug("{}: Reading subtree: {} from: {}", this, id, vppReader);
             return vppReader.read(id);
         } else {
+            LOG.debug("{}: Dedicated subtree reader missing for: {}. Reading current and filtering", this, next);
             // If there's no dedicated reader, use read current
             final InstanceIdentifier<D> currentId = VppRWUtils.cutId(id, getManagedDataObjectType());
             final List<D> current = readCurrent(currentId);
             // then perform post-reading filtering (return only requested sub-node)
-            return current.isEmpty() ? current : filterSubtree(current, id, getManagedDataObjectType().getTargetType()) ;
+            final List<? extends DataObject> readSubtree = current.isEmpty()
+                ? current
+                : filterSubtree(current, id, getManagedDataObjectType().getTargetType());
+
+            LOG.debug("{}: Subtree: {} read successfully. Result: {}", this, id, readSubtree);
+            return readSubtree;
         }
     }
 
@@ -203,4 +219,9 @@ abstract class AbstractCompositeVppReader<D extends DataObject, B extends Builde
             throw new IllegalArgumentException("Unable to get " + nextId + " from " + parent, e);
         }
     }
+
+    @Override
+    public String toString() {
+        return String.format("Reader[%s]", getManagedDataObjectType().getTargetType().getSimpleName());
+    }
 }
diff --git a/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/impl/CompositeListVppReader.java b/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/impl/CompositeListVppReader.java
index bc49a8fc7..74ca40696 100644
--- a/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/impl/CompositeListVppReader.java
+++ b/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/impl/CompositeListVppReader.java
@@ -20,11 +20,10 @@ import static com.google.common.base.Preconditions.checkArgument;
 import static com.google.common.base.Preconditions.checkState;
 
 import com.google.common.annotations.Beta;
-import com.google.common.base.Function;
-import com.google.common.collect.Lists;
 import io.fd.honeycomb.v3po.impl.trans.r.ChildVppReader;
 import io.fd.honeycomb.v3po.impl.trans.r.impl.spi.ListVppReaderCustomizer;
 import io.fd.honeycomb.v3po.impl.trans.r.util.VppRWUtils;
+import java.util.ArrayList;
 import java.util.List;
 import javax.annotation.Nonnull;
 import javax.annotation.concurrent.ThreadSafe;
@@ -35,6 +34,8 @@ import org.opendaylight.yangtools.yang.binding.DataObject;
 import org.opendaylight.yangtools.yang.binding.Identifiable;
 import org.opendaylight.yangtools.yang.binding.Identifier;
 import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * Composite implementation of {@link ChildVppReader} able to place the read result into
@@ -48,6 +49,8 @@ import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
 public final class CompositeListVppReader<C extends DataObject & Identifiable<K>, K extends Identifier<C>, B extends Builder<C>>
     extends AbstractCompositeVppReader<C, B> implements ChildVppReader<C> {
 
+    private static final Logger LOG = LoggerFactory.getLogger(CompositeListVppReader.class);
+
     private final ListVppReaderCustomizer<C, K, B> customizer;
 
     /**
@@ -101,19 +104,22 @@ public final class CompositeListVppReader<C extends DataObject & Identifiable<K>
     }
 
     private List<C> readList(@Nonnull final InstanceIdentifier<C> id) {
-        return Lists.transform(customizer.getAllIds(id), new Function<K, C>() {
-                @Override
-                public C apply(final K key) {
-                    final InstanceIdentifier.IdentifiableItem<C, K> currentBdItem =
-                        VppRWUtils.getCurrentIdItem(id, key);
-                    final InstanceIdentifier<C> keyedId = VppRWUtils.replaceLastInId(id, currentBdItem);
-                    final List<? extends DataObject> read = read(keyedId);
-                    checkState(read.size() == 1);
-                    final DataObject singleItem = read.get(0);
-                    checkArgument(getManagedDataObjectType().getTargetType().isAssignableFrom(singleItem.getClass()));
-                    return getManagedDataObjectType().getTargetType().cast(singleItem);
-                }
-            });
+        LOG.trace("{}: Reading all list entries", this);
+        final List<K> allIds = customizer.getAllIds(id);
+        LOG.debug("{}: Reading list entries for: {}", this, allIds);
+
+        final ArrayList<C> allEntries = new ArrayList<>(allIds.size());
+        for (K key : allIds) {
+            final InstanceIdentifier.IdentifiableItem<C, K> currentBdItem =
+                VppRWUtils.getCurrentIdItem(id, key);
+            final InstanceIdentifier<C> keyedId = VppRWUtils.replaceLastInId(id, currentBdItem);
+            final List<? extends DataObject> read = readCurrent(keyedId);
+            checkState(read.size() == 1);
+            final DataObject singleItem = read.get(0);
+            checkArgument(getManagedDataObjectType().getTargetType().isAssignableFrom(singleItem.getClass()));
+            allEntries.add(getManagedDataObjectType().getTargetType().cast(singleItem));
+        }
+        return allEntries;
     }
 
      private boolean shouldReadAll(@Nonnull final InstanceIdentifier<? extends DataObject> id) {
diff --git a/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/util/DelegatingReaderRegistry.java b/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/util/DelegatingReaderRegistry.java
index 9e672c92f..61435d9ed 100644
--- a/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/util/DelegatingReaderRegistry.java
+++ b/v3po/impl/src/main/java/io/fd/honeycomb/v3po/impl/trans/r/util/DelegatingReaderRegistry.java
@@ -27,6 +27,8 @@ import java.util.Map;
 import javax.annotation.Nonnull;
 import org.opendaylight.yangtools.yang.binding.DataObject;
 import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 /**
  * Simple reader registry able to perform and aggregated read (ROOT read) on top of all
@@ -36,6 +38,8 @@ import org.opendaylight.yangtools.yang.binding.InstanceIdentifier;
  */
 public final class DelegatingReaderRegistry implements ReaderRegistry {
 
+    private static final Logger LOG = LoggerFactory.getLogger(DelegatingReaderRegistry.class);
+
     private final Map<Class<? extends DataObject>, VppReader<? extends DataObject>> rootReaders;
 
     /**
@@ -50,8 +54,12 @@ public final class DelegatingReaderRegistry implements ReaderRegistry {
     @Override
     @Nonnull
     public List<? extends DataObject> readAll() {
+        LOG.debug("Reading from all delegates");
+        LOG.trace("Reading from all delegates: {}", rootReaders.values());
+
         final List<DataObject> objects = new ArrayList<>(rootReaders.size());
         for (VppReader<? extends DataObject> rootReader : rootReaders.values()) {
+            LOG.debug("Reading from delegate: {}", rootReader);
             final List<? extends DataObject> read = rootReader.read(rootReader.getManagedDataObjectType());
             objects.addAll(read);
         }
@@ -66,6 +74,7 @@ public final class DelegatingReaderRegistry implements ReaderRegistry {
         final VppReader<? extends DataObject> vppReader = rootReaders.get(first.getType());
         checkNotNull(vppReader,
             "Unable to read %s. Missing reader. Current readers for: %s", id, rootReaders.keySet());
+        LOG.debug("Reading from delegate: {}", vppReader);
         return vppReader.read(id);
     }
 
@@ -78,5 +87,4 @@ public final class DelegatingReaderRegistry implements ReaderRegistry {
     public InstanceIdentifier<DataObject> getManagedDataObjectType() {
         throw new UnsupportedOperationException("Root registry has no type");
     }
-
 }