From 4746347fe72134e28f96a1725e59d0249c37181a Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Wed, 20 May 2015 15:23:41 +0100 Subject: [PATCH 01/13] Revert "Stopped Unix plugin loader from throwing #4661" This reverts commit 1fd58836203a37eea81a31ae2d5c4cf64161db88. --- plugin-unix.diff | 15 --------------- 1 file changed, 15 deletions(-) delete mode 100644 plugin-unix.diff diff --git a/plugin-unix.diff b/plugin-unix.diff deleted file mode 100644 index e6e39633..00000000 --- a/plugin-unix.diff +++ /dev/null @@ -1,15 +0,0 @@ -diff --git a/src/lib/arch/unix/ArchPluginUnix.cpp b/src/lib/arch/unix/ArchPluginUnix.cpp -index 997c274..3e390f0 100644 ---- a/src/lib/arch/unix/ArchPluginUnix.cpp -+++ b/src/lib/arch/unix/ArchPluginUnix.cpp -@@ -76,8 +76,8 @@ ArchPluginUnix::load() - void* library = dlopen(path.c_str(), RTLD_LAZY); - - if (library == NULL) { -- LOG((CLOG_ERR "failed to load plugin: %s", (*it).c_str())); -- throw XArch(dlerror()); -+ LOG((CLOG_ERR "failed to load plugin '%s', error: %s", (*it).c_str(), dlerror())); -+ continue; - } - - String filename = synergy::string::removeFileExt(*it); From f1af62927ed66d172bf78a5d45b23bd85a60b83c Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Wed, 20 May 2015 15:24:10 +0100 Subject: [PATCH 02/13] Stopped Unix plugin loader from throwing #4661 Tested on Mac OS X only --- src/lib/arch/unix/ArchPluginUnix.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lib/arch/unix/ArchPluginUnix.cpp b/src/lib/arch/unix/ArchPluginUnix.cpp index 997c2748..3e390f06 100644 --- a/src/lib/arch/unix/ArchPluginUnix.cpp +++ b/src/lib/arch/unix/ArchPluginUnix.cpp @@ -76,8 +76,8 @@ ArchPluginUnix::load() void* library = dlopen(path.c_str(), RTLD_LAZY); if (library == NULL) { - LOG((CLOG_ERR "failed to load plugin: %s", (*it).c_str())); - throw XArch(dlerror()); + LOG((CLOG_ERR "failed to load plugin '%s', error: %s", (*it).c_str(), dlerror())); + continue; } String filename = synergy::string::removeFileExt(*it); From 9636af61d621cc7a1efe7dc6b1669875db78f01c Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Wed, 20 May 2015 15:51:07 +0100 Subject: [PATCH 03/13] Solution attempt for timing bugs in write_bufferRateLimit It's probably better to wait until the buffer is sent, rather than waiting until its empty. To test the output it has to be sent, but because of timing, it may be emptied at any point. --- src/lib/ipc/IpcLogOutputter.cpp | 20 --------------- src/lib/ipc/IpcLogOutputter.h | 2 -- src/test/mock/ipc/MockIpcServer.h | 25 ++++++++++++++++++- .../unittests/ipc/IpcLogOutputterTests.cpp | 11 ++++---- 4 files changed, 29 insertions(+), 29 deletions(-) diff --git a/src/lib/ipc/IpcLogOutputter.cpp b/src/lib/ipc/IpcLogOutputter.cpp index 7474f655..42749d68 100644 --- a/src/lib/ipc/IpcLogOutputter.cpp +++ b/src/lib/ipc/IpcLogOutputter.cpp @@ -46,8 +46,6 @@ IpcLogOutputter::IpcLogOutputter(IpcServer& ipcServer) : m_notifyMutex(ARCH->newMutex()), m_bufferWaiting(false), m_bufferMaxSize(kBufferMaxSize), - m_bufferEmptyCond(ARCH->newCondVar()), - m_bufferEmptyMutex(ARCH->newMutex()), m_bufferRateWriteLimit(kBufferRateWriteLimit), m_bufferRateTimeLimit(kBufferRateTimeLimit), m_bufferWriteCount(0), @@ -66,13 +64,6 @@ IpcLogOutputter::~IpcLogOutputter() ARCH->closeCondVar(m_notifyCond); ARCH->closeMutex(m_notifyMutex); - - ARCH->closeCondVar(m_bufferEmptyCond); - -#ifndef WINAPI_CARBON - // HACK: assert fails on mac debug, can't see why. - ARCH->closeMutex(m_bufferEmptyMutex); -#endif // WINAPI_CARBON } void @@ -172,11 +163,6 @@ IpcLogOutputter::bufferThread(void*) break; } - if (m_buffer.empty()) { - ArchMutexLock lock(m_bufferEmptyMutex); - ARCH->broadcastCondVar(m_bufferEmptyCond); - } - m_bufferWaiting = true; ARCH->waitCondVar(m_notifyCond, m_notifyMutex, -1); m_bufferWaiting = false; @@ -239,12 +225,6 @@ IpcLogOutputter::bufferMaxSize() const return m_bufferMaxSize; } -void -IpcLogOutputter::waitForEmpty() -{ - ARCH->waitCondVar(m_bufferEmptyCond, m_bufferEmptyMutex, -1); -} - void IpcLogOutputter::bufferRateLimit(UInt16 writeLimit, double timeLimit) { diff --git a/src/lib/ipc/IpcLogOutputter.h b/src/lib/ipc/IpcLogOutputter.h index 9b277a03..fb55cfbf 100644 --- a/src/lib/ipc/IpcLogOutputter.h +++ b/src/lib/ipc/IpcLogOutputter.h @@ -106,8 +106,6 @@ private: IArchMultithread::ThreadID m_bufferThreadId; UInt16 m_bufferMaxSize; - ArchCond m_bufferEmptyCond; - ArchMutex m_bufferEmptyMutex; UInt16 m_bufferRateWriteLimit; double m_bufferRateTimeLimit; UInt16 m_bufferWriteCount; diff --git a/src/test/mock/ipc/MockIpcServer.h b/src/test/mock/ipc/MockIpcServer.h index ae63cd34..ccbc99a1 100644 --- a/src/test/mock/ipc/MockIpcServer.h +++ b/src/test/mock/ipc/MockIpcServer.h @@ -19,17 +19,40 @@ #include "ipc/IpcServer.h" #include "ipc/IpcMessage.h" +#include "arch/Arch.h" #include "test/global/gmock.h" +using ::testing::_; +using ::testing::Invoke; + class IEventQueue; class MockIpcServer : public IpcServer { public: - MockIpcServer() { } + MockIpcServer() : + m_sendCond(ARCH->newCondVar()), + m_sendMutex(ARCH->newMutex()) { } MOCK_METHOD0(listen, void()); MOCK_METHOD2(send, void(const IpcMessage&, EIpcClientType)); MOCK_CONST_METHOD1(hasClients, bool(EIpcClientType)); + + void delegateToFake() { + ON_CALL(*this, send(_, _)).WillByDefault(Invoke(this, &MockIpcServer::mockSend)); + } + + void waitForSend() { + ARCH->waitCondVar(m_sendCond, m_sendMutex, -1); + } + +private: + void mockSend(const IpcMessage&, EIpcClientType) { + ArchMutexLock lock(m_sendMutex); + ARCH->broadcastCondVar(m_sendCond); + } + + ArchCond m_sendCond; + ArchMutex m_sendMutex; }; diff --git a/src/test/unittests/ipc/IpcLogOutputterTests.cpp b/src/test/unittests/ipc/IpcLogOutputterTests.cpp index 18f1eb21..449ebf6e 100644 --- a/src/test/unittests/ipc/IpcLogOutputterTests.cpp +++ b/src/test/unittests/ipc/IpcLogOutputterTests.cpp @@ -48,6 +48,7 @@ inline const Matcher IpcLogLineMessageEq(const String& s) { TEST(IpcLogOutputterTests, write_bufferSizeWrapping) { MockIpcServer mockServer; + mockServer.delegateToFake(); ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); @@ -61,14 +62,13 @@ TEST(IpcLogOutputterTests, write_bufferSizeWrapping) outputter.write(kNOTE, "mock 1"); outputter.write(kNOTE, "mock 2"); outputter.write(kNOTE, "mock 3"); - - // wait for the buffer to be empty (all lines sent to IPC) - outputter.waitForEmpty(); + mockServer.waitForSend(); } TEST(IpcLogOutputterTests, write_bufferRateLimit) { MockIpcServer mockServer; + mockServer.delegateToFake(); ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); @@ -82,14 +82,13 @@ TEST(IpcLogOutputterTests, write_bufferRateLimit) // log 1 more line than the buffer can accept in time limit. outputter.write(kNOTE, "mock 1"); outputter.write(kNOTE, "mock 2"); - outputter.waitForEmpty(); + mockServer.waitForSend(); // after waiting the time limit send another to make sure // we can log after the time limit passes. - ARCH->sleep(0.01); // 10ms outputter.write(kNOTE, "mock 3"); outputter.write(kNOTE, "mock 4"); - outputter.waitForEmpty(); + mockServer.waitForSend(); } #endif // WINAPI_MSWINDOWS From a710b2752b578b3d1d905a814881ab234a2dc7bf Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Wed, 20 May 2015 16:07:09 +0100 Subject: [PATCH 04/13] Reintroduced sleep for really fast computers #4624 --- src/test/unittests/ipc/IpcLogOutputterTests.cpp | 1 + 1 file changed, 1 insertion(+) diff --git a/src/test/unittests/ipc/IpcLogOutputterTests.cpp b/src/test/unittests/ipc/IpcLogOutputterTests.cpp index 449ebf6e..14720fa7 100644 --- a/src/test/unittests/ipc/IpcLogOutputterTests.cpp +++ b/src/test/unittests/ipc/IpcLogOutputterTests.cpp @@ -86,6 +86,7 @@ TEST(IpcLogOutputterTests, write_bufferRateLimit) // after waiting the time limit send another to make sure // we can log after the time limit passes. + ARCH->sleep(0.002); // 2ms outputter.write(kNOTE, "mock 3"); outputter.write(kNOTE, "mock 4"); mockServer.waitForSend(); From 89a977da663c3b8f3621b3758d467fcb2b85a56b Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Wed, 20 May 2015 16:16:22 +0100 Subject: [PATCH 05/13] Positive tests for IPC logging #4624 So far I had only tested what happens when the limits are exceeded. These new tests are for when usage is within limits. --- .../unittests/ipc/IpcLogOutputterTests.cpp | 49 ++++++++++++++++++- 1 file changed, 47 insertions(+), 2 deletions(-) diff --git a/src/test/unittests/ipc/IpcLogOutputterTests.cpp b/src/test/unittests/ipc/IpcLogOutputterTests.cpp index 14720fa7..48eaad1f 100644 --- a/src/test/unittests/ipc/IpcLogOutputterTests.cpp +++ b/src/test/unittests/ipc/IpcLogOutputterTests.cpp @@ -45,7 +45,7 @@ inline const Matcher IpcLogLineMessageEq(const String& s) { return MatcherCast(m); } -TEST(IpcLogOutputterTests, write_bufferSizeWrapping) +TEST(IpcLogOutputterTests, write_overBufferMaxSize_firstLineTruncated) { MockIpcServer mockServer; mockServer.delegateToFake(); @@ -65,7 +65,26 @@ TEST(IpcLogOutputterTests, write_bufferSizeWrapping) mockServer.waitForSend(); } -TEST(IpcLogOutputterTests, write_bufferRateLimit) +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) { MockIpcServer mockServer; mockServer.delegateToFake(); @@ -92,4 +111,30 @@ TEST(IpcLogOutputterTests, write_bufferRateLimit) mockServer.waitForSend(); } +TEST(IpcLogOutputterTests, write_underBufferRateLimit_allLinesAreSent) +{ + MockIpcServer mockServer; + mockServer.delegateToFake(); + + ON_CALL(mockServer, hasClients(_)).WillByDefault(Return(true)); + + EXPECT_CALL(mockServer, hasClients(_)).Times(2); + 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); + 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(); + + // 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(); +} + #endif // WINAPI_MSWINDOWS From 561204b2a795c750a73385a39bf28fa7ec739077 Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Wed, 20 May 2015 17:42:07 +0100 Subject: [PATCH 06/13] 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 From 950219b39e1a7907cf359f5d2fc6dbf40bfcbafc Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Wed, 20 May 2015 17:51:52 +0100 Subject: [PATCH 07/13] Fixed init order warning on Mac #4624 --- src/lib/ipc/IpcLogOutputter.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/lib/ipc/IpcLogOutputter.cpp b/src/lib/ipc/IpcLogOutputter.cpp index 4f7b63fa..6ce8d774 100644 --- a/src/lib/ipc/IpcLogOutputter.cpp +++ b/src/lib/ipc/IpcLogOutputter.cpp @@ -41,8 +41,8 @@ IpcLogOutputter::IpcLogOutputter(IpcServer& ipcServer, bool useThread) : m_ipcServer(ipcServer), m_bufferMutex(ARCH->newMutex()), m_sending(false), - m_running(false), m_bufferThread(nullptr), + m_running(false), m_notifyCond(ARCH->newCondVar()), m_notifyMutex(ARCH->newMutex()), m_bufferWaiting(false), From 994a9433fe3cfe085bc97fa89ca937aca36418c2 Mon Sep 17 00:00:00 2001 From: Adam Potolsky Date: Wed, 20 May 2015 12:08:25 -0700 Subject: [PATCH 08/13] Converting retry to a counter #4650 --- src/lib/plugin/ns/SecureSocket.cpp | 33 ++++++++++++++++++++---------- src/lib/plugin/ns/SecureSocket.h | 2 +- 2 files changed, 23 insertions(+), 12 deletions(-) diff --git a/src/lib/plugin/ns/SecureSocket.cpp b/src/lib/plugin/ns/SecureSocket.cpp index ad75e3c4..dd2937ca 100644 --- a/src/lib/plugin/ns/SecureSocket.cpp +++ b/src/lib/plugin/ns/SecureSocket.cpp @@ -111,7 +111,9 @@ SecureSocket::secureRead(void* buffer, UInt32 n) LOG((CLOG_DEBUG2 "reading secure socket")); r = SSL_read(m_ssl->m_ssl, buffer, n); - bool fatal, retry; + bool fatal; + static int retry; + checkResult(r, fatal, retry); if (retry) { @@ -130,7 +132,9 @@ SecureSocket::secureWrite(const void* buffer, UInt32 n) LOG((CLOG_DEBUG2 "writing secure socket")); r = SSL_write(m_ssl->m_ssl, buffer, n); - bool fatal, retry; + bool fatal; + static int retry; + checkResult(r, fatal, retry); if (retry) { @@ -253,7 +257,9 @@ SecureSocket::secureAccept(int socket) LOG((CLOG_DEBUG2 "accepting secure socket")); int r = SSL_accept(m_ssl->m_ssl); - bool fatal, retry; + bool fatal; + static int retry; + checkResult(r, fatal, retry); if (fatal) { @@ -263,12 +269,13 @@ SecureSocket::secureAccept(int socket) ARCH->sleep(1); } - m_secureReady = !retry; + m_secureReady = (0 == retry) ? true : false; + if (m_secureReady) { LOG((CLOG_INFO "accepted secure socket")); } - return retry; + return !m_secureReady; } bool @@ -282,7 +289,9 @@ SecureSocket::secureConnect(int socket) LOG((CLOG_DEBUG2 "connecting secure socket")); int r = SSL_connect(m_ssl->m_ssl); - bool fatal, retry; + bool fatal; + static int retry; + checkResult(r, fatal, retry); if (fatal) { @@ -291,7 +300,7 @@ SecureSocket::secureConnect(int socket) return false; } - m_secureReady = !retry; + m_secureReady = (0 == retry) ? true : false; if (m_secureReady) { if (verifyCertFingerprint()) { @@ -306,7 +315,7 @@ SecureSocket::secureConnect(int socket) } } - return retry; + return !m_secureReady; } bool @@ -332,22 +341,23 @@ SecureSocket::showCertificate() } void -SecureSocket::checkResult(int n, bool& fatal, bool& retry) +SecureSocket::checkResult(int n, bool& fatal, int& retry) { // ssl errors are a little quirky. the "want" errors are normal and // should result in a retry. fatal = false; - retry = false; int errorCode = SSL_get_error(m_ssl->m_ssl, n); switch (errorCode) { case SSL_ERROR_NONE: + retry = 0; // operation completed break; case SSL_ERROR_ZERO_RETURN: // connection closed + retry = 0; LOG((CLOG_DEBUG2 "SSL connection has been closed")); break; @@ -356,7 +366,7 @@ SecureSocket::checkResult(int n, bool& fatal, bool& retry) case SSL_ERROR_WANT_CONNECT: case SSL_ERROR_WANT_ACCEPT: LOG((CLOG_DEBUG2 "need to retry the same SSL function")); - retry = true; + retry += 1; break; case SSL_ERROR_SYSCALL: @@ -391,6 +401,7 @@ SecureSocket::checkResult(int n, bool& fatal, bool& retry) } if (fatal) { + retry = 0; showError(); disconnect(); } diff --git a/src/lib/plugin/ns/SecureSocket.h b/src/lib/plugin/ns/SecureSocket.h index 72bc51db..ba1f1df0 100644 --- a/src/lib/plugin/ns/SecureSocket.h +++ b/src/lib/plugin/ns/SecureSocket.h @@ -58,7 +58,7 @@ private: bool secureAccept(int s); bool secureConnect(int s); bool showCertificate(); - void checkResult(int n, bool& fatal, bool& retry); + void checkResult(int n, bool& fatal, int& retry); void showError(const char* reason = NULL); String getError(); void disconnect(); From 81a70135bd7bda6d97d77728131f4cbca7906d68 Mon Sep 17 00:00:00 2001 From: Adam Potolsky Date: Wed, 20 May 2015 13:50:18 -0700 Subject: [PATCH 09/13] Added concept of a max retry count to SecureSocket class #4650 --- src/lib/plugin/ns/SecureSocket.cpp | 7 +++++-- src/lib/plugin/ns/SecureSocket.h | 3 +++ 2 files changed, 8 insertions(+), 2 deletions(-) diff --git a/src/lib/plugin/ns/SecureSocket.cpp b/src/lib/plugin/ns/SecureSocket.cpp index dd2937ca..362bcce6 100644 --- a/src/lib/plugin/ns/SecureSocket.cpp +++ b/src/lib/plugin/ns/SecureSocket.cpp @@ -35,6 +35,7 @@ // #define MAX_ERROR_SIZE 65535 +#define MAX_RETRY_COUNT 60 static const char kFingerprintDirName[] = "SSL/Fingerprints"; //static const char kFingerprintLocalFilename[] = "Local.txt"; @@ -50,7 +51,8 @@ SecureSocket::SecureSocket( IEventQueue* events, SocketMultiplexer* socketMultiplexer) : TCPSocket(events, socketMultiplexer), - m_secureReady(false) + m_secureReady(false), + m_maxRetry(MAX_RETRY_COUNT) { } @@ -59,7 +61,8 @@ SecureSocket::SecureSocket( SocketMultiplexer* socketMultiplexer, ArchSocket socket) : TCPSocket(events, socketMultiplexer, socket), - m_secureReady(false) + m_secureReady(false), + m_maxRetry(MAX_RETRY_COUNT) { } diff --git a/src/lib/plugin/ns/SecureSocket.h b/src/lib/plugin/ns/SecureSocket.h index ba1f1df0..754956ca 100644 --- a/src/lib/plugin/ns/SecureSocket.h +++ b/src/lib/plugin/ns/SecureSocket.h @@ -50,6 +50,8 @@ public: UInt32 secureWrite(const void* buffer, UInt32 n); void initSsl(bool server); bool loadCertificates(String& CertFile); + void maxRetry(int limit) { m_maxRetry = limit; }; + int maxRetry() const { return m_maxRetry; }; private: // SSL @@ -78,4 +80,5 @@ private: private: Ssl* m_ssl; bool m_secureReady; + int m_maxRetry; }; From 1af9d58a9b210fb8fc2d154c4939634f79f113dc Mon Sep 17 00:00:00 2001 From: Adam Potolsky Date: Wed, 20 May 2015 14:14:30 -0700 Subject: [PATCH 10/13] Changed conditional to match coding standard #4650 --- src/lib/plugin/ns/SecureSocket.cpp | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/src/lib/plugin/ns/SecureSocket.cpp b/src/lib/plugin/ns/SecureSocket.cpp index 362bcce6..94deca8a 100644 --- a/src/lib/plugin/ns/SecureSocket.cpp +++ b/src/lib/plugin/ns/SecureSocket.cpp @@ -272,7 +272,12 @@ SecureSocket::secureAccept(int socket) ARCH->sleep(1); } - m_secureReady = (0 == retry) ? true : false; + if (retry == 0) { + m_secureReady = true; + } + else { + m_secureReady = false; + } if (m_secureReady) { LOG((CLOG_INFO "accepted secure socket")); @@ -303,7 +308,12 @@ SecureSocket::secureConnect(int socket) return false; } - m_secureReady = (0 == retry) ? true : false; + if (retry == 0) { + m_secureReady = true; + } + else { + m_secureReady = false; + } if (m_secureReady) { if (verifyCertFingerprint()) { From ad86041433ad4e0e9c8e7ba0326705bc28c3afd7 Mon Sep 17 00:00:00 2001 From: Adam Potolsky Date: Wed, 20 May 2015 14:27:25 -0700 Subject: [PATCH 11/13] Added code to test for and error out of max retry condition #4650 --- src/lib/plugin/ns/SecureSocket.cpp | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/src/lib/plugin/ns/SecureSocket.cpp b/src/lib/plugin/ns/SecureSocket.cpp index 94deca8a..7d7c9a83 100644 --- a/src/lib/plugin/ns/SecureSocket.cpp +++ b/src/lib/plugin/ns/SecureSocket.cpp @@ -378,8 +378,8 @@ SecureSocket::checkResult(int n, bool& fatal, int& retry) case SSL_ERROR_WANT_WRITE: case SSL_ERROR_WANT_CONNECT: case SSL_ERROR_WANT_ACCEPT: - LOG((CLOG_DEBUG2 "need to retry the same SSL function")); retry += 1; + LOG((CLOG_DEBUG2 "need to retry the same SSL function retry:%d", retry)); break; case SSL_ERROR_SYSCALL: @@ -413,6 +413,12 @@ SecureSocket::checkResult(int n, bool& fatal, int& retry) break; } + // If the retry max would exceed the allowed, treat it as a fatal error + if (retry > maxRetry()) { + LOG((CLOG_ERR "Maximum retry count exceeded:%d",retry)); + fatal = true; + } + if (fatal) { retry = 0; showError(); From 68ecdc07535ea9b22014bcfd38a7c7372c432903 Mon Sep 17 00:00:00 2001 From: Adam Potolsky Date: Wed, 20 May 2015 16:54:42 -0700 Subject: [PATCH 12/13] Added additional logging to help debug potential problems related to performance and SSL WAIT states #4650 --- src/lib/plugin/ns/SecureSocket.cpp | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/src/lib/plugin/ns/SecureSocket.cpp b/src/lib/plugin/ns/SecureSocket.cpp index 7d7c9a83..f182ee8a 100644 --- a/src/lib/plugin/ns/SecureSocket.cpp +++ b/src/lib/plugin/ns/SecureSocket.cpp @@ -379,7 +379,16 @@ SecureSocket::checkResult(int n, bool& fatal, int& retry) case SSL_ERROR_WANT_CONNECT: case SSL_ERROR_WANT_ACCEPT: retry += 1; - LOG((CLOG_DEBUG2 "need to retry the same SSL function retry:%d", retry)); + // If there are a lot of retrys, it's worth warning about + if ( retry % 5 == 0 ) { + LOG((CLOG_INFO "need to retry the same SSL function(%d) retry:%d", errorCode, retry)); + } + else if ( retry == (maxRetry() / 2) ) { + LOG((CLOG_WARN "need to retry the same SSL function(%d) retry:%d", errorCode, retry)); + } + else { + LOG((CLOG_DEBUG2 "need to retry the same SSL function(%d) retry:%d", errorCode, retry)); + } break; case SSL_ERROR_SYSCALL: From 0de7a08b4cfeb376bf8802e711b99459bf109dc7 Mon Sep 17 00:00:00 2001 From: Nick Bolton Date: Thu, 21 May 2015 16:49:07 +0100 Subject: [PATCH 13/13] Updated wizard version to '4' to force plugin download #4529 --- src/gui/src/AppConfig.h | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/gui/src/AppConfig.h b/src/gui/src/AppConfig.h index f9ed71c0..3a304b91 100644 --- a/src/gui/src/AppConfig.h +++ b/src/gui/src/AppConfig.h @@ -31,8 +31,10 @@ // 1: first version // 2: added language page // 3: added premium page and removed +// 4: ssl plugin 'ns' introduced +// 5: ssl plugin 'ns' updated // -const int kWizardVersion = 4; +const int kWizardVersion = 5; class QSettings; class SettingsDialog;