diff --git a/CMakeLists.txt b/CMakeLists.txt index 036295a5674..66090c1fea2 100644 --- a/CMakeLists.txt +++ b/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) diff --git a/build_autogenerated.yaml b/build_autogenerated.yaml index ab08482b054..e945677e959 100644 --- a/build_autogenerated.yaml +++ b/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 diff --git a/doc/environment_variables.md b/doc/environment_variables.md index 73337826c90..82cb28d0f40 100644 --- a/doc/environment_variables.md +++ b/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). diff --git a/include/grpc/impl/codegen/log.h b/include/grpc/impl/codegen/log.h index ad7f0241582..9dd3a518347 100644 --- a/include/grpc/impl/codegen/log.h +++ b/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); diff --git a/src/core/lib/gpr/log.cc b/src/core/lib/gpr/log.cc index 8a229b2adf1..4ce53017fd9 100644 --- a/src/core/lib/gpr/log.cc +++ b/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(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 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_LOG_SEVERITY_DEBUG); - } else if (gpr_stricmp(verbosity.get(), "INFO") == 0) { - min_severity_to_print = static_cast(GPR_LOG_SEVERITY_INFO); - } else if (gpr_stricmp(verbosity.get(), "ERROR") == 0) { - min_severity_to_print = static_cast(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 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 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) { diff --git a/src/core/lib/gpr/log_linux.cc b/src/core/lib/gpr/log_linux.cc index 3d1f4dd9270..6f64faab785 100644 --- a/src/core/lib/gpr/log_linux.cc +++ b/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 stack_trace = - args->severity >= GPR_LOG_SEVERITY_ERROR + gpr_should_log_stacktrace(args->severity) ? grpc_core::GetCurrentStackTrace() : absl::nullopt; if (stack_trace) { diff --git a/src/core/lib/gpr/log_posix.cc b/src/core/lib/gpr/log_posix.cc index de293ce0b79..4bd6117f76c 100644 --- a/src/core/lib/gpr/log_posix.cc +++ b/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 stack_trace = - args->severity >= GPR_LOG_SEVERITY_ERROR + gpr_should_log_stacktrace(args->severity) ? grpc_core::GetCurrentStackTrace() : absl::nullopt; if (stack_trace) { diff --git a/src/core/lib/gpr/log_windows.cc b/src/core/lib/gpr/log_windows.cc index bed202fab7a..472121b3a19 100644 --- a/src/core/lib/gpr/log_windows.cc +++ b/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 stack_trace = - args->severity >= GPR_LOG_SEVERITY_ERROR + gpr_should_log_stacktrace(args->severity) ? grpc_core::GetCurrentStackTrace() : absl::nullopt; if (stack_trace) { diff --git a/test/core/gpr/BUILD b/test/core/gpr/BUILD index b38b17f382d..83f3e3c8c37 100644 --- a/test/core/gpr/BUILD +++ b/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 = [ diff --git a/test/core/gpr/log_test.cc b/test/core/gpr/log_test.cc index d7b3a202938..2acefdaf083 100644 --- a/test/core/gpr/log_test.cc +++ b/test/core/gpr/log_test.cc @@ -16,19 +16,16 @@ * */ -#include - #include #include +#include + +#include + #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; } diff --git a/test/core/util/test_config.cc b/test/core/util/test_config.cc index d44e07bf073..9fe08bc1cd1 100644 --- a/test/core/util/test_config.cc +++ b/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, diff --git a/tools/run_tests/generated/tests.json b/tools/run_tests/generated/tests.json index 48bb34f5a55..e3548e789ca 100644 --- a/tools/run_tests/generated/tests.json +++ b/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,