ENH: Making smtk::io::Logger Thread-Safe

Added appropriate mutex locks and updated qt code to use Qt:QueuedConnection.

doc/release/notes/io-changes.md

+## I/O Changes
+
+### smtk::io::Logger is now thread-safe
+The class now does a mutex lock when modifying or accessing its records or its underlying stream.  Care must be taking when redirecting the logger's stream to avoid deadlocks.  For example using smtk::extension::qtEmittingStringBuffer, you should make sure to use Qt::QueuedConnection when doing a QObject::connect to the buffer's flush signal.  See smtk/extension/qt/cxx/testing/UnitTestEmittingStringBuffer.{h,cxx} for an example.

smtk/extension/paraview/appcomponents/pqSMTKBehavior.cxx

@@ -76,7 +76,7 @@ pqSMTKBehavior::pqSMTKBehavior(QObject* parent)
 
   // Redirect the singleton smtk::io::Logger::instance() to Qt's I/O stream,
   // which in turn is picked up by ParaView's output widget.
-  smtk::extension::qt::RedirectOutputToQt(smtk::io::Logger::instance());
+  smtk::extension::qt::RedirectOutputToQt(this, smtk::io::Logger::instance());
 }
 
 pqSMTKBehavior* pqSMTKBehavior::instance(QObject* parent)

smtk/extension/qt/RedirectOutput.cxx

