common/Log.hpp | 25 +++++ common/Protocol.hpp | 3 common/Util.cpp | 11 +- net/Socket.hpp | 23 ++--- test/TileCacheTests.cpp | 4 test/countloolkits.hpp | 13 +-- test/helpers.hpp | 141 ++++++++++++++++++++------------ test/httpcrashtest.cpp | 41 +++++---- test/httpwserror.cpp | 4 test/httpwstest.cpp | 168 ++++++++++++++++++++------------------- test/integration-http-server.cpp | 4 wsd/AdminModel.cpp | 6 - wsd/TileCache.cpp | 6 - 13 files changed, 268 insertions(+), 181 deletions(-)
New commits: commit 7be98efd93be513b34f7d0a81d30a777902e90de Author: Ashod Nakashian <[email protected]> Date: Mon Jan 22 09:11:43 2018 -0500 ut: log timestamp to track timeouts better And improve the logging support in unit-tests to help troubleshoot issues faster and more accurately. Also makes the code more readable (hopefully). Change-Id: I4f8aafb5245e2f774b03231591a74544f9ec84aa Reviewed-on: https://gerrit.libreoffice.org/48645 Reviewed-by: Ashod Nakashian <[email protected]> Tested-by: Ashod Nakashian <[email protected]> diff --git a/common/Log.hpp b/common/Log.hpp index a3e4a9ae..bb5a6155 100644 --- a/common/Log.hpp +++ b/common/Log.hpp @@ -14,6 +14,7 @@ #include <unistd.h> #include <functional> +#include <thread> #include <sstream> #include <string> @@ -187,6 +188,30 @@ namespace Log (void)end; lhs.flush(); } + + /// Dump the invalid id as 0, otherwise dump in hex. + inline std::string to_string(const std::thread::id& id) + { + if (id != std::thread::id()) + { + std::ostringstream os; + os << std::hex << "0x" << id << std::dec; + return os.str(); + } + + return "0"; + } + + inline StreamLogger& operator<<(StreamLogger& lhs, const std::thread::id& rhs) + { + if (lhs.enabled()) + { + lhs._stream << Log::to_string(rhs); + } + + return lhs; + } + } #define LOG_BODY_(PRIO, LVL, X) Poco::Message m_(l_.name(), "", Poco::Message::PRIO_##PRIO); char b_[1024]; std::ostringstream oss_(Log::prefix(b_, LVL, false), std::ostringstream::ate); oss_ << std::boolalpha << X << "| " << __FILE__ << ':' << __LINE__; m_.setText(oss_.str()); l_.log(m_); diff --git a/common/Protocol.hpp b/common/Protocol.hpp index 61f35b71..61e16d31 100644 --- a/common/Protocol.hpp +++ b/common/Protocol.hpp @@ -12,6 +12,7 @@ #include <cstdint> #include <cstring> +#include <iomanip> #include <map> #include <sstream> #include <string> @@ -320,7 +321,7 @@ namespace LOOLProtocol result << Poco::format("%#x", flags); break; } - result << " " << length << " bytes"; + result << " " << std::setw(3) << length << " bytes"; if (length > 0 && ((flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) == Poco::Net::WebSocket::FRAME_OP_TEXT || diff --git a/common/Util.cpp b/common/Util.cpp index 7605c5a3..7f320d38 100644 --- a/common/Util.cpp +++ b/common/Util.cpp @@ -453,13 +453,12 @@ namespace Util strncpy(ThreadName, s.c_str(), 31); ThreadName[31] = '\0'; if (prctl(PR_SET_NAME, reinterpret_cast<unsigned long>(s.c_str()), 0, 0, 0) != 0) - LOG_SYS("Cannot set thread name of " << getThreadId() << " (0x" << - std::hex << std::this_thread::get_id() << - std::dec << ") to [" << s << "]."); + LOG_SYS("Cannot set thread name of " << getThreadId() << " (" << + std::this_thread::get_id() << ") to [" << s << "]."); else - LOG_INF("Thread " << getThreadId() << " (0x" << - std::hex << std::this_thread::get_id() << - std::dec << ") is now called [" << s << "]."); + LOG_INF("Thread " << getThreadId() << " (" << + std::this_thread::get_id() << + ") is now called [" << s << "]."); } const char *getThreadName() diff --git a/net/Socket.hpp b/net/Socket.hpp index 7e5035b4..bec3744d 100644 --- a/net/Socket.hpp +++ b/net/Socket.hpp @@ -242,8 +242,8 @@ public: { if (id != _owner) { - LOG_DBG("#" << _fd << " Thread affinity set to 0x" << std::hex << - id << " (was 0x" << _owner << ")." << std::dec); + LOG_DBG("#" << _fd << " Thread affinity set to " << Log::to_string(id) << + " (was " << Log::to_string(_owner) << ")."); _owner = id; } } @@ -261,9 +261,9 @@ public: // 0 owner means detached and can be invoked by any thread. const bool sameThread = (_owner == std::thread::id(0) || std::this_thread::get_id() == _owner); if (!sameThread) - LOG_ERR("#" << _fd << " Invoked from foreign thread. Expected: 0x" << std::hex << - _owner << " but called from 0x" << std::this_thread::get_id() << " (" << - std::dec << Util::getThreadId() << ")."); + LOG_ERR("#" << _fd << " Invoked from foreign thread. Expected: " << + Log::to_string(_owner) << " but called from " << + std::this_thread::get_id() << " (" << Util::getThreadId() << ")."); assert(sameThread); } @@ -283,8 +283,7 @@ protected: setNoDelay(); _sendBufferSize = DefaultSendBufferSize; _owner = std::this_thread::get_id(); - LOG_DBG("#" << _fd << " Thread affinity set to 0x" << std::hex << - _owner << "." << std::dec); + LOG_DBG("#" << _fd << " Thread affinity set to " << _owner << "."); #if ENABLE_DEBUG if (std::getenv("LOOL_ZERO_BUFFER_SIZE")) @@ -381,9 +380,9 @@ public: // 0 owner means detached and can be invoked by any thread. const bool sameThread = (!isAlive() || _owner == std::thread::id(0) || std::this_thread::get_id() == _owner); if (!sameThread) - LOG_ERR("Incorrect thread affinity for " << _name << ". Expected: 0x" << std::hex << - _owner << " (" << std::dec << Util::getThreadId() << ") but called from 0x" << - std::hex << std::this_thread::get_id() << std::dec << ", stop: " << _stop); + LOG_ERR("Incorrect thread affinity for " << _name << ". Expected: " << + Log::to_string(_owner) << " (" << Util::getThreadId() << + ") but called from " << std::this_thread::get_id() << ", stop: " << _stop); assert(_stop || sameThread); } @@ -615,8 +614,8 @@ private: LOG_INF("Starting polling thread [" << _name << "]."); _owner = std::this_thread::get_id(); - LOG_DBG("Thread affinity of " << _name << " set to 0x" << - std::hex << _owner << "." << std::dec); + LOG_DBG("Thread affinity of " << _name << " set to " << + Log::to_string(_owner) << "."); // Invoke the virtual implementation. pollingThread(); diff --git a/test/TileCacheTests.cpp b/test/TileCacheTests.cpp index 2c22da3a..e770e1ff 100644 --- a/test/TileCacheTests.cpp +++ b/test/TileCacheTests.cpp @@ -143,12 +143,16 @@ public: void setUp() { + resetTestStartTime(); testCountHowManyLoolkits(); + resetTestStartTime(); } void tearDown() { + resetTestStartTime(); testNoExtraLoolKitsLeft(); + resetTestStartTime(); } }; diff --git a/test/countloolkits.hpp b/test/countloolkits.hpp index 4b157b9a..90b89e12 100644 --- a/test/countloolkits.hpp +++ b/test/countloolkits.hpp @@ -22,10 +22,12 @@ #include <Common.hpp> #include "test.hpp" +#include "helpers.hpp" static int countLoolKitProcesses(const int expected) { - std::cerr << "Waiting until loolkit processes are exactly " << expected << ". Loolkits: "; + const auto testname = "countLoolKitProcesses "; + TST_LOG_BEGIN("Waiting until loolkit processes are exactly " << expected << ". Loolkits: "); // This does not need to depend on any constant from Common.hpp. // The shorter the better (the quicker the test runs). @@ -36,7 +38,7 @@ static int countLoolKitProcesses(const int expected) int count = getLoolKitProcessCount(); for (size_t i = 0; i < repeat; ++i) { - std::cerr << count << ' '; + TST_LOG_APPEND(count << ' '); if (count == expected) { break; @@ -54,10 +56,10 @@ static int countLoolKitProcesses(const int expected) } } - std::cerr << std::endl; + TST_LOG_END; if (expected != count) { - std::cerr << "Found " << count << " LoKit processes but was expecting " << expected << "." << std::endl; + TST_LOG("Found " << count << " LoKit processes but was expecting " << expected << "."); } return count; @@ -84,13 +86,14 @@ static void testCountHowManyLoolkits() static void testNoExtraLoolKitsLeft() { + const char* testname = "noExtraLoolKitsLeft "; const int countNow = countLoolKitProcesses(InitialLoolKitCount); CPPUNIT_ASSERT_EQUAL(InitialLoolKitCount, countNow); const auto duration = (std::chrono::steady_clock::now() - TestStartTime); const std::chrono::milliseconds::rep durationMs = std::chrono::duration_cast<std::chrono::milliseconds>(duration).count(); - std::cout << " (" << durationMs << " ms)"; + TST_LOG(" (" << durationMs << " ms)"); } #endif diff --git a/test/helpers.hpp b/test/helpers.hpp index 68038a8d..67d5d97b 100644 --- a/test/helpers.hpp +++ b/test/helpers.hpp @@ -37,12 +37,41 @@ #error TDOC must be defined (see Makefile.am) #endif +// Logging in unit-tests go to cerr, for now at least. +#define TST_LOG_NAME_BEGIN(NAME, X) do { std::cerr << NAME << "(@" << helpers::timeSinceTestStartMs() << "ms) " << X; } while (false) +#define TST_LOG_BEGIN(X) TST_LOG_NAME_BEGIN(testname, X) +#define TST_LOG_APPEND(X) do { std::cerr << X; } while (false) +#define TST_LOG_END do { std::cerr << "| " << __FILE__ << ':' << __LINE__ << std::endl; } while (false) +#define TST_LOG_NAME(NAME, X) TST_LOG_NAME_BEGIN(NAME, X); TST_LOG_END +#define TST_LOG(X) TST_LOG_NAME(testname, X) + /// Common helper testing functions. /// Avoid the temptation to reuse from LOOL code! /// These are supposed to be testing the latter. namespace helpers { inline +std::chrono::time_point<std::chrono::steady_clock>& getTestStartTime() +{ + static auto TestStartTime = std::chrono::steady_clock::now(); + + return TestStartTime; +} + +inline +void resetTestStartTime() +{ + getTestStartTime() = std::chrono::steady_clock::now(); +} + +inline +size_t timeSinceTestStartMs() +{ + return std::chrono::duration_cast<std::chrono::milliseconds>( + std::chrono::steady_clock::now() - getTestStartTime()).count(); +} + +inline std::vector<char> genRandomData(const size_t size) { std::vector<char> v(size); @@ -101,21 +130,22 @@ std::vector<char> readDataFromFile(std::unique_ptr<std::fstream>& file) inline void getDocumentPathAndURL(const std::string& docFilename, std::string& documentPath, std::string& documentURL, std::string prefix) { + const auto testname = prefix; std::replace(prefix.begin(), prefix.end(), ' ', '_'); documentPath = FileUtil::getTempFilePath(TDOC, docFilename, prefix); std::string encodedUri; Poco::URI::encode("file://" + Poco::Path(documentPath).makeAbsolute().toString(), ":/?", encodedUri); documentURL = "lool/" + encodedUri + "/ws"; - std::cerr << "Test file: " << documentPath << std::endl; + TST_LOG("Test file: " << documentPath); } inline -void sendTextFrame(LOOLWebSocket& socket, const std::string& string, const std::string& name = "") +void sendTextFrame(LOOLWebSocket& socket, const std::string& string, const std::string& testname = "") { #ifndef FUZZER - std::cerr << name << "Sending " << string.size() << " bytes: " << LOOLProtocol::getAbbreviatedMessage(string) << std::endl; + TST_LOG("Sending " << string.size() << " bytes: " << LOOLProtocol::getAbbreviatedMessage(string)); #else - (void) name; + (void) testname; #endif socket.sendFrame(string.data(), string.size()); } @@ -165,7 +195,7 @@ int getErrorCode(LOOLWebSocket& ws, std::string& message, const std::string& tes do { bytes = ws.receiveFrame(buffer.begin(), READ_BUFFER_SIZE, flags); - std::cerr << testname << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer.begin(), bytes, flags) << std::endl; + TST_LOG("Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer.begin(), bytes, flags)); std::this_thread::sleep_for(std::chrono::milliseconds(POLL_TIMEOUT_MS)); } while (bytes > 0 && (flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) != Poco::Net::WebSocket::FRAME_OP_CLOSE); @@ -187,9 +217,8 @@ int getErrorCode(const std::shared_ptr<LOOLWebSocket>& ws, std::string& message, } inline -std::vector<char> getResponseMessage(LOOLWebSocket& ws, const std::string& prefix, std::string name = "", const size_t timeoutMs = 10000) +std::vector<char> getResponseMessage(LOOLWebSocket& ws, const std::string& prefix, const std::string& testname = "", const size_t timeoutMs = 10000) { - name = name + '[' + prefix + "] "; try { int flags = 0; @@ -205,19 +234,20 @@ std::vector<char> getResponseMessage(LOOLWebSocket& ws, const std::string& prefi { if (timedout) { - std::cerr << std::endl; + TST_LOG_END; timedout = false; } response.resize(READ_BUFFER_SIZE * 8); int bytes = ws.receiveFrame(response.data(), response.size(), flags); response.resize(std::max(bytes, 0)); - std::cerr << name << "Got " << LOOLProtocol::getAbbreviatedFrameDump(response.data(), bytes, flags) << std::endl; const auto message = LOOLProtocol::getFirstLine(response); if (bytes > 0 && (flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) != Poco::Net::WebSocket::FRAME_OP_CLOSE) { if (LOOLProtocol::matchPrefix(prefix, message)) { + TST_LOG("[" << prefix << "] Matched " << + LOOLProtocol::getAbbreviatedFrameDump(response.data(), bytes, flags)); return response; } } @@ -239,18 +269,19 @@ std::vector<char> getResponseMessage(LOOLWebSocket& ws, const std::string& prefi throw std::runtime_error(message); } - std::cerr << name << "Ignored: " << message << std::endl; + TST_LOG("[" << prefix << "] Ignored " << + LOOLProtocol::getAbbreviatedFrameDump(response.data(), bytes, flags)); } } else { if (!timedout) { - std::cerr << name << "Timeout "; + TST_LOG_BEGIN("Timeout (" << (retries > 1 ? "retrying" : "giving up") << ") "); } else { - std::cerr << retries << ' '; + TST_LOG_APPEND(retries << ' '); } --retries; @@ -261,59 +292,60 @@ std::vector<char> getResponseMessage(LOOLWebSocket& ws, const std::string& prefi if (timedout) { - std::cerr << std::endl; + TST_LOG_END; } } catch (const Poco::Net::WebSocketException& exc) { - std::cerr << std::endl << exc.message(); + TST_LOG_END; + TST_LOG(exc.message()); } return std::vector<char>(); } inline -std::vector<char> getResponseMessage(const std::shared_ptr<LOOLWebSocket>& ws, const std::string& prefix, const std::string& name = "", const size_t timeoutMs = 10000) +std::vector<char> getResponseMessage(const std::shared_ptr<LOOLWebSocket>& ws, const std::string& prefix, const std::string& testname = "", const size_t timeoutMs = 10000) { - return getResponseMessage(*ws, prefix, name, timeoutMs); + return getResponseMessage(*ws, prefix, testname, timeoutMs); } template <typename T> -std::string getResponseString(T& ws, const std::string& prefix, const std::string& name = "", const size_t timeoutMs = 10000) +std::string getResponseString(T& ws, const std::string& prefix, const std::string& testname = "", const size_t timeoutMs = 10000) { - const auto response = getResponseMessage(ws, prefix, name, timeoutMs); + const auto response = getResponseMessage(ws, prefix, testname, timeoutMs); return std::string(response.data(), response.size()); } template <typename T> -std::string assertResponseString(T& ws, const std::string& prefix, const std::string name = "") +std::string assertResponseString(T& ws, const std::string& prefix, const std::string testname = "") { - const auto res = getResponseString(ws, prefix, name); + const auto res = getResponseString(ws, prefix, testname); CPPUNIT_ASSERT_EQUAL(prefix, res.substr(0, prefix.length())); return res; } /// Assert that we don't get a response with the given prefix. template <typename T> -std::string assertNotInResponse(T& ws, const std::string& prefix, const std::string name = "") +std::string assertNotInResponse(T& ws, const std::string& prefix, const std::string testname = "") { - const auto res = getResponseString(ws, prefix, name, 1000); - CPPUNIT_ASSERT_MESSAGE(name + "Did not expect getting message [" + res + "].", res.empty()); + const auto res = getResponseString(ws, prefix, testname, 1000); + CPPUNIT_ASSERT_MESSAGE(testname + "Did not expect getting message [" + res + "].", res.empty()); return res; } inline -bool isDocumentLoaded(LOOLWebSocket& ws, const std::string& name = "", bool isView = true) +bool isDocumentLoaded(LOOLWebSocket& ws, const std::string& testname = "", bool isView = true) { const std::string prefix = isView ? "status:" : "statusindicatorfinish:"; - const auto message = getResponseString(ws, prefix, name); + const auto message = getResponseString(ws, prefix, testname); return LOOLProtocol::matchPrefix(prefix, message); } inline -bool isDocumentLoaded(std::shared_ptr<LOOLWebSocket>& ws, const std::string& name = "", bool isView = true) +bool isDocumentLoaded(std::shared_ptr<LOOLWebSocket>& ws, const std::string& testname = "", bool isView = true) { - return isDocumentLoaded(*ws, name, isView); + return isDocumentLoaded(*ws, testname, isView); } // Connecting to a Kit process is managed by document broker, that it does several @@ -325,9 +357,9 @@ std::shared_ptr<LOOLWebSocket> connectLOKit(const Poco::URI& uri, Poco::Net::HTTPRequest& request, Poco::Net::HTTPResponse& response, - const std::string& name = "") + const std::string& testname = "") { - std::cerr << name << "Connecting... "; + TST_LOG_BEGIN("Connecting... "); int retries = 10; do { @@ -336,40 +368,41 @@ connectLOKit(const Poco::URI& uri, std::unique_ptr<Poco::Net::HTTPClientSession> session(createSession(uri)); auto ws = std::make_shared<LOOLWebSocket>(*session, request, response); const char* expected_response = "statusindicator: ready"; - if (getResponseString(ws, expected_response, name) == expected_response) + if (getResponseString(ws, expected_response, testname) == expected_response) { return ws; } - std::cerr << (11 - retries); + TST_LOG_APPEND(11 - retries); } catch (const std::exception& ex) { - std::cerr << std::endl << "Error connecting: " << ex.what() << std::endl; + TST_LOG_END; + TST_LOG("Error connecting: " << ex.what()); } std::this_thread::sleep_for(std::chrono::milliseconds(POLL_TIMEOUT_MS)); } while (retries--); - std::cerr << std::endl; + TST_LOG_END; throw std::runtime_error("Cannot connect to [" + uri.toString() + "]."); } inline -std::shared_ptr<LOOLWebSocket> loadDocAndGetSocket(const Poco::URI& uri, const std::string& documentURL, const std::string& name = "", bool isView = true) +std::shared_ptr<LOOLWebSocket> loadDocAndGetSocket(const Poco::URI& uri, const std::string& documentURL, const std::string& testname = "", bool isView = true) { try { // Load a document and get its status. Poco::Net::HTTPRequest request(Poco::Net::HTTPRequest::HTTP_GET, documentURL); Poco::Net::HTTPResponse response; - std::shared_ptr<LOOLWebSocket> socket = connectLOKit(uri, request, response, name); + std::shared_ptr<LOOLWebSocket> socket = connectLOKit(uri, request, response, testname); - sendTextFrame(socket, "load url=" + documentURL, name); - CPPUNIT_ASSERT_MESSAGE("cannot load the document " + documentURL, isDocumentLoaded(*socket, name, isView)); + sendTextFrame(socket, "load url=" + documentURL, testname); + CPPUNIT_ASSERT_MESSAGE("cannot load the document " + documentURL, isDocumentLoaded(*socket, testname, isView)); - std::cerr << name << "Loaded document [" << documentURL << "]." << std::endl; + TST_LOG("Loaded document [" << documentURL << "]."); return socket; } catch (const Poco::Exception& exc) @@ -382,13 +415,13 @@ std::shared_ptr<LOOLWebSocket> loadDocAndGetSocket(const Poco::URI& uri, const s } inline -std::shared_ptr<LOOLWebSocket> loadDocAndGetSocket(const std::string& docFilename, const Poco::URI& uri, const std::string& name = "", bool isView = true) +std::shared_ptr<LOOLWebSocket> loadDocAndGetSocket(const std::string& docFilename, const Poco::URI& uri, const std::string& testname = "", bool isView = true) { try { std::string documentPath, documentURL; - getDocumentPathAndURL(docFilename, documentPath, documentURL, name); - return loadDocAndGetSocket(uri, documentURL, name, isView); + getDocumentPathAndURL(docFilename, documentPath, documentURL, testname); + return loadDocAndGetSocket(uri, documentURL, testname, isView); } catch (const Poco::Exception& exc) { @@ -400,7 +433,7 @@ std::shared_ptr<LOOLWebSocket> loadDocAndGetSocket(const std::string& docFilenam } inline -void SocketProcessor(const std::string& name, +void SocketProcessor(const std::string& testname, const std::shared_ptr<LOOLWebSocket>& socket, const std::function<bool(const std::string& msg)>& handler, const size_t timeoutMs = 10000) @@ -415,12 +448,12 @@ void SocketProcessor(const std::string& name, { if (!socket->poll(waitTime, Poco::Net::Socket::SELECT_READ)) { - std::cerr << name << "Timeout polling." << std::endl; + TST_LOG("Timeout polling."); break; } n = socket->receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << name << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, n, flags) << std::endl; + TST_LOG("Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, n, flags)); if (n > 0 && (flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) != Poco::Net::WebSocket::FRAME_OP_CLOSE) { if (!handler(std::string(buffer, n))) @@ -454,15 +487,15 @@ void parseDocSize(const std::string& message, const std::string& type, } inline -std::vector<char> getTileMessage(LOOLWebSocket& ws, const std::string& name = "") +std::vector<char> getTileMessage(LOOLWebSocket& ws, const std::string& testname = "") { - return getResponseMessage(ws, "tile", name); + return getResponseMessage(ws, "tile", testname); } inline -std::vector<char> assertTileMessage(LOOLWebSocket& ws, const std::string& name = "") +std::vector<char> assertTileMessage(LOOLWebSocket& ws, const std::string& testname = "") { - const std::vector<char> response = getTileMessage(ws, name); + const std::vector<char> response = getTileMessage(ws, testname); const std::string firstLine = LOOLProtocol::getFirstLine(response); Poco::StringTokenizer tileTokens(firstLine, " ", Poco::StringTokenizer::TOK_IGNORE_EMPTY | Poco::StringTokenizer::TOK_TRIM); @@ -479,9 +512,9 @@ std::vector<char> assertTileMessage(LOOLWebSocket& ws, const std::string& name = } inline -std::vector<char> assertTileMessage(const std::shared_ptr<LOOLWebSocket>& ws, const std::string& name = "") +std::vector<char> assertTileMessage(const std::shared_ptr<LOOLWebSocket>& ws, const std::string& testname = "") { - return assertTileMessage(*ws, name); + return assertTileMessage(*ws, testname); } enum SpecialKey { skNone=0, skShift=0x1000, skCtrl=0x2000, skAlt=0x4000 }; @@ -549,11 +582,11 @@ inline std::vector<char> getTileAndSave(std::shared_ptr<LOOLWebSocket>& socket, const std::string& filename, const std::string& testname) { - std::cerr << testname << "Requesting: " << req << std::endl; + TST_LOG("Requesting: " << req); sendTextFrame(socket, req, testname); const std::vector<char> tile = getResponseMessage(socket, "tile:", testname); - std::cerr << testname << " Tile PNG size: " << tile.size() << std::endl; + TST_LOG(" Tile PNG size: " << tile.size()); const std::string firstLine = LOOLProtocol::getFirstLine(tile); std::vector<char> res(tile.begin() + firstLine.size() + 1, tile.end()); @@ -565,7 +598,7 @@ inline std::vector<char> getTileAndSave(std::shared_ptr<LOOLWebSocket>& socket, std::fstream outStream(filename, std::ios::out); outStream.write(res.data(), res.size()); outStream.close(); - std::cerr << testname << "Saved [" << firstLine << "] to [" << filename << "]" << std::endl; + TST_LOG("Saved [" << firstLine << "] to [" << filename << "]"); } return res; @@ -589,7 +622,7 @@ inline void getServerVersion(LOOLWebSocket& socket, assert(stream.get() == '.'); stream >> minor; - std::cerr << testname << "Client [" << major << '.' << minor << "]." << std::endl; + TST_LOG("Client [" << major << '.' << minor << "]."); } inline void getServerVersion(std::shared_ptr<LOOLWebSocket>& socket, diff --git a/test/httpcrashtest.cpp b/test/httpcrashtest.cpp index 38c2961d..fa79c8be 100644 --- a/test/httpcrashtest.cpp +++ b/test/httpcrashtest.cpp @@ -93,12 +93,16 @@ public: void setUp() { + resetTestStartTime(); testCountHowManyLoolkits(); + resetTestStartTime(); } void tearDown() { + resetTestStartTime(); testNoExtraLoolKitsLeft(); + resetTestStartTime(); } }; @@ -111,7 +115,7 @@ void HTTPCrashTest::testBarren() killLoKitProcesses(); countLoolKitProcesses(0); - std::cerr << "Loading after kill." << std::endl; + TST_LOG("Loading after kill."); // Load a document and get its status. std::shared_ptr<LOOLWebSocket> socket = loadDocAndGetSocket("hello.odt", _uri, testname); @@ -132,14 +136,14 @@ void HTTPCrashTest::testCrashKit() { std::shared_ptr<LOOLWebSocket> socket = loadDocAndGetSocket("empty.odt", _uri, testname); - std::cerr << "Killing loolkit instances." << std::endl; + TST_LOG("Killing loolkit instances."); killLoKitProcesses(); countLoolKitProcesses(0); // We expect the client connection to close. // In the future we might restore the kit, but currently we don't. - std::cerr << "Reading after kill." << std::endl; + TST_LOG("Reading after kill."); // Drain the socket. getResponseMessage(socket, "", testname, 1000); @@ -149,16 +153,16 @@ void HTTPCrashTest::testCrashKit() CPPUNIT_ASSERT_EQUAL(static_cast<int>(Poco::Net::WebSocket::WS_ENDPOINT_GOING_AWAY), statusCode); // respond close frame - std::cerr << "Shutting down socket." << std::endl; + TST_LOG("Shutting down socket."); socket->shutdown(); - std::cerr << "Reading after shutdown." << std::endl; + TST_LOG("Reading after shutdown."); // no more messages is received. int flags; char buffer[READ_BUFFER_SIZE]; const int bytes = socket->receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << testname << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags) << std::endl; + TST_LOG(testname << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags)); // While we expect no more messages after shutdown call, apparently // sometimes we _do_ get data. Even when the receiveFrame in the loop @@ -181,13 +185,13 @@ void HTTPCrashTest::testRecoverAfterKitCrash() { std::shared_ptr<LOOLWebSocket> socket = loadDocAndGetSocket("empty.odt", _uri, testname); - std::cerr << "Killing loolkit instances." << std::endl; + TST_LOG("Killing loolkit instances."); killLoKitProcesses(); countLoolKitProcesses(0); // We expect the client connection to close. - std::cerr << "Reconnect after kill." << std::endl; + TST_LOG("Reconnect after kill."); std::shared_ptr<LOOLWebSocket> socket2 = loadDocAndGetSocket("empty.odt", _uri, testname); sendTextFrame(socket2, "status", testname); @@ -206,9 +210,9 @@ void HTTPCrashTest::testCrashForkit() { std::shared_ptr<LOOLWebSocket> socket = loadDocAndGetSocket("empty.odt", _uri, testname); - std::cerr << "Killing forkit." << std::endl; + TST_LOG("Killing forkit."); killForkitProcess(); - std::cerr << "Communicating after kill." << std::endl; + TST_LOG("Communicating after kill."); sendTextFrame(socket, "status", testname); assertResponseString(socket, "status:", testname); @@ -216,10 +220,10 @@ void HTTPCrashTest::testCrashForkit() // respond close frame socket->shutdown(); - std::cerr << "Killing loolkit." << std::endl; + TST_LOG("Killing loolkit."); killLoKitProcesses(); countLoolKitProcesses(0); - std::cerr << "Communicating after kill." << std::endl; + TST_LOG("Communicating after kill."); loadDocAndGetSocket("empty.odt", _uri, testname); } catch (const Poco::Exception& exc) @@ -228,26 +232,27 @@ void HTTPCrashTest::testCrashForkit() } } -void killPids(const std::vector<int> &pids) +static void killPids(const std::vector<int> &pids, const std::string& testname) { - std::cout << "kill pids " << pids.size() << "\n"; + TST_LOG("kill pids " << pids.size()); // Now kill them for (int pid : pids) { - std::cerr << "Killing " << pid << std::endl; + TST_LOG_BEGIN("Killing " << pid); if (kill(pid, SIGKILL) == -1) - std::cerr << "kill(" << pid << ", SIGKILL) failed: " << std::strerror(errno) << std::endl; + TST_LOG_APPEND("kill(" << pid << ", SIGKILL) failed: " << std::strerror(errno)); + TST_LOG_END; } } void HTTPCrashTest::killLoKitProcesses() { - killPids(getKitPids()); + killPids(getKitPids(), "killLoKitProcesses "); } void HTTPCrashTest::killForkitProcess() { - killPids(getForKitPids()); + killPids(getForKitPids(), "killForkitProcess "); } CPPUNIT_TEST_SUITE_REGISTRATION(HTTPCrashTest); diff --git a/test/httpwserror.cpp b/test/httpwserror.cpp index 6ba40d01..16c27d8f 100644 --- a/test/httpwserror.cpp +++ b/test/httpwserror.cpp @@ -74,12 +74,16 @@ public: void setUp() { + resetTestStartTime(); testCountHowManyLoolkits(); + resetTestStartTime(); } void tearDown() { + resetTestStartTime(); testNoExtraLoolKitsLeft(); + resetTestStartTime(); } }; diff --git a/test/httpwstest.cpp b/test/httpwstest.cpp index ad0980bb..99bcff0e 100644 --- a/test/httpwstest.cpp +++ b/test/httpwstest.cpp @@ -179,7 +179,8 @@ class HTTPWSTest : public CPPUNIT_NS::TestFixture const size_t thread_count, const size_t max_jitter_ms); - void getPartHashCodes(const std::string response, + void getPartHashCodes(const std::string& testname, + const std::string& response, std::vector<std::string>& parts); void getCursor(const std::string& message, @@ -225,12 +226,16 @@ public: void setUp() { + resetTestStartTime(); testCountHowManyLoolkits(); + resetTestStartTime(); } void tearDown() { + resetTestStartTime(); testNoExtraLoolKitsLeft(); + resetTestStartTime(); } }; @@ -279,17 +284,17 @@ void HTTPWSTest::testHandshake() int flags = 0; char buffer[1024] = {0}; int bytes = socket.receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << testname << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags) << std::endl; + TST_LOG("Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags)); CPPUNIT_ASSERT_EQUAL(std::string("statusindicator: find"), std::string(buffer, bytes)); bytes = socket.receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << testname << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags) << std::endl; + TST_LOG("Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags)); if (bytes > 0 && !std::strstr(buffer, "error:")) { CPPUNIT_ASSERT_EQUAL(std::string("statusindicator: connect"), std::string(buffer, bytes)); bytes = socket.receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << testname << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags) << std::endl; + TST_LOG("Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags)); if (!std::strstr(buffer, "error:")) { CPPUNIT_ASSERT_EQUAL(std::string("statusindicator: ready"), std::string(buffer, bytes)); @@ -301,7 +306,7 @@ void HTTPWSTest::testHandshake() // close frame message bytes = socket.receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << testname << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags) << std::endl; + TST_LOG("Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags)); CPPUNIT_ASSERT((flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) == Poco::Net::WebSocket::FRAME_OP_CLOSE); } } @@ -312,7 +317,7 @@ void HTTPWSTest::testHandshake() // close frame message bytes = socket.receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << testname << "Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags) << std::endl; + TST_LOG("Got " << LOOLProtocol::getAbbreviatedFrameDump(buffer, bytes, flags)); CPPUNIT_ASSERT((flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) == Poco::Net::WebSocket::FRAME_OP_CLOSE); } } @@ -327,11 +332,11 @@ void HTTPWSTest::testCloseAfterClose() const char* testname = "closeAfterClose "; try { - std::cerr << testname << "Connecting and loading." << std::endl; + TST_LOG("Connecting and loading."); std::shared_ptr<LOOLWebSocket> socket = loadDocAndGetSocket("hello.odt", _uri, testname); // send normal socket shutdown - std::cerr << testname << "Disconnecting." << std::endl; + TST_LOG("Disconnecting."); socket->shutdown(); // 5 seconds timeout @@ -344,17 +349,17 @@ void HTTPWSTest::testCloseAfterClose() do { bytes = socket->receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << testname << "Received [" << std::string(buffer, bytes) << "], flags: "<< std::hex << flags << std::dec << std::endl; + TST_LOG("Received [" << std::string(buffer, bytes) << "], flags: "<< std::hex << flags << std::dec); } while (bytes > 0 && (flags & Poco::Net::WebSocket::FRAME_OP_BITMASK) != Poco::Net::WebSocket::FRAME_OP_CLOSE); - std::cerr << testname << "Received " << bytes << " bytes, flags: "<< std::hex << flags << std::dec << std::endl; + TST_LOG("Received " << bytes << " bytes, flags: "<< std::hex << flags << std::dec); try { // no more messages is received. bytes = socket->receiveFrame(buffer, sizeof(buffer), flags); - std::cerr << testname << "Received " << bytes << " bytes, flags: "<< std::hex << flags << std::dec << std::endl; + TST_LOG("Received " << bytes << " bytes, flags: "<< std::hex << flags << std::dec); CPPUNIT_ASSERT_EQUAL(0, bytes); CPPUNIT_ASSERT_EQUAL(0, flags); } @@ -363,7 +368,7 @@ void HTTPWSTest::testCloseAfterClose() // This is not unexpected, since WSD will close the socket after // echoing back the shutdown status code. However, if it doesn't // we assert above that it doesn't send any more data. - std::cerr << testname << "Error: " << exc.displayText() << std::endl; + TST_LOG("Error: " << exc.displayText()); } } @@ -402,31 +407,31 @@ void HTTPWSTest::testConnectNoLoad() // Connect and disconnect without loading. Poco::Net::HTTPRequest request(Poco::Net::HTTPRequest::HTTP_GET, documentURL); - std::cerr << testname1 << "Connecting first to disconnect without loading." << std::endl; + TST_LOG_NAME(testname1, "Connecting first to disconnect without loading."); std::shared_ptr<LOOLWebSocket> socket = connectLOKit(_uri, request, _response, testname1); CPPUNIT_ASSERT_MESSAGE("Failed to connect.", socket); - std::cerr << testname1 << "Disconnecting first." << std::endl; + TST_LOG_NAME(testname1, "Disconnecting first."); socket.reset(); // Connect and load first view. - std::cerr << testname2 << "Connecting second to load first view." << std::endl; + TST_LOG_NAME(testname2, "Connecting second to load first view."); std::shared_ptr<LOOLWebSocket> socket1 = connectLOKit(_uri, request, _response, testname2); CPPUNIT_ASSERT_MESSAGE("Failed to connect.", socket1); sendTextFrame(socket1, "load url=" + documentURL, testname2); CPPUNIT_ASSERT_MESSAGE("cannot load the document " + documentURL, isDocumentLoaded(socket1)); // Connect but don't load second view. - std::cerr << testname3 << "Connecting third to disconnect without loading." << std::endl; + TST_LOG_NAME(testname3, "Connecting third to disconnect without loading."); std::shared_ptr<LOOLWebSocket> socket2 = connectLOKit(_uri, request, _response, testname3); CPPUNIT_ASSERT_MESSAGE("Failed to connect.", socket2); - std::cerr << testname3 << "Disconnecting third." << std::endl; + TST_LOG_NAME(testname3, "Disconnecting third."); socket2.reset(); - std::cerr << testname2 << "Getting status from first view." << std::endl; + TST_LOG_NAME(testname2, "Getting status from first view."); sendTextFrame(socket1, "status", testname2); assertResponseString(socket1, "status:"); - std::cerr << testname2 << "Disconnecting second." << std::endl; + TST_LOG_NAME(testname2, "Disconnecting second."); socket1.reset(); } @@ -462,7 +467,7 @@ int HTTPWSTest::loadTorture(const std::string& testname, oss << std::hex << std::this_thread::get_id(); const std::string id = oss.str(); - std::cerr << testname << ": #" << id << ", views: " << num_of_views << ", to load: " << num_to_load << std::endl; + TST_LOG(": #" << id << ", views: " << num_of_views << ", to load: " << num_to_load); try { // Load a document and wait for the status. @@ -478,14 +483,14 @@ int HTTPWSTest::loadTorture(const std::string& testname, ++num_of_views; --num_to_load; - std::cerr << testname << ": #" << id << ", loaded views: " << num_of_views << ", to load: " << num_to_load << std::endl; + TST_LOG(": #" << id << ", loaded views: " << num_of_views << ", to load: " << num_to_load); while (true) { if (num_to_load == 0) { // Unload at once, nothing more left to do. - std::cerr << testname << ": #" << id << ", no more to load, unloading." << std::endl; + TST_LOG(": #" << id << ", no more to load, unloading."); break; } @@ -497,7 +502,7 @@ int HTTPWSTest::loadTorture(const std::string& testname, // Unload only when we aren't the last/only. if (--num_of_views > 0) { - std::cerr << testname << ": #" << id << ", views: " << num_of_views << " not the last/only, unloading." << std::endl; + TST_LOG(": #" << id << ", views: " << num_of_views << " not the last/only, unloading."); break; } else @@ -509,7 +514,7 @@ int HTTPWSTest::loadTorture(const std::string& testname, } catch (const std::exception& exc) { - std::cerr << testname << ": #" << id << ", Exception: " << exc.what() << std::endl; + TST_LOG(": #" << id << ", Exception: " << exc.what()); --num_to_load; } }); @@ -523,7 +528,7 @@ int HTTPWSTest::loadTorture(const std::string& testname, } catch (const std::exception& exc) { - std::cerr << testname << ": Exception: " << exc.what() << std::endl; + TST_LOG(": Exception: " << exc.what()); } } @@ -627,7 +632,7 @@ void HTTPWSTest::testReload() getDocumentPathAndURL("hello.odt", documentPath, documentURL, testname); for (int i = 0; i < 3; ++i) { - std::cerr << testname << "loading #" << (i+1) << std::endl; + TST_LOG("loading #" << (i+1)); loadDoc(documentURL, testname); } } @@ -659,7 +664,7 @@ void HTTPWSTest::testSaveOnDisconnect() const char* testname = "saveOnDisconnect "; const std::string text = helpers::genRandomString(40); - std::cerr << "Test string: [" << text << "]." << std::endl; + TST_LOG("Test string: [" << text << "]."); std::string documentPath, documentURL; getDocumentPathAndURL("hello.odt", documentPath, documentURL, testname); @@ -676,6 +681,8 @@ void HTTPWSTest::testSaveOnDisconnect() sendTextFrame(socket, "uno .uno:Delete", testname); sendTextFrame(socket, "paste mimetype=text/plain;charset=utf-8\n" + text, testname); + TST_LOG("Validating what we sent before disconnecting."); + // Check if the document contains the pasted text. sendTextFrame(socket, "uno .uno:SelectAll", testname); sendTextFrame(socket, "gettextselection mimetype=text/plain;charset=utf-8", testname); @@ -690,7 +697,7 @@ void HTTPWSTest::testSaveOnDisconnect() kitcount = getLoolKitProcessCount(); // Shutdown abruptly. - std::cerr << "Closing connection after pasting." << std::endl; + TST_LOG("Closing connection after pasting."); socket->shutdown(); socket2->shutdown(); } @@ -701,7 +708,7 @@ void HTTPWSTest::testSaveOnDisconnect() // Allow time to save and destroy before we connect again. testNoExtraLoolKitsLeft(); - std::cerr << "Loading again." << std::endl; + TST_LOG("Loading again."); try { // Load the same document and check that the last changes (pasted text) is saved. @@ -727,7 +734,7 @@ void HTTPWSTest::testSavePassiveOnDisconnect() const char* testname = "saveOnPassiveDisconnect "; const std::string text = helpers::genRandomString(40); - std::cerr << "Test string: [" << text << "]." << std::endl; + TST_LOG("Test string: [" << text << "]."); std::string documentPath, documentURL; getDocumentPathAndURL("hello.odt", documentPath, documentURL, testname); @@ -758,7 +765,7 @@ void HTTPWSTest::testSavePassiveOnDisconnect() kitcount = getLoolKitProcessCount(); // Shutdown abruptly. - std::cerr << "Closing connection after pasting." << std::endl; + TST_LOG("Closing connection after pasting."); socket->shutdown(); // Should trigger saving. socket2->shutdown(); } @@ -769,7 +776,7 @@ void HTTPWSTest::testSavePassiveOnDisconnect() // Allow time to save and destroy before we connect again. testNoExtraLoolKitsLeft(); - std::cerr << "Loading again." << std::endl; + TST_LOG("Loading again."); try { // Load the same document and check that the last changes (pasted text) is saved. @@ -812,11 +819,11 @@ void HTTPWSTest::testReloadWhileDisconnecting() const int kitcount = getLoolKitProcessCount(); // Shutdown abruptly. - std::cerr << "Closing connection after pasting." << std::endl; + TST_LOG("Closing connection after pasting."); socket->shutdown(); // Load the same document and check that the last changes (pasted text) is saved. - std::cerr << "Loading again." << std::endl; + TST_LOG("Loading again."); socket = loadDocAndGetSocket(_uri, documentURL, testname); // Should have no new instances. @@ -858,26 +865,28 @@ void HTTPWSTest::testExcelLoad() void HTTPWSTest::testPaste() { const char* testname = "paste "; - try + + // Load a document and make it empty, then paste some text into it. + std::shared_ptr<LOOLWebSocket> socket = loadDocAndGetSocket("hello.odt", _uri, testname); + + for (int i = 0; i < 5; ++i) { - // Load a document and make it empty, then paste some text into it. - std::shared_ptr<LOOLWebSocket> socket = loadDocAndGetSocket("hello.odt", _uri, testname); + const std::string text = std::to_string(i + 1) + "_sh9le[;\"CFD7U[#B+_nW=$kXgx{sv9QE#\"l1y\"hr_" + Util::encodeId(Util::rng::getNext()); + TST_LOG("Pasting text #" << i + 1 << ": " << text); + // Always delete everything to have an empty doc. sendTextFrame(socket, "uno .uno:SelectAll", testname); sendTextFrame(socket, "uno .uno:Delete", testname); // Paste some text into it. - sendTextFrame(socket, "paste mimetype=text/plain;charset=utf-8\naaa bbb ccc", testname); + sendTextFrame(socket, "paste mimetype=text/plain;charset=utf-8\n" + text, testname); + const std::string expected = "textselectioncontent: " + text; // Check if the document contains the pasted text. sendTextFrame(socket, "uno .uno:SelectAll", testname); sendTextFrame(socket, "gettextselection mimetype=text/plain;charset=utf-8", testname); const auto selection = assertResponseString(socket, "textselectioncontent:", testname); - CPPUNIT_ASSERT_EQUAL(std::string("textselectioncontent: aaa bbb ccc"), selection); - } - catch (const Poco::Exception& exc) - { - CPPUNIT_FAIL(exc.displayText()); + CPPUNIT_ASSERT_EQUAL(expected, selection); } } @@ -926,7 +935,7 @@ void HTTPWSTest::testLargePaste() } const std::string documentContents = oss.str(); - std::cerr << "Pasting " << documentContents.size() << " characters into document." << std::endl; + TST_LOG("Pasting " << documentContents.size() << " characters into document."); sendTextFrame(socket, "paste mimetype=text/html\n" + documentContents, testname); // Check if the server is still alive. @@ -1130,23 +1139,23 @@ void HTTPWSTest::testInsertDelete() CPPUNIT_ASSERT_MESSAGE("cannot load the document " + documentURL, isDocumentLoaded(socket)); // check total slides 1 - std::cerr << "Expecting 1 slide." << std::endl; + TST_LOG("Expecting 1 slide."); sendTextFrame(socket, "status"); response = getResponseString(socket, "status:"); CPPUNIT_ASSERT_MESSAGE("did not receive a status: message as expected", !response.empty()); - getPartHashCodes(response.substr(7), parts); + getPartHashCodes(testname, response.substr(7), parts); CPPUNIT_ASSERT_EQUAL(1, (int)parts.size()); const std::string slide1Hash = parts[0]; // insert 10 slides - std::cerr << "Inserting 10 slides." << std::endl; + TST_LOG("Inserting 10 slides."); for (size_t it = 1; it <= 10; it++) { sendTextFrame(socket, "uno .uno:InsertPage"); response = getResponseString(socket, "status:"); CPPUNIT_ASSERT_MESSAGE("did not receive a status: message as expected", !response.empty()); - getPartHashCodes(response.substr(7), parts); + getPartHashCodes(testname, response.substr(7), parts); CPPUNIT_ASSERT_EQUAL(it + 1, parts.size()); } @@ -1154,7 +1163,7 @@ void HTTPWSTest::testInsertDelete() const std::vector<std::string> parts_after_insert(parts.begin(), parts.end()); // delete 10 slides - std::cerr << "Deleting 10 slides." << std::endl; + TST_LOG("Deleting 10 slides."); for (size_t it = 1; it <= 10; it++) { // Explicitly delete the nth slide. @@ -1162,20 +1171,20 @@ void HTTPWSTest::testInsertDelete() sendTextFrame(socket, "uno .uno:DeletePage"); response = getResponseString(socket, "status:"); CPPUNIT_ASSERT_MESSAGE("did not receive a status: message as expected", !response.empty()); - getPartHashCodes(response.substr(7), parts); + getPartHashCodes(testname, response.substr(7), parts); CPPUNIT_ASSERT_EQUAL(11 - it, parts.size()); } CPPUNIT_ASSERT_MESSAGE("Hash code of slide #1 changed after deleting extra slides.", parts[0] == slide1Hash); // undo delete slides - std::cerr << "Undoing 10 slide deletes." << std::endl; + TST_LOG("Undoing 10 slide deletes."); for (size_t it = 1; it <= 10; it++) { sendTextFrame(socket, "uno .uno:Undo"); response = getResponseString(socket, "status:"); CPPUNIT_ASSERT_MESSAGE("did not receive a status: message as expected", !response.empty()); - getPartHashCodes(response.substr(7), parts); + getPartHashCodes(testname, response.substr(7), parts); CPPUNIT_ASSERT_EQUAL(it + 1, parts.size()); } @@ -1184,24 +1193,24 @@ void HTTPWSTest::testInsertDelete() CPPUNIT_ASSERT_MESSAGE("Hash codes changed between deleting and undo.", parts_after_insert == parts_after_undo); // redo inserted slides - std::cerr << "Redoing 10 slide deletes." << std::endl; + TST_LOG("Redoing 10 slide deletes."); for (size_t it = 1; it <= 10; it++) { sendTextFrame(socket, "uno .uno:Redo"); response = getResponseString(socket, "status:"); CPPUNIT_ASSERT_MESSAGE("did not receive a status: message as expected", !response.empty()); - getPartHashCodes(response.substr(7), parts); + getPartHashCodes(testname, response.substr(7), parts); CPPUNIT_ASSERT_EQUAL(11 - it, parts.size()); } CPPUNIT_ASSERT_MESSAGE("Hash code of slide #1 changed after redoing slide delete.", parts[0] == slide1Hash); // check total slides 1 - std::cerr << "Expecting 1 slide." << std::endl; + TST_LOG("Expecting 1 slide."); sendTextFrame(socket, "status"); response = getResponseString(socket, "status:"); CPPUNIT_ASSERT_MESSAGE("did not receive a status: message as expected", !response.empty()); - getPartHashCodes(response.substr(7), parts); + getPartHashCodes(testname, response.substr(7), parts); CPPUNIT_ASSERT_EQUAL(1, (int)parts.size()); } catch (const Poco::Exception& exc) @@ -1276,7 +1285,7 @@ void HTTPWSTest::testSlideShow() std::istream& rs = session->receiveResponse(responseSVG); CPPUNIT_ASSERT_EQUAL(Poco::Net::HTTPResponse::HTTP_OK, responseSVG.getStatus()); CPPUNIT_ASSERT_EQUAL(std::string("image/svg+xml"), responseSVG.getContentType()); - std::cerr << "SVG file size: " << responseSVG.getContentLength() << std::endl; + TST_LOG("SVG file size: " << responseSVG.getContentLength()); // std::ofstream ofs("/tmp/slide.svg"); // Poco::StreamCopier::copyStream(rs, ofs); @@ -1315,7 +1324,7 @@ void HTTPWSTest::testInactiveClient() std::shared_ptr<LOOLWebSocket> socket1 = loadDocAndGetSocket(_uri, documentURL, "inactiveClient-1 "); // Connect another and go inactive. - std::cerr << "Connecting second client." << std::endl; + TST_LOG("Connecting second client."); std::shared_ptr<LOOLWebSocket> socket2 = loadDocAndGetSocket(_uri, documentURL, "inactiveClient-2 ", true); sendTextFrame(socket2, "userinactive", "inactiveClient-2 "); @@ -1349,7 +1358,7 @@ void HTTPWSTest::testInactiveClient() return (token != "statechanged:"); }); - std::cerr << "Second client finished." << std::endl; + TST_LOG("Second client finished."); socket1->shutdown(); socket2->shutdown(); } @@ -1437,14 +1446,15 @@ void HTTPWSTest::testMaxRow() } } -void HTTPWSTest::getPartHashCodes(const std::string status, +void HTTPWSTest::getPartHashCodes(const std::string& testname, + const std::string& response, std::vector<std::string>& parts) { std::string line; - std::istringstream istr(status); + std::istringstream istr(response); std::getline(istr, line); - std::cerr << "Reading parts from [" << status << "]." << std::endl; + TST_LOG("Reading parts from [" << response << "]."); // Expected format is something like 'type= parts= current= width= height= viewid='. Poco::StringTokenizer tokens(line, " ", Poco::StringTokenizer::TOK_IGNORE_EMPTY | Poco::StringTokenizer::TOK_TRIM); @@ -1455,7 +1465,7 @@ void HTTPWSTest::getPartHashCodes(const std::string status, type == "presentation" || type == "spreadsheet"); const int totalParts = std::stoi(tokens[1].substr(std::string("parts=").size())); - std::cerr << "Status reports " << totalParts << " parts." << std::endl; + TST_LOG("Status reports " << totalParts << " parts."); Poco::RegularExpression endLine("[^\n\r]+"); Poco::RegularExpression number("^[0-9]+$"); @@ -1463,10 +1473,10 @@ void HTTPWSTest::getPartHashCodes(const std::string status, int offset = 0; parts.clear(); - while (endLine.match(status, offset, matches) > 0) + while (endLine.match(response, offset, matches) > 0) { CPPUNIT_ASSERT_EQUAL(1, (int)matches.size()); - const std::string str = status.substr(matches[0].offset, matches[0].length); + const std::string str = response.substr(matches[0].offset, matches[0].length); if (number.match(str, 0)) { parts.push_back(str); @@ -1475,7 +1485,7 @@ void HTTPWSTest::getPartHashCodes(const std::string status, offset = static_cast<int>(matches[0].offset + matches[0].length); } - std::cerr << "Found " << parts.size() << " part names/codes." << std::endl; + TST_LOG("Found " << parts.size() << " part names/codes."); // Validate that Core is internally consistent when emitting status messages. CPPUNIT_ASSERT_EQUAL(totalParts, (int)parts.size()); @@ -1617,7 +1627,7 @@ void HTTPWSTest::testInsertAnnotationWriter() // Make sure the document is fully unloaded. testNoExtraLoolKitsLeft(); - std::cerr << "Reloading " << std::endl; + TST_LOG("Reloading "); socket = loadDocAndGetSocket(_uri, documentURL, testname); // Confirm that the text is in the comment and not doc body. @@ -1682,10 +1692,10 @@ void HTTPWSTest::testEditAnnotationWriter() const int kitcount = getLoolKitProcessCount(); // Close and reopen the same document and test again. - std::cerr << "Closing connection after pasting." << std::endl; + TST_LOG("Closing connection after pasting."); socket->shutdown(); - std::cerr << "Reloading " << std::endl; + TST_LOG("Reloading "); socket = loadDocAndGetSocket(_uri, documentURL, testname); // Should have no new instances. @@ -1751,7 +1761,7 @@ void HTTPWSTest::testCalcEditRendering() sendTextFrame(socket, req, testname); const std::vector<char> tile = getResponseMessage(socket, "tile:", testname); - std::cerr << "size: " << tile.size() << std::endl; + TST_LOG("size: " << tile.size()); // Return early for now when on LO >= 5.2. int major = 0; @@ -1793,7 +1803,7 @@ void HTTPWSTest::testCalcEditRendering() // This is a very strict test that breaks often/easily due to slight rendering // differences. So for now just keep it informative only. //CPPUNIT_ASSERT_MESSAGE("Tile not rendered as expected @ row #" + std::to_string(itRow), eq); - std::cerr << "\nFAILURE: Tile not rendered as expected @ row #" << itRow << std::endl; + TST_LOG("\nFAILURE: Tile not rendered as expected @ row #" << itRow); break; } } @@ -1817,8 +1827,8 @@ void HTTPWSTest::testCalcRenderAfterNewView51() getServerVersion(socket, major, minor, testname); if (major != 5 || minor != 1) { - std::cerr << testname << "Skipping test on incompatible client [" - << major << '.' << minor << "], expected [5.1]." << std::endl; + TST_LOG("Skipping test on incompatible client [" + << major << '.' << minor << "], expected [5.1]."); return; } @@ -1838,12 +1848,12 @@ void HTTPWSTest::testCalcRenderAfterNewView51() // Connect second client, which will load at the top. - std::cerr << testname << "Connecting second client." << std::endl; + TST_LOG("Connecting second client."); std::shared_ptr<LOOLWebSocket> socket2 = loadDocAndGetSocket(_uri, documentURL, testname); // Up one row on the first view to trigger the bug. - std::cerr << testname << "Up." << std::endl; + TST_LOG("Up."); sendTextFrame(socket, "key type=input char=0 key=1025", testname); assertResponseString(socket, "invalidatetiles:", testname); // Up invalidates. @@ -1868,8 +1878,8 @@ void HTTPWSTest::testCalcRenderAfterNewView53() getServerVersion(socket, major, minor, testname); if (major < 5 || minor < 3) { - std::cerr << testname << "Skipping test on incompatible client [" - << major << '.' << minor << "], expected [>=5.3]." << std::endl; + TST_LOG("Skipping test on incompatible client [" + << major << '.' << minor << "], expected [>=5.3]."); return; } @@ -1882,11 +1892,11 @@ void HTTPWSTest::testCalcRenderAfterNewView53() // Connect second client, which will load at the top. - std::cerr << testname << "Connecting second client." << std::endl; + TST_LOG("Connecting second client."); std::shared_ptr<LOOLWebSocket> socket2 = loadDocAndGetSocket(_uri, documentURL, testname); - std::cerr << testname << "Waiting for cellviewcursor of second on first." << std::endl; + TST_LOG("Waiting for cellviewcursor of second on first."); assertResponseString(socket, "cellviewcursor:", testname); // Get same tile again. diff --git a/test/integration-http-server.cpp b/test/integration-http-server.cpp index ef478fcb..25fee24d 100644 --- a/test/integration-http-server.cpp +++ b/test/integration-http-server.cpp @@ -78,12 +78,16 @@ public: void setUp() { + helpers::resetTestStartTime(); testCountHowManyLoolkits(); + helpers::resetTestStartTime(); } void tearDown() { + helpers::resetTestStartTime(); testNoExtraLoolKitsLeft(); + helpers::resetTestStartTime(); } }; diff --git a/wsd/AdminModel.cpp b/wsd/AdminModel.cpp index 6a9065fd..7f2b8dac 100644 --- a/wsd/AdminModel.cpp +++ b/wsd/AdminModel.cpp @@ -169,9 +169,9 @@ void AdminModel::assertCorrectThread() const // FIXME: share this code [!] const bool sameThread = std::this_thread::get_id() == _owner; if (!sameThread) - LOG_ERR("Admin command invoked from foreign thread. Expected: 0x" << std::hex << - _owner << " but called from 0x" << std::this_thread::get_id() << " (" << - std::dec << Util::getThreadId() << ")."); + LOG_ERR("Admin command invoked from foreign thread. Expected: " << + Log::to_string(_owner) << " but called from " << + std::this_thread::get_id() << " (" << Util::getThreadId() << ")."); assert(sameThread); } diff --git a/wsd/TileCache.cpp b/wsd/TileCache.cpp index 95ed5089..51f1933d 100644 --- a/wsd/TileCache.cpp +++ b/wsd/TileCache.cpp @@ -537,9 +537,9 @@ void TileCache::assertCorrectThread() { const bool correctThread = _owner == std::thread::id(0) || std::this_thread::get_id() == _owner; if (!correctThread) - LOG_ERR("TileCache method invoked from foreign thread. Expected: 0x" << std::hex << - _owner << " but called from 0x" << std::this_thread::get_id() << " (" << - std::dec << Util::getThreadId() << ")."); + LOG_ERR("TileCache method invoked from foreign thread. Expected: " << + Log::to_string(_owner) << " but called from " << + std::this_thread::get_id() << " (" << Util::getThreadId() << ")."); assert (correctThread); } _______________________________________________ Libreoffice-commits mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits
