logger: Make log prefix configurable

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 <config_application_logs>` 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:%#] %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
+   removed at 1.17.0 release.
 
 .. option:: --log-format-escaped
 

docs/root/version_history/current.rst

@@ -15,6 +15,7 @@ Changes
   `google.api.HttpBody <https://github.com/googleapis/googleapis/blob/master/google/api/httpbody.proto>`_.
 * 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 <operations_cli>` command line option to prefix '%v' with file path and line number.
 * network filters: added a :ref:`postgres proxy filter <config_network_filters_postgres_proxy>`.
 * router: allow retries of streaming or incomplete requests. This removes stat `rq_retry_skipped_request_not_complete`.
 * tracing: tracing configuration has been made fully dynamic and every HTTP connection manager

source/common/common/logger.h

@@ -282,27 +282,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/server/options_impl.cc

@@ -15,6 +15,7 @@
 
 #include "server/options_impl_platform.h"
 
+#include "absl/strings/str_replace.h"
 #include "absl/strings/str_split.h"
 #include "absl/strings/string_view.h"
 #include "spdlog/spdlog.h"
@@ -92,6 +93,11 @@ 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 occurrences of '%v' in log format with with '[%g:%#] ' ('[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,
@@ -168,6 +174,9 @@ OptionsImpl::OptionsImpl(std::vector<std::string> args,
   }
 
   log_format_ = log_format.getValue();
+  if (log_format_prefix_with_location.getValue()) {
+    log_format_ = absl::StrReplaceAll(log_format_, {{"%%", "%%"}, {"%v", "[%g:%#] %v"}});
+  }
   log_format_escaped_ = log_format_escaped.getValue();
 
   parseComponentLogLevels(component_log_level.getValue());

test/server/options_impl_test.cc

@@ -48,6 +48,11 @@ class OptionsImplTest : public testing::Test {
     return std::make_unique<OptionsImpl>(
         std::move(words), [](bool) { return "1"; }, spdlog::level::warn);
   }
+
+  std::unique_ptr<OptionsImpl> createOptionsImpl(std::vector<std::string> args) {
+    return std::make_unique<OptionsImpl>(
+        std::move(args), [](bool) { return "1"; }, spdlog::level::warn);
+  }
 };
 
 TEST_F(OptionsImplTest, HotRestartVersion) {
@@ -90,7 +95,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());
@@ -256,7 +261,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) {
@@ -401,6 +407,30 @@ TEST_F(OptionsImplTest, SetCpusetOnly) {
   EXPECT_NE(options->concurrency(), 0);
 }
 
+TEST_F(OptionsImplTest, LogFormatDefault) {
+  std::unique_ptr<OptionsImpl> 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<OptionsImpl> 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<OptionsImpl> 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<OptionsImpl> 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;