logger: Make log prefix configurable

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;
 

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;
 

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.
    */

source/common/common/logger.cc

@@ -47,15 +47,28 @@ void DelegatingLogSink::set_formatter(std::unique_ptr<spdlog::formatter> 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_);
 }

source/common/common/logger.h

@@ -145,6 +145,9 @@ class DelegatingLogSink : public spdlog::sinks::sink {
   }
   void set_formatter(std::unique_ptr<spdlog::formatter> 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<spdlog::formatter> 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_;
 };
 
@@ -282,27 +287,24 @@ template <Id id> 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<spdlog::level::level_enum>(Envoy::Logger::Logger::LEVEL) >= LOGGER.level())
+#define ENVOY_SPDLOG_LEVEL(LEVEL)                                                                  \
+  (static_cast<spdlog::level::level_enum>(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.
 // The same filtering will also occur in spdlog::logger.
 #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)
 

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<Logger::Context>(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<Server::HotRestartNopImpl>();
-    logging_context_ =
-        std::make_unique<Logger::Context>(options_.logLevel(), options_.logFormat(),
-                                          restarter_->logLock(), options_.logFormatEscaped());
+    logging_context_ = std::make_unique<Logger::Context>(
+        options_.logLevel(), options_.logFormat(), restarter_->logLock(),
+        options_.logFormatEscaped(), options_.logFormatPrefixWithLocation());
     break;
   }
 }

source/server/options_impl.cc

@@ -92,6 +92,9 @@ OptionsImpl::OptionsImpl(std::vector<std::string> args,
   TCLAP::SwitchArg log_format_escaped("", "log-format-escaped",
                                       "Escape c-style escape sequences in the application logs",
                                       cmd, false);
+  TCLAP::ValueArg<bool> log_format_prefix_with_location(
+      "", "log-format-prefix-with-location",
+      "Prefix all logged messages with '[path/to/file.cc:99] '.", false, true, "bool", cmd);
   TCLAP::ValueArg<std::string> log_path("", "log-path", "Path to logfile", false, "", "string",
                                         cmd);
   TCLAP::ValueArg<uint32_t> restart_epoch("", "restart-epoch", "hot restart epoch #", false, 0,
@@ -169,6 +172,7 @@ OptionsImpl::OptionsImpl(std::vector<std::string> 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<std::string>& names) {
   for (const auto& name : names) {

source/server/options_impl.h

@@ -118,6 +118,7 @@ class OptionsImpl : public Server::Options, protected Logger::Loggable<Logger::I
   }
   const std::string& logFormat() const override { return log_format_; }
   bool logFormatEscaped() const override { return log_format_escaped_; }
+  bool logFormatPrefixWithLocation() const override { return log_format_prefix_with_location_; }
   const std::string& logPath() const override { return log_path_; }
   std::chrono::seconds parentShutdownTime() const override { return parent_shutdown_time_; }
   uint64_t restartEpoch() const override { return restart_epoch_; }
@@ -166,6 +167,7 @@ class OptionsImpl : public Server::Options, protected Logger::Loggable<Logger::I
   std::string component_log_level_str_;
   std::string log_format_;
   bool log_format_escaped_;
+  bool log_format_prefix_with_location_;
   std::string log_path_;
   uint64_t restart_epoch_;
   std::string service_cluster_;

test/mocks/server/mocks.h

@@ -84,6 +84,7 @@ 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));

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<AccessLog::MockAccessLogManager> access_log_manager;