Merge pull request #17480 from vespa-engine/arnej/more-slobrok-info-messages

add more logging

5 files changed, 63 insertions, 26 deletions

diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java b/jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java
index d8a6718b407..f883ac32b72 100644
--- a/jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java
+++ b/jrt/src/com/yahoo/jrt/slobrok/api/BackOff.java
@@ -1,15 +1,18 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 package com.yahoo.jrt.slobrok.api;
 
-
 class BackOff implements BackOffPolicy
 {
-    private double time = 0.50;
+    private static final double initialTime = 0.50;
+
+    private double time = initialTime;
 
+    @Override
     public void reset() {
-        time = 0.50;
+        time = initialTime;
     }
 
+    @Override
     public double get() {
         double ret = time;
         if (time < 5.0) {
@@ -24,7 +27,13 @@ class BackOff implements BackOffPolicy
         return ret;
     }
 
+    @Override
     public boolean shouldWarn(double t) {
         return ((t > 8.1 && t < 9.9) || (t > 29.9));
     }
+
+    @Override
+    public boolean shouldInform(double t) {
+        return (t == initialTime);
+    }
 }
diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/BackOffPolicy.java b/jrt/src/com/yahoo/jrt/slobrok/api/BackOffPolicy.java
index f98e3456880..4cc402b1706 100644
--- a/jrt/src/com/yahoo/jrt/slobrok/api/BackOffPolicy.java
+++ b/jrt/src/com/yahoo/jrt/slobrok/api/BackOffPolicy.java
@@ -35,4 +35,12 @@ public interface BackOffPolicy
      * @param t current delay value
      **/
     public boolean shouldWarn(double t);
+
+    /**
+     * Check if a certain delay should result in an information message logged.
+     *
+     * @return true if we should log
+     * @param t current delay value
+     **/
+    public boolean shouldInform(double t);
 }
diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java b/jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java
index 1a00cd25a2c..6e39e2a3dbd 100644
--- a/jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java
+++ b/jrt/src/com/yahoo/jrt/slobrok/api/Mirror.java
@@ -39,6 +39,7 @@ public class Mirror implements IMirror {
     private final BackOffPolicy     backOff;
     private volatile int      updates    = 0;
     private boolean requestDone = false;
+    private boolean logOnSuccess = true;
     private AtomicReference<Entry[]>  specs = new AtomicReference<>(new Entry[0]);
     private int specsGeneration = 0;
     private final TransportThread transportThread;
@@ -176,18 +177,22 @@ public class Mirror implements IMirror {
         }
 
         if (target != null && ! slobroks.contains(currSlobrok)) {
+            log.log(Level.INFO, "location broker "+currSlobrok+" removed, will disconnect and use one of: "+slobroks);
             target.close();
             target = null;
         }
         if (target == null) {
+            logOnSuccess = true;
             currSlobrok = slobroks.nextSlobrokSpec();
             if (currSlobrok == null) {
                 double delay = backOff.get();
+                Level level = Level.FINE;
+                if (backOff.shouldInform(delay)) level = Level.INFO;
+                // note: since this happens quite often during normal operation,
+                // the level is lower than the more-natural Level.WARNING:
+                if (backOff.shouldWarn(delay)) level = Level.INFO;
+                log.log(level, "no location brokers available, retrying: "+slobroks+" (in " + delay + " seconds)");
                 updateTask.schedule(delay);
-                if (backOff.shouldWarn(delay)) {
-                    log.log(Level.INFO, "no location brokers available "
-                            + "(retry in " + delay + " seconds) for: " + slobroks);
-                }
                 return;
             }
             target = orb.connect(new Spec(currSlobrok));
@@ -216,6 +221,11 @@ public class Mirror implements IMirror {
                 for (int idx = 0; idx < numNames; idx++) {
                     newSpecs[idx] = new Entry(n[idx], s[idx]);
                 }
+                if (logOnSuccess) {
+                    log.log(Level.INFO, "successfully connected to location broker "+currSlobrok+
+                            "(mirror initialized with "+numNames+" service names)");
+                    logOnSuccess = false;
+                }
                 specs.set(newSpecs);
 
                 specsGeneration = answer.get(2).asInt32();
@@ -233,15 +243,16 @@ public class Mirror implements IMirror {
             || (req.returnValues().get(2).count() !=
                 req.returnValues().get(3).count()))
         {
-            log.log(Level.INFO, "Error when handling update from slobrok. Error: " + req.errorMessage() +
-                    " (error code " + req.errorCode() + ")" + ", target: " + target);
+            if (! logOnSuccess) {
+                log.log(Level.INFO, "Error with location broker "+currSlobrok+" update: " + req.errorMessage() +
+                        " (error code " + req.errorCode() + ")");
+            }
             target.close();
             target = null;
             updateTask.scheduleNow(); // try next slobrok
             return;
         }
 
-
         Values answer = req.returnValues();
 
         int diffFromGeneration = answer.get(0).asInt32();
@@ -279,7 +290,10 @@ public class Mirror implements IMirror {
                     newSpecs[idx++] = e;
                 }
             }
-
+            if (logOnSuccess) {
+                log.log(Level.INFO, "successfully connected to location broker "+currSlobrok+" (mirror initialized with "+newSpecs.length+" service names)");
+                logOnSuccess = false;
+            }
             specs.set(newSpecs);
 
             specsGeneration = diffToGeneration;
diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/Register.java b/jrt/src/com/yahoo/jrt/slobrok/api/Register.java
index 713cecc62d1..0da390f8bf6 100644
--- a/jrt/src/com/yahoo/jrt/slobrok/api/Register.java
+++ b/jrt/src/com/yahoo/jrt/slobrok/api/Register.java
@@ -181,6 +181,7 @@ public class Register {
             reqDone = false;
 
             boolean logOnSuccess = false;
+            boolean logOnFailure = true;
             synchronized (this) {
                 if (req.methodName().equals(UNREGISTER_METHOD_NAME)) {
                     logOnSuccess = true;
@@ -191,16 +192,21 @@ public class Register {
                     lastRegisterSucceeded.remove(name);
                 } else {
                     final Boolean lastSucceeded = lastRegisterSucceeded.get(name);
-                    if (lastSucceeded == null || lastSucceeded != !req.isError()) {
+                    if (lastSucceeded == null) {
+                        logOnSuccess = true;
+                        logOnFailure = false;
+                    } else if (lastSucceeded != !req.isError()) {
                         logOnSuccess = true;
-                        lastRegisterSucceeded.put(name, !req.isError());
                     }
+                    lastRegisterSucceeded.put(name, !req.isError());
                 }
             }
 
             if (req.isError()) {
                  if (req.errorCode() != ErrorCode.METHOD_FAILED) {
-                    log.log(Level.INFO, logMessagePrefix() + " failed, will disconnect: " + req.errorMessage() + " (code " + req.errorCode() + ")");
+                     if (logOnFailure) {
+                         log.log(Level.INFO, logMessagePrefix() + " failed, will disconnect: " + req.errorMessage() + " (code " + req.errorCode() + ")");
+                     }
                     target.close();
                     target = null;
                 } else {
@@ -210,7 +216,6 @@ public class Register {
                 log.log(logOnSuccess ? Level.INFO : Level.FINE, logMessagePrefix() + " completed successfully");
                 backOff.reset();
             }
-
             req = null;
             name = null;
         }
@@ -219,7 +224,7 @@ public class Register {
             return; // current request still in progress
         }
         if (target != null && ! slobroks.contains(currSlobrok)) {
-            log.log(Level.INFO, "RPC server " + mySpec + ": Slobrok server " + currSlobrok + " removed, will disconnect");
+            log.log(Level.INFO, "[RPC @ " + mySpec + "] location broker " + currSlobrok + " removed, will disconnect and use one of: "+slobroks);
             target.close();
             target = null;
         }
@@ -227,9 +232,10 @@ public class Register {
             currSlobrok = slobroks.nextSlobrokSpec();
             if (currSlobrok == null) {
                 double delay = backOff.get();
-                Level level = backOff.shouldWarn(delay) ? Level.WARNING : Level.FINE;
-                log.log(level, "RPC server " + mySpec + ": All Slobrok servers tried, will retry in " + delay
-                            + " seconds: " + slobroks);
+                Level level = Level.FINE;
+                if (backOff.shouldInform(delay)) level = Level.INFO;
+                if (backOff.shouldWarn(delay)) level = Level.WARNING;
+                log.log(level, "[RPC @ " + mySpec + "] no location brokers available, retrying: "+slobroks+" (in " + delay + " seconds)");
                 updateTask.schedule(delay);
                 return;
             }
@@ -247,8 +253,8 @@ public class Register {
             }
 
             if (logFine) {
-                log.log(Level.FINE, "RPC server " + mySpec + ": Connect to Slobrok server " + currSlobrok +
-                        " and reregister all Slobrok names: " + namesString);
+                log.log(Level.FINE, "[RPC @ " + mySpec + "] Connect to location broker " + currSlobrok +
+                        " and reregister all service names: " + namesString);
             }
         }
 
@@ -261,7 +267,7 @@ public class Register {
                 req = new Request(REGISTER_METHOD_NAME);
             } else {
                 pending.addAll(names);
-                log.log(Level.FINE, "RPC server " + mySpec + ": Reregister all Slobrok names in 30 seconds: " + names);
+                log.log(Level.FINE, "[RPC @ " + mySpec + "] Reregister all service names in 30 seconds: " + names);
                 updateTask.schedule(30.0);
                 return;
             }
@@ -274,9 +280,9 @@ public class Register {
     }
 
     private String logMessagePrefix() {
-        return "RPC server " + mySpec
-                + (req.methodName().equals(UNREGISTER_METHOD_NAME) ? " unregistering " : " registering ")
-                + name + " with Slobrok server " + currSlobrok;
+        return "[RPC @ " + mySpec + "] "
+                + (req.methodName().equals(UNREGISTER_METHOD_NAME) ? "unregistering " : "registering ")
+                + name + " with location broker " + currSlobrok;
     }
 
     private synchronized void handleRpcList(Request req) {
diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java b/jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java
index b524c25d8ff..10d8923d9f5 100644
--- a/jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java
+++ b/jrt/src/com/yahoo/jrt/slobrok/api/SlobrokList.java
@@ -48,7 +48,7 @@ public class SlobrokList {
     public boolean contains(String slobrok) {
         checkUpdate();
         for (String s : slobroks) {
-            if (s == slobrok) return true;
+            if (s.equals(slobrok)) return true;
         }
         return false;
     }