Merge pull request #24793 from veblush/log-trace

Added grpc_stacktrace_minloglevel

CMakeLists.txt

@@ -617,7 +617,6 @@ if(gRPC_BUILD_TESTS)
   add_dependencies(buildtests_c jwt_verifier_test)
   add_dependencies(buildtests_c lame_client_test)
   add_dependencies(buildtests_c load_file_test)
-  add_dependencies(buildtests_c log_test)
   add_dependencies(buildtests_c manual_constructor_test)
   add_dependencies(buildtests_c message_compress_test)
   add_dependencies(buildtests_c metadata_test)
@@ -864,6 +863,7 @@ if(gRPC_BUILD_TESTS)
   add_dependencies(buildtests_cxx lb_get_cpu_stats_test)
   add_dependencies(buildtests_cxx lb_load_data_store_test)
   add_dependencies(buildtests_cxx linux_system_roots_test)
+  add_dependencies(buildtests_cxx log_test)
   add_dependencies(buildtests_cxx message_allocator_end2end_test)
   add_dependencies(buildtests_cxx mock_test)
   add_dependencies(buildtests_cxx nonblocking_test)
@@ -6299,36 +6299,6 @@ target_link_libraries(load_file_test
 )
 
 
-endif()
-if(gRPC_BUILD_TESTS)
-
-add_executable(log_test
-  test/core/gpr/log_test.cc
-)
-
-target_include_directories(log_test
-  PRIVATE
-    ${CMAKE_CURRENT_SOURCE_DIR}
-    ${CMAKE_CURRENT_SOURCE_DIR}/include
-    ${_gRPC_ADDRESS_SORTING_INCLUDE_DIR}
-    ${_gRPC_RE2_INCLUDE_DIR}
-    ${_gRPC_SSL_INCLUDE_DIR}
-    ${_gRPC_UPB_GENERATED_DIR}
-    ${_gRPC_UPB_GRPC_GENERATED_DIR}
-    ${_gRPC_UPB_INCLUDE_DIR}
-    ${_gRPC_ZLIB_INCLUDE_DIR}
-)
-
-target_link_libraries(log_test
-  ${_gRPC_ALLTARGETS_LIBRARIES}
-  grpc_test_util
-  grpc
-  gpr
-  address_sorting
-  upb
-)
-
-
 endif()
 if(gRPC_BUILD_TESTS)
 
@@ -12749,6 +12719,44 @@ target_link_libraries(linux_system_roots_test
 )
 
 
+endif()
+if(gRPC_BUILD_TESTS)
+
+add_executable(log_test
+  test/core/gpr/log_test.cc
+  third_party/googletest/googletest/src/gtest-all.cc
+  third_party/googletest/googlemock/src/gmock-all.cc
+)
+
+target_include_directories(log_test
+  PRIVATE
+    ${CMAKE_CURRENT_SOURCE_DIR}
+    ${CMAKE_CURRENT_SOURCE_DIR}/include
+    ${_gRPC_ADDRESS_SORTING_INCLUDE_DIR}
+    ${_gRPC_RE2_INCLUDE_DIR}
+    ${_gRPC_SSL_INCLUDE_DIR}
+    ${_gRPC_UPB_GENERATED_DIR}
+    ${_gRPC_UPB_GRPC_GENERATED_DIR}
+    ${_gRPC_UPB_INCLUDE_DIR}
+    ${_gRPC_ZLIB_INCLUDE_DIR}
+    third_party/googletest/googletest/include
+    third_party/googletest/googletest
+    third_party/googletest/googlemock/include
+    third_party/googletest/googlemock
+    ${_gRPC_PROTO_GENS_DIR}
+)
+
+target_link_libraries(log_test
+  ${_gRPC_PROTOBUF_LIBRARIES}
+  ${_gRPC_ALLTARGETS_LIBRARIES}
+  grpc_test_util
+  grpc
+  gpr
+  address_sorting
+  upb
+)
+
+
 endif()
 if(gRPC_BUILD_TESTS)
 

build_autogenerated.yaml

@@ -3859,19 +3859,6 @@ targets:
   - address_sorting
   - upb
   uses_polling: false
