testing: improved logging + CLIENT_TEST_SOURCE_DELAY

Exceptions reported by CppUnit only contained one file+line pair. If
that location was called multiple times inside a larger test, then it
was impossible to tell where it was called. The new assertion macros
and in particular CT_ASSERT_NO_THROW() solve this problem by catching
exceptions, adding the current file+line information and then
rethrowing an extended exception. When CppUnit finally logs the
problem, it will contain a complete call stack.

For this to work, every single line which might throw an exception
must be wrapped in a macro. Entering and leaving the line is logged
together with the wrapped expression as part of the test .log file.

doSync() is handled as a special case and gets the file+line info of
its caller via parameters.

New logging macros are introduced and used in LocalTests::testChanges:
instead of writing comments, call the logging macros and the string
will appear also in the .log file of the test.

Further areas for improvements:
- use CLIENT_TEST_LOG() everywhere
- reduce file names to just the base name is logged
- convert .log file into HTML with links into session logs and
  ClientTest.cpp source file

src/backends/webdav/WebDAVSourceRegister.cpp

@@ -266,6 +266,8 @@ public:
                                 nodes,
                                 context);
         SyncSource *ss = SyncSource::createSource(params);
+        ss->setDisplayName(ss->getDisplayName() +
+                           (isSourceA ? " #A" : " #B"));
         return static_cast<TestingSyncSource *>(ss);
     }
 };

src/src.am

@@ -186,6 +186,7 @@ src_client_test_SOURCES = \
   src/CmdlineSyncClient.cpp \
   test/ClientTest.cpp \
   test/ClientTest.h \
+  test/ClientTestAssert.h \
   test/client-test-main.cpp \
   $(CORE_SOURCES)
 nodist_src_client_test_SOURCES = test/test.cpp

src/syncevo/SyncSource.h

@@ -1213,6 +1213,7 @@ class SyncSource : virtual public SyncSourceBase, public SyncSourceConfig, publi
     /* implementation of SyncSourceBase */
     virtual std::string getName() const { return SyncSourceConfig::getName(); }
     virtual std::string getDisplayName() const { return m_name.c_str(); }
+    virtual void setDisplayName(const std::string &name) { m_name = name; }
     virtual long getNumDeleted() const { return m_numDeleted; }
     virtual void setNumDeleted(long num) { m_numDeleted = num; }
     virtual void incrementNumDeleted() { m_numDeleted++; }

test/ClientTest.h

@@ -34,6 +34,7 @@
 #include <SyncSource.h>
 
 #include "test.h"
+#include "ClientTestAssert.h"
 
 #ifdef ENABLE_INTEGRATION_TESTS
 
@@ -41,6 +42,9 @@
 #include <cppunit/TestAssert.h>
 #include <cppunit/TestFixture.h>
 
+#include <syncevo/Logging.h>
+#include <syncevo/util.h>
+
 #include <syncevo/declarations.h>
 SE_BEGIN_CXX
 
@@ -840,6 +844,15 @@ protected:
         SyncPrefix prefix(logPrefix, *this);
         doSync(options);
     }
+    void doSync(const char *file, int line,
+                const char *logPrefix,
+                const SyncOptions &options) {
+        CT_WRAP_ASSERT(file, line, doSync(logPrefix, options));
+    }
+    void doSync(const char *file, int line,
+                const SyncOptions &options) {
+        CT_WRAP_ASSERT(file, line, doSync(options));
+    }
     virtual void postSync(int res, const std::string &logname);
 };
 
@@ -895,40 +908,46 @@ public:
     virtual void setTimeout(int seconds) { m_wrappedAgent->setTimeout(seconds); }
 };
 
+/** write log message into *.log file of a test */
+#define CLIENT_TEST_LOG(_format, _args...) \
+    SE_LOG_DEBUG(NULL, NULL, "\n%s:%d *** " _format, \
+                 getBasename(__FILE__).c_str(), __LINE__, \
+                 ##_args)
+
 /** assert equality, include string in message if unequal */
 #define CLIENT_TEST_EQUAL( _prefix, \
                            _expected, \
                            _actual ) \
