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 (<output enabled>)
  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
  <do something> // not run when !cond

// equivalently:
if (cond)
  if (<output enabled>)
    logging::Capture(...).Stream() << "a";
  else
    <do something> // not run when !cond
```

Updated the logging macros to handle this case by replacing `if (<enabled>) logging::Capture(...).Stream()` with `if (!<enabled>) {} else logging::Capture(...).Stream()`.

Thanks @tlh20 for the idea for the fix!
This commit is contained in:
Edward Chen 2021-05-07 15:40:47 -07:00 committed by GitHub
parent e91bdbde20
commit 5a5fec0452
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
4 changed files with 193 additions and 99 deletions

View file

@ -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__)

View file

@ -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;
}

View file

@ -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;
}

View file

@ -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<MockSink>();
{
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