Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Added simple logging abstraction so mixer client logs can be relayed to envoy logs. #2116

Merged
merged 4 commits into from
Feb 15, 2019
+428 −42
Merged

Added simple logging abstraction so mixer client logs can be relayed to envoy logs. #2116

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
0813b19
Added simple logging abstraction so mixer client logs can be relayed …
Feb 14, 2019
0ad321e
Log threshold guards that prevent needless serialization of logging a…
Feb 14, 2019
a0a9ea0
Format
Feb 14, 2019
0c261b2
Added do/while guards around logging statements.
Feb 15, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
43 changes: 43 additions & 0 deletions src/envoy/http/mixer/control_factory.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@
#include "envoy/local_info/local_info.h"
#include "src/envoy/http/mixer/control.h"
#include "src/envoy/utils/stats.h"
#include "src/istio/utils/logger.h"

namespace Envoy {
namespace Http {
Expand Down Expand Up @@ -51,6 +52,10 @@ class ControlFactory : public Logger::Loggable<Logger::Id::config> {
return std::make_shared<Control>(control_data, cm, dispatcher, random,
scope, local_info);
});

// All MIXER_DEBUG(), MIXER_WARN(), etc log messages will be passed to
// ENVOY_LOG().
istio::utils::setLogger(std::make_unique<LoggerAdaptor>());
}

Control& control() { return tls_->getTyped<Control>(); }
Expand All @@ -62,6 +67,44 @@ class ControlFactory : public Logger::Loggable<Logger::Id::config> {
return {ALL_MIXER_FILTER_STATS(POOL_COUNTER_PREFIX(scope, name))};
}

class LoggerAdaptor : public istio::utils::Logger,
Envoy::Logger::Loggable<Envoy::Logger::Id::filter> {
virtual bool isLoggable(istio::utils::Logger::Level level) override {
switch (level) {
case istio::utils::Logger::Level::DEBUG_:
return ENVOY_LOG_CHECK_LEVEL(debug);
case istio::utils::Logger::Level::TRACE_:
return ENVOY_LOG_CHECK_LEVEL(trace);
case istio::utils::Logger::Level::INFO_:
return ENVOY_LOG_CHECK_LEVEL(info);
case istio::utils::Logger::Level::WARN_:
return ENVOY_LOG_CHECK_LEVEL(warn);
case istio::utils::Logger::Level::ERROR_:
return ENVOY_LOG_CHECK_LEVEL(error);
}
}

virtual void writeBuffer(istio::utils::Logger::Level level,
const char* buffer) override {
switch (level) {
case istio::utils::Logger::Level::DEBUG_:
ENVOY_LOGGER().debug(buffer);
break;
case istio::utils::Logger::Level::TRACE_:
ENVOY_LOGGER().trace(buffer);
break;
case istio::utils::Logger::Level::INFO_:
ENVOY_LOGGER().info(buffer);
break;
case istio::utils::Logger::Level::WARN_:
ENVOY_LOGGER().warn(buffer);
break;
case istio::utils::Logger::Level::ERROR_:
ENVOY_LOGGER().error(buffer);
}
}
};

// The control data object
ControlDataSharedPtr control_data_;
// Thread local slot.
Expand Down
16 changes: 10 additions & 6 deletions src/istio/control/client_context_base.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@
#include "include/istio/mixerclient/check_response.h"
#include "include/istio/utils/attribute_names.h"
#include "include/istio/utils/attributes_builder.h"
#include "src/istio/utils/logger.h"

using ::google::protobuf::util::Status;
using ::istio::mixer::v1::config::client::NetworkFailPolicy;
Expand Down Expand Up @@ -98,17 +99,20 @@ CancelFunc ClientContextBase::SendCheck(TransportCheckFunc transport,
on_done(check_response_info);
};

