diff options
author | Arne Juul <arnej@verizonmedia.com> | 2021-04-19 06:43:43 +0000 |
---|---|---|
committer | Arne Juul <arnej@verizonmedia.com> | 2021-04-19 06:46:44 +0000 |
commit | 2d5417f39cac7b5c093ab6e26a760f1428611389 (patch) | |
tree | f5bed16853ba8a6236e766d7aa1e9df321f28466 /slobrok | |
parent | fd9dba8fe5f5db6624f5ce771322f90a504286da (diff) |
add more logging
* make it possible to track which location broker
various components are registered with or
mirroring information from.
* most of these log messages should now look the same
in the Java and C++ implementations
Diffstat (limited to 'slobrok')
-rw-r--r-- | slobrok/src/vespa/slobrok/CMakeLists.txt | 1 | ||||
-rw-r--r-- | slobrok/src/vespa/slobrok/backoff.cpp | 39 | ||||
-rw-r--r-- | slobrok/src/vespa/slobrok/backoff.h | 39 | ||||
-rw-r--r-- | slobrok/src/vespa/slobrok/sblist.cpp | 8 | ||||
-rw-r--r-- | slobrok/src/vespa/slobrok/sbmirror.cpp | 15 | ||||
-rw-r--r-- | slobrok/src/vespa/slobrok/sbmirror.h | 1 | ||||
-rw-r--r-- | slobrok/src/vespa/slobrok/sbregister.cpp | 21 | ||||
-rw-r--r-- | slobrok/src/vespa/slobrok/sbregister.h | 1 |
8 files changed, 80 insertions, 45 deletions
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..8d5a0e39c6a 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(); + static 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..7ec3325a22a 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); + static 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; |