-    CPPUNIT_ASSERT_EQUAL_MESSAGE( std::string(_prefix) + ": " + #_expected + " == " + #_actual, \
-                                  _expected, \
-                                  _actual )
+    CT_ASSERT_EQUAL_MESSAGE( std::string(_prefix) + ": " + #_expected + " == " + #_actual, \
+                             _expected, \
+                             _actual )
 
 /** execute _x and then check the status of the _source pointer */
 #define SOURCE_ASSERT_NO_FAILURE(_source, _x) \
 { \
-    CPPUNIT_ASSERT_NO_THROW(_x); \
-    CPPUNIT_ASSERT((_source)); \
+    CT_ASSERT_NO_THROW(_x); \
+    CT_ASSERT((_source)); \
 }
 
 /** check _x for true and then the status of the _source pointer */
 #define SOURCE_ASSERT(_source, _x) \
 { \
-    CPPUNIT_ASSERT(_x); \
-    CPPUNIT_ASSERT((_source)); \
+    CT_ASSERT(_x); \
+    CT_ASSERT((_source)); \
 }
 
 /** check that _x evaluates to a specific value and then the status of the _source pointer */
 #define SOURCE_ASSERT_EQUAL(_source, _value, _x) \
 { \
-    CPPUNIT_ASSERT_EQUAL(_value, _x); \
-    CPPUNIT_ASSERT((_source)); \
+    CT_ASSERT_EQUAL(_value, _x); \
+    CT_ASSERT((_source)); \
 }
 
 /** same as SOURCE_ASSERT() with a specific failure message */
 #define SOURCE_ASSERT_MESSAGE(_message, _source, _x)     \
 { \
-    CPPUNIT_ASSERT_MESSAGE((_message), (_x)); \
-    CPPUNIT_ASSERT((_source)); \
+    CT_ASSERT_MESSAGE((_message), (_x)); \
+    CT_ASSERT((_source)); \
 }
 
 /**

test/ClientTestAssert.h

@@ -0,0 +1,113 @@
+/*
+ * Copyright (C) 2011 Intel Corporation
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 2.1 of the License, or (at your option) version 3.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
+ * 02110-1301  USA
+ */
+
+#ifndef INCL_CLIENTTESTASSERT
+#define INCL_CLIENTTESTASSERT
+
+#include <cppunit/Exception.h>
+#include <syncevo/util.h>
+
+#include <syncevo/declarations.h>
+SE_BEGIN_CXX
+
+/**
+ * All of the macros below include the behavior of the corresponding
+ * CPUNIT assertion. In addition they catch exceptions and turn them
+ * into the following, extended CPPUnit exception by preserving the
+ * information from the original exception and adding the current
+ * source code line.
+ *
+ * Source information is listed as inner first (as part of the error
+ * preamble), followed by error at that location and all locations
+ * that the error passed through until caught at the top level of a
+ * test.
+ */
+class CTException : public CppUnit::Exception
+{
+
+ public:
+    CTException(const CppUnit::Message &message = CppUnit::Message(),
+                const CppUnit::SourceLine &currentSourceLine = CppUnit::SourceLine(),
+                const CppUnit::SourceLine &previousSourceLine = CppUnit::SourceLine()) :
+    CppUnit::Exception(message, previousSourceLine)
+    {
+        if (currentSourceLine.isValid()) {
+            CppUnit::Message extendedMessage = message;
+            extendedMessage.addDetail(StringPrintf("%s:%d",
+                                                   currentSourceLine.fileName().c_str(),
+                                                   currentSourceLine.lineNumber()));
+            setMessage(extendedMessage);
+        }
+    }
+};
+
+static void inline ClientTestExceptionHandle(const char *file, int line)
+{
+    CppUnit::SourceLine here(file, line);
+    try {
+        throw;
+    }  catch (const CTException &ex) {
+        throw(CTException(ex.message(),
+                          here,
+                          ex.sourceLine()));
+    } catch (const CppUnit::Exception &ex) {
+        if (ex.sourceLine() == CPPUNIT_SOURCELINE()) {
+            /* failure in condition expression itself, already includes source info, pass through */
+            throw;
+        } else {
+            throw(CTException(ex.message(),
+                              here,
+                              ex.sourceLine()));
+        }
+    } catch (const Exception &ex) {
+        throw(CTException(CppUnit::Message(ex.what()),
+                          here,
+                          CppUnit::SourceLine(ex.m_file, ex.m_line)));
+    } catch (const std::exception &ex) {
+        CppUnit::Message msg(CPPUNIT_EXTRACT_EXCEPTION_TYPE_(ex,
+                                                             "std::exception or derived"));
+        msg.addDetail(std::string("What(): ") + ex.what());
+        throw(CTException(msg,
+                          here));
+    }
+}
+
+#define CT_WRAP_ASSERT(_file, _line, _assert) \
+    do { \
+       try { \
+           SE_LOG_DEBUG(NULL, NULL, "%s:%d: starting %s", _file, _line, #_assert); \
+           _assert; \
+           SE_LOG_DEBUG(NULL, NULL, "%s:%d: ending %s", _file, _line, #_assert); \
+       } catch (...) { \
+           ClientTestExceptionHandle(_file, _line); \
+       } \
+    } while (false)
+
+#define CT_ASSERT(condition) CT_WRAP_ASSERT(__FILE__, __LINE__, CPPUNIT_ASSERT(condition))
+#define CT_ASSERT_NO_THROW(expression) CT_WRAP_ASSERT(__FILE__, __LINE__, expression)
+#define CT_ASSERT_MESSAGE(message,condition) CT_WRAP_ASSERT(__FILE__, __LINE__, CPPUNIT_ASSERT_MESSAGE(message,condition))
+#define CT_FAIL(message) CPPUNIT_FAIL(message)
+#define CT_ASSERT_EQUAL(expected,actual) CT_WRAP_ASSERT(__FILE__, __LINE__, CPPUNIT_ASSERT_EQUAL(expected,actual))
+#define CT_ASSERT_EQUAL_MESSAGE(message,expected,actual) CT_WRAP_ASSERT(__FILE__, __LINE__, CPPUNIT_ASSERT_EQUAL_MESSAGE(message,expected,actual))
+#define CT_ASSERT_DOUBLES_EQUAL(expected,actual,delta) CT_WRAP_ASSERT(__FILE__, __LINE__, CPPUNIT_ASSERT_DOUBLES_EQUAL(expected,actual,delta))
+#define CT_ASSERT_DOUBLES_EQUAL_MESSAGE(message,expected,actual,delta) CT_WRAP_ASSERT(__FILE__, __LINE__, CPPUNIT_ASSERT_DOUBLES_EQUAL_MESSAGE(__FILE__, __LINE__, message,expected,actual,delta))
+
+SE_END_CXX
+
+#endif  // INCL_CLIENTTESTASSERT

test/test.am

@@ -1,6 +1,7 @@
 dist_noinst_DATA += \
   test/abort-redirect.cpp \
   test/ClientTest.h \
+  test/ClientTestAssert.h \
   test/ClientTest.cpp \
   test/client-test-main.cpp \
   test/test.h \