// TODO: add debug message
// GOOGLE_LOG(INFO) << "Check attributes: " <<
// request->attributes->DebugString();
if (MIXER_DEBUG_ENABLED) {
Copy link
Contributor

@qiwzhang qiwzhang Feb 14, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Each MIXER_DEBUG has this "if MIXER_DEBUG_ENABLE" check. Can they be combined?

Put the isEnabled() check inside MIXER_DEBUG macro?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wonderful idea if I can make it work. I'll do it if I can ensure that log arguments won't be serialized into nice pretty printed messages, etc when the log threshold wouldn't log them.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done. src/istio/utils/logger_test.cc shows that arguments to the logging macros will not be needlessly invoked if the log message is under the logging threshold.

MIXER_DEBUG("Check attributes: %s",
request->attributes->DebugString().c_str());
}

return mixer_client_->Check(*request->attributes, request->quotas, transport,
local_on_done);
}

void ClientContextBase::SendReport(const RequestContext& request) {
// TODO: add debug message
// GOOGLE_LOG(INFO) << "Report attributes: " <<
// request.attributes->DebugString();
if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Report attributes: %s", request.attributes->DebugString().c_str());
}

mixer_client_->Report(*request.attributes);
}

Expand Down
16 changes: 11 additions & 5 deletions src/istio/mixerclient/check_cache.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@

#include "src/istio/mixerclient/check_cache.h"
#include "include/istio/utils/protobuf.h"
#include "src/istio/utils/logger.h"

using namespace std::chrono;
using ::google::protobuf::util::Status;
Expand Down Expand Up @@ -147,18 +148,23 @@ Status CheckCache::CacheResponse(const Attributes &attributes,
}
utils::HashType signature;
if (!referenced.Signature(attributes, "", &signature)) {
GOOGLE_LOG(ERROR) << "Response referenced mismatchs with request";
GOOGLE_LOG(ERROR) << "Request attributes: " << attributes.DebugString();
GOOGLE_LOG(ERROR) << "Referenced attributes: " << referenced.DebugString();
if (MIXER_WARN_ENABLED) {
MIXER_WARN(
"Response referenced does not match request. Request attributes: "
"%s. Referenced attributes: %s",
attributes.DebugString().c_str(), referenced.DebugString().c_str());
}
return ConvertRpcStatus(response.precondition().status());
}

std::lock_guard<std::mutex> lock(cache_mutex_);
utils::HashType hash = referenced.Hash();
if (referenced_map_.find(hash) == referenced_map_.end()) {
referenced_map_[hash] = referenced;
GOOGLE_LOG(INFO) << "Add a new Referenced for check cache: "
<< referenced.DebugString();
if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Add a new Referenced for check cache: %s",
referenced.DebugString().c_str());
}
}

CheckLRUCache::ScopedLookup lookup(cache_.get(), signature);
Expand Down
28 changes: 21 additions & 7 deletions src/istio/mixerclient/quota_cache.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@

#include "src/istio/mixerclient/quota_cache.h"
#include "include/istio/utils/protobuf.h"
#include "src/istio/utils/logger.h"

