Revert "add more logging"

9 files changed, 108 insertions, 105 deletions

diff --git a/slobrok/src/tests/backoff/testbackoff.cpp b/slobrok/src/tests/backoff/testbackoff.cpp
index 40ca1ac17ba..e3d799bfb72 100644
--- a/slobrok/src/tests/backoff/testbackoff.cpp
+++ b/slobrok/src/tests/backoff/testbackoff.cpp
@@ -11,47 +11,85 @@ 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_TRUE(one.shouldWarn());
+    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());
-    }
+    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());
+
     TEST_FLUSH();
 
     BackOff two;
-    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) {
+    for (int i = 0; i < 21; i++) {
+        EXPECT_EQUAL(expectWait[i], two.get());
+        if (i == 3 || i == 8 || i == 16) {
             EXPECT_TRUE(two.shouldWarn());
         } else {
             EXPECT_FALSE(two.shouldWarn());
         }
     }
     two.reset();
-    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) {
+    for (int i = 0; i < 21; i++) {
+        EXPECT_EQUAL(expectWait[i], two.get());
+        if (i == 7 || i == 15) {
             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 00ccadb1226..92edaf79c7d 100644
--- a/slobrok/src/vespa/slobrok/CMakeLists.txt
+++ b/slobrok/src/vespa/slobrok/CMakeLists.txt
@@ -1,7 +1,6 @@
 # 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
deleted file mode 100644
index e09e688f646..00000000000
--- a/slobrok/src/vespa/slobrok/backoff.cpp
+++ /dev/null
@@ -1,39 +0,0 @@
-// 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 53193a9de6e..9bfc4667e6d 100644
--- a/slobrok/src/vespa/slobrok/backoff.h
+++ b/slobrok/src/vespa/slobrok/backoff.h
@@ -1,8 +1,6 @@
 // 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 {
 
@@ -10,14 +8,39 @@ class BackOff
 {
 private:
     double _time;
-    double _since_last_warn;
-    size_t _nextwarn_idx;
+    double _warntime;
+    double _nextwarn;
 
 public:
-    BackOff();
-    void reset();
-    double get();
-    bool shouldWarn();
+    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;
+        }
+    }
 };
 
 } // namespace api
diff --git a/slobrok/src/vespa/slobrok/sblist.cpp b/slobrok/src/vespa/slobrok/sblist.cpp
index 2cb5f0b3d60..e7528fb6db2 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 = "[";
-    for (size_t i = 0 ; i < _slobrokSpecs.size(); ++i) {
-        if (i > 0) v += ", ";
+    std::string v;
+    v = _slobrokSpecs[0];
+    for (size_t i = 1 ; i < _slobrokSpecs.size(); ++i) {
+        v += " or ";
         v += _slobrokSpecs[i];
     }
-    v += "]";
     return v;
 }
 
diff --git a/slobrok/src/vespa/slobrok/sbmirror.cpp b/slobrok/src/vespa/slobrok/sbmirror.cpp
index 6aff47e13fd..460d61cb2a8 100644
--- a/slobrok/src/vespa/slobrok/sbmirror.cpp
+++ b/slobrok/src/vespa/slobrok/sbmirror.cpp
@@ -16,7 +16,6 @@ MirrorAPI::MirrorAPI(FRT_Supervisor &orb, const ConfiguratorFactory & config)
       _reqPending(false),
       _scheduled(false),
       _reqDone(false),
-      _logOnSuccess(true),
       _specs(),
       _specsGen(),
       _updates(),
@@ -235,11 +234,6 @@ 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;
         }
     }
@@ -251,7 +245,6 @@ void
 MirrorAPI::handleReconnect()
 {
     if (_target == 0) {
-        _logOnSuccess = true;
         _currSlobrok = _slobrokSpecs.nextSlobrokSpec();
         if (_currSlobrok.size() > 0) {
             _target = _orb.GetTarget(_currSlobrok.c_str());
@@ -263,12 +256,10 @@ 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()) {
-                LOG(warning, msgfmt, cps.c_str(), delay);
-            } else {
-                LOG(debug, msgfmt, cps.c_str(), delay);
+                std::string cps = _slobrokSpecs.logString();
+                LOG(warning, "cannot connect to location broker at %s (retry in %f seconds)",
+                    cps.c_str(), delay);
             }
         }
     }
diff --git a/slobrok/src/vespa/slobrok/sbmirror.h b/slobrok/src/vespa/slobrok/sbmirror.h
index c1c7009ce12..437ef334af6 100644
--- a/slobrok/src/vespa/slobrok/sbmirror.h
+++ b/slobrok/src/vespa/slobrok/sbmirror.h
@@ -92,7 +92,6 @@ 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 06a9fb2d79e..72be5f69538 100644
--- a/slobrok/src/vespa/slobrok/sbregister.cpp
+++ b/slobrok/src/vespa/slobrok/sbregister.cpp
@@ -58,7 +58,6 @@ RegisterAPI::RegisterAPI(FRT_Supervisor &orb, const ConfiguratorFactory & config
       _hooks(*this),
       _lock(),
       _reqDone(false),
-      _logOnSuccess(true),
       _busy(false),
       _slobrokSpecs(),
       _configurator(config.create(_slobrokSpecs)),
@@ -147,11 +146,6 @@ 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();
         }
@@ -167,14 +161,13 @@ RegisterAPI::handleReconnect()
     if (_configurator->poll() && _target != 0) {
         if (! _slobrokSpecs.contains(_currSlobrok)) {
             vespalib::string cps = _slobrokSpecs.logString();
-            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());
+            LOG(warning, "current server %s not in list of location brokers: %s",
+                _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.
@@ -192,13 +185,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()) {
-                LOG(warning, msgfmt, createSpec(_orb).c_str(), cps.c_str(), delay);
+                vespalib::string cps = _slobrokSpecs.logString();
+                LOG(warning, "cannot connect to location broker at %s "
+                    "(retry in %f seconds)", cps.c_str(), delay);
             } else {
-                LOG(debug, msgfmt, createSpec(_orb).c_str(), cps.c_str(), delay);
-            }
+                LOG(debug, "slobrok retry in %f seconds", delay);
+	    }
             return;
         }
     }
diff --git a/slobrok/src/vespa/slobrok/sbregister.h b/slobrok/src/vespa/slobrok/sbregister.h
index 8e849e1ea13..8e8614fdf0a 100644
--- a/slobrok/src/vespa/slobrok/sbregister.h
+++ b/slobrok/src/vespa/slobrok/sbregister.h
@@ -87,7 +87,6 @@ private:
     RPCHooks                 _hooks;
     std::mutex               _lock;
     bool                     _reqDone;
-    bool                     _logOnSuccess;
     std::atomic<bool>        _busy;
     SlobrokList              _slobrokSpecs;
     Configurator::UP         _configurator;