From 5a5fec0452740f93c6d0f7ac73ee455983a338a7 Mon Sep 17 00:00:00 2001 From: Edward Chen <18449977+edgchen1@users.noreply.github.com> Date: Fri, 7 May 2021 15:40:47 -0700 Subject: [PATCH] Fix logs getting skipped in single-line conditionals. (#7589) Fix an issue where a log message got skipped. A log call like this: ``` LOGS(...) << "message"; ``` expands to something like this: ``` if () logging::Capture(...).Stream() << "message"; ``` This if statement without brackets is handy for logging arbitrary arguments with the `<<` operator. However, it has other drawbacks like possibly associating with a subsequent `else`. ``` if (cond) LOGS(...) << "a"; else // not run when !cond // equivalently: if (cond) if () logging::Capture(...).Stream() << "a"; else // not run when !cond ``` Updated the logging macros to handle this case by replacing `if () logging::Capture(...).Stream()` with `if (!) {} else logging::Capture(...).Stream()`. Thanks @tlh20 for the idea for the fix! --- .../onnxruntime/core/common/logging/macros.h | 247 +++++++++++------- .../coreml/coreml_execution_provider.cc | 5 +- .../nnapi_builtin/nnapi_execution_provider.cc | 5 +- .../test/common/logging/logging_test.cc | 35 +++ 4 files changed, 193 insertions(+), 99 deletions(-) diff --git a/include/onnxruntime/core/common/logging/macros.h b/include/onnxruntime/core/common/logging/macros.h index 570bc14fa8..fbf14ce69c 100644 --- a/include/onnxruntime/core/common/logging/macros.h +++ b/include/onnxruntime/core/common/logging/macros.h @@ -4,7 +4,7 @@ #pragma once // NOTE: Don't include this file directly. Include logging.h -#define CREATE_MESSAGE(logger, severity, category, datatype) \ +#define CREATE_MESSAGE(logger, severity, category, datatype) \ ::onnxruntime::logging::Capture(logger, ::onnxruntime::logging::Severity::k##severity, category, datatype, ORT_WHERE) /* @@ -43,167 +43,224 @@ */ +/** + * Note: + * The stream style logging macros (something like `LOGS() << message`) are designed to be appended to. + * Normally, we can isolate macro code in a separate scope (e.g., `do {...} while(0)`), but here we need the macro code + * to interact with subsequent code (i.e., the values to log). + * + * When an unisolated conditional is involved, extra care needs to be taken to avoid unexpected parsing behavior. + * For example: + * + * if (enabled) + * Capture().Stream() + * + * is more direct, but + * + * if (!enabled) { + * } else Capture().Stream() + * + * ensures that the `if` does not unintentionally associate with a subsequent `else`. + */ + // Logging with explicit category // iostream style logging. Capture log info in Message, and push to the logger in ~Message. -#define LOGS_CATEGORY(logger, severity, category) \ - if ((logger).OutputIsEnabled(::onnxruntime::logging::Severity::k##severity, ::onnxruntime::logging::DataType::SYSTEM)) \ +#define LOGS_CATEGORY(logger, severity, category) \ + if (!(logger).OutputIsEnabled(::onnxruntime::logging::Severity::k##severity, \ + ::onnxruntime::logging::DataType::SYSTEM)) { \ + /* do nothing */ \ + } else \ CREATE_MESSAGE(logger, severity, category, ::onnxruntime::logging::DataType::SYSTEM).Stream() -#define LOGS_USER_CATEGORY(logger, severity, category) \ - if ((logger).OutputIsEnabled(::onnxruntime::logging::Severity::k##severity, ::onnxruntime::logging::DataType::USER)) \ - CREATE_MESSAGE(logger, severity, category, ::onnxruntime::logging::DataType::USER).Stream() +#define LOGS_USER_CATEGORY(logger, severity, category) \ + if (!(logger).OutputIsEnabled(::onnxruntime::logging::Severity::k##severity, \ + ::onnxruntime::logging::DataType::USER)) { \ + /* do nothing */ \ + } else \ + CREATE_MESSAGE(logger, severity, category, ::onnxruntime::logging::DataType::USER).Stream() - // printf style logging. Capture log info in Message, and push to the logger in ~Message. -#define LOGF_CATEGORY(logger, severity, category, format_str, ...) \ - if ((logger).OutputIsEnabled(::onnxruntime::logging::Severity::k##severity, ::onnxruntime::logging::DataType::SYSTEM)) \ - CREATE_MESSAGE(logger, severity, category, ::onnxruntime::logging::DataType::SYSTEM).CapturePrintf(format_str, ##__VA_ARGS__) +// printf style logging. Capture log info in Message, and push to the logger in ~Message. +#define LOGF_CATEGORY(logger, severity, category, format_str, ...) \ + do { \ + if ((logger).OutputIsEnabled(::onnxruntime::logging::Severity::k##severity, \ + ::onnxruntime::logging::DataType::SYSTEM)) \ + CREATE_MESSAGE(logger, severity, category, ::onnxruntime::logging::DataType::SYSTEM) \ + .CapturePrintf(format_str, ##__VA_ARGS__); \ + } while (0) -#define LOGF_USER_CATEGORY(logger, severity, category, format_str, ...) \ - if ((logger).OutputIsEnabled(::onnxruntime::logging::Severity::k##severity, ::onnxruntime::logging::DataType::USER)) \ - CREATE_MESSAGE(logger, severity, category, ::onnxruntime::logging::DataType::USER).CapturePrintf(format_str, ##__VA_ARGS__) +#define LOGF_USER_CATEGORY(logger, severity, category, format_str, ...) \ + do { \ + if ((logger).OutputIsEnabled(::onnxruntime::logging::Severity::k##severity, \ + ::onnxruntime::logging::DataType::USER)) \ + CREATE_MESSAGE(logger, severity, category, ::onnxruntime::logging::DataType::USER) \ + .CapturePrintf(format_str, ##__VA_ARGS__); \ + } while (0) - // Logging with category of "onnxruntime" +// Logging with category of "onnxruntime" -#define LOGS(logger, severity) \ - LOGS_CATEGORY(logger, severity, ::onnxruntime::logging::Category::onnxruntime) +#define LOGS(logger, severity) \ + LOGS_CATEGORY(logger, severity, ::onnxruntime::logging::Category::onnxruntime) -#define LOGS_USER(logger, severity) \ +#define LOGS_USER(logger, severity) \ LOGS_USER_CATEGORY(logger, severity, ::onnxruntime::logging::Category::onnxruntime) - // printf style logging. Capture log info in Message, and push to the logger in ~Message. -#define LOGF(logger, severity, format_str, ...) \ - LOGF_CATEGORY(logger, severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) +// printf style logging. Capture log info in Message, and push to the logger in ~Message. +#define LOGF(logger, severity, format_str, ...) \ + LOGF_CATEGORY(logger, severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) -#define LOGF_USER(logger, severity, format_str, ...) \ - LOGF_USER_CATEGORY(logger, severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) +#define LOGF_USER(logger, severity, format_str, ...) \ + LOGF_USER_CATEGORY(logger, severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) - /* +/* + Macros that use the default logger. + A LoggingManager instance must be currently valid for the default logger to be available. +*/ - Macros that use the default logger. - A LoggingManager instance must be currently valid for the default logger to be available. +// Logging with explicit category - */ +#define LOGS_DEFAULT_CATEGORY(severity, category) \ + LOGS_CATEGORY(::onnxruntime::logging::LoggingManager::DefaultLogger(), severity, category) - // Logging with explicit category +#define LOGS_USER_DEFAULT_CATEGORY(severity, category) \ + LOGS_USER_CATEGORY(::onnxruntime::logging::LoggingManager::DefaultLogger(), severity, category) -#define LOGS_DEFAULT_CATEGORY(severity, category) \ - LOGS_CATEGORY(::onnxruntime::logging::LoggingManager::DefaultLogger(), severity, category) - -#define LOGS_USER_DEFAULT_CATEGORY(severity, category) \ - LOGS_USER_CATEGORY(::onnxruntime::logging::LoggingManager::DefaultLogger(), severity, category) - -#define LOGF_DEFAULT_CATEGORY(severity, category, format_str, ...) \ - LOGF_CATEGORY(::onnxruntime::logging::LoggingManager::DefaultLogger(), severity, category, format_str, ##__VA_ARGS__) +#define LOGF_DEFAULT_CATEGORY(severity, category, format_str, ...) \ + LOGF_CATEGORY(::onnxruntime::logging::LoggingManager::DefaultLogger(), severity, category, format_str, ##__VA_ARGS__) #define LOGF_USER_DEFAULT_CATEGORY(severity, category, format_str, ...) \ LOGF_USER_CATEGORY(::onnxruntime::logging::LoggingManager::DefaultLogger(), severity, category, format_str, ##__VA_ARGS__) // Logging with category of "onnxruntime" -#define LOGS_DEFAULT(severity) \ +#define LOGS_DEFAULT(severity) \ LOGS_DEFAULT_CATEGORY(severity, ::onnxruntime::logging::Category::onnxruntime) -#define LOGS_USER_DEFAULT(severity) \ +#define LOGS_USER_DEFAULT(severity) \ LOGS_USER_DEFAULT_CATEGORY(severity, ::onnxruntime::logging::Category::onnxruntime) -#define LOGF_DEFAULT(severity, format_str, ...) \ - LOGF_DEFAULT_CATEGORY(severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) +#define LOGF_DEFAULT(severity, format_str, ...) \ + LOGF_DEFAULT_CATEGORY(severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) -#define LOGF_USER_DEFAULT(severity, format_str, ...) \ - LOGF_USER_DEFAULT_CATEGORY(severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) +#define LOGF_USER_DEFAULT(severity, format_str, ...) \ + LOGF_USER_DEFAULT_CATEGORY(severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) - /* +/* + Conditional logging +*/ - Conditional logging - - */ - - // Logging with explicit category +// Logging with explicit category #define LOGS_CATEGORY_IF(boolean_expression, logger, severity, category) \ - if ((boolean_expression) == true) LOGS_CATEGORY(logger, severity, category) + if (!((boolean_expression) == true)) { \ + /* do nothing */ \ + } else \ + LOGS_CATEGORY(logger, severity, category) #define LOGS_DEFAULT_CATEGORY_IF(boolean_expression, severity, category) \ - if ((boolean_expression) == true) LOGS_DEFAULT_CATEGORY(severity, category) + if (!((boolean_expression) == true)) { \ + /* do nothing */ \ + } else \ + LOGS_DEFAULT_CATEGORY(severity, category) #define LOGS_USER_CATEGORY_IF(boolean_expression, logger, severity, category) \ - if ((boolean_expression) == true) LOGS_USER_CATEGORY(logger, severity, category) + if (!((boolean_expression) == true)) { \ + /* do nothing */ \ + } else \ + LOGS_USER_CATEGORY(logger, severity, category) #define LOGS_USER_DEFAULT_CATEGORY_IF(boolean_expression, severity, category) \ - if ((boolean_expression) == true) LOGS_USER_DEFAULT_CATEGORY(severity, category) + if (!((boolean_expression) == true)) { \ + /* do nothing */ \ + } else \ + LOGS_USER_DEFAULT_CATEGORY(severity, category) -#define LOGF_CATEGORY_IF(boolean_expression, logger, severity, category, format_str, ...) \ - if ((boolean_expression) == true) LOGF_CATEGORY(logger, severity, category, format_str, ##__VA_ARGS__) +#define LOGF_CATEGORY_IF(boolean_expression, logger, severity, category, format_str, ...) \ + do { \ + if ((boolean_expression) == true) LOGF_CATEGORY(logger, severity, category, format_str, ##__VA_ARGS__); \ + } while (0) -#define LOGF_DEFAULT_CATEGORY_IF(boolean_expression, severity, category, format_str, ...) \ - if ((boolean_expression) == true) LOGF_DEFAULT_CATEGORY(severity, category, format_str, ##__VA_ARGS__) +#define LOGF_DEFAULT_CATEGORY_IF(boolean_expression, severity, category, format_str, ...) \ + do { \ + if ((boolean_expression) == true) LOGF_DEFAULT_CATEGORY(severity, category, format_str, ##__VA_ARGS__); \ + } while (0) -#define LOGF_USER_CATEGORY_IF(boolean_expression, logger, severity, category, format_str, ...) \ - if ((boolean_expression) == true) LOGF_USER_CATEGORY(logger, severity, category, format_str, ##__VA_ARGS__) +#define LOGF_USER_CATEGORY_IF(boolean_expression, logger, severity, category, format_str, ...) \ + do { \ + if ((boolean_expression) == true) LOGF_USER_CATEGORY(logger, severity, category, format_str, ##__VA_ARGS__); \ + } while (0) -#define LOGF_USER_DEFAULT_CATEGORY_IF(boolean_expression, severity, category, format_str, ...) \ - if ((boolean_expression) == true) LOGF_USER_DEFAULT_CATEGORY(severity, category, format_str, ##__VA_ARGS__) +#define LOGF_USER_DEFAULT_CATEGORY_IF(boolean_expression, severity, category, format_str, ...) \ + do { \ + if ((boolean_expression) == true) LOGF_USER_DEFAULT_CATEGORY(severity, category, format_str, ##__VA_ARGS__); \ + } while (0) - // Logging with category of "onnxruntime" +// Logging with category of "onnxruntime" -#define LOGS_IF(boolean_expression, logger, severity) \ - LOGS_CATEGORY_IF(boolean_expression, logger, severity, ::onnxruntime::logging::Category::onnxruntime) +#define LOGS_IF(boolean_expression, logger, severity) \ + LOGS_CATEGORY_IF(boolean_expression, logger, severity, ::onnxruntime::logging::Category::onnxruntime) -#define LOGS_DEFAULT_IF(boolean_expression, severity) \ - LOGS_DEFAULT_CATEGORY_IF(boolean_expression, severity, ::onnxruntime::logging::Category::onnxruntime) +#define LOGS_DEFAULT_IF(boolean_expression, severity) \ + LOGS_DEFAULT_CATEGORY_IF(boolean_expression, severity, ::onnxruntime::logging::Category::onnxruntime) -#define LOGS_USER_IF(boolean_expression, logger, severity) \ - LOGS_USER_CATEGORY_IF(boolean_expression, logger, severity, ::onnxruntime::logging::Category::onnxruntime) +#define LOGS_USER_IF(boolean_expression, logger, severity) \ + LOGS_USER_CATEGORY_IF(boolean_expression, logger, severity, ::onnxruntime::logging::Category::onnxruntime) -#define LOGS_USER_DEFAULT_IF(boolean_expression, severity) \ - LOGS_USER_DEFAULT_CATEGORY_IF(boolean_expression, severity, ::onnxruntime::logging::Category::onnxruntime) +#define LOGS_USER_DEFAULT_IF(boolean_expression, severity) \ + LOGS_USER_DEFAULT_CATEGORY_IF(boolean_expression, severity, ::onnxruntime::logging::Category::onnxruntime) -#define LOGF_IF(boolean_expression, logger, severity, format_str, ...) \ - LOGF_CATEGORY_IF(boolean_expression, logger, severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) +#define LOGF_IF(boolean_expression, logger, severity, format_str, ...) \ + LOGF_CATEGORY_IF(boolean_expression, logger, severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) -#define LOGF_DEFAULT_IF(boolean_expression, severity, format_str, ...) \ - LOGF_DEFAULT_CATEGORY_IF(boolean_expression, severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) +#define LOGF_DEFAULT_IF(boolean_expression, severity, format_str, ...) \ + LOGF_DEFAULT_CATEGORY_IF(boolean_expression, severity, ::onnxruntime::logging::Category::onnxruntime, format_str, ##__VA_ARGS__) -#define LOGF_USER_IF(boolean_expression, logger, severity, format_str, ...) \ - LOGF_USER_CATEGORY_IF(boolean_expression, logger, severity, ::onnxruntime::logging::Category::onnxruntime, \ - format_str, ##__VA_ARGS__) +#define LOGF_USER_IF(boolean_expression, logger, severity, format_str, ...) \ + LOGF_USER_CATEGORY_IF(boolean_expression, logger, severity, ::onnxruntime::logging::Category::onnxruntime, \ + format_str, ##__VA_ARGS__) -#define LOGF_USER_DEFAULT_IF(boolean_expression, severity, format_str, ...) \ +#define LOGF_USER_DEFAULT_IF(boolean_expression, severity, format_str, ...) \ LOGF_USER_DEFAULT_CATEGORY_IF(boolean_expression, severity, ::onnxruntime::logging::Category::onnxruntime, \ format_str, ##__VA_ARGS__) /* - Debug verbose logging of caller provided level. Disabled in Release builds. Use the _USER variants for VLOG statements involving user data that may need to be filtered. */ -#define VLOGS(logger, level) \ - if (::onnxruntime::logging::vlog_enabled && level <= (logger).VLOGMaxLevel()) \ +#define VLOGS(logger, level) \ + if (!(::onnxruntime::logging::vlog_enabled && level <= (logger).VLOGMaxLevel())) { \ + /* do nothing */ \ + } else \ LOGS_CATEGORY(logger, VERBOSE, "VLOG" #level) -#define VLOGS_USER(logger, level) \ - if (::onnxruntime::logging::vlog_enabled && level <= (logger).VLOGMaxLevel()) \ +#define VLOGS_USER(logger, level) \ + if (!(::onnxruntime::logging::vlog_enabled && level <= (logger).VLOGMaxLevel())) { \ + /* do nothing */ \ + } else \ LOGS_USER_CATEGORY(logger, VERBOSE, "VLOG" #level) -#define VLOGF(logger, level, format_str, ...) \ - if (::onnxruntime::logging::vlog_enabled && level <= (logger).VLOGMaxLevel()) \ - LOGF_CATEGORY(logger, VERBOSE, "VLOG" #level, format_str, ##__VA_ARGS__) - -#define VLOGF_USER(logger, level, format_str, ...) \ +#define VLOGF(logger, level, format_str, ...) \ + do { \ if (::onnxruntime::logging::vlog_enabled && level <= (logger).VLOGMaxLevel()) \ - LOGF_USER_CATEGORY(logger, VERBOSE, "VLOG" #level, format_str, ##__VA_ARGS__) + LOGF_CATEGORY(logger, VERBOSE, "VLOG" #level, format_str, ##__VA_ARGS__); \ + } while (0) - // Default logger variants -#define VLOGS_DEFAULT(level) \ - VLOGS(::onnxruntime::logging::LoggingManager::DefaultLogger(), level) +#define VLOGF_USER(logger, level, format_str, ...) \ + do { \ + if (::onnxruntime::logging::vlog_enabled && level <= (logger).VLOGMaxLevel()) \ + LOGF_USER_CATEGORY(logger, VERBOSE, "VLOG" #level, format_str, ##__VA_ARGS__); \ + } while (0) -#define VLOGS_USER_DEFAULT(level) \ - VLOGS_USER(::onnxruntime::logging::LoggingManager::DefaultLogger(), level) +// Default logger variants +#define VLOGS_DEFAULT(level) \ + VLOGS(::onnxruntime::logging::LoggingManager::DefaultLogger(), level) -#define VLOGF_DEFAULT(level, format_str, ...) \ - VLOGF(::onnxruntime::logging::LoggingManager::DefaultLogger(), level, format_str, ##__VA_ARGS__) +#define VLOGS_USER_DEFAULT(level) \ + VLOGS_USER(::onnxruntime::logging::LoggingManager::DefaultLogger(), level) -#define VLOGF_USER_DEFAULT(level, format_str, ...) \ +#define VLOGF_DEFAULT(level, format_str, ...) \ + VLOGF(::onnxruntime::logging::LoggingManager::DefaultLogger(), level, format_str, ##__VA_ARGS__) + +#define VLOGF_USER_DEFAULT(level, format_str, ...) \ VLOGF_USER(::onnxruntime::logging::LoggingManager::DefaultLogger(), level, format_str, ##__VA_ARGS__) diff --git a/onnxruntime/core/providers/coreml/coreml_execution_provider.cc b/onnxruntime/core/providers/coreml/coreml_execution_provider.cc index dcc7a05716..4d5f7783ad 100644 --- a/onnxruntime/core/providers/coreml/coreml_execution_provider.cc +++ b/onnxruntime/core/providers/coreml/coreml_execution_provider.cc @@ -172,10 +172,11 @@ CoreMLExecutionProvider::GetCapability(const onnxruntime::GraphViewer& graph_vie // If the graph is partitioned in multiple subgraphs, and this may impact performance, // we want to give users a summary message at warning level. - if (num_of_partitions > 1) + if (num_of_partitions > 1) { LOGS_DEFAULT(WARNING) << summary_msg; - else + } else { LOGS_DEFAULT(INFO) << summary_msg; + } return result; } diff --git a/onnxruntime/core/providers/nnapi/nnapi_builtin/nnapi_execution_provider.cc b/onnxruntime/core/providers/nnapi/nnapi_builtin/nnapi_execution_provider.cc index 92a42a2beb..bc87a322f0 100644 --- a/onnxruntime/core/providers/nnapi/nnapi_builtin/nnapi_execution_provider.cc +++ b/onnxruntime/core/providers/nnapi/nnapi_builtin/nnapi_execution_provider.cc @@ -205,10 +205,11 @@ NnapiExecutionProvider::GetCapability(const onnxruntime::GraphViewer& graph_view // If the graph is partitioned in multiple subgraphs, and this may impact performance, // we want to give users a summary message at warning level. - if (num_of_partitions > 1) + if (num_of_partitions > 1) { LOGS_DEFAULT(WARNING) << summary_msg; - else + } else { LOGS_DEFAULT(INFO) << summary_msg; + } return result; } diff --git a/onnxruntime/test/common/logging/logging_test.cc b/onnxruntime/test/common/logging/logging_test.cc index 79fef6c05f..c88eff79b2 100644 --- a/onnxruntime/test/common/logging/logging_test.cc +++ b/onnxruntime/test/common/logging/logging_test.cc @@ -262,5 +262,40 @@ TEST_F(LoggingTestsFixture, TestTruncation) { EXPECT_THAT(out.str(), HasSubstr("[...truncated...]")); } +TEST_F(LoggingTestsFixture, TestStreamMacroFromConditionalWithoutCompoundStatement) { + constexpr const char* logger_id = "TestStreamMacroFromConditionalWithoutCompoundStatement"; + constexpr Severity min_log_level = Severity::kVERBOSE; + constexpr bool filter_user_data = false; + constexpr const char* true_message = "true"; + constexpr const char* false_message = "false"; + + auto sink = std::make_unique(); + { + testing::InSequence s{}; + EXPECT_CALL(*sink, SendImpl(testing::_, + HasSubstr(logger_id), + testing::Property(&Capture::Message, Eq(true_message)))) + .WillOnce(PrintArgs()); + EXPECT_CALL(*sink, SendImpl(testing::_, + HasSubstr(logger_id), + testing::Property(&Capture::Message, Eq(false_message)))) + .WillOnce(PrintArgs()); + } + + LoggingManager manager{std::move(sink), min_log_level, filter_user_data, InstanceType::Temporal}; + + auto logger = manager.CreateLogger(logger_id, min_log_level, filter_user_data); + + auto log_from_conditional_without_compound_statement = [&](bool condition) { + if (condition) + LOGS(*logger, VERBOSE) << true_message; + else + LOGS(*logger, VERBOSE) << false_message; + }; + + log_from_conditional_without_compound_statement(true); + log_from_conditional_without_compound_statement(false); +} + } // namespace test } // namespace onnxruntime