@@ -23,7 +23,7 @@ namespace extension
 namespace qt
 {
 
-void RedirectOutputToQt(smtk::io::Logger& log)
+void RedirectOutputToQt(QObject* context, smtk::io::Logger& log)
 {
   qtEmittingStringBuffer* stringBuf = new qtEmittingStringBuffer();
   std::ostream* stream = new std::ostream(stringBuf);
@@ -36,33 +36,35 @@ void RedirectOutputToQt(smtk::io::Logger& log)
   // Connect to the emitting string buffer's flush signal. Since the emitting
   // string buffer is local to the logger and is scoped by its lifetime, we do
   // not need to guard against the logger being out of scope.
-  QObject::connect(stringBuf, &qtEmittingStringBuffer::flush, [&]() {
-    QLoggingCategory smtkCategory("SMTK", QtInfoMsg);
-    for (auto& record : log.records())
-    {
-      switch (record.severity)
+  QObject::connect(stringBuf, &qtEmittingStringBuffer::flush, context,
+    [&]() {
+      QLoggingCategory smtkCategory("SMTK", QtInfoMsg);
+      for (auto& record : log.records())
       {
-        case smtk::io::Logger::DEBUG:
-          qCDebug(smtkCategory) << smtk::io::Logger::toString(record, true).c_str();
-          break;
-        case smtk::io::Logger::INFO:
-          qCInfo(smtkCategory) << smtk::io::Logger::toString(record, false).c_str();
-          break;
-        case smtk::io::Logger::WARNING:
-          qCWarning(smtkCategory) << smtk::io::Logger::toString(record, true).c_str();
-          break;
-        case smtk::io::Logger::ERROR:
-          qCCritical(smtkCategory) << smtk::io::Logger::toString(record, true).c_str();
-          break;
-        case smtk::io::Logger::FATAL:
-        default:
-          qFatal("%s", smtk::io::Logger::toString(record, true).c_str());
-          break;
+        switch (record.severity)
+        {
+          case smtk::io::Logger::DEBUG:
+            qCDebug(smtkCategory) << smtk::io::Logger::toString(record, true).c_str();
+            break;
+          case smtk::io::Logger::INFO:
+            qCInfo(smtkCategory) << smtk::io::Logger::toString(record, false).c_str();
+            break;
+          case smtk::io::Logger::WARNING:
+            qCWarning(smtkCategory) << smtk::io::Logger::toString(record, true).c_str();
+            break;
+          case smtk::io::Logger::ERROR:
+            qCCritical(smtkCategory) << smtk::io::Logger::toString(record, true).c_str();
+            break;
+          case smtk::io::Logger::FATAL:
+          default:
+            qFatal("%s", smtk::io::Logger::toString(record, true).c_str());
+            break;
+        }
       }
-    }
 
-    log.reset();
-  });
+      log.reset();
+    },
+    Qt::QueuedConnection);
 
   log.setFlushToStream(stream, false, false);
   log.setCallback(cleanup);

smtk/extension/qt/RedirectOutput.h

@@ -13,7 +13,7 @@
 #include "smtk/PublicPointerDefs.h"
 
 #include "smtk/extension/qt/Exports.h"
-
+#include <QObject>
 namespace smtk
 {
 namespace io
@@ -30,7 +30,7 @@ namespace qt
 {
 
 //Redirect the output from smtk::io::Logger to Qt's messaging stream.
-SMTKQTEXT_EXPORT void RedirectOutputToQt(smtk::io::Logger& log);
+SMTKQTEXT_EXPORT void RedirectOutputToQt(QObject* context, smtk::io::Logger& log);
 }
 }
 }

smtk/extension/qt/testing/cxx/CMakeLists.txt

@@ -12,6 +12,7 @@
 
   set(unit_tests_headers
     qtPrintLog.h
+    UnitTestEmittingStringBuffer.h
     )
 
   set(unit_tests_headers_data

smtk/extension/qt/testing/cxx/UnitTestEmittingStringBuffer.cxx

@@ -12,11 +12,28 @@
 // .SECTION Description
 // .SECTION See Also
 
+#include "smtk/extension/qt/testing/cxx/UnitTestEmittingStringBuffer.h"
 #include "smtk/extension/qt/qtEmittingStringBuffer.h"
 
 #include "smtk/extension/qt/testing/cxx/qtPrintLog.h"
 
-int UnitTestEmittingStringBuffer(int, char** const)
+#include <QCoreApplication>
+#include <QTime>
+#include <QTimer>
+
+namespace
+{
+void flushEventQueue()
+{
+  QTime dieTime = QTime::currentTime().addMSecs(1);
+  while (QTime::currentTime() < dieTime)
+  {
+    QCoreApplication::processEvents(QEventLoop::AllEvents, 1);
+  }
+}
+}
+
+void TestEmittingStringBuffer::run()
 {
   // Create an instance of Logger
   smtk::io::Logger logger;
@@ -32,13 +49,35 @@ int UnitTestEmittingStringBuffer(int, char** const)
 
   // Create a PrintLogInstance to connect with our EmittingStringBuffer
   qtPrintLog printLog(logger);
-  QObject::connect(&stringbuf, SIGNAL(flush()), &printLog, SLOT(print()));
+  QObject::connect(&stringbuf, SIGNAL(flush()), &printLog, SLOT(print()), Qt::QueuedConnection);
 
   // Test the logger.
   smtkErrorMacro(logger, "this is an error no = " << 45 << " ERROR!");
+  flushEventQueue();
   smtkWarningMacro(logger, "this is a warning no = " << 10.1234 << " WARNING!");
+  flushEventQueue();
   smtkDebugMacro(logger, "this is a Debug no = " << 1 << " DEBUG!");
+  flushEventQueue();
   logger.addRecord(smtk::io::Logger::INFO, "Sample Info String\n");
+  flushEventQueue();
+  emit finished();
+}
+
+int UnitTestEmittingStringBuffer(int argc, char** const argv)
+{
+  QCoreApplication application(argc, argv);
+
+  // Create an instance of our test harness
+  TestEmittingStringBuffer* testEmittingStringBuffer = new TestEmittingStringBuffer(&application);
+
+  // Exit when the task signals finished
+  QObject::connect(testEmittingStringBuffer, &TestEmittingStringBuffer::finished,
+    [&application]() { QTimer::singleShot(0, &application, &QCoreApplication::quit); });
+
+  // Run the task from the application event loop
+  QTimer::singleShot(0, testEmittingStringBuffer, SLOT(run()));
+
+  return application.exec();
 
   return 0;
 }

smtk/extension/qt/testing/cxx/UnitTestEmittingStringBuffer.h

+//=========================================================================
+//  Copyright (c) Kitware, Inc.
+//  All rights reserved.
+//  See LICENSE.txt for details.
+//
+//  This software is distributed WITHOUT ANY WARRANTY; without even
+//  the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR
+//  PURPOSE.  See the above copyright notice for more information.
+//=========================================================================
+
+#ifndef __smtk_extension_qt_testing_cxx_UnitTestEmittingStringBuffer_h
+#define __smtk_extension_qt_testing_cxx_UnitTestEmittingStringBuffer_h
+
+#include <QObject>
+
+class TestEmittingStringBuffer : public QObject
+{
+  Q_OBJECT
+
+public:
+  TestEmittingStringBuffer(QObject* parent)
+    : QObject(parent)
+  {
+  }
+
+signals:
+  void finished();
+
+public slots:
+  void run();
+};
+
+#endif

smtk/io/Logger.cxx

@@ -32,9 +32,18 @@ Logger::~Logger()
   }
 }
 