using namespace std::chrono;
using ::google::protobuf::util::Status;
Expand Down Expand Up @@ -96,6 +97,9 @@ bool QuotaCache::CheckResult::BuildRequest(CheckRequest* request) {
}
}
if (!rejected_quota_names.empty()) {
if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Quota is exhausted for: %s", rejected_quota_names.c_str());
}
status_ =
Status(Code::RESOURCE_EXHAUSTED,
std::string("Quota is exhausted for: ") + rejected_quota_names);
Expand All @@ -118,8 +122,10 @@ void QuotaCache::CheckResult::SetResponse(const Status& status,
if (it != quotas.end()) {
result = &it->second;
} else {
GOOGLE_LOG(ERROR)
<< "Quota response did not have quota for: " << quota.name;
if (MIXER_WARN_ENABLED) {
MIXER_WARN("Quota response did not have quota for: %s",
quota.name.c_str());
}
}
}
if (!quota.response_func(attributes, result)) {
Expand All @@ -131,6 +137,9 @@ void QuotaCache::CheckResult::SetResponse(const Status& status,
}
}
if (!rejected_quota_names.empty()) {
if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Quota is exhausted for: %s", rejected_quota_names.c_str());
}
status_ =
Status(Code::RESOURCE_EXHAUSTED,
std::string("Quota is exhausted for: ") + rejected_quota_names);
Expand Down Expand Up @@ -218,9 +227,12 @@ void QuotaCache::SetResponse(const Attributes& attributes,

utils::HashType signature;
if (!referenced.Signature(attributes, quota_name, &signature)) {
GOOGLE_LOG(ERROR) << "Quota response referenced mismatchs with request";
GOOGLE_LOG(ERROR) << "Request attributes: " << attributes.DebugString();
GOOGLE_LOG(ERROR) << "Referenced attributes: " << referenced.DebugString();
if (MIXER_WARN_ENABLED) {
MIXER_WARN(
"Quota response referenced does not match request. Request "
"attributes: %s, Referenced attributes: %s",
attributes.DebugString().c_str(), referenced.DebugString().c_str());
}
return;
}

Expand All @@ -235,8 +247,10 @@ void QuotaCache::SetResponse(const Attributes& attributes,
utils::HashType hash = referenced.Hash();
if (quota_ref.referenced_map.find(hash) == quota_ref.referenced_map.end()) {
quota_ref.referenced_map[hash] = referenced;
GOOGLE_LOG(INFO) << "Add a new Referenced for quota cache: " << quota_name
<< ", reference: " << referenced.DebugString();
if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Add a new Referenced for quota cache: %s, reference: %s",
quota_name.c_str(), referenced.DebugString().c_str());
}
}

cache_->Insert(signature, quota_ref.pending_item.release(), 1);
Expand Down
11 changes: 10 additions & 1 deletion src/istio/mixerclient/report_batch.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@

#include "src/istio/mixerclient/report_batch.h"
#include "include/istio/utils/protobuf.h"
#include "src/istio/utils/logger.h"

