BUG-6522: Improve parser reactor logging

Add a few logging calls and implement toString() methods
so that the reactor progress can be observed.

Change-Id: Id475ba3aaba75040fe523b1d43c23e893ad25464
Signed-off-by: Robert Varga <rovarga@cisco.com>
(cherry picked from commit 5b290448af7fb73d73ae22b2647c03b2457728fb)

diff --git a/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/ModifierImpl.java b/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/ModifierImpl.java
index 530b38984bd58fd2d44a385a485893f704d0fa13..e2778d90bcc9a6078aa9b1e1193f303d2dee0146 100644 (file)
--- a/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/ModifierImpl.java
+++ b/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/ModifierImpl.java
@@ -9,7 +9,10 @@ package org.opendaylight.yangtools.yang.parser.stmt.reactor;
 
 import static org.opendaylight.yangtools.yang.parser.spi.meta.ModelProcessingPhase.EFFECTIVE_MODEL;
 import static org.opendaylight.yangtools.yang.parser.spi.meta.ModelProcessingPhase.FULL_DECLARATION;
+
 import com.google.common.base.Function;
+import com.google.common.base.MoreObjects;
+import com.google.common.base.MoreObjects.ToStringHelper;
 import com.google.common.base.Preconditions;
 import java.util.HashSet;
 import java.util.Iterator;
