From 9aa3d6fe6567e3eee9108d6fffbc50d5874e72e3 Mon Sep 17 00:00:00 2001 From: Harald Musum Date: Tue, 20 Apr 2021 09:28:12 +0200 Subject: Revert "add more logging" --- slobrok/src/tests/backoff/testbackoff.cpp | 88 ++++++++++++++++++++++--------- slobrok/src/vespa/slobrok/CMakeLists.txt | 1 - slobrok/src/vespa/slobrok/backoff.cpp | 39 -------------- slobrok/src/vespa/slobrok/backoff.h | 39 +++++++++++--- slobrok/src/vespa/slobrok/sblist.cpp | 8 +-- slobrok/src/vespa/slobrok/sbmirror.cpp | 15 ++---- slobrok/src/vespa/slobrok/sbmirror.h | 1 - slobrok/src/vespa/slobrok/sbregister.cpp | 21 +++----- slobrok/src/vespa/slobrok/sbregister.h | 1 - 9 files changed, 108 insertions(+), 105 deletions(-) delete mode 100644 slobrok/src/vespa/slobrok/backoff.cpp (limited to 'slobrok/src') 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 - 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 _busy; SlobrokList _slobrokSpecs; Configurator::UP _configurator; -- cgit v1.2.3