Skip to content

test: Add ASSERT_DEBUG_LOG to unit test framework #16540

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Nov 5, 2019
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions src/Makefile.test.include
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,8 @@ GENERATED_TEST_FILES = $(JSON_TEST_FILES:.json=.json.h) $(RAW_TEST_FILES:.raw=.r
BITCOIN_TEST_SUITE = \
test/lib/blockfilter.cpp \
test/lib/blockfilter.h \
test/lib/logging.cpp \
test/lib/logging.h \
test/lib/transaction_utils.cpp \
test/lib/transaction_utils.h \
test/main.cpp \
Expand Down
7 changes: 7 additions & 0 deletions src/logging.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,9 @@ bool BCLog::Logger::StartLogging()

if (m_print_to_file) FileWriteStr(s, m_fileout);
if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
for (const auto& cb : m_print_callbacks) {
cb(s);
}

m_msgs_before_open.pop_front();
}
Expand All @@ -81,6 +84,7 @@ void BCLog::Logger::DisconnectTestLogger()
m_buffering = true;
if (m_fileout != nullptr) fclose(m_fileout);
m_fileout = nullptr;
m_print_callbacks.clear();
}

void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
Expand Down Expand Up @@ -270,6 +274,9 @@ void BCLog::Logger::LogPrintStr(const std::string& str)
fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
fflush(stdout);
}
for (const auto& cb : m_print_callbacks) {
cb(str_prefixed);
}
if (m_print_to_file) {
assert(m_fileout != nullptr);

Expand Down
20 changes: 19 additions & 1 deletion src/logging.h
Original file line number Diff line number Diff line change
Expand Up @@ -77,6 +77,9 @@ namespace BCLog {

std::string LogTimestampStr(const std::string& str);

/** Slots that connect to the print signal */
std::list<std::function<void(const std::string&)>> m_print_callbacks /* GUARDED_BY(m_cs) */ {};

public:
bool m_print_to_console = false;
bool m_print_to_file = false;
Expand All @@ -95,7 +98,22 @@ namespace BCLog {
bool Enabled() const
{
std::lock_guard<std::mutex> scoped_lock(m_cs);
return m_buffering || m_print_to_console || m_print_to_file;
return m_buffering || m_print_to_console || m_print_to_file || !m_print_callbacks.empty();
}

/** Connect a slot to the print signal and return the connection */
std::list<std::function<void(const std::string&)>>::iterator PushBackCallback(std::function<void(const std::string&)> fun)
{
std::lock_guard<std::mutex> scoped_lock(m_cs);
m_print_callbacks.push_back(std::move(fun));
return --m_print_callbacks.end();
}

/** Delete a connection */
void DeleteCallback(std::list<std::function<void(const std::string&)>>::iterator it)
{
std::lock_guard<std::mutex> scoped_lock(m_cs);
m_print_callbacks.erase(it);
}

/** Start logging (and flush all buffered messages) */
Expand Down
17 changes: 10 additions & 7 deletions src/noui.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -66,28 +66,31 @@ void noui_connect()
noui_InitMessageConn = uiInterface.InitMessage_connect(noui_InitMessage);
}

bool noui_ThreadSafeMessageBoxSuppressed(const std::string& message, const std::string& caption, unsigned int style)
bool noui_ThreadSafeMessageBoxRedirect(const std::string& message, const std::string& caption, unsigned int style)
{
LogPrintf("%s: %s\n", caption, message);
return false;
}

bool noui_ThreadSafeQuestionSuppressed(const std::string& /* ignored interactive message */, const std::string& message, const std::string& caption, unsigned int style)
bool noui_ThreadSafeQuestionRedirect(const std::string& /* ignored interactive message */, const std::string& message, const std::string& caption, unsigned int style)
{
LogPrintf("%s: %s\n", caption, message);
return false;
}

void noui_InitMessageSuppressed(const std::string& message)
void noui_InitMessageRedirect(const std::string& message)
{
LogPrintf("init message: %s\n", message);
}

void noui_suppress()
void noui_test_redirect()
{
noui_ThreadSafeMessageBoxConn.disconnect();
noui_ThreadSafeQuestionConn.disconnect();
noui_InitMessageConn.disconnect();
noui_ThreadSafeMessageBoxConn = uiInterface.ThreadSafeMessageBox_connect(noui_ThreadSafeMessageBoxSuppressed);
noui_ThreadSafeQuestionConn = uiInterface.ThreadSafeQuestion_connect(noui_ThreadSafeQuestionSuppressed);
noui_InitMessageConn = uiInterface.InitMessage_connect(noui_InitMessageSuppressed);
noui_ThreadSafeMessageBoxConn = uiInterface.ThreadSafeMessageBox_connect(noui_ThreadSafeMessageBoxRedirect);
noui_ThreadSafeQuestionConn = uiInterface.ThreadSafeQuestion_connect(noui_ThreadSafeQuestionRedirect);
noui_InitMessageConn = uiInterface.InitMessage_connect(noui_InitMessageRedirect);
}

void noui_reconnect()
Expand Down
6 changes: 3 additions & 3 deletions src/noui.h
Original file line number Diff line number Diff line change
Expand Up @@ -17,10 +17,10 @@ void noui_InitMessage(const std::string& message);
/** Connect all bitcoind signal handlers */
void noui_connect();

/** Suppress all bitcoind signal handlers. Used to suppress output during test runs that produce expected errors */
void noui_suppress();
/** Redirect all bitcoind signal handlers to LogPrintf. Used to check or suppress output during test runs that produce expected errors */
void noui_test_redirect();

/** Reconnects the regular Non-GUI handlers after having used noui_suppress */
/** Reconnects the regular Non-GUI handlers after having used noui_test_redirect */
void noui_reconnect();

#endif // BITCOIN_NOUI_H
32 changes: 32 additions & 0 deletions src/test/lib/logging.cpp
Original file line number Diff line number Diff line change
@@ -0,0 +1,32 @@
// Copyright (c) 2019 The Bitcoin Core developers
// Distributed under the MIT software license, see the accompanying
// file COPYING or http://www.opensource.org/licenses/mit-license.php.

#include <test/lib/logging.h>

#include <logging.h>
#include <noui.h>
#include <tinyformat.h>
#include <util/memory.h>

#include <stdexcept>

DebugLogHelper::DebugLogHelper(std::string message)
: m_message{std::move(message)}
{
m_print_connection = LogInstance().PushBackCallback(
[this](const std::string& s) {
if (m_found) return;
m_found = s.find(m_message) != std::string::npos;
});
noui_test_redirect();
}

void DebugLogHelper::check_found()
{
noui_reconnect();
LogInstance().DeleteCallback(m_print_connection);
if (!m_found) {
throw std::runtime_error(strprintf("'%s' not found in debug log\n", m_message));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Haven't looked closely, but I'm kind of surprised you can get away with throwing an exception in a destructor (check_found is called by ~DebugLogHelper).

If this works, it seems fine. But in case there are issues, an alternative could be to use a callback instead of a scope, so instead of:

{
    ASSERT_DEBUG_LOG("Please check that your computer's date and time are correct!");
    MultiAddTimeData(1, DEFAULT_MAX_TIME_ADJUSTMENT + 1); //filter size 5
}

Something like:

AssertDebugLog("Please check that your computer's date and time are correct!", [&] {
    MultiAddTimeData(1, DEFAULT_MAX_TIME_ADJUSTMENT + 1); //filter size 5
});

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe C++11 makes destructors implicitly noexcept, which means that an uncaught exception from results in std::terminate() being called, which is what we want from throwing a runtime exception anyway

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I forgot about this, but indeed the test seem to fail either way, which is what we want.

}
}
29 changes: 29 additions & 0 deletions src/test/lib/logging.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
// Copyright (c) 2019 The Bitcoin Core developers
// Distributed under the MIT software license, see the accompanying
// file COPYING or http://www.opensource.org/licenses/mit-license.php.

#ifndef BITCOIN_TEST_LIB_LOGGING_H
#define BITCOIN_TEST_LIB_LOGGING_H

#include <util/macros.h>

#include <functional>
#include <list>
#include <string>

class DebugLogHelper
{
const std::string m_message;
bool m_found{false};
std::list<std::function<void(const std::string&)>>::iterator m_print_connection;

void check_found();

public:
DebugLogHelper(std::string message);
~DebugLogHelper() { check_found(); }
};

#define ASSERT_DEBUG_LOG(message) DebugLogHelper PASTE2(debugloghelper, __COUNTER__)(message)

#endif // BITCOIN_TEST_LIB_LOGGING_H
8 changes: 5 additions & 3 deletions src/test/timedata_tests.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@

#include <netaddress.h>
#include <noui.h>
#include <test/lib/logging.h>
#include <test/setup_common.h>
#include <timedata.h>
#include <warnings.h>
Expand Down Expand Up @@ -59,9 +60,10 @@ BOOST_AUTO_TEST_CASE(addtimedata)
MultiAddTimeData(3, DEFAULT_MAX_TIME_ADJUSTMENT + 1);
// Filter size is 1 + 3 = 4: It is always initialized with a single element (offset 0)

noui_suppress();
MultiAddTimeData(1, DEFAULT_MAX_TIME_ADJUSTMENT + 1); //filter size 5
noui_reconnect();
{
ASSERT_DEBUG_LOG("Please check that your computer's date and time are correct!");
MultiAddTimeData(1, DEFAULT_MAX_TIME_ADJUSTMENT + 1); //filter size 5
}

BOOST_CHECK(GetWarnings("gui").find("clock is wrong") != std::string::npos);

Expand Down
28 changes: 16 additions & 12 deletions src/wallet/test/init_tests.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
#include <boost/test/unit_test.hpp>

#include <noui.h>
#include <test/lib/logging.h>
#include <test/setup_common.h>
#include <util/system.h>
#include <wallet/test/init_test_fixture.h>
Expand Down Expand Up @@ -34,28 +35,31 @@ BOOST_AUTO_TEST_CASE(walletinit_verify_walletdir_custom)
BOOST_AUTO_TEST_CASE(walletinit_verify_walletdir_does_not_exist)
{
SetWalletDir(m_walletdir_path_cases["nonexistent"]);
noui_suppress();
bool result = m_chain_client->verify();
noui_reconnect();
BOOST_CHECK(result == false);
{
ASSERT_DEBUG_LOG("does not exist");
bool result = m_chain_client->verify();
BOOST_CHECK(result == false);
}
}

BOOST_AUTO_TEST_CASE(walletinit_verify_walletdir_is_not_directory)
{
SetWalletDir(m_walletdir_path_cases["file"]);
noui_suppress();
bool result = m_chain_client->verify();
noui_reconnect();
BOOST_CHECK(result == false);
{
ASSERT_DEBUG_LOG("is not a directory");
bool result = m_chain_client->verify();
BOOST_CHECK(result == false);
}
}

BOOST_AUTO_TEST_CASE(walletinit_verify_walletdir_is_not_relative)
{
SetWalletDir(m_walletdir_path_cases["relative"]);
noui_suppress();
bool result = m_chain_client->verify();
noui_reconnect();
BOOST_CHECK(result == false);
{
ASSERT_DEBUG_LOG("is a relative path");
bool result = m_chain_client->verify();
BOOST_CHECK(result == false);
}
}

BOOST_AUTO_TEST_CASE(walletinit_verify_walletdir_no_trailing)
Expand Down