-- name: log_test
-  build: test
-  language: c
-  headers: []
-  src:
-  - test/core/gpr/log_test.cc
-  deps:
-  - grpc_test_util
-  - grpc
-  - gpr
-  - address_sorting
-  - upb
-  uses_polling: false
 - name: manual_constructor_test
   build: test
   language: c
@@ -6710,6 +6697,20 @@ targets:
   - gpr
   - address_sorting
   - upb
+- name: log_test
+  gtest: true
+  build: test
+  language: c++
+  headers: []
+  src:
+  - test/core/gpr/log_test.cc
+  deps:
+  - grpc_test_util
+  - grpc
+  - gpr
+  - address_sorting
+  - upb
+  uses_polling: false
 - name: message_allocator_end2end_test
   gtest: true
   build: test

doc/environment_variables.md

@@ -134,7 +134,12 @@ some configuration as environment variables that can be set.
   Default gRPC logging verbosity - one of:
   - DEBUG - log all gRPC messages
   - INFO - log INFO and ERROR message
-  - ERROR - log only errors
+  - ERROR - log only errors (default)
+  - NONE - won't log any
+
+* GRPC_STACKTRACE_MINLOGLEVEL
+  Minimum loglevel to print the stack-trace - one of DEBUG, INFO, ERROR, and NONE.
+  NONE is a default value.
 
 * GRPC_TRACE_FUZZER
   if set, the fuzzers will output trace (it is usually suppressed).

include/grpc/impl/codegen/log.h

@@ -46,8 +46,6 @@ typedef enum gpr_log_severity {
   GPR_LOG_SEVERITY_ERROR
 } gpr_log_severity;
 
-#define GPR_LOG_VERBOSITY_UNSET -1
-
 /** Returns a string representation of the log severity */
 GPRAPI const char* gpr_log_severity_string(gpr_log_severity severity);
 

src/core/lib/gpr/log.cc

@@ -30,10 +30,17 @@
 
 GPR_GLOBAL_CONFIG_DEFINE_STRING(grpc_verbosity, "ERROR",
                                 "Default gRPC logging verbosity")
+GPR_GLOBAL_CONFIG_DEFINE_STRING(grpc_stacktrace_minloglevel, "",
+                                "Messages logged at the same or higher level "
+                                "than this will print stacktrace")
+
+static constexpr gpr_atm GPR_LOG_SEVERITY_UNSET = GPR_LOG_SEVERITY_ERROR + 10;
+static constexpr gpr_atm GPR_LOG_SEVERITY_NONE = GPR_LOG_SEVERITY_ERROR + 11;
 
 void gpr_default_log(gpr_log_func_args* args);
 static gpr_atm g_log_func = (gpr_atm)gpr_default_log;
