Add logging and comments to container and config retriever.

2 files changed, 43 insertions, 13 deletions

diff --git a/container-di/src/main/scala/com/yahoo/container/di/ConfigRetriever.scala b/container-di/src/main/scala/com/yahoo/container/di/ConfigRetriever.scala
index 994162695d3..dc94d789f7b 100644
--- a/container-di/src/main/scala/com/yahoo/container/di/ConfigRetriever.scala
+++ b/container-di/src/main/scala/com/yahoo/container/di/ConfigRetriever.scala
@@ -7,7 +7,7 @@ import java.util.logging.{Level, Logger}
 import com.yahoo.config.ConfigInstance
 import com.yahoo.container.di.ConfigRetriever._
 import com.yahoo.container.di.config.Subscriber
-import com.yahoo.log.LogLevel
+import com.yahoo.log.LogLevel.DEBUG
 
 import scala.annotation.tailrec
 import scala.collection.JavaConverters._
@@ -31,7 +31,7 @@ final class ConfigRetriever(bootstrapKeys: Set[ConfigKeyT],
   @tailrec
   final def getConfigs(componentConfigKeys: Set[ConfigKeyT], leastGeneration: Long): ConfigSnapshot = {
     require(componentConfigKeys intersect bootstrapKeys isEmpty)
-    log.log(LogLevel.DEBUG, "getConfigs: " + componentConfigKeys)
+    log.log(DEBUG, "getConfigs: " + componentConfigKeys)
 
     setupComponentSubscriber(componentConfigKeys ++ bootstrapKeys)
 
@@ -43,16 +43,26 @@ final class ConfigRetriever(bootstrapKeys: Set[ConfigKeyT],
 
   private def getConfigsOptional(leastGeneration: Long): Option[ConfigSnapshot] = {
     val newestComponentGeneration = componentSubscriber.waitNextGeneration()
+    log.log(DEBUG, s"getConfigsOptional: new component generation: $newestComponentGeneration")
 
+    // leastGeneration is only used to ensure newer generation when the previous generation was invalidated due to an exception
     if (newestComponentGeneration < leastGeneration) {
       None
     } else if (bootstrapSubscriber.generation < newestComponentGeneration) {
       val newestBootstrapGeneration = bootstrapSubscriber.waitNextGeneration()
+      log.log(DEBUG, s"getConfigsOptional: new bootstrap generation: ${bootstrapSubscriber.generation}")
       bootstrapConfigIfChanged() orElse {
-        if (newestBootstrapGeneration == newestComponentGeneration) componentsConfigIfChanged()
-        else None
+        if (newestBootstrapGeneration == newestComponentGeneration){
+          log.log(DEBUG, s"Got new components configs with unchanged bootstrap configs.")
+          componentsConfigIfChanged()
+        } else {
+          // This should not be a normal case, and hence a warning to allow investigation.
+          log.warning(s"Did not get same generation for bootstrap ($newestBootstrapGeneration) and components configs ($newestComponentGeneration).")
+          None
+        }
       }
     } else {
+      // bootstrapGen==componentGen (happens only when a new component subscriber returns first config after bootstrap)
       componentsConfigIfChanged()
     }
   }
@@ -61,8 +71,7 @@ final class ConfigRetriever(bootstrapKeys: Set[ConfigKeyT],
   private def componentsConfigIfChanged(): Option[ComponentsConfigs] = configIfChanged(componentSubscriber, ComponentsConfigs)
 
   private def configIfChanged[T <: ConfigSnapshot](subscriber: Subscriber,
-                                                   constructor: Map[ConfigKeyT, ConfigInstance] => T ):
-  Option[T] = {
+                                                   constructor: Map[ConfigKeyT, ConfigInstance] => T ): Option[T] = {
     if (subscriber.configChanged) Some(constructor(subscriber.config.asScala.toMap))
     else None
   }
@@ -77,9 +86,9 @@ final class ConfigRetriever(bootstrapKeys: Set[ConfigKeyT],
   private def setupComponentSubscriber(keys: Set[ConfigKeyT]) {
     if (componentSubscriberKeys != keys) {
       componentSubscriber.close()
-
       componentSubscriberKeys = keys
       try {
+        log.log(DEBUG, s"Setting up new component subscriber for keys: $keys")
         componentSubscriber = subscribe(keys)
       } catch {
         case e: Throwable =>
diff --git a/container-di/src/main/scala/com/yahoo/container/di/Container.scala b/container-di/src/main/scala/com/yahoo/container/di/Container.scala
index c6812c52242..50ebff6ece9 100644
--- a/container-di/src/main/scala/com/yahoo/container/di/Container.scala
+++ b/container-di/src/main/scala/com/yahoo/container/di/Container.scala
@@ -14,6 +14,7 @@ import com.yahoo.container.di.componentgraph.core.ComponentNode.ComponentConstru
 import com.yahoo.container.di.componentgraph.core.{ComponentGraph, ComponentNode, JerseyNode}
 import com.yahoo.container.di.config.{RestApiContext, SubscriberFactory}
 import com.yahoo.container.{BundlesConfig, ComponentsConfig}
+import com.yahoo.log.LogLevel.DEBUG
 import com.yahoo.protect.Process
 import com.yahoo.vespa.config.ConfigKey
 
@@ -116,22 +117,42 @@ class Container(
                            fallbackInjector: Injector): ComponentGraph = {
 
     val snapshot = configurer.getConfigs(graph.configKeys, leastGeneration)
-    log.fine("""createNewGraph:
-      graph.configKeys = %s
-      graph.generation = %s
-      snapshot = %s
-    """.format(graph.configKeys, graph.generation, snapshot))
+    log.log(DEBUG,
+            """createNewGraph:
+              |graph.configKeys = %s
+              |graph.generation = %s
+              |snapshot = %s"""
+              .format(graph.configKeys, graph.generation, snapshot).stripMargin)
 
     val preventTailRecursion =
       snapshot match {
         case BootstrapConfigs(configs) if getBootstrapGeneration > previousConfigGeneration =>
+          log.log(DEBUG,
+            """Got new bootstrap generation
+              |bootstrap generation = %d
+              |components generation: %d
+              |previous generation: %d"""
+              .format(getBootstrapGeneration, getComponentsGeneration, previousConfigGeneration).stripMargin)
           installBundles(configs)
           createNewGraph(
             createComponentsGraph(configs, getBootstrapGeneration,fallbackInjector),
             fallbackInjector)
-        case BootstrapConfigs(_)        =>
+        case BootstrapConfigs(_) =>
+          // This is an assumed dead code branch, most likely remains from before config set subscriptions were available.
+          log.warning(
+            """Got bootstrap configs with previous generation. (This should not happen.)
+              |bootstrap generation = %d
+              |components generation: %d
+              |previous generation: %d"""
+              .format(getBootstrapGeneration, getComponentsGeneration, previousConfigGeneration).stripMargin)
           createNewGraph(graph, fallbackInjector)
         case ComponentsConfigs(configs) =>
+          log.log(DEBUG,
+            """Got components configs,
+              |bootstrap generation = %d
+              |components generation: %d
+              |previous generation: %d"""
+              .format(getBootstrapGeneration, getComponentsGeneration, previousConfigGeneration).stripMargin)
           createAndConfigureComponentsGraph(configs, fallbackInjector)
       }