From 561204b2a795c750a73385a39bf28fa7ec739077 Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Wed, 20 May 2015 17:42:07 +0100 Subject: [PATCH] Disabled threading on most IPC logging tests #4624 Threading was making it very hard to reliably run the IPC logging tests (many timing issues), so I disabled threading for most of the tests. --- src/lib/ipc/IpcLogOutputter.cpp | 79 +++++-------- src/lib/ipc/IpcLogOutputter.h | 29 ++--- src/lib/platform/MSWindowsWatchdog.cpp | 4 +- src/lib/synergy/DaemonApp.cpp | 2 +- src/test/mock/ipc/MockIpcServer.h | 2 +- .../unittests/ipc/IpcLogOutputterTests.cpp | 110 ++++++++++-------- 6 files changed, 111 insertions(+), 115 deletions(-) diff --git a/src/lib/ipc/IpcLogOutputter.cpp b/src/lib/ipc/IpcLogOutputter.cpp index 42749d68..4f7b63fa 100644 --- a/src/lib/ipc/IpcLogOutputter.cpp +++ b/src/lib/ipc/IpcLogOutputter.cpp @@ -37,11 +37,12 @@ enum EIpcLogOutputter { kBufferRateTimeLimit = 1 // seconds }; -IpcLogOutputter::IpcLogOutputter(IpcServer& ipcServer) : +IpcLogOutputter::IpcLogOutputter(IpcServer& ipcServer, bool useThread) : m_ipcServer(ipcServer), m_bufferMutex(ARCH->newMutex()), m_sending(false), - m_running(true), + m_running(false), + m_bufferThread(nullptr), m_notifyCond(ARCH->newCondVar()), m_notifyMutex(ARCH->newMutex()), m_bufferWaiting(false), @@ -51,8 +52,10 @@ IpcLogOutputter::IpcLogOutputter(IpcServer& ipcServer) : m_bufferWriteCount(0), m_bufferRateStart(ARCH->time()) { - m_bufferThread = new Thread(new TMethodJob( - this, &IpcLogOutputter::bufferThread)); + if (useThread) { + m_bufferThread = new Thread(new TMethodJob( + this, &IpcLogOutputter::bufferThread)); + } } IpcLogOutputter::~IpcLogOutputter() @@ -60,7 +63,10 @@ IpcLogOutputter::~IpcLogOutputter() close(); ARCH->closeMutex(m_bufferMutex); - delete m_bufferThread; + + if (m_bufferThread != nullptr) { + delete m_bufferThread; + } ARCH->closeCondVar(m_notifyCond); ARCH->closeMutex(m_notifyMutex); @@ -74,9 +80,11 @@ IpcLogOutputter::open(const char* title) void IpcLogOutputter::close() { - m_running = false; - notifyBuffer(); - m_bufferThread->wait(5); + if (m_bufferThread != nullptr) { + m_running = false; + notifyBuffer(); + m_bufferThread->wait(5); + } } void @@ -85,27 +93,12 @@ IpcLogOutputter::show(bool showIfEmpty) } bool -IpcLogOutputter::write(ELevel level, const char* text) +IpcLogOutputter::write(ELevel, const char* text) { - return write(level, text, false); -} - -bool -IpcLogOutputter::write(ELevel, const char* text, bool force) -{ - // TODO: discard based on thread id? hmm... - // sending the buffer generates log messages, which we must throw - // away (otherwise this would cause recursion). this is just a drawback - // of logging this way. there is also the risk that this could throw - // away log messages not generated by the ipc, but it seems like it - // would be difficult to distinguish (other than looking at the stack - // trace somehow). perhaps a file stream might be a better option :-/ - if (m_sending && !force) { - - // ignore events from the buffer thread (would cause recursion). - if (Thread::getCurrentThread().getID() == m_bufferThreadId) { - return true; - } + // ignore events from the buffer thread (would cause recursion). + if (m_bufferThread != nullptr && + Thread::getCurrentThread().getID() == m_bufferThreadId) { + return true; } appendBuffer(text); @@ -143,29 +136,17 @@ IpcLogOutputter::appendBuffer(const String& text) void IpcLogOutputter::bufferThread(void*) { - ArchMutexLock lock(m_notifyMutex); m_bufferThreadId = m_bufferThread->getID(); + m_running = true; try { while (m_running) { - - if (m_ipcServer.hasClients(kIpcClientGui)) { - - // buffer is sent in chunks, so keep sending until it's - // empty (or the program has stopped in the meantime). - while (m_running && !m_buffer.empty()) { - sendBuffer(); - } + if (m_buffer.empty()) { + ArchMutexLock lock(m_notifyMutex); + ARCH->waitCondVar(m_notifyCond, m_notifyMutex, -1); } - // program may be stopping while we were in the send loop. - if (!m_running) { - break; - } - - m_bufferWaiting = true; - ARCH->waitCondVar(m_notifyCond, m_notifyMutex, -1); - m_bufferWaiting = false; + sendBuffer(); } } catch (XArch& e) { @@ -178,9 +159,6 @@ IpcLogOutputter::bufferThread(void*) void IpcLogOutputter::notifyBuffer() { - if (!m_bufferWaiting) { - return; - } ArchMutexLock lock(m_notifyMutex); ARCH->broadcastCondVar(m_notifyCond); } @@ -206,8 +184,11 @@ IpcLogOutputter::getChunk(size_t count) void IpcLogOutputter::sendBuffer() { - IpcLogLineMessage message(getChunk(kMaxSendLines)); + if (m_buffer.empty() || !m_ipcServer.hasClients(kIpcClientGui)) { + return; + } + IpcLogLineMessage message(getChunk(kMaxSendLines)); m_sending = true; m_ipcServer.send(message, kIpcClientGui); m_sending = false; diff --git a/src/lib/ipc/IpcLogOutputter.h b/src/lib/ipc/IpcLogOutputter.h index fb55cfbf..a6a476a6 100644 --- a/src/lib/ipc/IpcLogOutputter.h +++ b/src/lib/ipc/IpcLogOutputter.h @@ -34,7 +34,12 @@ This outputter writes output to the GUI via IPC. */ class IpcLogOutputter : public ILogOutputter { public: - IpcLogOutputter(IpcServer& ipcServer); + /*! + If \p useThread is \c true, the buffer will be sent using a thread. + If \p useThread is \c false, then the buffer needs to be sent manually + using the \c sendBuffer() function. + */ + IpcLogOutputter(IpcServer& ipcServer, bool useThread); virtual ~IpcLogOutputter(); // ILogOutputter overrides @@ -46,30 +51,28 @@ public: //! @name manipulators //@{ - //! Same as write, but allows message to sidestep anti-recursion mechanism. - bool write(ELevel level, const char* text, bool force); - //! Notify that the buffer should be sent. void notifyBuffer(); - //! Set the buffer size. + //! Set the buffer size /*! Set the maximum size of the buffer to protect memory from runaway logging. */ void bufferMaxSize(UInt16 bufferMaxSize); - - //! Wait for empty buffer - /*! - Wait on a cond var until the buffer is empty. - */ - void waitForEmpty(); - //! Set the buffer size. + //! Set the rate limit /*! Set the maximum number of \p writeRate for every \p timeRate in seconds. */ void bufferRateLimit(UInt16 writeLimit, double timeLimit); + + //! Send the buffer + /*! + Sends a chunk of the buffer to the IPC server, normally called + when threaded mode is on. + */ + void sendBuffer(); //@} @@ -88,7 +91,6 @@ private: void init(); void bufferThread(void*); String getChunk(size_t count); - void sendBuffer(); void appendBuffer(const String& text); private: @@ -110,4 +112,5 @@ private: double m_bufferRateTimeLimit; UInt16 m_bufferWriteCount; double m_bufferRateStart; + bool m_useThread; }; diff --git a/src/lib/platform/MSWindowsWatchdog.cpp b/src/lib/platform/MSWindowsWatchdog.cpp index a43c7194..8bbb0ab2 100644 --- a/src/lib/platform/MSWindowsWatchdog.cpp +++ b/src/lib/platform/MSWindowsWatchdog.cpp @@ -420,9 +420,7 @@ MSWindowsWatchdog::outputLoop(void*) testOutput(buffer); - // send process output over IPC to GUI, and force it to be sent - // which bypasses the ipc logging anti-recursion mechanism. - m_ipcLogOutputter.write(kINFO, buffer, true); + m_ipcLogOutputter.write(kINFO, buffer); if (m_fileLogOutputter != NULL) { m_fileLogOutputter->write(kINFO, buffer); diff --git a/src/lib/synergy/DaemonApp.cpp b/src/lib/synergy/DaemonApp.cpp index 980dd54b..15ff14df 100644 --- a/src/lib/synergy/DaemonApp.cpp +++ b/src/lib/synergy/DaemonApp.cpp @@ -211,7 +211,7 @@ DaemonApp::mainLoop(bool logToFile) m_ipcServer = new IpcServer(m_events, &multiplexer); // send logging to gui via ipc, log system adopts outputter. - m_ipcLogOutputter = new IpcLogOutputter(*m_ipcServer); + m_ipcLogOutputter = new IpcLogOutputter(*m_ipcServer, true); CLOG->insert(m_ipcLogOutputter); #if SYSAPI_WIN32 diff --git a/src/test/mock/ipc/MockIpcServer.h b/src/test/mock/ipc/MockIpcServer.h index ccbc99a1..6500887b 100644 --- a/src/test/mock/ipc/MockIpcServer.h +++ b/src/test/mock/ipc/MockIpcServer.h @@ -44,7 +44,7 @@ public: } void waitForSend() { - ARCH->waitCondVar(m_sendCond, m_sendMutex, -1); + ARCH->waitCondVar(m_sendCond, m_sendMutex, 5); } private: diff --git a/src/test/unittests/ipc/IpcLogOutputterTests.cpp b/src/test/unittests/ipc/IpcLogOutputterTests.cpp index 48eaad1f..254752c4 100644 --- a/src/test/unittests/ipc/IpcLogOutputterTests.cpp +++ b/src/test/unittests/ipc/IpcLogOutputterTests.cpp @@ -45,76 +45,90 @@ inline const Matcher IpcLogLineMessageEq(const String& s) { return MatcherCast(m); } -TEST(IpcLogOutputterTests, write_overBufferMaxSize_firstLineTruncated) -{ - MockIpcServer mockServer; - mockServer.delegateToFake(); - - ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); - - EXPECT_CALL(mockServer, hasClients(_)).Times(1); - EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 2\nmock 3\n"), _)).Times(1); - - IpcLogOutputter outputter(mockServer); - outputter.bufferMaxSize(2); - - // log more lines than the buffer can contain - outputter.write(kNOTE, "mock 1"); - outputter.write(kNOTE, "mock 2"); - outputter.write(kNOTE, "mock 3"); - mockServer.waitForSend(); -} - -TEST(IpcLogOutputterTests, write_underBufferMaxSize_allLinesAreSent) -{ - MockIpcServer mockServer; - mockServer.delegateToFake(); - - ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); - - EXPECT_CALL(mockServer, hasClients(_)).Times(1); - EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 1\nmock 2\n"), _)).Times(1); - - IpcLogOutputter outputter(mockServer); - outputter.bufferMaxSize(2); - - // log more lines than the buffer can contain - outputter.write(kNOTE, "mock 1"); - outputter.write(kNOTE, "mock 2"); - mockServer.waitForSend(); -} - -TEST(IpcLogOutputterTests, write_overBufferRateLimit_lastLineTruncated) +TEST(IpcLogOutputterTests, write_threadingEnabled_bufferIsSent) { MockIpcServer mockServer; mockServer.delegateToFake(); ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); + EXPECT_CALL(mockServer, hasClients(_)).Times(2); + EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 1\n"), _)).Times(1); + EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 2\n"), _)).Times(1); + + IpcLogOutputter outputter(mockServer, true); + outputter.write(kNOTE, "mock 1"); + mockServer.waitForSend(); + outputter.write(kNOTE, "mock 2"); + mockServer.waitForSend(); +} + +TEST(IpcLogOutputterTests, write_overBufferMaxSize_firstLineTruncated) +{ + MockIpcServer mockServer; + + ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); + + EXPECT_CALL(mockServer, hasClients(_)).Times(1); + EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 2\nmock 3\n"), _)).Times(1); + + IpcLogOutputter outputter(mockServer, false); + outputter.bufferMaxSize(2); + + // log more lines than the buffer can contain + outputter.write(kNOTE, "mock 1"); + outputter.write(kNOTE, "mock 2"); + outputter.write(kNOTE, "mock 3"); + outputter.sendBuffer(); +} + +TEST(IpcLogOutputterTests, write_underBufferMaxSize_allLinesAreSent) +{ + MockIpcServer mockServer; + + ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); + + EXPECT_CALL(mockServer, hasClients(_)).Times(1); + EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 1\nmock 2\n"), _)).Times(1); + + IpcLogOutputter outputter(mockServer, false); + outputter.bufferMaxSize(2); + + // log more lines than the buffer can contain + outputter.write(kNOTE, "mock 1"); + outputter.write(kNOTE, "mock 2"); + outputter.sendBuffer(); +} + +TEST(IpcLogOutputterTests, write_overBufferRateLimit_lastLineTruncated) +{ + MockIpcServer mockServer; + + ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); + EXPECT_CALL(mockServer, hasClients(_)).Times(2); EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 1\n"), _)).Times(1); EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 3\n"), _)).Times(1); - IpcLogOutputter outputter(mockServer); + IpcLogOutputter outputter(mockServer, false); outputter.bufferRateLimit(1, 0.001); // 1ms // log 1 more line than the buffer can accept in time limit. outputter.write(kNOTE, "mock 1"); outputter.write(kNOTE, "mock 2"); - mockServer.waitForSend(); + outputter.sendBuffer(); // after waiting the time limit send another to make sure // we can log after the time limit passes. - ARCH->sleep(0.002); // 2ms + ARCH->sleep(0.01); // 10ms outputter.write(kNOTE, "mock 3"); outputter.write(kNOTE, "mock 4"); - mockServer.waitForSend(); + outputter.sendBuffer(); } TEST(IpcLogOutputterTests, write_underBufferRateLimit_allLinesAreSent) { MockIpcServer mockServer; - mockServer.delegateToFake(); ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); @@ -122,19 +136,19 @@ TEST(IpcLogOutputterTests, write_underBufferRateLimit_allLinesAreSent) EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 1\nmock 2\n"), _)).Times(1); EXPECT_CALL(mockServer, send(IpcLogLineMessageEq("mock 3\nmock 4\n"), _)).Times(1); - IpcLogOutputter outputter(mockServer); + IpcLogOutputter outputter(mockServer, false); outputter.bufferRateLimit(4, 1); // 1s (should be plenty of time) // log 1 more line than the buffer can accept in time limit. outputter.write(kNOTE, "mock 1"); outputter.write(kNOTE, "mock 2"); - mockServer.waitForSend(); + outputter.sendBuffer(); // after waiting the time limit send another to make sure // we can log after the time limit passes. outputter.write(kNOTE, "mock 3"); outputter.write(kNOTE, "mock 4"); - mockServer.waitForSend(); + outputter.sendBuffer(); } #endif // WINAPI_MSWINDOWS