Catch2 icon indicating copy to clipboard operation
Catch2 copied to clipboard

Logging macro similar to UNSCOPED_INFO but that doesn't remove it from the buffer

Open reddwarf69 opened this issue 3 years ago • 1 comments

Sometimes I have something similar to the following

#define CATCH_CONFIG_MAIN
#include <catch2/catch.hpp>
#include <spdlog/spdlog.h>
#include <spdlog/sinks/base_sink.h>

class spdlog_catch_sink final : public spdlog::sinks::base_sink<spdlog::details::null_mutex>
{
  protected:
    void sink_it_(const spdlog::details::log_msg& msg) override
    {
        spdlog::memory_buf_t formatted;
        spdlog::sinks::base_sink<spdlog::details::null_mutex>::formatter_->format(msg, formatted);
        UNSCOPED_INFO(fmt::to_string(formatted));
    }

    void flush_() override {}
};

static bool factorial_called_with_one;

static unsigned int Factorial( unsigned int number ) {
    spdlog::info("Factorial called with {}", number);

    if(factorial_called_with_one) {
        return 0;
    }
    if(number == 1) {
        factorial_called_with_one = true;
    }

    return number <= 1 ? number : Factorial(number-1)*number;
}

TEST_CASE( "Factorials are computed", "[factorial]" ) {
    spdlog::default_logger_raw()->sinks() = { std::make_shared<spdlog_catch_sink>() };

    factorial_called_with_one = false;

    REQUIRE( Factorial(1) == 1 );

    SECTION( "even after calling it with 1" ) {
        REQUIRE( Factorial(2) == 2 );
    }
}

which outputs this

$ ./catch_test

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
catch_test is a Catch v2.13.7 host application.
Run with -? for options

-------------------------------------------------------------------------------
Factorials are computed
  even after calling it with 1
-------------------------------------------------------------------------------
catch_test.cpp:41
...............................................................................

catch_test.cpp:42: FAILED:
  REQUIRE( Factorial(2) == 2 )
with expansion:
  0 == 2
with message:
  [2021-12-27 11:12:35.543] [info] Factorial called with 2

===============================================================================
test cases: 1 | 1 failed
assertions: 3 | 2 passed | 1 failed

So basically I have the logging infrastructure, set to maximum verbose level, report to Catch. I do this because I only want to see the logging output if a test fails, but when it fails I want to have as much logging information as possible. In general, it works fine. But since the output of UNSCOPED_INFO is flushed with every assertion, sometimes I lose useful output when an assertion fails, but a previous one had succeeded.

I could probably handle this by using an event listener instead of UNSCOPED_INFO, handling the buffering myself. But for this use case, it may have been nice to have had a NOT_FLUSHED_UNSCOPED_INFO that is only flushed at the end of the "path" (it's still flushed before starting testing a new path, since that's basically a different test run).

In the given example (which admittedly is forced), the fact that Factorial was called first with 1 is important but not logged.

reddwarf69 avatar Dec 27 '21 11:12 reddwarf69

Given

$ ./catch_test -s

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
catch_test is a Catch v2.13.7 host application.
Run with -? for options

-------------------------------------------------------------------------------
Factorials are computed
-------------------------------------------------------------------------------
catch_test.cpp:34
...............................................................................

catch_test.cpp:39: PASSED:
  REQUIRE( Factorial(1) == 1 )
with expansion:
  1 == 1
with message:
  [2021-12-27 14:32:53.597] [info] Factorial called with 1

-------------------------------------------------------------------------------
Factorials are computed
  even after calling it with 1
-------------------------------------------------------------------------------
catch_test.cpp:41
...............................................................................

catch_test.cpp:42: FAILED:
  REQUIRE( Factorial(2) == 2 )
with expansion:
  0 == 2
with message:
  [2021-12-27 14:32:53.597] [info] Factorial called with 2

-------------------------------------------------------------------------------
Factorials are computed
-------------------------------------------------------------------------------
catch_test.cpp:34
...............................................................................

catch_test.cpp:39: PASSED:
  REQUIRE( Factorial(1) == 1 )
with expansion:
  1 == 1
with message:
  [2021-12-27 14:32:53.597] [info] Factorial called with 1

===============================================================================
test cases: 1 | 1 failed
assertions: 3 | 2 passed | 1 failed

maybe another solution would be to increase the output when an assertion fails?

I would probably be OK with having

$ ./catch_test

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
catch_test is a Catch v2.13.7 host application.
Run with -? for options

-------------------------------------------------------------------------------
Factorials are computed
  even after calling it with 1
-------------------------------------------------------------------------------
catch_test.cpp:41
...............................................................................

catch_test.cpp:42: FAILED:
  REQUIRE( Factorial(2) == 2 )
with expansion:
  0 == 2
with message:
  [2021-12-27 14:32:53.597] [info] Factorial called with 2

-------------------------------------------------------------------------------
Factorials are computed
-------------------------------------------------------------------------------
catch_test.cpp:34
...............................................................................

catch_test.cpp:39: PASSED:
  REQUIRE( Factorial(1) == 1 )
with expansion:
  1 == 1
with message:
  [2021-12-27 14:32:53.597] [info] Factorial called with 1

===============================================================================
test cases: 1 | 1 failed
assertions: 3 | 2 passed | 1 failed

i.e. when the assertion fails getting the output of the whole path/branch.

reddwarf69 avatar Dec 27 '21 14:12 reddwarf69