wsd: improve test logging

Logs from test are now more atomic (less interleaving).
And each integration-test (old-style tests running from
new-style tests) will now print clearly when it begins
and when it fails, making it easier to find failures.
Misc other minor cleanups in test logging.

Change-Id: Iff664e42a04d1c6dbf1332b2884c35183ef85e21
Reviewed-on: https://gerrit.libreoffice.org/c/online/+/89309
Tested-by: Ashod Nakashian <ashnakash@gmail.com>
Reviewed-by: Ashod Nakashian <ashnakash@gmail.com>
This commit is contained in:
Ashod Nakashian 2020-02-23 13:32:10 -05:00 committed by Ashod Nakashian
parent 18ab1ccaed
commit c742ca1011
2 changed files with 100 additions and 24 deletions

View file

@ -31,7 +31,6 @@
#include <Common.hpp>
#include "common/FileUtil.hpp"
#include "test/test.hpp"
#include <LOOLWebSocket.hpp>
#include <Util.hpp>
@ -41,22 +40,71 @@
// Oh dear std::cerr and/or its re-direction is not
// necessarily thread safe on Linux
// This is the canonical test log function.
inline void writeTestLog(const char* const p)
{
fputs(p, stderr);
fflush(stderr);
}
inline void writeTestLog(const std::string& s) { writeTestLog(s.c_str()); }
#ifdef TST_LOG_REDIRECT
void tstLog(const std::ostringstream &stream);
void tstLog(const std::ostringstream& stream);
#else
inline void tstLog(const std::ostringstream &stream)
{
fprintf(stderr, "%s", stream.str().c_str());
}
inline void tstLog(const std::ostringstream& stream) { writeTestLog(stream.str()); }
#endif
#define TST_LOG_NAME_BEGIN(NAME, X) do { \
char t[64]; Poco::DateTime time; snprintf(t, sizeof(t), "%.2u:%.2u:%.2u.%.6u (@%zums) ", \
time.hour(), time.minute(), time.second(), time.millisecond() * 1000 + time.microsecond(), helpers::timeSinceTestStartMs()); \
std::ostringstream str; str << NAME << t << X; tstLog(str); } while (false)
#define TST_LOG_BEGIN(X) TST_LOG_NAME_BEGIN(testname, X)
#define TST_LOG_APPEND(X) do { std::ostringstream str; str << X; tstLog(str); } while (false)
#define TST_LOG_END do { std::ostringstream str; str << "| " << __FILE__ << ':' << __LINE__ << std::endl; tstLog(str); } while (false)
#define TST_LOG_NAME(NAME, X) TST_LOG_NAME_BEGIN(NAME, X); TST_LOG_END
#define TST_LOG_NAME_BEGIN(OSS, NAME, X, FLUSH) \
do \
{ \
char t[64]; \
Poco::DateTime time; \
snprintf(t, sizeof(t), "%.2u:%.2u:%.2u.%.6u (@%zums) ", time.hour(), time.minute(), \
time.second(), time.millisecond() * 1000 + time.microsecond(), \
helpers::timeSinceTestStartMs()); \
OSS << NAME << t << X; \
if (FLUSH) \
tstLog(OSS); \
} while (false)
#define TST_LOG_BEGIN(X) \
do \
{ \
std::ostringstream oss; \
TST_LOG_NAME_BEGIN(oss, testname, X, true); \
} while (false)
#define TST_LOG_APPEND(X) \
do \
{ \
std::ostringstream str; \
str << X; \
tstLog(str); \
} while (false)
#define TST_LOG_END_X(OSS) \
do \
{ \
OSS << "| " __FILE__ ":" << __LINE__ << '\n'; \
tstLog(OSS); \
} while (false)
#define TST_LOG_END \
do \
{ \
std::ostringstream oss_log_end; \
TST_LOG_END_X(oss_log_end); \
} while (false)
#define TST_LOG_NAME(NAME, X) \
do \
{ \
std::ostringstream oss_log_name; \
TST_LOG_NAME_BEGIN(oss_log_name, NAME, X, false); \
TST_LOG_END_X(oss_log_name); \
} while (false)
#define TST_LOG(X) TST_LOG_NAME(testname, X)
// Sometimes we need to retry some commands as they can (due to timing or load) soft-fail.

View file

@ -30,6 +30,7 @@
#include <Poco/FileStream.h>
#include <Poco/StreamCopier.h>
#include <helpers.hpp>
#include <Unit.hpp>
#include <wsd/LOOLWSD.hpp>
@ -100,21 +101,50 @@ bool isStandalone()
return IsStandalone;
}
static std::mutex errorMutex;
static std::mutex ErrorMutex;
static bool IsVerbose = false;
static std::stringstream errors;
static std::ostringstream ErrorsStream;
void tstLog(const std::ostringstream &stream)
{
if (IsVerbose)
std::cerr << stream.str() << std::endl;
writeTestLog(stream.str() + '\n');
else
{
std::lock_guard<std::mutex> lock(errorMutex);
errors << stream.str();
std::lock_guard<std::mutex> lock(ErrorMutex);
ErrorsStream << stream.str();
}
}
class TestProgressListener : public CppUnit::TestListener
{
TestProgressListener(const TestProgressListener& copy) = delete;
void operator=(const TestProgressListener& copy) = delete;
public:
TestProgressListener() {}
virtual ~TestProgressListener() {}
void startTest(CppUnit::Test* test)
{
_name = test->getName();
writeTestLog("\n=============== START " + _name + '\n');
}
void addFailure(const CppUnit::TestFailure& failure)
{
if (failure.isError())
writeTestLog("\n>>>>>>>> FAILED " + _name + " <<<<<<<<<\n");
else
writeTestLog("\n>>>>>>>> PASS " + _name + " <<<<<<<<<\n");
}
void done() { writeTestLog("\n=============== END " + _name + " ===============\n"); }
private:
std::string _name;
};
// returns true on success
bool runClientTests(bool standalone, bool verbose)
{
@ -124,9 +154,7 @@ bool runClientTests(bool standalone, bool verbose)
CPPUNIT_NS::TestResult controller;
CPPUNIT_NS::TestResultCollector result;
controller.addListener(&result);
CPPUNIT_NS::BriefTestProgressListener progress;
controller.addListener(&progress);
CPPUNIT_NS::TextTestProgressListener listener;
TestProgressListener listener;
controller.addListener(&listener);
CPPUNIT_NS::Test* testRegistry = CPPUNIT_NS::TestFactoryRegistry::getRegistry().makeTest();
@ -158,9 +186,9 @@ bool runClientTests(bool standalone, bool verbose)
{
runner.run(controller);
// output the errors we got during the testing
// output the ErrorsStream we got during the testing
if (!result.wasSuccessful())
std::cerr << errors.str() << std::endl;
writeTestLog(ErrorsStream.str() + '\n');
}
else
{