Reapply "add more logging" (new and updated slobrok logging)

This reverts commit 9aa3d6fe6567e3eee9108d6fffbc50d5874e72e3.

9 files changed, 105 insertions, 108 deletions

diff --git a/slobrok/src/tests/backoff/testbackoff.cpp b/slobrok/src/tests/backoff/testbackoff.cpp
index e3d799bfb72..40ca1ac17ba 100644
--- a/slobrok/src/tests/backoff/testbackoff.cpp
+++ b/slobrok/src/tests/backoff/testbackoff.cpp
@@ -11,85 +11,47 @@ TEST_SETUP(Test);
 
 //-----------------------------------------------------------------------------
 
-static double expectWait[21] = {
-	0.5, 1.0, 1.5, 2.0, 2.5,
-        3.0, 3.5, 4.0, 4.5,
-	5.0, 6.0, 7.0, 8.0, 9.0,
-        10, 15, 20, 25, 30, 30, 30
-};
-
 int
 Test::Main()
 {
     TEST_INIT("backoff_test");
 
     BackOff one;
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(0.500, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(1.000, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(1.500, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(2.000, one.get());
-    EXPECT_TRUE(one.shouldWarn());
-
-    EXPECT_EQUAL(2.500, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(3.000, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(3.500, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(4.000, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(4.500, one.get());
     EXPECT_TRUE(one.shouldWarn());
-
-    EXPECT_EQUAL(5.000, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(6.000, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(7.000, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(8.000, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(9.000, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(10.00, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(15.00, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(20.00, one.get());
-    EXPECT_TRUE(one.shouldWarn());
-
-    EXPECT_EQUAL(25.00, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(30.00, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(30.00, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(30.00, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(30.00, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-    EXPECT_EQUAL(30.00, one.get());
-    EXPECT_FALSE(one.shouldWarn());
-
+    EXPECT_EQUAL(0.500, one.get());
+    for (int i = 2; i < 41; i++) {
+        EXPECT_EQUAL(0.5 * i, one.get());
+    }
+    for (int i = 1; i < 1000; i++) {
+        EXPECT_EQUAL(20.0, one.get());
+    }
     TEST_FLUSH();
 
     BackOff two;
-    for (int i = 0; i < 21; i++) {
-        EXPECT_EQUAL(expectWait[i], two.get());
-        if (i == 3 || i == 8 || i == 16) {
+    for (int i = 1; i < 50; i++) {
+        double expect = 0.5 * i;
+        if (expect > 20.0) expect = 20.0;
+        EXPECT_EQUAL(expect, two.get());
+        if (i == 1 || i == 7 || i == 18) {
             EXPECT_TRUE(two.shouldWarn());
         } else {
             EXPECT_FALSE(two.shouldWarn());
         }
     }
     two.reset();
-    for (int i = 0; i < 21; i++) {
-        EXPECT_EQUAL(expectWait[i], two.get());
-        if (i == 7 || i == 15) {
+    for (int i = 1; i < 50; i++) {
+        double expect = 0.5 * i;
+        if (expect > 20.0) expect = 20.0;
+        EXPECT_EQUAL(expect, two.get());
+        if (i == 1 || i == 7 || i == 18) {
+            EXPECT_TRUE(two.shouldWarn());
+        } else {
+            EXPECT_FALSE(two.shouldWarn());
+        }
+    }
+    for (int i = 0; i < 50000; i++) {
+        EXPECT_EQUAL(20.0, two.get());
+        if ((i % 180) == 5) {
             EXPECT_TRUE(two.shouldWarn());
         } else {
             EXPECT_FALSE(two.shouldWarn());
diff --git a/slobrok/src/vespa/slobrok/CMakeLists.txt b/slobrok/src/vespa/slobrok/CMakeLists.txt
index 92edaf79c7d..00ccadb1226 100644
--- a/slobrok/src/vespa/slobrok/CMakeLists.txt
+++ b/slobrok/src/vespa/slobrok/CMakeLists.txt
@@ -1,6 +1,7 @@
 # Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 vespa_add_library(slobrok
     SOURCES
+    backoff.cpp
     sblist.cpp
     cfg.cpp
     sbmirror.cpp
diff --git a/slobrok/src/vespa/slobrok/backoff.cpp b/slobrok/src/vespa/slobrok/backoff.cpp
new file mode 100644
index 00000000000..e09e688f646
--- /dev/null
+++ b/slobrok/src/vespa/slobrok/backoff.cpp
@@ -0,0 +1,39 @@
+// Copyright Verizon Media. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+
+#include "backoff.h"
+
+namespace slobrok::api {
+
+namespace {
+constexpr size_t num_warn_intervals = 5;
+const double warn_intervals[num_warn_intervals] = { 0.0, 10.0, 60.0, 600.0, 3600.0 };
+}
+
+BackOff::BackOff() { reset(); }
+
+void BackOff::reset() {
+    _time = 0.0;
+    _since_last_warn = 0.0;
+    _nextwarn_idx = 0;
+}
+
+double BackOff::get() {
+        _since_last_warn += _time;
+        if (_time < 20.0) {
+            _time += 0.5;
+        }
+        return _time;
+}
+
+bool BackOff::shouldWarn() {
+    if (_since_last_warn >= warn_intervals[_nextwarn_idx]) {
+        if (_nextwarn_idx + 1 < num_warn_intervals) {
+            ++_nextwarn_idx;
+        }
+        _since_last_warn = 0.0;
+        return true;
+    }
+    return false;
+}
+
+} // namespace slobrok::api
diff --git a/slobrok/src/vespa/slobrok/backoff.h b/slobrok/src/vespa/slobrok/backoff.h
index 9bfc4667e6d..53193a9de6e 100644
--- a/slobrok/src/vespa/slobrok/backoff.h
+++ b/slobrok/src/vespa/slobrok/backoff.h
@@ -1,6 +1,8 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 #pragma once
 
+#include <stdio.h>
+
 namespace slobrok {
 namespace api {
 
@@ -8,39 +10,14 @@ class BackOff
 {
 private:
     double _time;
-    double _warntime;
-    double _nextwarn;
+    double _since_last_warn;
+    size_t _nextwarn_idx;
 
 public:
-    BackOff() : _time(0.50), _warntime(0.0), _nextwarn(4.0) {}
-    void reset() { _time = 0.50; _warntime = 0.0; _nextwarn = 15.0; }
-    double get() {
-        double ret = _time;
-        _warntime += ret;
-        if (_time < 5.0) {
-            _time += 0.5;
-        } else if (_time < 10.0) {
-            _time += 1.0;
-        } else if (_time < 30.0) {
-            _time += 5;
-        } else {
-            // max retry time is 30 seconds
-            _time = 30.0;
-        }
-        return ret;
-    }
-    bool shouldWarn() {
-        if (_warntime > _nextwarn) {
-            _warntime = 0.0;
-            _nextwarn *= 4.0;
-            if (_nextwarn > 86400.0) {
-                _nextwarn = 86400.0;
-            }
-            return true;
-        } else {
-            return false;
-        }
-    }
+    BackOff();
+    void reset();
+    double get();
+    bool shouldWarn();
 };
 
 } // namespace api
diff --git a/slobrok/src/vespa/slobrok/sblist.cpp b/slobrok/src/vespa/slobrok/sblist.cpp
index e7528fb6db2..2cb5f0b3d60 100644
--- a/slobrok/src/vespa/slobrok/sblist.cpp
+++ b/slobrok/src/vespa/slobrok/sblist.cpp
@@ -60,12 +60,12 @@ SlobrokList::logString()
     if (_slobrokSpecs.size() == 0) {
         return "[empty service location broker list]";
     }
-    std::string v;
-    v = _slobrokSpecs[0];
-    for (size_t i = 1 ; i < _slobrokSpecs.size(); ++i) {
-        v += " or ";
+    std::string v = "[";
+    for (size_t i = 0 ; i < _slobrokSpecs.size(); ++i) {
+        if (i > 0) v += ", ";
         v += _slobrokSpecs[i];
     }
+    v += "]";
     return v;
 }
 
diff --git a/slobrok/src/vespa/slobrok/sbmirror.cpp b/slobrok/src/vespa/slobrok/sbmirror.cpp
index 460d61cb2a8..6aff47e13fd 100644
--- a/slobrok/src/vespa/slobrok/sbmirror.cpp
+++ b/slobrok/src/vespa/slobrok/sbmirror.cpp
@@ -16,6 +16,7 @@ MirrorAPI::MirrorAPI(FRT_Supervisor &orb, const ConfiguratorFactory & config)
       _reqPending(false),
       _scheduled(false),
       _reqDone(false),
+      _logOnSuccess(true),
       _specs(),
       _specsGen(),
       _updates(),
@@ -234,6 +235,11 @@ MirrorAPI::handleReqDone()
         } else {
             _backOff.reset();
             // req done OK
+            if (_logOnSuccess) {
+                LOG(info, "successfully connected to location broker %s (mirror initialized with %zu service names)",
+                    _currSlobrok.c_str(), _specs.size());
+                _logOnSuccess = false;
+            }
             return true;
         }
     }
@@ -245,6 +251,7 @@ void
 MirrorAPI::handleReconnect()
 {
     if (_target == 0) {
+        _logOnSuccess = true;
         _currSlobrok = _slobrokSpecs.nextSlobrokSpec();
         if (_currSlobrok.size() > 0) {
             _target = _orb.GetTarget(_currSlobrok.c_str());
@@ -256,10 +263,12 @@ MirrorAPI::handleReconnect()
             }
             double delay = _backOff.get();
             reSched(delay);
+            std::string cps = _slobrokSpecs.logString();
+            const char * const msgfmt = "no location brokers available, retrying: %s (in %.1f seconds)";
             if (_backOff.shouldWarn()) {
-                std::string cps = _slobrokSpecs.logString();
-                LOG(warning, "cannot connect to location broker at %s (retry in %f seconds)",
-                    cps.c_str(), delay);
+                LOG(warning, msgfmt, cps.c_str(), delay);
+            } else {
+                LOG(debug, msgfmt, cps.c_str(), delay);
             }
         }
     }
diff --git a/slobrok/src/vespa/slobrok/sbmirror.h b/slobrok/src/vespa/slobrok/sbmirror.h
index 437ef334af6..c1c7009ce12 100644
--- a/slobrok/src/vespa/slobrok/sbmirror.h
+++ b/slobrok/src/vespa/slobrok/sbmirror.h
@@ -92,6 +92,7 @@ private:
     bool                     _reqPending;
     bool                     _scheduled;
     bool                     _reqDone;
+    bool                     _logOnSuccess;
     SpecList                 _specs;
     vespalib::GenCnt         _specsGen;
     vespalib::GenCnt         _updates;
diff --git a/slobrok/src/vespa/slobrok/sbregister.cpp b/slobrok/src/vespa/slobrok/sbregister.cpp
index 72be5f69538..06a9fb2d79e 100644
--- a/slobrok/src/vespa/slobrok/sbregister.cpp
+++ b/slobrok/src/vespa/slobrok/sbregister.cpp
@@ -58,6 +58,7 @@ RegisterAPI::RegisterAPI(FRT_Supervisor &orb, const ConfiguratorFactory & config
       _hooks(*this),
       _lock(),
       _reqDone(false),
+      _logOnSuccess(true),
       _busy(false),
       _slobrokSpecs(),
       _configurator(config.create(_slobrokSpecs)),
@@ -146,6 +147,11 @@ RegisterAPI::handleReqDone()
                     _req->GetErrorMessage());
             }
         } else {
+            if (_logOnSuccess && (_pending.size() == 0) && (_names.size() > 0)) {
+                LOG(info, "[RPC @ %s] registering %s with location broker %s completed successfully",
+                    createSpec(_orb).c_str(), _names[0].c_str(), _currSlobrok.c_str());
+                _logOnSuccess = false;
+            }
             // reset backoff strategy on any successful request
             _backOff.reset();
         }
@@ -161,13 +167,14 @@ RegisterAPI::handleReconnect()
     if (_configurator->poll() && _target != 0) {
         if (! _slobrokSpecs.contains(_currSlobrok)) {
             vespalib::string cps = _slobrokSpecs.logString();
-            LOG(warning, "current server %s not in list of location brokers: %s",
-                _currSlobrok.c_str(), cps.c_str());
+            LOG(warning, "[RPC @ %s] location broker %s removed, will disconnect and use one of: %s",
+                createSpec(_orb).c_str(), _currSlobrok.c_str(), cps.c_str());
             _target->SubRef();
             _target = 0;
         }
     }
     if (_target == 0) {
+        _logOnSuccess = true;
         _currSlobrok = _slobrokSpecs.nextSlobrokSpec();
         if (_currSlobrok.size() > 0) {
             // try next possible server.
@@ -185,13 +192,13 @@ RegisterAPI::handleReconnect()
             // possibly with a warning.
             double delay = _backOff.get();
             Schedule(delay);
+            const char * const msgfmt = "[RPC @ %s] no location brokers available, retrying: %s (in %.1f seconds)";
+            vespalib::string cps = _slobrokSpecs.logString();
             if (_backOff.shouldWarn()) {
-                vespalib::string cps = _slobrokSpecs.logString();
-                LOG(warning, "cannot connect to location broker at %s "
-                    "(retry in %f seconds)", cps.c_str(), delay);
+                LOG(warning, msgfmt, createSpec(_orb).c_str(), cps.c_str(), delay);
             } else {
-                LOG(debug, "slobrok retry in %f seconds", delay);
-	    }
+                LOG(debug, msgfmt, createSpec(_orb).c_str(), cps.c_str(), delay);
+            }
             return;
         }
     }
diff --git a/slobrok/src/vespa/slobrok/sbregister.h b/slobrok/src/vespa/slobrok/sbregister.h
index 8e8614fdf0a..8e849e1ea13 100644
--- a/slobrok/src/vespa/slobrok/sbregister.h
+++ b/slobrok/src/vespa/slobrok/sbregister.h
@@ -87,6 +87,7 @@ private:
     RPCHooks                 _hooks;
     std::mutex               _lock;
     bool                     _reqDone;
+    bool                     _logOnSuccess;
     std::atomic<bool>        _busy;
     SlobrokList              _slobrokSpecs;
     Configurator::UP         _configurator;