@@ -27,12 +30,15 @@ import org.opendaylight.yangtools.yang.parser.spi.source.SourceException;
 import org.opendaylight.yangtools.yang.parser.stmt.reactor.StatementContextBase.ContextMutation;
 import org.opendaylight.yangtools.yang.parser.stmt.reactor.StatementContextBase.OnNamespaceItemAdded;
 import org.opendaylight.yangtools.yang.parser.stmt.reactor.StatementContextBase.OnPhaseFinished;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 class ModifierImpl implements ModelActionBuilder {
+    private static final Logger LOG = LoggerFactory.getLogger(ModifierImpl.class);
 
-    private final ModelProcessingPhase phase;
     private final Set<AbstractPrerequisite<?>> unsatisfied = new HashSet<>();
     private final Set<AbstractPrerequisite<?>> mutations = new HashSet<>();
+    private final ModelProcessingPhase phase;
 
     private InferenceAction action;
     private boolean actionApplied = false;
@@ -42,32 +48,34 @@ class ModifierImpl implements ModelActionBuilder {
     }
 
     private <D> AbstractPrerequisite<D> addReq(final AbstractPrerequisite<D> prereq) {
+        LOG.trace("Modifier {} adding prerequisite {}", this, prereq);
         unsatisfied.add(prereq);
         return prereq;
     }
 
     private <T> AbstractPrerequisite<T> addMutation(final AbstractPrerequisite<T> mutation) {
+        LOG.trace("Modifier {} adding mutation {}", this, mutation);
         mutations.add(mutation);
         return mutation;
     }
 
-
-
     private void checkNotRegistered() {
         Preconditions.checkState(action == null, "Action was already registered.");
     }
 
     private static IllegalStateException shouldNotHappenProbablyBug(final SourceException e) {
-        return new IllegalStateException("Source exception during registering prerequisite. This is probably bug.",e);
+        return new IllegalStateException("Source exception during registering prerequisite. This is probably bug.", e);
     }
 
     private boolean removeSatisfied() {
-        Iterator<AbstractPrerequisite<?>> prereq = unsatisfied.iterator();
+        Iterator<AbstractPrerequisite<?>> it = unsatisfied.iterator();
         boolean allSatisfied = true;
-        while (prereq.hasNext()) {
-            if (prereq.next().isDone()) {
+        while (it.hasNext()) {
+            final AbstractPrerequisite<?> prereq = it.next();
+            if (prereq.isDone()) {
                 // We are removing current prerequisite from list.
-                prereq.remove();
+                LOG.trace("Modifier {} prerequisite {} satisfied", this, prereq);
+                it.remove();
             } else {
                 allSatisfied  = false;
             }
@@ -80,7 +88,6 @@ class ModifierImpl implements ModelActionBuilder {
     }
 
     boolean isApplied() {
-
         return actionApplied;
     }
 
@@ -160,7 +167,7 @@ class ModifierImpl implements ModelActionBuilder {
     }
 
     @Override
-    public  <A,D extends DeclaredStatement<A>,E extends EffectiveStatement<A, D>> AbstractPrerequisite<StmtContext<A, D, E>> requiresCtx(final StmtContext<A, D, E> context, final ModelProcessingPhase phase) {
+    public <A,D extends DeclaredStatement<A>,E extends EffectiveStatement<A, D>> AbstractPrerequisite<StmtContext<A, D, E>> requiresCtx(final StmtContext<A, D, E> context, final ModelProcessingPhase phase) {
         return requiresCtxImpl(context, phase);
     }
 
@@ -222,46 +229,42 @@ class ModifierImpl implements ModelActionBuilder {
         return mutatesCtx(stmt, EFFECTIVE_MODEL);
     }
 
-
    @Override
     public <K, E extends EffectiveStatement<?, ?>, N extends IdentifierNamespace<K, ? extends StmtContext<?, ?, ?>>> AbstractPrerequisite<Mutable<?, ?, E>> mutatesEffectiveCtx(
             final StmtContext<?, ?, ?> context, final Class<N> namespace, final K key) {
         return mutatesCtxImpl(context, namespace, key, EFFECTIVE_MODEL);
     }
 
-
-
     @Override
     public void apply(final InferenceAction action) {
+        Preconditions.checkState(this.action == null, "Action already defined to %s", this.action);
         this.action = Preconditions.checkNotNull(action);
     }
 
     private abstract class AbstractPrerequisite<T> implements Prerequisite<T> {
 
-        private T value;
         private boolean done = false;
+        private T value;
 
         @Override
-        public T get() {
+        public final T get() {
             Preconditions.checkState(isDone());
             return value;
         }
 
         @Override
-        public boolean isDone() {
+        public final boolean isDone() {
             return done;
         }
 
-        protected boolean resolvePrereq(final T value) {
+        final boolean resolvePrereq(final T value) {
             this.value = value;
             this.done = true;
             return isApplied();
         }
 
-        protected <O> Prerequisite<O> transform(final Function<? super T,O> transformation) {
-
+        final <O> Prerequisite<O> transform(final Function<? super T,O> transformation) {
             return new Prerequisite<O>() {
-
                 @Override
                 public O get() {
                     return transformation.apply(AbstractPrerequisite.this.get());
@@ -271,14 +274,20 @@ class ModifierImpl implements ModelActionBuilder {
                 public boolean isDone() {
                     return AbstractPrerequisite.this.isDone();
                 }
-
             };
         }
 
+        @Override
+        public final String toString() {
+            return addToStringAttributes(MoreObjects.toStringHelper(this).omitNullValues()).toString();
+        }
+
+        ToStringHelper addToStringAttributes(final ToStringHelper toStringHelper) {
+            return toStringHelper.add("value", value);
+        }
     }
 
     private class PhaseMutation<C> extends AbstractPrerequisite<C> implements ContextMutation {
-
         @SuppressWarnings("unchecked")
         public PhaseMutation(final StatementContextBase<?, ?, ?> context, final ModelProcessingPhase phase) {
             context.addMutation(phase, this);
@@ -289,11 +298,9 @@ class ModifierImpl implements ModelActionBuilder {
         public boolean isFinished() {
             return isApplied();
         }
-
-
     }
-    private class PhaseFinished<C extends StmtContext<?, ?, ?>> extends AbstractPrerequisite<C> implements OnPhaseFinished {
 
+    private class PhaseFinished<C extends StmtContext<?, ?, ?>> extends AbstractPrerequisite<C> implements OnPhaseFinished {
         @SuppressWarnings("unchecked")
         @Override
         public boolean phaseFinished(final StatementContextBase<?, ?, ?> context, final ModelProcessingPhase phase) {
@@ -302,15 +309,12 @@ class ModifierImpl implements ModelActionBuilder {
     }
 
     private class NamespaceMutation<N extends IdentifierNamespace<?,?>> extends  AbstractPrerequisite<StmtContext.Mutable<?, ?, ?>>  {
-
         public NamespaceMutation(final StatementContextBase<?, ?, ?> ctx, final Class<N> namespace) {
             resolvePrereq(ctx);
         }
-
     }
 
     private class AddedToNamespace<C extends StmtContext<?,?,?>> extends  AbstractPrerequisite<C> implements OnNamespaceItemAdded,OnPhaseFinished {
-
         private final ModelProcessingPhase phase;
 
         public <K, N extends StatementNamespace<K, ?, ?>> AddedToNamespace(final ModelProcessingPhase phase) {
@@ -330,10 +334,13 @@ class ModifierImpl implements ModelActionBuilder {
             return resolvePrereq((C) context);
         }
 
+        @Override
+        ToStringHelper addToStringAttributes(final ToStringHelper toStringHelper) {
+            return super.addToStringAttributes(toStringHelper).add("phase", phase);
+        }
     }
 
     private class PhaseModificationInNamespace<C extends Mutable<?,?,?>> extends AbstractPrerequisite<C> implements OnNamespaceItemAdded, ContextMutation {
-
         private final ModelProcessingPhase modPhase;
 
         public <K, N extends StatementNamespace<K, ?, ?>> PhaseModificationInNamespace(final ModelProcessingPhase phase) {
@@ -346,7 +353,7 @@ class ModifierImpl implements ModelActionBuilder {
         public void namespaceItemAdded(final StatementContextBase<?, ?, ?> context, final Class<?> namespace, final Object key,
                 final Object value) {
             StatementContextBase<?, ?, ?> targetCtx = contextImpl(value);
-            targetCtx.addMutation(modPhase,this);
+            targetCtx.addMutation(modPhase, this);
             resolvePrereq((C) targetCtx);
         }
 
@@ -355,5 +362,4 @@ class ModifierImpl implements ModelActionBuilder {
             return isApplied();
         }
     }
-
 }

diff --git a/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/SourceSpecificContext.java b/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/SourceSpecificContext.java
index 5c8f67f31294bf8358e20ba17be2ee48dff48a9a..48447300ef9699139cea6c389d23bf558ef650c1 100644 (file)
--- a/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/SourceSpecificContext.java
+++ b/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/SourceSpecificContext.java
@@ -63,6 +63,8 @@ import org.opendaylight.yangtools.yang.parser.stmt.rfc6020.TypeUtils;
 import org.opendaylight.yangtools.yang.parser.stmt.rfc6020.UnionSpecificationImpl;
 import org.opendaylight.yangtools.yang.parser.stmt.rfc6020.UnknownStatementImpl;
 import org.opendaylight.yangtools.yang.parser.stmt.rfc6020.Utils;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 public class SourceSpecificContext implements NamespaceStorageNode, NamespaceBehaviour.Registry, Mutable {
 
@@ -72,22 +74,24 @@ public class SourceSpecificContext implements NamespaceStorageNode, NamespaceBeh
         FINISHED
     }
 
+    private static final Logger LOG = LoggerFactory.getLogger(SourceSpecificContext.class);
+
     private final StatementStreamSource source;
     private final BuildGlobalContext currentContext;
     private final Collection<NamespaceStorageNode> importedNamespaces = new ArrayList<>();
     private final Multimap<ModelProcessingPhase, ModifierImpl> modifiers = HashMultimap.create();
 
-    private RootStatementContext<?, ?, ?> root;
 
-    private ModelProcessingPhase inProgressPhase;
-    private ModelProcessingPhase finishedPhase = ModelProcessingPhase.INIT;
     private final QNameToStatementDefinitionMap qNameToStmtDefMap = new QNameToStatementDefinitionMap();
     private final PrefixToModuleMap prefixToModuleMap = new PrefixToModuleMap();
 
+    private ModelProcessingPhase finishedPhase = ModelProcessingPhase.INIT;
+    private ModelProcessingPhase inProgressPhase;
+    private RootStatementContext<?, ?, ?> root;
 
     SourceSpecificContext(final BuildGlobalContext currentContext, final StatementStreamSource source) {
-        this.source = source;
         this.currentContext = currentContext;
+        this.source = source;
     }
 
     public boolean isEnabledSemanticVersioning(){
@@ -167,11 +171,11 @@ public class SourceSpecificContext implements NamespaceStorageNode, NamespaceBeh
     }
 
     void startPhase(final ModelProcessingPhase phase) {
-        @Nullable
-        final ModelProcessingPhase previousPhase = phase.getPreviousPhase();
+        @Nullable final ModelProcessingPhase previousPhase = phase.getPreviousPhase();
         Preconditions.checkState(Objects.equals(previousPhase, finishedPhase));
         Preconditions.checkState(modifiers.get(previousPhase).isEmpty());
         inProgressPhase = phase;
+        LOG.debug("Source {} started phase {}", source, phase);
     }
 
     @Override
@@ -241,17 +245,16 @@ public class SourceSpecificContext implements NamespaceStorageNode, NamespaceBeh
         Preconditions.checkNotNull(this.root, "Malformed source. Valid root element is missing.");
         final boolean phaseCompleted = root.tryToCompletePhase(phase);
 
-        hasProgressed = (tryToProgress(currentPhaseModifiers) | hasProgressed);
+        hasProgressed |= tryToProgress(currentPhaseModifiers);
 
-        if (phaseCompleted && (currentPhaseModifiers.isEmpty())) {
+        if (phaseCompleted && currentPhaseModifiers.isEmpty()) {
             finishedPhase = phase;
+            LOG.debug("Source {} finished phase {}", source, phase);
             return PhaseCompletionProgress.FINISHED;
 
         }
-        if (hasProgressed) {
-            return PhaseCompletionProgress.PROGRESS;
-        }
-        return PhaseCompletionProgress.NO_PROGRESS;
+
+        return hasProgressed ? PhaseCompletionProgress.PROGRESS : PhaseCompletionProgress.NO_PROGRESS;
     }
 
 
@@ -308,6 +311,8 @@ public class SourceSpecificContext implements NamespaceStorageNode, NamespaceBeh
     }
 
     void loadStatements() throws SourceException {
+        LOG.trace("Source {} loading statements for phase {}", source, inProgressPhase);
+
         switch (inProgressPhase) {
             case SOURCE_PRE_LINKAGE:
                 source.writePreLinkage(new StatementContextWriter(this, inProgressPhase), stmtDef());

diff --git a/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/StatementContextBase.java b/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/StatementContextBase.java
index a84f9b81a56a604d109bb14f1a715c32d84717b1..3651a66a96ca8315cfb11fa10798898b9e0d174d 100644 (file)
--- a/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/StatementContextBase.java
+++ b/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/StatementContextBase.java
@@ -7,6 +7,8 @@
  */
 package org.opendaylight.yangtools.yang.parser.stmt.reactor;
 
+import com.google.common.base.MoreObjects;
+import com.google.common.base.MoreObjects.ToStringHelper;
 import com.google.common.base.Preconditions;
 import com.google.common.base.Throwables;
 import com.google.common.collect.ImmutableCollection;
@@ -669,4 +671,13 @@ public abstract class StatementContextBase<A, D extends DeclaredStatement<A>, E
             final StmtContext<?, ?, ?> stmt) {
         addContextToNamespace(namespace, (K) key, stmt);
     }
+
+    @Override
+    public final String toString() {
+        return addToStringAttributes(MoreObjects.toStringHelper(this).omitNullValues()).toString();
+    }
+
+    protected ToStringHelper addToStringAttributes(final ToStringHelper toStringHelper) {
+        return toStringHelper.add("definition", definition).add("id", identifier);
+    }
 }

diff --git a/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/StatementDefinitionContext.java b/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/StatementDefinitionContext.java
index fa5a0a4ec93d4670f2e6eb1aa91e60f18fa6437f..5d63ec30b3e179ce26bfd5524500ef302985a8c5 100644 (file)
--- a/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/StatementDefinitionContext.java
+++ b/yang/yang-parser-impl/src/main/java/org/opendaylight/yangtools/yang/parser/stmt/reactor/StatementDefinitionContext.java
@@ -7,6 +7,9 @@
  */
 package org.opendaylight.yangtools.yang.parser.stmt.reactor;
 
+import com.google.common.base.MoreObjects;
+import com.google.common.base.MoreObjects.ToStringHelper;
+import com.google.common.base.Preconditions;
 import org.opendaylight.yangtools.yang.common.QName;
 import org.opendaylight.yangtools.yang.model.api.meta.DeclaredStatement;
 import org.opendaylight.yangtools.yang.model.api.meta.EffectiveStatement;
@@ -17,25 +20,23 @@ import org.opendaylight.yangtools.yang.parser.spi.meta.StatementFactory;
 import org.opendaylight.yangtools.yang.parser.spi.meta.StatementSupport;
 import org.opendaylight.yangtools.yang.parser.spi.meta.StmtContext;
 import org.opendaylight.yangtools.yang.parser.spi.meta.StmtContext.Mutable;
-import org.opendaylight.yangtools.yang.parser.spi.source.SourceException;
 
 public class StatementDefinitionContext<A,D extends DeclaredStatement<A>,E extends EffectiveStatement<A,D>> {
     private final StatementSupport<A,D,E> support;
-    public StatementDefinitionContext(StatementSupport<A,D,E> support) {
-        this.support= support;
-    }
 
+    public StatementDefinitionContext(final StatementSupport<A,D,E> support) {
+        this.support = Preconditions.checkNotNull(support);
+    }
 
     public StatementFactory<A,D,E> getFactory() {
         return support;
     }
 
-    public A parseArgumentValue(StmtContext<A,D,E> context, String value) throws SourceException {
+    public A parseArgumentValue(final StmtContext<A,D,E> context, final String value) {
         return support.parseArgumentValue(context,value);
     }
 
-
-    public void checkNamespaceAllowed(Class<? extends IdentifierNamespace<?,?>> namespace) {
+    public void checkNamespaceAllowed(final Class<? extends IdentifierNamespace<?,?>> namespace) {
         // Noop
     }
 
@@ -43,13 +44,13 @@ public class StatementDefinitionContext<A,D extends DeclaredStatement<A>,E exten
         return support.getPublicView();
     }
 
-    public boolean onStatementAdded(Mutable<A,D,E> stmt) {
+    public boolean onStatementAdded(final Mutable<A,D,E> stmt) {
         support.onStatementAdded(stmt);
         return false;
     }
 
 
-    public void onDeclarationFinished(Mutable<A,D,E> statement, ModelProcessingPhase phase) throws SourceException {
+    public void onDeclarationFinished(final Mutable<A,D,E> statement, final ModelProcessingPhase phase) {
         switch (phase) {
         case SOURCE_PRE_LINKAGE:
             support.onPreLinkageDeclared(statement);
@@ -68,20 +69,24 @@ public class StatementDefinitionContext<A,D extends DeclaredStatement<A>,E exten
         }
     }
 
-
-
     public Class<?> getRepresentingClass() {
         return support.getDeclaredRepresentationClass();
     }
 
-
     public boolean hasArgument() {
         return support.getArgumentName() != null;
     }
 
-
     public QName getStatementName() {
         return support.getStatementName();
     }
 
+    @Override
+    public final String toString() {
+        return addToStringAttributes(MoreObjects.toStringHelper(this).omitNullValues()).toString();
+    }
+
+    protected ToStringHelper addToStringAttributes(final ToStringHelper toStringHelper) {
+        return toStringHelper.add("statement", getStatementName());
+    }
 }