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

gRPC service logging bugfix #363

Merged
merged 6 commits into from
Jun 19, 2020
Merged

gRPC service logging bugfix #363

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
7ee8abf
gRPC service logging bugfix
oschaaf Jun 16, 2020
afebe8c
Fix clang-tidy issue
oschaaf Jun 16, 2020
619c05e
Review feedback: regression test for gRPC service log behavior
oschaaf Jun 18, 2020
da26a80
Review: add doc comments
oschaaf Jun 18, 2020
a63396b
Merge remote-tracking branch 'upstream/master' into fix-service-logging
oschaaf Jun 18, 2020
593fe3c
Review feedback
oschaaf Jun 18, 2020
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
7 changes: 5 additions & 2 deletions source/client/process_impl.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -92,8 +92,11 @@ class ClusterManagerFactory : public Envoy::Upstream::ProdClusterManagerFactory
bool prefetch_connections_{};
};

ProcessImpl::ProcessImpl(const Options& options, Envoy::Event::TimeSystem& time_system)
: time_system_(time_system), stats_allocator_(symbol_table_), store_root_(stats_allocator_),
ProcessImpl::ProcessImpl(const Options& options, Envoy::Event::TimeSystem& time_system,
Copy link
Collaborator

Choose a reason for hiding this comment

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

Is there any way how we can add test coverage for this change to keep the fixed functionality working?

Copy link
Member Author

Choose a reason for hiding this comment

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

Actually, yes. Lacking C++ mocks for the logging, we can't easily unit-test this issue.
But I could add an end-to-end integration test for this, see 619c05e

const std::shared_ptr<Envoy::ProcessWide>& process_wide)
: process_wide_(process_wide == nullptr ? std::make_shared<Envoy::ProcessWide>()
Copy link
Collaborator

Choose a reason for hiding this comment

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

Unsure about the context - do we need to worry about thread safety here or is ProcessImpl guaranteed to be constructed from a single thread?

Copy link
Member Author

Choose a reason for hiding this comment

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

All ProcessImpl clients should ensure there's only a single active instance at any given time. We don't have to worry about it.

: process_wide),
time_system_(time_system), stats_allocator_(symbol_table_), store_root_(stats_allocator_),
api_(std::make_unique<Envoy::Api::Impl>(platform_impl_.threadFactory(), store_root_,
time_system_, platform_impl_.fileSystem())),
dispatcher_(api_->allocateDispatcher("main_thread")), benchmark_client_factory_(options),
Expand Down
5 changes: 3 additions & 2 deletions source/client/process_impl.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,8 @@ class ClusterManagerFactory;
*/
class ProcessImpl : public Process, public Envoy::Logger::Loggable<Envoy::Logger::Id::main> {
public:
ProcessImpl(const Options& options, Envoy::Event::TimeSystem& time_system);
ProcessImpl(const Options& options, Envoy::Event::TimeSystem& time_system,
Copy link
Collaborator

Choose a reason for hiding this comment

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

Can we add a doc comment? We could also explain the optional process_wide argument and say what happens if it isn't provided.

const std::shared_ptr<Envoy::ProcessWide>& process_wide = nullptr);
~ProcessImpl() override;

/**
Expand Down Expand Up @@ -96,7 +97,7 @@ class ProcessImpl : public Process, public Envoy::Logger::Loggable<Envoy::Logger
bool runInternal(OutputCollector& collector, const std::vector<UriPtr>& uris,
const UriPtr& request_source_uri, const UriPtr& tracing_uri);

Envoy::ProcessWide process_wide_;
std::shared_ptr<Envoy::ProcessWide> process_wide_;
Envoy::PlatformImpl platform_impl_;
Envoy::Event::TimeSystem& time_system_;
Envoy::Stats::SymbolTableImpl symbol_table_;
Expand Down
6 changes: 1 addition & 5 deletions source/client/service_impl.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,11 +33,7 @@ void ServiceImpl::handleExecutionRequest(const nighthawk::client::ExecutionReque
return;
}

ProcessImpl process(*options, time_system_);
Copy link
Member Author

Choose a reason for hiding this comment

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

Note to reviewers: the fix is to not do this here. We do this once now at construction time, and hold on to the logging context throughout the lifetime of the ServiceImpl.
Note that ProcessImpl instantiations will change the log level per inbound configured options. We only allow one ProcessImpl instantiation at a time today, so this might be allright for now.

auto logging_context = std::make_unique<Envoy::Logger::Context>(
spdlog::level::from_str(
nighthawk::client::Verbosity::VerbosityOptions_Name(options->verbosity())),
"[%T.%f][%t][%L] %v", log_lock_, false);
ProcessImpl process(*options, time_system_, process_wide_);
OutputCollectorImpl output_collector(time_system_, *options);
const bool ok = process.run(output_collector);
if (!ok) {
Expand Down
8 changes: 8 additions & 0 deletions source/client/service_impl.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,10 +11,12 @@
#endif

#include <future>
#include <memory>

#include "external/envoy/source/common/common/logger.h"
#include "external/envoy/source/common/common/thread.h"
#include "external/envoy/source/common/event/real_time_system.h"
#include "external/envoy/source/exe/process_wide.h"

#include "nighthawk/client/process.h"
#include "nighthawk/common/request_source.h"
Expand All @@ -26,6 +28,10 @@ class ServiceImpl final : public nighthawk::client::NighthawkService::Service,
public Envoy::Logger::Loggable<Envoy::Logger::Id::main> {

public:
ServiceImpl() : process_wide_(std::make_shared<Envoy::ProcessWide>()) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Can we add a doc comment for the public constructor?

logging_context_ = std::make_unique<Envoy::Logger::Context>(
spdlog::level::from_str("info"), "[%T.%f][%t][%L] %v", log_lock_, false);
}
::grpc::Status ExecutionStream(
::grpc::ServerContext* context,
::grpc::ServerReaderWriter<::nighthawk::client::ExecutionResponse,
Expand All @@ -36,6 +42,8 @@ class ServiceImpl final : public nighthawk::client::NighthawkService::Service,
void writeResponse(const nighthawk::client::ExecutionResponse& response);
::grpc::Status finishGrpcStream(const bool success, absl::string_view description = "");

std::unique_ptr<Envoy::Logger::Context> logging_context_;
std::shared_ptr<Envoy::ProcessWide> process_wide_;
Envoy::Event::RealTimeSystem time_system_; // NO_CHECK_FORMAT(real_time)
Envoy::Thread::MutexBasicLockable log_lock_;
::grpc::ServerReaderWriter<::nighthawk::client::ExecutionResponse,
Expand Down