+Logger& Logger::operator=(const Logger& logger)
+{
+  std::lock_guard<std::mutex> lock(m_mutex);
+  m_records = logger.m_records;
+  m_hasErrors = logger.m_hasErrors;
+  return *this;
+}
+
 void Logger::addRecord(
   Severity s, const std::string& m, const std::string& fname, unsigned int line)
 {
+  std::lock_guard<std::mutex> lock(m_mutex);
   if ((s == Logger::ERROR) || (s == Logger::FATAL))
   {
     m_hasErrors = true;
@@ -52,6 +61,7 @@ void Logger::append(const Logger& l)
     return;
   }
 
+  std::lock_guard<std::mutex> lock(m_mutex);
   m_records.insert(m_records.end(), l.m_records.begin(), l.m_records.end());
   if (l.m_hasErrors)
   {
@@ -63,6 +73,7 @@ void Logger::append(const Logger& l)
 
 void Logger::reset()
 {
+  std::lock_guard<std::mutex> lock(m_mutex);
   m_hasErrors = false;
   m_records.clear();
 }
@@ -107,6 +118,7 @@ std::string Logger::toString(const Logger::Record& record, bool includeSourceLoc
   */
 std::string Logger::toString(std::size_t i, bool includeSourceLoc) const
 {
+  std::lock_guard<std::mutex> lock(m_mutex);
   return this->toString(m_records[i], includeSourceLoc);
 }
 
@@ -114,6 +126,12 @@ std::string Logger::toString(std::size_t i, bool includeSourceLoc) const
   *
   */
 std::string Logger::toString(std::size_t i, std::size_t j, bool includeSourceLoc) const
+{
+  std::lock_guard<std::mutex> lock(m_mutex);
+  return this->toStringInternal(i, j, includeSourceLoc);
+}
+
+std::string Logger::toStringInternal(std::size_t i, std::size_t j, bool includeSourceLoc) const
 {
   std::stringstream ss;
   for (; i < j; i++)
@@ -130,6 +148,7 @@ std::string Logger::toString(std::size_t i, std::size_t j, bool includeSourceLoc
 
 std::string Logger::toHTML(std::size_t i, std::size_t j, bool includeSourceLoc) const
 {
+  std::lock_guard<std::mutex> lock(m_mutex);
   std::stringstream ss;
   ss << "<table>";
   for (; i < j; i++)
@@ -180,6 +199,7 @@ std::string Logger::convertToHTML(bool includeSourceLog) const
   */
 void Logger::setFlushToStream(std::ostream* output, bool ownFile, bool includePast)
 {
+  std::lock_guard<std::mutex> lock(m_mutex);
   if (m_ownStream)
     delete m_stream;
   m_stream = output;
@@ -260,7 +280,7 @@ void Logger::flushRecordsToStream(std::size_t beginRec, std::size_t endRec)
 {
   if (m_stream && beginRec < endRec && beginRec < numberOfRecords() && endRec <= numberOfRecords())
   {
-    (*m_stream) << this->toString(beginRec, endRec);
+    (*m_stream) << this->toStringInternal(beginRec, endRec);
     m_stream->flush();
   }
 }

smtk/io/Logger.h

@@ -15,6 +15,7 @@
 #include "smtk/SystemConfig.h"
 #include <functional>
 #include <iostream>
+#include <mutex>
 #include <sstream>
 #include <string>
 #include <vector>
@@ -120,7 +121,17 @@ public:
     , m_ownStream(false)
   {
   }
+
+  Logger(const Logger& logger)
+    : m_hasErrors(logger.m_hasErrors)
+    , m_records(logger.m_records)
+    , m_ownStream(false)
+  {
+  }
+
   virtual ~Logger();
+
+  Logger& operator=(const Logger& logger);
   std::size_t numberOfRecords() const { return m_records.size(); }
 
   bool hasErrors() const { return m_hasErrors; }
@@ -155,15 +166,17 @@ public:
 
 protected:
   void flushRecordsToStream(std::size_t beginRec, std::size_t endRec);
+  std::string toStringInternal(std::size_t i, std::size_t j, bool includeSourceLoc = false) const;
 
-  std::vector<Record> m_records;
   bool m_hasErrors;
+  std::vector<Record> m_records;
   std::ostream* m_stream;
   bool m_ownStream;
   std::function<void()> m_callback;
 
 private:
   static Logger m_instance;
+  mutable std::mutex m_mutex;
 };
 
 template <typename J>

smtk/io/testing/cxx/CMakeLists.txt

@@ -2,12 +2,13 @@ set(ioTests
   extensibleAttributeIOTest
   fileItemTest
   loggerTest
+  loggerThreadTest
   ResourceSetTest
 )
 
 foreach (test ${ioTests})
   add_executable(${test}  ${test}.cxx)
-  target_link_libraries(${test} smtkCore smtkCoreModelTesting ${Boost_LIBRARIES})
+  target_link_libraries(${test} smtkCore smtkCoreModelTesting ${Boost_LIBRARIES} Threads::Threads)
   add_test(NAME ${test} COMMAND ${test})
   target_compile_definitions(${test} PRIVATE "SMTK_SCRATCH_DIR=\"${CMAKE_BINARY_DIR}/Testing/Temporary\"")
   set_tests_properties(${test} PROPERTIES SKIP_RETURN_CODE 125)

smtk/io/testing/cxx/loggerThreadTest.cxx

+//=========================================================================
+//  Copyright (c) Kitware, Inc.
+//  All rights reserved.
+//  See LICENSE.txt for details.
+//
+//  This software is distributed WITHOUT ANY WARRANTY; without even
+//  the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR
+//  PURPOSE.  See the above copyright notice for more information.
+//=========================================================================
+
+// .NAME Logger.h -
+// .SECTION Description
+// .SECTION See Also
+
+#include "smtk/io/Logger.h"
+#include <chrono>
+#include <iostream>
+#include <thread>
+
+void foo(int i)
+{
+  smtkErrorMacro(smtk::io::Logger::instance(), "Hey I'm running in a thread! - i = " << i);
+}
+int main()
+{
+  std::vector<std::thread> threads;
+  for (int i = 0; i < 10; i++)
+  {
+    threads.emplace_back(std::thread(foo, i));
+  }
+
+  for (auto& th : threads)
+  {
+    th.join();
+  }
+  return 0;
+}