using ::google::protobuf::util::Status;
using ::google::protobuf::util::error::Code;
Expand All @@ -25,6 +26,9 @@ using ::istio::mixer::v1::ReportResponse;
namespace istio {
namespace mixerclient {

static std::atomic<uint32_t> REPORT_FAIL_LOG_MESSAGES{0};
static constexpr uint32_t REPORT_FAIL_LOG_MODULUS{100};

ReportBatch::ReportBatch(const ReportOptions& options,
TransportReportFunc transport,
TimerCreateFunc timer_create,
Expand Down Expand Up @@ -70,7 +74,12 @@ void ReportBatch::FlushWithLock() {
transport_(request, response, [this, response](const Status& status) {
delete response;
if (!status.ok()) {
GOOGLE_LOG(ERROR) << "Mixer Report failed with: " << status.ToString();
if (MIXER_WARN_ENABLED &&
0 == REPORT_FAIL_LOG_MESSAGES++ % REPORT_FAIL_LOG_MODULUS) {
MIXER_WARN("Mixer Report failed with: %s", status.ToString().c_str());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

my only question here is whether or not we also want to track (via stats) the number of times this is happening to make monitoring easier.

if so, we can do that in a follow-up PR if it is going to slow down this PR.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, that's coming in a separate PR. Already done and tested, just trying to create smaller PRs

} else if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Mixer Report failed with: %s", status.ToString().c_str());
}
if (utils::InvalidDictionaryStatus(status)) {
compressor_.ShrinkGlobalDictionary();
}
Expand Down
1 change: 1 addition & 0 deletions src/istio/prefetch/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ cc_library(
visibility = ["//visibility:public"],
deps = [
"//include/istio/prefetch:headers_lib",
"//src/istio/utils:utils_lib",
],
)

Expand Down
43 changes: 19 additions & 24 deletions src/istio/prefetch/quota_prefetch.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,28 +16,12 @@
#include "include/istio/prefetch/quota_prefetch.h"
#include "src/istio/prefetch/circular_queue.h"
#include "src/istio/prefetch/time_based_counter.h"
#include "src/istio/utils/logger.h"

#include <mutex>

using namespace std::chrono;

// Turn this on to debug for quota_prefetch_test.cc
// Not for debugging in production.
#if 0
#include <iostream>
#define LOG(t) \
std::cerr << "(" \
<< duration_cast<milliseconds>(t.time_since_epoch()).count() \
<< "):"
#else
// Pipe to stringstream to disable logging.
#include <sstream>
std::ostringstream os;
#define LOG(t) \
os.clear(); \
os
#endif

namespace istio {
namespace prefetch {
namespace {
Expand Down Expand Up @@ -168,6 +152,12 @@ void QuotaPrefetchImpl::AttemptPrefetch(int amount, Tick t) {
int avail = CountAvailable(t);
int pass_count = counter_.Count(t);
int desired = std::max(pass_count, options_.min_prefetch_amount);
if (MIXER_TRACE_ENABLED) {
MIXER_TRACE(
"Prefetch decision: available=%d, desired=%d, inflight_count=%d, "
"requested=%d",
avail, desired, inflight_count_, amount);
}
if ((avail < desired / 2 && inflight_count_ == 0) || avail < amount) {
bool use_not_granted = (avail == 0 && mode_ == OPEN);
Prefetch(std::max(amount, desired), use_not_granted, t);
Expand All @@ -181,7 +171,9 @@ void QuotaPrefetchImpl::Prefetch(int req_amount, bool use_not_granted, Tick t) {
slot_id = Add(req_amount, t + milliseconds(kMaxExpirationInMs));
}

LOG(t) << "Prefetch: " << req_amount << ", id: " << slot_id << std::endl;
if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Prefetch amount %d for slotid: %lu", req_amount, slot_id);
}

last_prefetch_time_ = t;
++inflight_count_;
Expand Down Expand Up @@ -225,7 +217,9 @@ int QuotaPrefetchImpl::Substract(int delta, Tick t) {
}
} else {
if (n->available > 0) {
LOG(t) << "Expired:" << n->available << std::endl;
if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Expired: %d", n->available);
}
}
}
queue_.Pop();
Expand All @@ -240,9 +234,10 @@ void QuotaPrefetchImpl::OnResponse(SlotId slot_id, int req_amount,
std::lock_guard<std::mutex> lock(mutex_);
--inflight_count_;

LOG(t) << "OnResponse: req:" << req_amount << ", resp: " << resp_amount
<< ", expire: " << expiration.count() << ", id: " << slot_id
<< std::endl;
if (MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("OnResponse: req: %d, resp: %d, expire: %ld, id: %lu",
req_amount, resp_amount, expiration.count(), slot_id);
}

// resp_amount of -1 indicates any network failures.
// Use fail open policy to handle any netowrk failures.
Expand Down Expand Up @@ -300,8 +295,8 @@ bool QuotaPrefetchImpl::Check(int amount, Tick t) {
Substract(amount, t);
}
}
if (!ret) {
LOG(t) << "Rejected amount: " << amount << std::endl;
if (!ret && MIXER_DEBUG_ENABLED) {
MIXER_DEBUG("Rejected amount: %d", amount);
}
return ret;
}
Expand Down
2 changes: 2 additions & 0 deletions src/istio/utils/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,11 +18,13 @@ cc_library(
name = "utils_lib",
srcs = [
"local_attributes.cc",
"logger.cc",
"protobuf.cc",
"status.cc",
"utils.cc"
],
hdrs = [
"logger.h",
"utils.h",
],
visibility = ["//visibility:public"],
Expand Down
Loading