From 0216fd85f7d72f59b6ac8993183559b32ebc030b Mon Sep 17 00:00:00 2001 From: Ruslan Nigmatullin Date: Wed, 8 Apr 2020 00:29:45 -0700 Subject: [PATCH 01/10] logger: Make log prefix configurable Signed-off-by: Ruslan Nigmatullin --- source/common/common/base_logger.cc | 2 +- source/common/common/logger.h | 15 ++++++--------- 2 files changed, 7 insertions(+), 10 deletions(-) diff --git a/source/common/common/base_logger.cc b/source/common/common/base_logger.cc index 912c649337d65..2491ab389dc33 100644 --- a/source/common/common/base_logger.cc +++ b/source/common/common/base_logger.cc @@ -3,7 +3,7 @@ namespace Envoy { namespace Logger { -const char* Logger::DEFAULT_LOG_FORMAT = "[%Y-%m-%d %T.%e][%t][%l][%n] %v"; +const char* Logger::DEFAULT_LOG_FORMAT = "[%Y-%m-%d %T.%e][%t][%l][%n] [%g:%#] %v"; Logger::Logger(std::shared_ptr logger) : logger_(logger) { logger_->set_pattern(DEFAULT_LOG_FORMAT); diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 324d08e476a28..30b44628076dc 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -282,19 +282,15 @@ template class Loggable { } // namespace Logger -// Convert the line macro to a string literal for concatenation in log macros. -#define DO_STRINGIZE(x) STRINGIZE(x) -#define STRINGIZE(x) #x -#define LINE_STRING DO_STRINGIZE(__LINE__) -#define LOG_PREFIX "[" __FILE__ ":" LINE_STRING "] " - /** * Base logging macros. It is expected that users will use the convenience macros below rather than * invoke these directly. */ -#define ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL) \ - (static_cast(Envoy::Logger::Logger::LEVEL) >= LOGGER.level()) +#define ENVOY_SPDLOG_LEVEL(LEVEL) \ + (static_cast(Envoy::Logger::Logger::LEVEL)) + +#define ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL) (ENVOY_SPDLOG_LEVEL(LEVEL) >= LOGGER.level()) // Compare levels before invoking logger. This is an optimization to avoid // executing expressions computing log contents when they would be suppressed. @@ -302,7 +298,8 @@ template class Loggable { #define ENVOY_LOG_COMP_AND_LOG(LOGGER, LEVEL, ...) \ do { \ if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) { \ - LOGGER.LEVEL(LOG_PREFIX __VA_ARGS__); \ + LOGGER.log(::spdlog::source_loc{__FILE__, __LINE__, __func__}, ENVOY_SPDLOG_LEVEL(LEVEL), \ + __VA_ARGS__); \ } \ } while (0) From b868adbbd5008d5060b8c821f1e098a70fe1686f Mon Sep 17 00:00:00 2001 From: Ruslan Nigmatullin Date: Wed, 8 Apr 2020 00:51:28 -0700 Subject: [PATCH 02/10] add cli option Signed-off-by: Ruslan Nigmatullin --- api/envoy/admin/v3/server_info.proto | 5 ++++- api/envoy/admin/v4alpha/server_info.proto | 5 ++++- .../envoy/admin/v3/server_info.proto | 5 ++++- .../envoy/admin/v4alpha/server_info.proto | 5 ++++- include/envoy/server/options.h | 5 +++++ source/server/options_impl.cc | 15 ++++++++++----- source/server/options_impl.h | 2 ++ test/mocks/server/mocks.h | 1 + 8 files changed, 34 insertions(+), 9 deletions(-) diff --git a/api/envoy/admin/v3/server_info.proto b/api/envoy/admin/v3/server_info.proto index ac0204428053e..f0912486857cd 100644 --- a/api/envoy/admin/v3/server_info.proto +++ b/api/envoy/admin/v3/server_info.proto @@ -54,7 +54,7 @@ message ServerInfo { CommandLineOptions command_line_options = 6; } -// [#next-free-field: 29] +// [#next-free-field: 30] message CommandLineOptions { option (udpa.annotations.versioning).previous_message_type = "envoy.admin.v2alpha.CommandLineOptions"; @@ -115,6 +115,9 @@ message CommandLineOptions { // See :option:`--log-format-escaped` for details. bool log_format_escaped = 27; + // See :option:`--log-format-prefix-with-location` for details. + bool log_format_prefix_with_location = 29; + // See :option:`--log-path` for details. string log_path = 11; diff --git a/api/envoy/admin/v4alpha/server_info.proto b/api/envoy/admin/v4alpha/server_info.proto index 867a9255bc51f..2af031b8c7ba9 100644 --- a/api/envoy/admin/v4alpha/server_info.proto +++ b/api/envoy/admin/v4alpha/server_info.proto @@ -54,7 +54,7 @@ message ServerInfo { CommandLineOptions command_line_options = 6; } -// [#next-free-field: 29] +// [#next-free-field: 30] message CommandLineOptions { option (udpa.annotations.versioning).previous_message_type = "envoy.admin.v3.CommandLineOptions"; @@ -114,6 +114,9 @@ message CommandLineOptions { // See :option:`--log-format-escaped` for details. bool log_format_escaped = 27; + // See :option:`--log-format-prefix-with-location` for details. + bool log_format_prefix_with_location = 29; + // See :option:`--log-path` for details. string log_path = 11; diff --git a/generated_api_shadow/envoy/admin/v3/server_info.proto b/generated_api_shadow/envoy/admin/v3/server_info.proto index d412a7f011de0..b77a863e1ad40 100644 --- a/generated_api_shadow/envoy/admin/v3/server_info.proto +++ b/generated_api_shadow/envoy/admin/v3/server_info.proto @@ -54,7 +54,7 @@ message ServerInfo { CommandLineOptions command_line_options = 6; } -// [#next-free-field: 29] +// [#next-free-field: 30] message CommandLineOptions { option (udpa.annotations.versioning).previous_message_type = "envoy.admin.v2alpha.CommandLineOptions"; @@ -113,6 +113,9 @@ message CommandLineOptions { // See :option:`--log-format-escaped` for details. bool log_format_escaped = 27; + // See :option:`--log-format-prefix-with-location` for details. + bool log_format_prefix_with_location = 29; + // See :option:`--log-path` for details. string log_path = 11; diff --git a/generated_api_shadow/envoy/admin/v4alpha/server_info.proto b/generated_api_shadow/envoy/admin/v4alpha/server_info.proto index 867a9255bc51f..2af031b8c7ba9 100644 --- a/generated_api_shadow/envoy/admin/v4alpha/server_info.proto +++ b/generated_api_shadow/envoy/admin/v4alpha/server_info.proto @@ -54,7 +54,7 @@ message ServerInfo { CommandLineOptions command_line_options = 6; } -// [#next-free-field: 29] +// [#next-free-field: 30] message CommandLineOptions { option (udpa.annotations.versioning).previous_message_type = "envoy.admin.v3.CommandLineOptions"; @@ -114,6 +114,9 @@ message CommandLineOptions { // See :option:`--log-format-escaped` for details. bool log_format_escaped = 27; + // See :option:`--log-format-prefix-with-location` for details. + bool log_format_prefix_with_location = 29; + // See :option:`--log-path` for details. string log_path = 11; diff --git a/include/envoy/server/options.h b/include/envoy/server/options.h index 3a9ad7545ef7e..caadcac8d9248 100644 --- a/include/envoy/server/options.h +++ b/include/envoy/server/options.h @@ -127,6 +127,11 @@ class Options { */ virtual bool logFormatEscaped() const PURE; + /** + * @return const bool indicating whether to prefix the log message with location. + */ + virtual bool logFormatPrefixWithLocation() const PURE; + /** * @return const std::string& the log file path. */ diff --git a/source/server/options_impl.cc b/source/server/options_impl.cc index f054546f11c7f..232e688d5640c 100644 --- a/source/server/options_impl.cc +++ b/source/server/options_impl.cc @@ -92,6 +92,9 @@ OptionsImpl::OptionsImpl(std::vector args, TCLAP::SwitchArg log_format_escaped("", "log-format-escaped", "Escape c-style escape sequences in the application logs", cmd, false); + TCLAP::SwitchArg log_format_prefix_with_location( + "", "log-format-prefix-with-location", + "Prefix all logged messages with '[path/to/file.cc:99] '.", cmd, true); TCLAP::ValueArg log_path("", "log-path", "Path to logfile", false, "", "string", cmd); TCLAP::ValueArg restart_epoch("", "restart-epoch", "hot restart epoch #", false, 0, @@ -169,6 +172,7 @@ OptionsImpl::OptionsImpl(std::vector args, log_format_ = log_format.getValue(); log_format_escaped_ = log_format_escaped.getValue(); + log_format_prefix_with_location_ = log_format_prefix_with_location.getValue(); parseComponentLogLevels(component_log_level.getValue()); @@ -310,6 +314,7 @@ Server::CommandLineOptionsPtr OptionsImpl::toCommandLineOptions() const { spdlog::level::to_string_view(logLevel()).size()); command_line_options->set_log_format(logFormat()); command_line_options->set_log_format_escaped(logFormatEscaped()); + command_line_options->set_log_format_prefix_with_location(logFormatPrefixWithLocation()); command_line_options->set_log_path(logPath()); command_line_options->set_service_cluster(serviceClusterName()); command_line_options->set_service_node(serviceNodeName()); @@ -347,11 +352,11 @@ OptionsImpl::OptionsImpl(const std::string& service_cluster, const std::string& : base_id_(0u), concurrency_(1u), config_path_(""), config_yaml_(""), local_address_ip_version_(Network::Address::IpVersion::v4), log_level_(log_level), log_format_(Logger::Logger::DEFAULT_LOG_FORMAT), log_format_escaped_(false), - restart_epoch_(0u), service_cluster_(service_cluster), service_node_(service_node), - service_zone_(service_zone), file_flush_interval_msec_(10000), drain_time_(600), - parent_shutdown_time_(900), mode_(Server::Mode::Serve), hot_restart_disabled_(false), - signal_handling_enabled_(true), mutex_tracing_enabled_(false), cpuset_threads_(false), - fake_symbol_table_enabled_(false) {} + log_format_prefix_with_location_(false), restart_epoch_(0u), + service_cluster_(service_cluster), service_node_(service_node), service_zone_(service_zone), + file_flush_interval_msec_(10000), drain_time_(600), parent_shutdown_time_(900), + mode_(Server::Mode::Serve), hot_restart_disabled_(false), signal_handling_enabled_(true), + mutex_tracing_enabled_(false), cpuset_threads_(false), fake_symbol_table_enabled_(false) {} void OptionsImpl::disableExtensions(const std::vector& names) { for (const auto& name : names) { diff --git a/source/server/options_impl.h b/source/server/options_impl.h index b8f3e64695c47..648409b92c822 100644 --- a/source/server/options_impl.h +++ b/source/server/options_impl.h @@ -118,6 +118,7 @@ class OptionsImpl : public Server::Options, protected Logger::Loggable Date: Wed, 8 Apr 2020 01:45:46 -0700 Subject: [PATCH 03/10] safe but expensive rollout Signed-off-by: Ruslan Nigmatullin --- source/common/common/base_logger.cc | 2 +- source/common/common/logger.cc | 26 ++++++++++++++++++++------ source/common/common/logger.h | 7 ++++++- source/exe/main_common.cc | 9 +++++---- source/server/options_impl.cc | 4 ++-- test/test_runner.cc | 3 ++- 6 files changed, 36 insertions(+), 15 deletions(-) diff --git a/source/common/common/base_logger.cc b/source/common/common/base_logger.cc index 2491ab389dc33..912c649337d65 100644 --- a/source/common/common/base_logger.cc +++ b/source/common/common/base_logger.cc @@ -3,7 +3,7 @@ namespace Envoy { namespace Logger { -const char* Logger::DEFAULT_LOG_FORMAT = "[%Y-%m-%d %T.%e][%t][%l][%n] [%g:%#] %v"; +const char* Logger::DEFAULT_LOG_FORMAT = "[%Y-%m-%d %T.%e][%t][%l][%n] %v"; Logger::Logger(std::shared_ptr logger) : logger_(logger) { logger_->set_pattern(DEFAULT_LOG_FORMAT); diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index 3816c0f61ca79..ebbaf218b8a57 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -47,15 +47,28 @@ void DelegatingLogSink::set_formatter(std::unique_ptr formatt formatter_ = std::move(formatter); } -void DelegatingLogSink::log(const spdlog::details::log_msg& msg) { - absl::ReleasableMutexLock lock(&format_mutex_); - absl::string_view msg_view = absl::string_view(msg.payload.data(), msg.payload.size()); +void DelegatingLogSink::log(const spdlog::details::log_msg& msg_candidate) { + const spdlog::details::log_msg* msg = &msg_candidate; + // This memory buffer is used for compatibility and has to be in the scope of the function to + // avoid use-after-free. + // TODO(euroelessar): Delete this logic after after 0.16 release. + std::string msg_payload_with_prefix; + spdlog::details::log_msg msg_with_prefix = msg_candidate; + if (prefix_with_location_) { + msg_payload_with_prefix = + fmt::format("[{}:{}] {}", msg->source.filename, msg->source.line, + absl::string_view(msg->payload.data(), msg->payload.size())); + msg_with_prefix.payload = msg_payload_with_prefix; + msg = &msg_with_prefix; + } + absl::ReleasableMutexLock lock(&format_mutex_); + absl::string_view msg_view = absl::string_view(msg->payload.data(), msg->payload.size()); // This memory buffer must exist in the scope of the entire function, // otherwise the string_view will refer to memory that is already free. spdlog::memory_buf_t formatted; if (formatter_) { - formatter_->format(msg, formatted); + formatter_->format(*msg, formatted); msg_view = absl::string_view(formatted.data(), formatted.size()); } lock.Release(); @@ -87,9 +100,9 @@ DelegatingLogSinkSharedPtr DelegatingLogSink::init() { static Context* current_context = nullptr; Context::Context(spdlog::level::level_enum log_level, const std::string& log_format, - Thread::BasicLockable& lock, bool should_escape) + Thread::BasicLockable& lock, bool should_escape, bool prefix_with_location) : log_level_(log_level), log_format_(log_format), lock_(lock), should_escape_(should_escape), - save_context_(current_context) { + prefix_with_location_(prefix_with_location), save_context_(current_context) { current_context = this; activate(); } @@ -106,6 +119,7 @@ Context::~Context() { void Context::activate() { Registry::getSink()->setLock(lock_); Registry::getSink()->set_should_escape(should_escape_); + Registry::getSink()->set_prefix_with_location(prefix_with_location_); Registry::setLogLevel(log_level_); Registry::setLogFormat(log_format_); } diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 30b44628076dc..93fec18c5a220 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -145,6 +145,9 @@ class DelegatingLogSink : public spdlog::sinks::sink { } void set_formatter(std::unique_ptr formatter) override; void set_should_escape(bool should_escape) { should_escape_ = should_escape; } + void set_prefix_with_location(bool prefix_with_location) { + prefix_with_location_ = prefix_with_location; + } /** * @return bool whether a lock has been established. @@ -186,6 +189,7 @@ class DelegatingLogSink : public spdlog::sinks::sink { std::unique_ptr formatter_ ABSL_GUARDED_BY(format_mutex_); absl::Mutex format_mutex_; // direct absl reference to break build cycle. bool should_escape_{false}; + bool prefix_with_location_{false}; }; /** @@ -202,7 +206,7 @@ class DelegatingLogSink : public spdlog::sinks::sink { class Context { public: Context(spdlog::level::level_enum log_level, const std::string& log_format, - Thread::BasicLockable& lock, bool should_escape); + Thread::BasicLockable& lock, bool should_escape, bool prefix_with_location = true); ~Context(); private: @@ -212,6 +216,7 @@ class Context { const std::string log_format_; Thread::BasicLockable& lock_; bool should_escape_; + bool prefix_with_location_; Context* const save_context_; }; diff --git a/source/exe/main_common.cc b/source/exe/main_common.cc index a46523033ab54..589df2c3d0998 100644 --- a/source/exe/main_common.cc +++ b/source/exe/main_common.cc @@ -72,7 +72,8 @@ MainCommonBase::MainCommonBase(const OptionsImpl& options, Event::TimeSystem& ti Thread::BasicLockable& access_log_lock = restarter_->accessLogLock(); auto local_address = Network::Utility::getLocalAddress(options_.localAddressIpVersion()); logging_context_ = std::make_unique(options_.logLevel(), options_.logFormat(), - log_lock, options_.logFormatEscaped()); + log_lock, options_.logFormatEscaped(), + options_.logFormatPrefixWithLocation()); configureComponentLogLevels(); @@ -91,9 +92,9 @@ MainCommonBase::MainCommonBase(const OptionsImpl& options, Event::TimeSystem& ti } case Server::Mode::Validate: restarter_ = std::make_unique(); - logging_context_ = - std::make_unique(options_.logLevel(), options_.logFormat(), - restarter_->logLock(), options_.logFormatEscaped()); + logging_context_ = std::make_unique( + options_.logLevel(), options_.logFormat(), restarter_->logLock(), + options_.logFormatEscaped(), options_.logFormatPrefixWithLocation()); break; } } diff --git a/source/server/options_impl.cc b/source/server/options_impl.cc index 232e688d5640c..31e4cc8e141b3 100644 --- a/source/server/options_impl.cc +++ b/source/server/options_impl.cc @@ -92,9 +92,9 @@ OptionsImpl::OptionsImpl(std::vector args, TCLAP::SwitchArg log_format_escaped("", "log-format-escaped", "Escape c-style escape sequences in the application logs", cmd, false); - TCLAP::SwitchArg log_format_prefix_with_location( + TCLAP::ValueArg log_format_prefix_with_location( "", "log-format-prefix-with-location", - "Prefix all logged messages with '[path/to/file.cc:99] '.", cmd, true); + "Prefix all logged messages with '[path/to/file.cc:99] '.", false, true, "bool", cmd); TCLAP::ValueArg log_path("", "log-path", "Path to logfile", false, "", "string", cmd); TCLAP::ValueArg restart_epoch("", "restart-epoch", "hot restart epoch #", false, 0, diff --git a/test/test_runner.cc b/test/test_runner.cc index 5eedad5ae23f6..b2404806d1eb7 100644 --- a/test/test_runner.cc +++ b/test/test_runner.cc @@ -120,7 +120,8 @@ int TestRunner::RunTests(int argc, char** argv) { Thread::MutexBasicLockable lock; Server::Options& options = TestEnvironment::getOptions(); - Logger::Context logging_state(options.logLevel(), options.logFormat(), lock, false); + Logger::Context logging_state(options.logLevel(), options.logFormat(), lock, + options.logFormatEscaped(), options.logFormatPrefixWithLocation()); // Allocate fake log access manager. testing::NiceMock access_log_manager; From 4231460f5ccda675cc1300067a6cc2874405ae7b Mon Sep 17 00:00:00 2001 From: Ruslan Nigmatullin Date: Mon, 13 Apr 2020 15:57:19 -0700 Subject: [PATCH 04/10] revert complexity Signed-off-by: Ruslan Nigmatullin --- api/envoy/admin/v3/server_info.proto | 5 +--- api/envoy/admin/v4alpha/server_info.proto | 5 +--- .../envoy/admin/v3/server_info.proto | 5 +--- .../envoy/admin/v4alpha/server_info.proto | 5 +--- include/envoy/server/options.h | 5 ---- source/common/common/logger.cc | 26 +++++-------------- source/common/common/logger.h | 7 +---- test/mocks/server/mocks.h | 1 - test/test_runner.cc | 3 +-- 9 files changed, 12 insertions(+), 50 deletions(-) diff --git a/api/envoy/admin/v3/server_info.proto b/api/envoy/admin/v3/server_info.proto index f0912486857cd..ac0204428053e 100644 --- a/api/envoy/admin/v3/server_info.proto +++ b/api/envoy/admin/v3/server_info.proto @@ -54,7 +54,7 @@ message ServerInfo { CommandLineOptions command_line_options = 6; } -// [#next-free-field: 30] +// [#next-free-field: 29] message CommandLineOptions { option (udpa.annotations.versioning).previous_message_type = "envoy.admin.v2alpha.CommandLineOptions"; @@ -115,9 +115,6 @@ message CommandLineOptions { // See :option:`--log-format-escaped` for details. bool log_format_escaped = 27; - // See :option:`--log-format-prefix-with-location` for details. - bool log_format_prefix_with_location = 29; - // See :option:`--log-path` for details. string log_path = 11; diff --git a/api/envoy/admin/v4alpha/server_info.proto b/api/envoy/admin/v4alpha/server_info.proto index 2af031b8c7ba9..867a9255bc51f 100644 --- a/api/envoy/admin/v4alpha/server_info.proto +++ b/api/envoy/admin/v4alpha/server_info.proto @@ -54,7 +54,7 @@ message ServerInfo { CommandLineOptions command_line_options = 6; } -// [#next-free-field: 30] +// [#next-free-field: 29] message CommandLineOptions { option (udpa.annotations.versioning).previous_message_type = "envoy.admin.v3.CommandLineOptions"; @@ -114,9 +114,6 @@ message CommandLineOptions { // See :option:`--log-format-escaped` for details. bool log_format_escaped = 27; - // See :option:`--log-format-prefix-with-location` for details. - bool log_format_prefix_with_location = 29; - // See :option:`--log-path` for details. string log_path = 11; diff --git a/generated_api_shadow/envoy/admin/v3/server_info.proto b/generated_api_shadow/envoy/admin/v3/server_info.proto index b77a863e1ad40..d412a7f011de0 100644 --- a/generated_api_shadow/envoy/admin/v3/server_info.proto +++ b/generated_api_shadow/envoy/admin/v3/server_info.proto @@ -54,7 +54,7 @@ message ServerInfo { CommandLineOptions command_line_options = 6; } -// [#next-free-field: 30] +// [#next-free-field: 29] message CommandLineOptions { option (udpa.annotations.versioning).previous_message_type = "envoy.admin.v2alpha.CommandLineOptions"; @@ -113,9 +113,6 @@ message CommandLineOptions { // See :option:`--log-format-escaped` for details. bool log_format_escaped = 27; - // See :option:`--log-format-prefix-with-location` for details. - bool log_format_prefix_with_location = 29; - // See :option:`--log-path` for details. string log_path = 11; diff --git a/generated_api_shadow/envoy/admin/v4alpha/server_info.proto b/generated_api_shadow/envoy/admin/v4alpha/server_info.proto index 2af031b8c7ba9..867a9255bc51f 100644 --- a/generated_api_shadow/envoy/admin/v4alpha/server_info.proto +++ b/generated_api_shadow/envoy/admin/v4alpha/server_info.proto @@ -54,7 +54,7 @@ message ServerInfo { CommandLineOptions command_line_options = 6; } -// [#next-free-field: 30] +// [#next-free-field: 29] message CommandLineOptions { option (udpa.annotations.versioning).previous_message_type = "envoy.admin.v3.CommandLineOptions"; @@ -114,9 +114,6 @@ message CommandLineOptions { // See :option:`--log-format-escaped` for details. bool log_format_escaped = 27; - // See :option:`--log-format-prefix-with-location` for details. - bool log_format_prefix_with_location = 29; - // See :option:`--log-path` for details. string log_path = 11; diff --git a/include/envoy/server/options.h b/include/envoy/server/options.h index caadcac8d9248..3a9ad7545ef7e 100644 --- a/include/envoy/server/options.h +++ b/include/envoy/server/options.h @@ -127,11 +127,6 @@ class Options { */ virtual bool logFormatEscaped() const PURE; - /** - * @return const bool indicating whether to prefix the log message with location. - */ - virtual bool logFormatPrefixWithLocation() const PURE; - /** * @return const std::string& the log file path. */ diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index ebbaf218b8a57..3816c0f61ca79 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -47,28 +47,15 @@ void DelegatingLogSink::set_formatter(std::unique_ptr formatt formatter_ = std::move(formatter); } -void DelegatingLogSink::log(const spdlog::details::log_msg& msg_candidate) { - const spdlog::details::log_msg* msg = &msg_candidate; - // This memory buffer is used for compatibility and has to be in the scope of the function to - // avoid use-after-free. - // TODO(euroelessar): Delete this logic after after 0.16 release. - std::string msg_payload_with_prefix; - spdlog::details::log_msg msg_with_prefix = msg_candidate; - if (prefix_with_location_) { - msg_payload_with_prefix = - fmt::format("[{}:{}] {}", msg->source.filename, msg->source.line, - absl::string_view(msg->payload.data(), msg->payload.size())); - msg_with_prefix.payload = msg_payload_with_prefix; - msg = &msg_with_prefix; - } - +void DelegatingLogSink::log(const spdlog::details::log_msg& msg) { absl::ReleasableMutexLock lock(&format_mutex_); - absl::string_view msg_view = absl::string_view(msg->payload.data(), msg->payload.size()); + absl::string_view msg_view = absl::string_view(msg.payload.data(), msg.payload.size()); + // This memory buffer must exist in the scope of the entire function, // otherwise the string_view will refer to memory that is already free. spdlog::memory_buf_t formatted; if (formatter_) { - formatter_->format(*msg, formatted); + formatter_->format(msg, formatted); msg_view = absl::string_view(formatted.data(), formatted.size()); } lock.Release(); @@ -100,9 +87,9 @@ DelegatingLogSinkSharedPtr DelegatingLogSink::init() { static Context* current_context = nullptr; Context::Context(spdlog::level::level_enum log_level, const std::string& log_format, - Thread::BasicLockable& lock, bool should_escape, bool prefix_with_location) + Thread::BasicLockable& lock, bool should_escape) : log_level_(log_level), log_format_(log_format), lock_(lock), should_escape_(should_escape), - prefix_with_location_(prefix_with_location), save_context_(current_context) { + save_context_(current_context) { current_context = this; activate(); } @@ -119,7 +106,6 @@ Context::~Context() { void Context::activate() { Registry::getSink()->setLock(lock_); Registry::getSink()->set_should_escape(should_escape_); - Registry::getSink()->set_prefix_with_location(prefix_with_location_); Registry::setLogLevel(log_level_); Registry::setLogFormat(log_format_); } diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 93fec18c5a220..30b44628076dc 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -145,9 +145,6 @@ class DelegatingLogSink : public spdlog::sinks::sink { } void set_formatter(std::unique_ptr formatter) override; void set_should_escape(bool should_escape) { should_escape_ = should_escape; } - void set_prefix_with_location(bool prefix_with_location) { - prefix_with_location_ = prefix_with_location; - } /** * @return bool whether a lock has been established. @@ -189,7 +186,6 @@ class DelegatingLogSink : public spdlog::sinks::sink { std::unique_ptr formatter_ ABSL_GUARDED_BY(format_mutex_); absl::Mutex format_mutex_; // direct absl reference to break build cycle. bool should_escape_{false}; - bool prefix_with_location_{false}; }; /** @@ -206,7 +202,7 @@ class DelegatingLogSink : public spdlog::sinks::sink { class Context { public: Context(spdlog::level::level_enum log_level, const std::string& log_format, - Thread::BasicLockable& lock, bool should_escape, bool prefix_with_location = true); + Thread::BasicLockable& lock, bool should_escape); ~Context(); private: @@ -216,7 +212,6 @@ class Context { const std::string log_format_; Thread::BasicLockable& lock_; bool should_escape_; - bool prefix_with_location_; Context* const save_context_; }; diff --git a/test/mocks/server/mocks.h b/test/mocks/server/mocks.h index 57d1532544e87..57515cf77fcee 100644 --- a/test/mocks/server/mocks.h +++ b/test/mocks/server/mocks.h @@ -84,7 +84,6 @@ class MockOptions : public Options { componentLogLevels, (), (const)); MOCK_METHOD(const std::string&, logFormat, (), (const)); MOCK_METHOD(bool, logFormatEscaped, (), (const)); - MOCK_METHOD(bool, logFormatPrefixWithLocation, (), (const)); MOCK_METHOD(const std::string&, logPath, (), (const)); MOCK_METHOD(std::chrono::seconds, parentShutdownTime, (), (const)); MOCK_METHOD(uint64_t, restartEpoch, (), (const)); diff --git a/test/test_runner.cc b/test/test_runner.cc index b2404806d1eb7..5eedad5ae23f6 100644 --- a/test/test_runner.cc +++ b/test/test_runner.cc @@ -120,8 +120,7 @@ int TestRunner::RunTests(int argc, char** argv) { Thread::MutexBasicLockable lock; Server::Options& options = TestEnvironment::getOptions(); - Logger::Context logging_state(options.logLevel(), options.logFormat(), lock, - options.logFormatEscaped(), options.logFormatPrefixWithLocation()); + Logger::Context logging_state(options.logLevel(), options.logFormat(), lock, false); // Allocate fake log access manager. testing::NiceMock access_log_manager; From d377f955e06dd2db8fa406e3ecf68f61e73d7d1a Mon Sep 17 00:00:00 2001 From: Ruslan Nigmatullin Date: Mon, 13 Apr 2020 16:51:21 -0700 Subject: [PATCH 05/10] alter log-format Signed-off-by: Ruslan Nigmatullin --- source/exe/main_common.cc | 9 ++++----- source/server/options_impl.cc | 34 ++++++++++++++++++++++++++-------- source/server/options_impl.h | 2 -- 3 files changed, 30 insertions(+), 15 deletions(-) diff --git a/source/exe/main_common.cc b/source/exe/main_common.cc index 589df2c3d0998..a46523033ab54 100644 --- a/source/exe/main_common.cc +++ b/source/exe/main_common.cc @@ -72,8 +72,7 @@ MainCommonBase::MainCommonBase(const OptionsImpl& options, Event::TimeSystem& ti Thread::BasicLockable& access_log_lock = restarter_->accessLogLock(); auto local_address = Network::Utility::getLocalAddress(options_.localAddressIpVersion()); logging_context_ = std::make_unique(options_.logLevel(), options_.logFormat(), - log_lock, options_.logFormatEscaped(), - options_.logFormatPrefixWithLocation()); + log_lock, options_.logFormatEscaped()); configureComponentLogLevels(); @@ -92,9 +91,9 @@ MainCommonBase::MainCommonBase(const OptionsImpl& options, Event::TimeSystem& ti } case Server::Mode::Validate: restarter_ = std::make_unique(); - logging_context_ = std::make_unique( - options_.logLevel(), options_.logFormat(), restarter_->logLock(), - options_.logFormatEscaped(), options_.logFormatPrefixWithLocation()); + logging_context_ = + std::make_unique(options_.logLevel(), options_.logFormat(), + restarter_->logLock(), options_.logFormatEscaped()); break; } } diff --git a/source/server/options_impl.cc b/source/server/options_impl.cc index 31e4cc8e141b3..5db9fd2ef11bf 100644 --- a/source/server/options_impl.cc +++ b/source/server/options_impl.cc @@ -22,6 +22,22 @@ namespace Envoy { namespace { +std::string prefixLogFormatWithLocation(const std::string& log_format) { + std::string result; + for (size_t i = 0; i < log_format.size(); ++i) { + if (i + 1 < log_format.size() && log_format[i] == '%') { + if (log_format[i] == 'v') { + result += "[%g:%#] "; + } + // Print '%' and go directly to the next character. + result += '%'; + i++; + } + result += log_format[i]; + } + return result; +} + std::vector toArgsVector(int argc, const char* const* argv) { std::vector args; args.reserve(argc); @@ -170,9 +186,12 @@ OptionsImpl::OptionsImpl(std::vector args, log_level_ = default_log_level; } - log_format_ = log_format.getValue(); + if (log_format_prefix_with_location.getValue()) { + log_format_ = prefixLogFormatWithLocation(log_format.getValue()); + } else { + log_format_ = log_format.getValue(); + } log_format_escaped_ = log_format_escaped.getValue(); - log_format_prefix_with_location_ = log_format_prefix_with_location.getValue(); parseComponentLogLevels(component_log_level.getValue()); @@ -314,7 +333,6 @@ Server::CommandLineOptionsPtr OptionsImpl::toCommandLineOptions() const { spdlog::level::to_string_view(logLevel()).size()); command_line_options->set_log_format(logFormat()); command_line_options->set_log_format_escaped(logFormatEscaped()); - command_line_options->set_log_format_prefix_with_location(logFormatPrefixWithLocation()); command_line_options->set_log_path(logPath()); command_line_options->set_service_cluster(serviceClusterName()); command_line_options->set_service_node(serviceNodeName()); @@ -352,11 +370,11 @@ OptionsImpl::OptionsImpl(const std::string& service_cluster, const std::string& : base_id_(0u), concurrency_(1u), config_path_(""), config_yaml_(""), local_address_ip_version_(Network::Address::IpVersion::v4), log_level_(log_level), log_format_(Logger::Logger::DEFAULT_LOG_FORMAT), log_format_escaped_(false), - log_format_prefix_with_location_(false), restart_epoch_(0u), - service_cluster_(service_cluster), service_node_(service_node), service_zone_(service_zone), - file_flush_interval_msec_(10000), drain_time_(600), parent_shutdown_time_(900), - mode_(Server::Mode::Serve), hot_restart_disabled_(false), signal_handling_enabled_(true), - mutex_tracing_enabled_(false), cpuset_threads_(false), fake_symbol_table_enabled_(false) {} + restart_epoch_(0u), service_cluster_(service_cluster), service_node_(service_node), + service_zone_(service_zone), file_flush_interval_msec_(10000), drain_time_(600), + parent_shutdown_time_(900), mode_(Server::Mode::Serve), hot_restart_disabled_(false), + signal_handling_enabled_(true), mutex_tracing_enabled_(false), cpuset_threads_(false), + fake_symbol_table_enabled_(false) {} void OptionsImpl::disableExtensions(const std::vector& names) { for (const auto& name : names) { diff --git a/source/server/options_impl.h b/source/server/options_impl.h index 648409b92c822..b8f3e64695c47 100644 --- a/source/server/options_impl.h +++ b/source/server/options_impl.h @@ -118,7 +118,6 @@ class OptionsImpl : public Server::Options, protected Logger::Loggable Date: Mon, 13 Apr 2020 17:22:16 -0700 Subject: [PATCH 06/10] test Signed-off-by: Ruslan Nigmatullin --- source/server/options_impl.cc | 2 +- test/server/options_impl_test.cc | 34 ++++++++++++++++++++++++++++++-- 2 files changed, 33 insertions(+), 3 deletions(-) diff --git a/source/server/options_impl.cc b/source/server/options_impl.cc index 5db9fd2ef11bf..1dbd1c715d083 100644 --- a/source/server/options_impl.cc +++ b/source/server/options_impl.cc @@ -26,7 +26,7 @@ std::string prefixLogFormatWithLocation(const std::string& log_format) { std::string result; for (size_t i = 0; i < log_format.size(); ++i) { if (i + 1 < log_format.size() && log_format[i] == '%') { - if (log_format[i] == 'v') { + if (log_format[i + 1] == 'v') { result += "[%g:%#] "; } // Print '%' and go directly to the next character. diff --git a/test/server/options_impl_test.cc b/test/server/options_impl_test.cc index 6e6219ec35a46..469340f845c4a 100644 --- a/test/server/options_impl_test.cc +++ b/test/server/options_impl_test.cc @@ -47,6 +47,11 @@ class OptionsImplTest : public testing::Test { return std::make_unique( std::move(words), [](bool) { return "1"; }, spdlog::level::warn); } + + std::unique_ptr createOptionsImpl(std::vector args) { + return std::make_unique( + std::move(args), [](bool) { return "1"; }, spdlog::level::warn); + } }; TEST_F(OptionsImplTest, HotRestartVersion) { @@ -89,7 +94,7 @@ TEST_F(OptionsImplTest, All) { EXPECT_EQ(1U, options->restartEpoch()); EXPECT_EQ(spdlog::level::info, options->logLevel()); EXPECT_EQ(2, options->componentLogLevels().size()); - EXPECT_EQ("[%v]", options->logFormat()); + EXPECT_EQ("[[%g:%#] %v]", options->logFormat()); EXPECT_EQ("/foo/bar", options->logPath()); EXPECT_EQ("cluster", options->serviceClusterName()); EXPECT_EQ("node", options->serviceNodeName()); @@ -255,7 +260,8 @@ TEST_F(OptionsImplTest, OptionsAreInSyncWithProto) { // 4. allow-unknown-fields - deprecated alias of allow-unknown-static-fields. // 5. use-fake-symbol-table - short-term override for rollout of real symbol-table implementation. // 6. hot restart version - print the hot restart version and exit. - EXPECT_EQ(options->count() - 6, command_line_options->GetDescriptor()->field_count()); + // 7. log-format-prefix-with-location - short-term override for rollout of dynamic log format. + EXPECT_EQ(options->count() - 7, command_line_options->GetDescriptor()->field_count()); } TEST_F(OptionsImplTest, OptionsFromArgv) { @@ -400,6 +406,30 @@ TEST_F(OptionsImplTest, SetCpusetOnly) { EXPECT_NE(options->concurrency(), 0); } +TEST_F(OptionsImplTest, LogFormatDefault) { + std::unique_ptr options = createOptionsImpl({"envoy", "-c", "hello"}); + EXPECT_EQ(options->logFormat(), "[%Y-%m-%d %T.%e][%t][%l][%n] [%g:%#] %v"); +} + +TEST_F(OptionsImplTest, LogFormatDefaultNoPrefix) { + std::unique_ptr options = + createOptionsImpl({"envoy", "-c", "hello", "--log-format-prefix-with-location", "0"}); + EXPECT_EQ(options->logFormat(), "[%Y-%m-%d %T.%e][%t][%l][%n] %v"); +} + +TEST_F(OptionsImplTest, LogFormatOverride) { + std::unique_ptr options = + createOptionsImpl({"envoy", "-c", "hello", "--log-format", "%%v %v %t %v"}); + EXPECT_EQ(options->logFormat(), "%%v [%g:%#] %v %t [%g:%#] %v"); +} + +TEST_F(OptionsImplTest, LogFormatOverrideNoPrefix) { + std::unique_ptr options = + createOptionsImpl({"envoy", "-c", "hello", "--log-format", "%%v %v %t %v", + "--log-format-prefix-with-location 0"}); + EXPECT_EQ(options->logFormat(), "%%v %v %t %v"); +} + #if defined(__linux__) using testing::DoAll; From eae658a2bc01aa6f48d95f92aeadd8c83b61bb34 Mon Sep 17 00:00:00 2001 From: Ruslan Nigmatullin Date: Wed, 15 Apr 2020 18:32:34 -0700 Subject: [PATCH 07/10] cr Signed-off-by: Ruslan Nigmatullin --- source/server/options_impl.cc | 25 +++++-------------------- 1 file changed, 5 insertions(+), 20 deletions(-) diff --git a/source/server/options_impl.cc b/source/server/options_impl.cc index 1dbd1c715d083..6c64b212b6340 100644 --- a/source/server/options_impl.cc +++ b/source/server/options_impl.cc @@ -16,28 +16,13 @@ #include "server/options_impl_platform.h" #include "absl/strings/str_split.h" +#include "absl/strings/str_replace.h" #include "absl/strings/string_view.h" #include "spdlog/spdlog.h" #include "tclap/CmdLine.h" namespace Envoy { namespace { -std::string prefixLogFormatWithLocation(const std::string& log_format) { - std::string result; - for (size_t i = 0; i < log_format.size(); ++i) { - if (i + 1 < log_format.size() && log_format[i] == '%') { - if (log_format[i + 1] == 'v') { - result += "[%g:%#] "; - } - // Print '%' and go directly to the next character. - result += '%'; - i++; - } - result += log_format[i]; - } - return result; -} - std::vector toArgsVector(int argc, const char* const* argv) { std::vector args; args.reserve(argc); @@ -110,7 +95,8 @@ OptionsImpl::OptionsImpl(std::vector args, cmd, false); TCLAP::ValueArg log_format_prefix_with_location( "", "log-format-prefix-with-location", - "Prefix all logged messages with '[path/to/file.cc:99] '.", false, true, "bool", cmd); + "Prefix all occurences of '%v' in log format with with '[%g:%#] ' ('[path/to/file.cc:99] ').", + false, true, "bool", cmd); TCLAP::ValueArg log_path("", "log-path", "Path to logfile", false, "", "string", cmd); TCLAP::ValueArg restart_epoch("", "restart-epoch", "hot restart epoch #", false, 0, @@ -186,10 +172,9 @@ OptionsImpl::OptionsImpl(std::vector args, log_level_ = default_log_level; } + log_format_ = log_format.getValue(); if (log_format_prefix_with_location.getValue()) { - log_format_ = prefixLogFormatWithLocation(log_format.getValue()); - } else { - log_format_ = log_format.getValue(); + log_format_ = absl::StrReplaceAll(log_format_, {{"%%", "%%"}, {"%v", "[%g:%#] %v"}}); } log_format_escaped_ = log_format_escaped.getValue(); From db22fffb3d05c580baee5acef4f6b773ba996b38 Mon Sep 17 00:00:00 2001 From: Ruslan Nigmatullin Date: Wed, 15 Apr 2020 19:36:36 -0700 Subject: [PATCH 08/10] docs Signed-off-by: Ruslan Nigmatullin --- docs/root/operations/cli.rst | 22 +++++++++++++++++++++- docs/root/version_history/current.rst | 1 + source/server/options_impl.cc | 2 +- 3 files changed, 23 insertions(+), 2 deletions(-) diff --git a/docs/root/operations/cli.rst b/docs/root/operations/cli.rst index a14f7efe97f43..d86f537eeade0 100644 --- a/docs/root/operations/cli.rst +++ b/docs/root/operations/cli.rst @@ -94,7 +94,13 @@ following are the command line options that Envoy supports. *(optional)* The format string to use for laying out the log message metadata. If this is not set, a default format string ``"[%Y-%m-%d %T.%e][%t][%l][%n] %v"`` is used. - When used in conjunction with ``--log-format-escaped``, the logger can be configured + When used in conjunction with :option:`--log-format-prefix-with-location` set to 0, the logger can be + configured to not prefix ``%v`` by a file path and a line number. + + **NOTE**: The default log format will be changed to ``"[%Y-%m-%d %T.%e][%t][%l][%n] [%g:%#] %v"`` + together with the default value of :option:`--log-format-prefix-with-location` to 0 at 1.16.0 release. + + When used in conjunction with :option:`--log-format-escaped`, the logger can be configured to log in a format that is parsable by log viewers. Known integrations are documented in the :ref:`application logging configuration ` section. @@ -129,6 +135,20 @@ following are the command line options that Envoy supports. :%T, %X: ISO 8601 time format (HH:MM:SS), equivalent to %H:%M:%S ("13:25:06") :%z: ISO 8601 offset from UTC in timezone ([+/-]HH:MM) ("-07:00") :%%: The % sign ("%") + :%@: Source file and line ("my_file.cc:123") + :%s: Basename of the source file ("my_file.cc") + :%g: Full relative path of the source file ("/some/dir/my_file.cc") + :%#: Source line ("123") + :%!: Source function ("myFunc") + +.. option:: --log-format-prefix-with-location <1|0> + + *(optional)* This temporary flag allows replacing all entries of ``"%v"`` in the log format by + ``"[%g:%#] "``. This flag is provided for migration purposes only. If this is not set, a + default value 1 is used. + + **NOTE**: The default value will be changed to 0 at 1.16.0 release and the flag will be + removed at 1.17.0 release. .. option:: --log-format-escaped diff --git a/docs/root/version_history/current.rst b/docs/root/version_history/current.rst index 3ceea3457e589..7085e9b359dd9 100644 --- a/docs/root/version_history/current.rst +++ b/docs/root/version_history/current.rst @@ -9,6 +9,7 @@ Changes are applied to using :ref:`HTTP headers ` to the HTTP fault filter. * http: fixed a bug where the upgrade header was not cleared on responses to non-upgrade requests. Can be reverted temporarily by setting runtime feature `envoy.reloadable_features.fix_upgrade_response` to false. +* logger: added :ref:`--log-format-prefix-with-location ` command line option to prefix '%v' with file path and line number. * tracing: tracing configuration has been made fully dynamic and every HTTP connection manager can now have a separate :ref:`tracing provider `. diff --git a/source/server/options_impl.cc b/source/server/options_impl.cc index 6c64b212b6340..8d8a74deac42d 100644 --- a/source/server/options_impl.cc +++ b/source/server/options_impl.cc @@ -95,7 +95,7 @@ OptionsImpl::OptionsImpl(std::vector args, cmd, false); TCLAP::ValueArg log_format_prefix_with_location( "", "log-format-prefix-with-location", - "Prefix all occurences of '%v' in log format with with '[%g:%#] ' ('[path/to/file.cc:99] ').", + "Prefix all entrancies of '%v' in log format with with '[%g:%#] ' ('[path/to/file.cc:99] ').", false, true, "bool", cmd); TCLAP::ValueArg log_path("", "log-path", "Path to logfile", false, "", "string", cmd); From 0c1145e6d8f3bce85f0049c550127c71460c92ea Mon Sep 17 00:00:00 2001 From: Ruslan Nigmatullin Date: Wed, 15 Apr 2020 19:38:32 -0700 Subject: [PATCH 09/10] style Signed-off-by: Ruslan Nigmatullin --- source/server/options_impl.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/server/options_impl.cc b/source/server/options_impl.cc index 8d8a74deac42d..c8362d31adee5 100644 --- a/source/server/options_impl.cc +++ b/source/server/options_impl.cc @@ -15,8 +15,8 @@ #include "server/options_impl_platform.h" -#include "absl/strings/str_split.h" #include "absl/strings/str_replace.h" +#include "absl/strings/str_split.h" #include "absl/strings/string_view.h" #include "spdlog/spdlog.h" #include "tclap/CmdLine.h" From 4a687ea54b2cb3d6819156e1466333a50cfd880d Mon Sep 17 00:00:00 2001 From: Ruslan Nigmatullin Date: Thu, 16 Apr 2020 11:25:54 -0700 Subject: [PATCH 10/10] cr Signed-off-by: Ruslan Nigmatullin --- docs/root/operations/cli.rst | 2 +- source/server/options_impl.cc | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/docs/root/operations/cli.rst b/docs/root/operations/cli.rst index d86f537eeade0..a4729f1e3f078 100644 --- a/docs/root/operations/cli.rst +++ b/docs/root/operations/cli.rst @@ -144,7 +144,7 @@ following are the command line options that Envoy supports. .. option:: --log-format-prefix-with-location <1|0> *(optional)* This temporary flag allows replacing all entries of ``"%v"`` in the log format by - ``"[%g:%#] "``. This flag is provided for migration purposes only. If this is not set, a + ``"[%g:%#] %v"``. This flag is provided for migration purposes only. If this is not set, a default value 1 is used. **NOTE**: The default value will be changed to 0 at 1.16.0 release and the flag will be diff --git a/source/server/options_impl.cc b/source/server/options_impl.cc index c8362d31adee5..e2ca56f39e26b 100644 --- a/source/server/options_impl.cc +++ b/source/server/options_impl.cc @@ -95,7 +95,8 @@ OptionsImpl::OptionsImpl(std::vector args, cmd, false); TCLAP::ValueArg log_format_prefix_with_location( "", "log-format-prefix-with-location", - "Prefix all entrancies of '%v' in log format with with '[%g:%#] ' ('[path/to/file.cc:99] ').", + "Prefix all occurrences of '%v' in log format with with '[%g:%#] ' ('[path/to/file.cc:99] " + "').", false, true, "bool", cmd); TCLAP::ValueArg log_path("", "log-path", "Path to logfile", false, "", "string", cmd);