Logging macros scoped to test case instead of current scope

[rcdailey]

So I'm familiar with the INFO macro for logging. However, these logs get lost once the enclosing scope ends. I'd instead like logs to be scoped to a TEST_CASE or SECTION. I have a logging system (basically a singleton) that I can register logging sinks to. For only catch tests, I override the logger to sink all logs to INFO. My hope was, that for failed test cases, it would dump logs that occurred within its own test case across our whole code base (since they all use this logger). But this doesn't work since it's nested so deep, outside of actual test case scope (but still inside; just not explicitly).

Is there some way I can make all logs in the code base funnel into Catch? Maybe an INFO_WITHIN_TESTCASE macro could be added or something? It would basically keep a list of all logs created, until the test case or section ends and then it is erased.

ideas?

[horenmar]

There are couple requests for the old INFO behaviour to come back (perhaps as UNSCOPED_INFO ?), so it might eventually get in. For now and for your usecase I recommend an alternative solution: Sink all logs to std::cerr (Catch 1.9.6 doesn't properly redirect std::clog) and modify your favourite reporter to request std stream redirection (see the junit and xml reporters for examples). This should give you the desired behaviour.

[rcdailey]

If I'm using latest on master as of today, does your recommendation still stand? I noticed commit 7e4038d which is similar to the cerr issue you brought up.

[rcdailey]

Also is it intended that I implement CumulativeReporterBase? Or is everything in reporters/catch_reporter_bases.hpp implementation detail?

[horenmar]

Yes, current master properly redirects std::clog writes.

IIRC you need to implement IStreamingReporter, but we provide two basic reporter bases to provide common bookkeeping - CumulativeReporterBase, used by junit and StreamingReporterBase used by the other reporters. CumulativeReporterBase is meant to be used by reporters that need global(ish) view of results before writing and StreamingReporterBase is meant to be used by reporters that can write output as soon as an assertion ends.

[rcdailey]

So all I need to do is implement IStreamingReporter and stream out logs in the test case results variable in the test case ended overload? I looked at the junit one, and that's the gist of what it seems to be doing. But it's far more complex than what I need I think.

[horenmar]

Actually I think all you need to do is to take your favourite reporter and enable iostream redirection if it isn't (so if you are using compact reporter, you need to enable it, if you are using xml reporter, it already is) and make your logging adapter write to std::clog/std::cout.

[rcdailey]

Can you give me an example? I started implementing IStreamReporter and it's becoming very complicated... what I have so far:

class ErrorLogReporter : public IStreamingReporter
{
public:
   void addLogEntry(std::string log_entry)
   {
      m_logEntries.push_back(std::move(log_entry));
   }

   void testCaseStarting(TestCaseInfo const& info) override
   {
      m_logEntries.clear();
   }

   void testCaseEnded(TestCaseStats const& stats) override
   {
      for (auto const& entry : m_logEntries)
      {
         std::cout << entry << '\n';
      }
   }

   ReporterPreferences getPreferences() const override
   {
      static ReporterPreferences preferences;
      return preferences;
   }

   void noMatchingTestCases(std::string const& spec) override {}
   void testRunStarting(TestRunInfo const& testRunInfo) override {}
   void testGroupStarting(GroupInfo const& groupInfo) override {}
   void sectionStarting(SectionInfo const& sectionInfo) override {}
   void assertionStarting(AssertionInfo const& assertionInfo) override {}
   bool assertionEnded(AssertionStats const& assertionStats) override { return false; }
   void sectionEnded(SectionStats const& sectionStats) override {}
   void testGroupEnded(TestGroupStats const& testGroupStats) override {}
   void testRunEnded(TestRunStats const& testRunStats) override {}
   void skipTest(TestCaseInfo const& testInfo) override {}

private:

   std::vector<std::string> m_logEntries;
};

CATCH_REGISTER_REPORTER("ErrorLogReporter", ErrorLogReporter)

class CatchSink : public LogSink
{
public:

   ///////////////////////////////////////////////////////////////////////////////
   ///
   ///////////////////////////////////////////////////////////////////////////////
   CatchSink(std::shared_ptr<ErrorLogReporter> catch_reporter)
      : m_reporter(catch_reporter)
   {}

   ///////////////////////////////////////////////////////////////////////////////
   ///
   ///////////////////////////////////////////////////////////////////////////////
   void Consume(Severity severity, std::string const& module_name, std::string const& file_name,
      LoggerLineNumberType line, std::string const& uxid, std::string const& tag,
      std::string const& message) override
   {
      std::ostringstream ss;
      BuildLogPrefix(ss, module_name, file_name, line, uxid);
      ss << std::setw(8) << std::left << severity
         << " [" << ErrorLog::Instance().GetTag() << "] " << message;

      m_reporter->addLogEntry(ss.str());
   }

private:

   std::shared_ptr<ErrorLogReporter> m_reporter;
};

And to set it up I'm trying:

void SetupLogging()
{
   auto reporter = std::make_shared<ErrorLogReporter>();
   auto sink = std::make_unique<CatchSink>(reporter);

   ErrorLog::Instance().RemoveAllSinks(); // get rid of auto-added platform sinks
   ErrorLog::Instance().AddSink(std::move(sink));

   // somehow add `reporter` to catch?
}

But it looks like you don't add reporters this way. You have to use the CATCH_REGISTER_REPORTER, but this is failing with:

Error C2275 'ErrorLogReporter': illegal use of this type as an expression

It's not clear to me how to do what you're saying. I'm not that familiar with the internals of Catch and most of this doesn't seem documented in the reference document.

[rcdailey]

Ok CATCH_REGISTER_REPORTER doesn't work but INTERNAL_CATCH_REGISTER_REPORTER does. This seems broken.

[rcdailey]

I can't get access to the reporter object that Catch seems to be creating internally, so I can't connect it to my Sink. Not sure how to do this.

[horenmar]

Ok, consider the following test file as an example

#define CATCH_CONFIG_MAIN
#include "catch.hpp"

#include <iostream>

TEST_CASE("Foo") {
    std::cout << "This is cout\n";
    std::cerr << "Inter";
    std::clog << "leaved";
    std::cerr << ' ';
    std::clog << "input\n";
    REQUIRE(1 == 1);
}

TEST_CASE("Bar") {
    std::cout << "Write to cout\n";
    std::cerr << "And this is a write to cerr\n";
    REQUIRE(1 == 2);
}

And this modified console reporter

$ git diff include/reporters/catch_reporter_console.hpp
diff --git a/include/reporters/catch_reporter_console.hpp b/include/reporters/catch_reporter_console.hpp
index 5f18124..b0ba6e5 100644
--- a/include/reporters/catch_reporter_console.hpp
+++ b/include/reporters/catch_reporter_console.hpp
@@ -23,7 +23,9 @@ namespace Catch {
         ConsoleReporter( ReporterConfig const& _config )
         :   StreamingReporterBase( _config ),
             m_headerPrinted( false )
-        {}
+        {
+            m_reporterPrefs.shouldRedirectStdOut = true;
+        }

         virtual ~ConsoleReporter() CATCH_OVERRIDE;
         static std::string getDescription() {
@@ -80,6 +82,17 @@ namespace Catch {
         virtual void testCaseEnded( TestCaseStats const& _testCaseStats ) CATCH_OVERRIDE {
             StreamingReporterBase::testCaseEnded( _testCaseStats );
             m_headerPrinted = false;
+            // Skip printing outputting on passed test cases
+            if (_testCaseStats.totals.assertions.allOk()) {
+                return;
+            }
+
+            if (!_testCaseStats.stdOut.empty()) {
+                Catch::cout() << _testCaseStats.stdOut;
+            }
+            if (!_testCaseStats.stdErr.empty()) {
+                Catch::clog() << _testCaseStats.stdErr;
+            }
         }
         virtual void testGroupEnded( TestGroupStats const& _testGroupStats ) CATCH_OVERRIDE {
             if( currentGroupInfo.used ) {

when I compile the test file against my modified catch and run it, I get the following output

$ clang++ redir-test.cpp && ./a.out
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
a.out is a Catch v1.9.6 host application.
Run with -? for options

-------------------------------------------------------------------------------
Bar
-------------------------------------------------------------------------------
redir-test.cpp:15
...............................................................................

redir-test.cpp:18: FAILED:
  REQUIRE( 1 == 2 )

Write to cout
And this is a write to cerr
===============================================================================
test cases: 2 | 1 passed | 1 failed
assertions: 2 | 1 passed | 1 failed

Note that the writes for the passing test case is not written out, only for the failing one. If you have std::clog logging sink, the same will happen with your logs.

Obviously this isn't complete solution, for example it has only test case level granularity, instead of assertion level granularity, but it should be a good enough starting point. You could further improve it by abusing Listeners, by storing the logs instead of printing them, and use your own listener to tell your sink to either send the output to standard stream, or dump it entirely.

[rcdailey]

I'll try your example. How does stdOut and stdErr normally get printed? Seems like the code you added to check allOk() should already happen somewhere, because I do not see logs printed to std::cout usually unless a test case fails.

[horenmar]

What reporter are you using?

[rcdailey]

I normally do not mess with reporters explicitly. Based on the code this means "console" becomes the default if the reporters list is empty. I'm asking on a more general level though (basically, ignore any customization). I just want to know about how the console reporter normally handles stdout & stderr, and how your changes impact/supplement that behavior.

[rcdailey]

How can I implement assertion-level granularity with your solution?

[rcdailey]

This is getting too complicated, so I'm going to go ahead and implement UnscopedMessage and respective macros.

[horenmar]

Normally console reporter ignores std streams and lets them go straight to output. My change makes console reporter ask Catch to redirect std streams during test case and then handle them at the end of a test case, specifically don't use them if the whole test case passed and print them if it didnt.

As mentioned, it doesn't provide assertion level granularity, but it is a start. Assertion level granularity should be possible by abusing Listener interface. I might be able to provide a small example in the evening.

[rcdailey]

Ok I got UNSCOPED_INFO working but there's a few issues I don't like:

1. The messages do not get cleared between failed assertions
2. The messages get word-wrapped (I want them to not be word wrapped)

Based on this I think I want to try the reporter again. However, I want to meet the following requirements:

1. Each failed test case should print stdout logs that occurred since the following (whichever happened last):
   • The beginning of the containing section or test case
   • The last failed assertion
2. Line wrapping should not occur on the printed logs (no processing at all)

I'm still not sure how to do this on the assertion begin/end macros, since the stdOut member is not available, so thus I am not sure how to clear the logs each time.

[rcdailey]

So after struggling with Catch code even more, I decided it's much simpler to bypass Catch completely. Basically, I implement a custom reporter that manages printing its own log buffer separate from Catch:

using namespace Catch;

namespace
{
   std::string g_logSinkOutput;
}

class CatchSink : public LogSink
{
public:

   ///////////////////////////////////////////////////////////////////////////////
   ///
   ///////////////////////////////////////////////////////////////////////////////
   void Consume(Severity severity, std::string const& module_name, std::string const& file_name,
      LoggerLineNumberType line, std::string const& uxid, std::string const& tag,
      std::string const& message) override
   {
      std::ostringstream ss;
      if (!g_logSinkOutput.empty())
      {
         ss << '\n';
      }

      BuildLogPrefix(ss, module_name, file_name, line, uxid);
      ss << std::setw(8) << std::left << severity
         << " [" << ErrorLog::Instance().GetTag() << "] " << message;

      g_logSinkOutput += ss.str();
   }
};

class ErrorLogReporter : public ConsoleReporter
{
public:
   ErrorLogReporter(ReporterConfig const& config)
      : ConsoleReporter(config)
   {}

   static std::string getDescription()
   {
      return "ErrorLogReporter";
   }

   void testCaseEnded(TestCaseStats const& stats) override
   {
      ConsoleReporter::testCaseEnded(stats);
      g_logSinkOutput.clear();
   }

   bool assertionEnded(AssertionStats const& stats) override
   {
      auto result = ConsoleReporter::assertionEnded(stats);

      if (!stats.assertionResult.isOk() && !g_logSinkOutput.empty())
      {
         Catch::cout()
            << "#######################################################################\n"
            << "## CAPTURED LOGS\n"
            << "#######################################################################\n"
            << g_logSinkOutput << "\n"
            << "#######################################################################\n"
            << "\n"
         ;

         g_logSinkOutput.clear();
      }

      return result;
   }

};

INTERNAL_CATCH_REGISTER_REPORTER("ErrorLogReporter", ErrorLogReporter)

My CatchSink is where all logs in our code base funnel to. This fills a global std::string as if it were std::cout. Then when the reporter detects a failed assertion, it prints the contents of the global std::string and clears it (that way I only see logs that happen between each failed assertion or since the beginning of the test case).

So far this is working nicely and it's simple.

If there's anything Catch could benefit from after my struggles, is better documentation for the reporters. Explain the inputs to each reporter member function. Explain the base reporters and their purpose, as well as potential use cases for overriding them.

Hopefully that gets more flushed out over time.

[ozars]

Hi there! I also needed scoped info messages in a way I can use them to report stuff from my own helper functions in case of a failure. Currently, calling INFO() from my helper functions doesn't help me since they are scoped to the my helper functions. So, they are created in the helper function scope and destroyed while returning from there, before they had a chance to get reported when an assertion fails.

I'd like implement this functionality if nobody is working on that. I have a couple of questions. Let me describe my understanding first:

Currently, INFO() is an alias for this internal macro:

Catch2/include/internal/catch_capture.hpp

Lines 130 to 131 in 67308bb

	#define INTERNAL_CATCH_INFO( macroName, log ) \
	Catch::ScopedMessage INTERNAL_CATCH_UNIQUE_NAME( scopedMessage )( Catch::MessageBuilder( macroName##_catch_sr, CATCH_INTERNAL_LINEINFO, Catch::ResultWas::Info ) << log );

It creates this object:

Catch2/include/internal/catch_message.cpp

Lines 49 to 60 in 67308bb

	ScopedMessage::ScopedMessage( MessageBuilder const& builder )
	: m_info( builder.m_info )
	{
	m_info.message = builder.m_stream.str();
	getResultCapture().pushScopedMessage( m_info );
	}
	ScopedMessage::~ScopedMessage() {
	if ( !uncaught_exceptions() ){
	getResultCapture().popScopedMessage(m_info);
	}
	}

ScopedMessage pushes itself on construction and pops itself upon destruction by calling below two methods.

I assume these two are not overridden in somewhere else, are they?

Catch2/include/internal/catch_run_context.cpp

Lines 237 to 243 in 63d1a96

	void RunContext::pushScopedMessage(MessageInfo const & message) {
	m_messages.push_back(message);
	}
	void RunContext::popScopedMessage(MessageInfo const & message) {
	m_messages.erase(std::remove(m_messages.begin(), m_messages.end(), message), m_messages.end());
	}

In popScopedMessage, the message being destroyed along with all messages appended after that are being removed from the messages vector. I didn't understand why following items are popped out. Aren't they supposed to be popped out already while they were being destroyed? Is there some other way to push info messages other than INFO() macro or is this something left from previous implementations? I just realized it just removes the element and remove pass the end.

I'm thinking of adding some message vectors to RunContext such as vector<ScopedMessage> m_assertionMessages. In this case m_assertionMessages will be cleared in RunContext::assertionEnded. Similarly m_sectionMessages, m_testCaseMessages may be added. For this to work I need to change above behavior of popScopedMessage though, since those messages supposed to outlive messages created by INFO() macro on the stack scope.

Eventually these functionalities can be exposed with some macros, e.g. ASSERTION_INFO, SECTION_INFO, TEST_CASE_INFO similar to INFO. They will just emplace ScopedMessage to corresponding vector in running context.

@horenmar I'd appreciate if you could provide me feedback before I start implementation. Is this right approach? Do you have any objections or suggestions?

[ozars]

cc #415 @philsquared

[horenmar]

@ozars
We used to have both UNSCOPED_INFO and SCOPED_INFO, but the unscoped version went away at some point, and the support plumbing for it became vestigial and then went away as well.

In general, I think that providing full granularity (e.g. separate macros for test case scope, section scope, assertion scope) is not a good idea -- I think that we should just bring back UNSCOPED_* macros where their semantics are that they are valid until either of

• TEST_CASE ends
• assertion (REQUIRE, CHECK, ...) happens

and then they are removed.

For implementation details, you want to rope in @JoeyGrajciar, because I am taking 2 weeks break.

[ozars]

In general, I think that providing full granularity (e.g. separate macros for test case scope, section scope, assertion scope) is not a good idea -- I think that we should just bring back UNSCOPED_* macros

Fair enough.

where their semantics are that they are valid until either of

* `TEST_CASE` ends

* assertion (`REQUIRE`, `CHECK`, ...) happens

and then they are removed.

If I understood you correctly, this is actually how assertion info (#1522) behaves since RunContext::m_messages cleared at the end of each test case already and I added Runcontext::m_assertMessageScopes, which is cleared at the end of each assertion. I will rename/remove "assertion" part and add "unscoped" then.

ps. Nope, messages are currently cleared when sectionEnded. I will just add cleaning unscoped messages at the end of test case then.

For implementation details, you want to rope in @JoeyGrajciar, because I am taking 2 weeks break.

Have a nice break! @JoeyGrajciar: I'd appreciate if you could provide some feedback on #1522.

[horenmar]

UNSCOPED_INFO was just added, so this should be done.

[rcdailey]

@horenmar Thank you !!!

For auditing purposes: 1701325