-static gpr_atm g_min_severity_to_print = GPR_LOG_VERBOSITY_UNSET;
+static gpr_atm g_min_severity_to_print = GPR_LOG_SEVERITY_UNSET;
+static gpr_atm g_min_severity_to_print_stacktrace = GPR_LOG_SEVERITY_UNSET;
 
 const char* gpr_log_severity_string(gpr_log_severity severity) {
   switch (severity) {
@@ -54,6 +61,13 @@ int gpr_should_log(gpr_log_severity severity) {
              : 0;
 }
 
+int gpr_should_log_stacktrace(gpr_log_severity severity) {
+  return static_cast<gpr_atm>(severity) >=
+                 gpr_atm_no_barrier_load(&g_min_severity_to_print_stacktrace)
+             ? 1
+             : 0;
+}
+
 void gpr_log_message(const char* file, int line, gpr_log_severity severity,
                      const char* message) {
   if (gpr_should_log(severity) == 0) {
@@ -74,23 +88,46 @@ void gpr_set_log_verbosity(gpr_log_severity min_severity_to_print) {
                            (gpr_atm)min_severity_to_print);
 }
 
-void gpr_log_verbosity_init() {
-  grpc_core::UniquePtr<char> verbosity = GPR_GLOBAL_CONFIG_GET(grpc_verbosity);
-
-  gpr_atm min_severity_to_print = GPR_LOG_SEVERITY_ERROR;
-  if (strlen(verbosity.get()) > 0) {
-    if (gpr_stricmp(verbosity.get(), "DEBUG") == 0) {
-      min_severity_to_print = static_cast<gpr_atm>(GPR_LOG_SEVERITY_DEBUG);
-    } else if (gpr_stricmp(verbosity.get(), "INFO") == 0) {
-      min_severity_to_print = static_cast<gpr_atm>(GPR_LOG_SEVERITY_INFO);
-    } else if (gpr_stricmp(verbosity.get(), "ERROR") == 0) {
-      min_severity_to_print = static_cast<gpr_atm>(GPR_LOG_SEVERITY_ERROR);
-    }
+static gpr_atm parse_log_severity(const char* str, gpr_atm error_value) {
+  if (gpr_stricmp(str, "DEBUG") == 0) {
+    return GPR_LOG_SEVERITY_DEBUG;
+  } else if (gpr_stricmp(str, "INFO") == 0) {
+    return GPR_LOG_SEVERITY_INFO;
+  } else if (gpr_stricmp(str, "ERROR") == 0) {
+    return GPR_LOG_SEVERITY_ERROR;
+  } else if (gpr_stricmp(str, "NONE") == 0) {
+    return GPR_LOG_SEVERITY_NONE;
+  } else {
+    return error_value;
   }
+}
+
+void gpr_log_verbosity_init() {
+  // init verbosity when it hasn't been set
   if ((gpr_atm_no_barrier_load(&g_min_severity_to_print)) ==
-      GPR_LOG_VERBOSITY_UNSET) {
+      GPR_LOG_SEVERITY_UNSET) {
+    grpc_core::UniquePtr<char> verbosity =
+        GPR_GLOBAL_CONFIG_GET(grpc_verbosity);
+    gpr_atm min_severity_to_print = GPR_LOG_SEVERITY_ERROR;
+    if (strlen(verbosity.get()) > 0) {
+      min_severity_to_print =
+          parse_log_severity(verbosity.get(), min_severity_to_print);
+    }
     gpr_atm_no_barrier_store(&g_min_severity_to_print, min_severity_to_print);
   }
+  // init stacktrace_minloglevel when it hasn't been set
+  if ((gpr_atm_no_barrier_load(&g_min_severity_to_print_stacktrace)) ==
+      GPR_LOG_SEVERITY_UNSET) {
+    grpc_core::UniquePtr<char> stacktrace_minloglevel =
+        GPR_GLOBAL_CONFIG_GET(grpc_stacktrace_minloglevel);
+    gpr_atm min_severity_to_print_stacktrace = GPR_LOG_SEVERITY_NONE;
+    if (strlen(stacktrace_minloglevel.get()) > 0) {
+      min_severity_to_print_stacktrace = parse_log_severity(
+          stacktrace_minloglevel.get(), min_severity_to_print_stacktrace);
+    }
+    gpr_atm_no_barrier_store(&g_min_severity_to_print_stacktrace,
+                             min_severity_to_print_stacktrace);
+  }
 }
 
 void gpr_set_log_function(gpr_log_func f) {

src/core/lib/gpr/log_linux.cc

@@ -44,6 +44,8 @@
 #include "absl/strings/str_format.h"
 #include "src/core/lib/gprpp/examine_stack.h"
 
+int gpr_should_log_stacktrace(gpr_log_severity severity);
+
 static long sys_gettid(void) { return syscall(__NR_gettid); }
 
 void gpr_log(const char* file, int line, gpr_log_severity severity,
@@ -95,7 +97,7 @@ void gpr_default_log(gpr_log_func_args* args) {
       time_buffer, now.tv_nsec, tid, display_file, args->line);
 
   absl::optional<std::string> stack_trace =
-      args->severity >= GPR_LOG_SEVERITY_ERROR
+      gpr_should_log_stacktrace(args->severity)
           ? grpc_core::GetCurrentStackTrace()
           : absl::nullopt;
   if (stack_trace) {

src/core/lib/gpr/log_posix.cc

@@ -34,6 +34,8 @@
 #include "absl/strings/str_format.h"
 #include "src/core/lib/gprpp/examine_stack.h"
 
+int gpr_should_log_stacktrace(gpr_log_severity severity);
+
 static intptr_t sys_gettid(void) { return (intptr_t)pthread_self(); }
 
 void gpr_log(const char* file, int line, gpr_log_severity severity,
@@ -91,7 +93,7 @@ void gpr_default_log(gpr_log_func_args* args) {
       time_buffer, (int)(now.tv_nsec), sys_gettid(), display_file, args->line);
 
   absl::optional<std::string> stack_trace =
-      args->severity >= GPR_LOG_SEVERITY_ERROR
+      gpr_should_log_stacktrace(args->severity)
           ? grpc_core::GetCurrentStackTrace()
           : absl::nullopt;
   if (stack_trace) {

src/core/lib/gpr/log_windows.cc

@@ -33,6 +33,8 @@
 #include "src/core/lib/gpr/string_windows.h"
 #include "src/core/lib/gprpp/examine_stack.h"
 
+int gpr_should_log_stacktrace(gpr_log_severity severity);
+
 void gpr_log(const char* file, int line, gpr_log_severity severity,
              const char* format, ...) {
   /* Avoid message construction if gpr_log_message won't log */
@@ -94,7 +96,7 @@ void gpr_default_log(gpr_log_func_args* args) {
   }
 
   absl::optional<std::string> stack_trace =
-      args->severity >= GPR_LOG_SEVERITY_ERROR
+      gpr_should_log_stacktrace(args->severity)
           ? grpc_core::GetCurrentStackTrace()
           : absl::nullopt;
   if (stack_trace) {

test/core/gpr/BUILD

@@ -65,6 +65,9 @@ grpc_cc_test(
 grpc_cc_test(
     name = "log_test",
     srcs = ["log_test.cc"],
+    external_deps = [
+        "gtest",
+    ],
     language = "C++",
     uses_polling = False,
     deps = [

test/core/gpr/log_test.cc

@@ -16,19 +16,16 @@
  *
  */
 
-#include <grpc/support/log.h>
-
 #include <stdbool.h>
 #include <string.h>
 
+#include <gtest/gtest.h>
+
+#include <grpc/support/log.h>
+
 #include "src/core/lib/gprpp/global_config.h"
 #include "test/core/util/test_config.h"
 
-// Config declaration is supposed to be located at log.h but
-// log.h doesn't include global_config headers because it has to
-// be a strict C so declaration statement gets to be here.
-GPR_GLOBAL_CONFIG_DECLARE_STRING(grpc_verbosity);
-
 static bool log_func_reached = false;
 
 static void test_callback(gpr_log_func_args* args) {
@@ -52,15 +49,16 @@ static void test_should_not_log(gpr_log_func_args* /*args*/) {
   GPR_ASSERT(log_func_reached);                 \
   log_func_reached = false;                     \
   gpr_log(SEVERITY, "hello %d %d %d", 1, 2, 3); \
-  GPR_ASSERT(log_func_reached);
+  GPR_ASSERT(log_func_reached);                 \
+  gpr_set_log_function(nullptr);
 
-#define test_log_function_unreached(SEVERITY) \
-  gpr_set_log_function(test_should_not_log);  \
-  gpr_log_message(SEVERITY, "hello 1 2 3");   \
-  gpr_log(SEVERITY, "hello %d %d %d", 1, 2, 3);
+#define test_log_function_unreached(SEVERITY)   \
+  gpr_set_log_function(test_should_not_log);    \
+  gpr_log_message(SEVERITY, "hello 1 2 3");     \
+  gpr_log(SEVERITY, "hello %d %d %d", 1, 2, 3); \
+  gpr_set_log_function(nullptr);
 
-int main(int argc, char** argv) {
-  grpc::testing::TestEnvironment env(argc, argv);
+TEST(LogTest, Basic) {
   /* test logging at various verbosity levels */
   gpr_log(GPR_DEBUG, "%s", "hello world");
   gpr_log(GPR_INFO, "%s", "hello world");
@@ -71,23 +69,9 @@ int main(int argc, char** argv) {
   gpr_log_message(GPR_INFO, "hello 1 2 3");
   gpr_log(GPR_INFO, "hello %d %d %d", 1, 2, 3);
   gpr_set_log_function(nullptr);
+}
 
-  /* gpr_log_verbosity_init() will be effective only once, and only before
-   * gpr_set_log_verbosity() is called */
-  GPR_GLOBAL_CONFIG_SET(grpc_verbosity, "ERROR");
-  gpr_log_verbosity_init();
-
-  test_log_function_reached(GPR_ERROR);
-  test_log_function_unreached(GPR_INFO);
-  test_log_function_unreached(GPR_DEBUG);
-
-  /* gpr_log_verbosity_init() should not be effective */
-  GPR_GLOBAL_CONFIG_SET(grpc_verbosity, "DEBUG");
-  gpr_log_verbosity_init();
-  test_log_function_reached(GPR_ERROR);
-  test_log_function_unreached(GPR_INFO);
-  test_log_function_unreached(GPR_DEBUG);
-
+TEST(LogTest, LogVerbosity) {
   gpr_set_log_verbosity(GPR_LOG_SEVERITY_DEBUG);
   test_log_function_reached(GPR_ERROR);
   test_log_function_reached(GPR_INFO);
@@ -102,14 +86,11 @@ int main(int argc, char** argv) {
   test_log_function_reached(GPR_ERROR);
   test_log_function_unreached(GPR_INFO);
   test_log_function_unreached(GPR_DEBUG);
+}
 
-  /* gpr_log_verbosity_init() should not be effective */
-  GPR_GLOBAL_CONFIG_SET(grpc_verbosity, "DEBUG");
-  gpr_log_verbosity_init();
-  test_log_function_reached(GPR_ERROR);
-  test_log_function_unreached(GPR_INFO);
-  test_log_function_unreached(GPR_DEBUG);
-
-  /* TODO(ctiller): should we add a GPR_ASSERT failure test here */
-  return 0;
+int main(int argc, char** argv) {
+  grpc::testing::TestEnvironment env(argc, argv);
+  ::testing::InitGoogleTest(&argc, argv);
+  int ret = RUN_ALL_TESTS();
+  return ret;
 }

test/core/util/test_config.cc

@@ -157,6 +157,7 @@ void grpc_test_init(int argc, char** argv) {
   grpc_core::testing::InitializeStackTracer(argv[0]);
   absl::FailureSignalHandlerOptions options;
   absl::InstallFailureSignalHandler(options);
+  gpr_log_verbosity_init();
   gpr_log(GPR_DEBUG,
           "test slowdown factor: sanitizer=%" PRId64 ", fixture=%" PRId64
           ", poller=%" PRId64 ", total=%" PRId64,

tools/run_tests/generated/tests.json

@@ -1751,30 +1751,6 @@
     ],
     "uses_polling": false
   },
-  {
-    "args": [],
-    "benchmark": false,
-    "ci_platforms": [
-      "linux",
-      "mac",
-      "posix",
-      "windows"
-    ],
-    "cpu_cost": 1.0,
-    "exclude_configs": [],
-    "exclude_iomgrs": [],
-    "flaky": false,
-    "gtest": false,
-    "language": "c",
-    "name": "log_test",
-    "platforms": [
-      "linux",
-      "mac",
-      "posix",
-      "windows"
-    ],
-    "uses_polling": false
-  },
   {
     "args": [],
     "benchmark": false,
@@ -5071,6 +5047,30 @@
     ],
     "uses_polling": true
   },
+  {
+    "args": [],
+    "benchmark": false,
+    "ci_platforms": [
+      "linux",
+      "mac",
+      "posix",
+      "windows"
+    ],
+    "cpu_cost": 1.0,
+    "exclude_configs": [],
+    "exclude_iomgrs": [],
+    "flaky": false,
+    "gtest": true,
+    "language": "c++",
+    "name": "log_test",
+    "platforms": [
+      "linux",
+      "mac",
+      "posix",
+      "windows"
+    ],
+    "uses_polling": false
+  },
   {
     "args": [],
     "benchmark": false,