Add LoggingModule including tests and documentation.

CMakeLists.txt

@@ -165,6 +165,7 @@ target_link_libraries(${PROJECT_NAME} ${mtca4u-deviceaccess_LIBRARIES}
 set_property(TARGET ${PROJECT_NAME} PROPERTY INSTALL_RPATH_USE_LINK_PATH TRUE)
 
 # add a target to generate API documentation with Doxygen
+configure_file(${CMAKE_CURRENT_SOURCE_DIR}/cmake/main.dox.in ${CMAKE_CURRENT_BINARY_DIR}/main.dox @ONLY)
 include(cmake/enable_doxygen_documentation.cmake)
 
 # Install the library and the executables

Modules/include/Logging.h

+/*!
+ * \author Klaus Zenker (HZDR)
+ * \date 03.04.2018
+ * \page loggingdoc Logging module and Logger
+ * \section into Introduction to the logging mechanism
+ * The logging provided here requires to add the LoggingModule to your Application.
+ * The module introduces the following input variables, that need to be connected to the control system:
+ * - targetStream: Allows to choose where messages send to the logging module end up:
+ *   - 0: cout/cerr+logfile
+ *   - 1: logfile
+ *   - 2: cout/cerr
+ *   - 3: nowhere
+ * - logFile: Give the logfile name. If the file is not empty logging messages will be appended. If
+ *   you choose targetStream 0 or 1 and don't set a logFile the Logging module simply skips the file
+ *   writing.
+ * - logLevel: Choose a certain logging level of the Module. Messages send to the Logging module also include a logging
+ *   level. The Logging module compares both levels and decides if a message is dropped (e.g. message level is
+ *   DEBUG and Module level is ERROR) or broadcasted.
+ * - tailLength: The number of messages published by the Logging module (see logTail), i.e. to the control system.
+ *   This length has no influence on the targetStreams, that receive all messages (depending on the logLevel). The
+ *   logLevel also applies to messages that are published by the Logging module via the logTail
+ *
+ * Available logging levels are:
+ *  - DEBUG
+ *  - INFO
+ *  - WARNING
+ *  - ERROR
+ *  - SILENT
+ *
+ *  The only variable that is published by the Logging module is the logTail. It contains the list of latest messages.
+ *  Messages are separated by a newline character. The number of messages published in the logTail is set via the
+ *  input variable tailLength. Other than that, messages are written to cout/cerr and/or a log file as explained above.
+ *
+ *  In order to add a source to the Logging module the method \c addSource(Logger*) is
+ *  available.
+ *  The foreseen way of using the Logger is to add a Logger to a module that should send log messages.
+ *  In the definition of connections of the application (\c defineConnections() ) one can add this source to the Logging module.
+ *
+ *  The following example shows how to integrate the Logging module and the Logging into an application (myApp) and one module sending
+ *  messages (TestModule).
+ *  \code
+ *  sruct TestModule: public ChimeraTK::ApplicationModule{
+ *  Logger{this};
+ *  ...
+ *  };
+ *  struct myApp : public ChimeraTK::Application{
+ *
+ *  LoggingModule log { this, "LoggingModule", "LoggingModule test" };
+ *
+ *  ChimeraTK::ControlSystemModule cs;
+ *
+ *  TestModule { this, "test", "" };
+ *  ...
+ *  };
+ *
+ *
+ *  void myAPP::defineConnctions(){
+ *  cs["Logging"]("targetStream") >> log.targetStream;
+ *  cs["Logging"]("logLevel") >> log.logLevel;
+ *  cs["Logging"]("logFile") >> log.logFile;
+ *  cs["Logging"]("tailLength") >> log.tailLength;
+ *  log.addSource(&TestModule.logger)
+ *  ...
+ *  }
+ *
+ *  void TestModule::mainLoop{
+ *    logger.sendMessage("Test",LogLevel::DEBUG);
+ *    ...
+ *  }
+ *  \endcode
+ *
+ *  A message always looks like this:
+ *  LogLevel::LoggingModuleName/SendingModuleName TimeString -> message\n
+ *  In the example given above the meassge could look like:
+ *  \code
+ *  DEBUG::LogggingModule/test 2018-Apr-12 14:03:07.947949 -> Test
+ *  \endcode
+ *  \remark Instead of adding a Logger to every module that should feed the Logging module, one could also consider using only one Logger object.
+ *  This is not thread safe and would not work for multiple modules trying to send messages via the Logger object to the Logging module at the same time.
+
+ */
+
+
+#ifndef MODULES_LOGGING_H_
+#define MODULES_LOGGING_H_
+
+#undef GENERATE_XML
+#include <ChimeraTK/ApplicationCore/ApplicationCore.h>
+
+namespace ctk = ChimeraTK;
+
+namespace logging{
+
+/** Pair of message and messageLevel */
+using Message = std::pair<ctk::ScalarPushInput<std::string>,ctk::ScalarPushInput<uint> >;
+
+/** Define available logging levels. */
+enum LogLevel { DEBUG, INFO, WARNING, ERROR, SILENT };
+
+/** Define stream operator to use the LogLevel in streams, e.g. std::cout */
+std::ostream& operator<<(std::ostream& os, const LogLevel &level);
+
+/** Construct a sting containing the current time. */
+std::string getTime();
+
+/**
+ * \brief Class used to send messages in a convenient way to the LoggingModule.
+ *
+ * In principle this class only adds two output variables and provides simple method
+ * to fill these variables. They are supposed to be connected to the LoggingModule via LoggingModule::addSource.
+ */
+class Logger{
+public:
+  /**
+   * \brief Default constructor: Allows late initialization of modules (e.g. when creating arrays of modules).
+   *
+   *  This constructor also has to be here to mitigate a bug in gcc. It is needed to allow constructor
+   *  inheritance of modules owning other modules. This constructor will not actually be called then.
+   *  See this bug report: https://gcc.gnu.org/bugzilla/show_bug.cgi?id=67054 */
+  Logger(){};
+
+  /**
+   * \brief Constructor to be used.
+   *
+   * \param module The owning module that is using the Logger. It will appear as sender in the LoggingModule,
+   * which is receiving messages from the Logger.
+   */
+  Logger(ctk::Module *module);
+  /** Message to be send to the logging module */
+  std::unique_ptr<ctk::ScalarOutput<std::string> > message;
+
+  /** Message to be send to the logging module */
+  std::unique_ptr<ctk::ScalarOutput<uint> > messageLevel;
+
+  /**
+   * \brief Send a message, which means to update the message and messageLevel member variables.
+   *
+   */
+  void sendMessage(const std::string &msg, const logging::LogLevel &level);
+};
+
+/**
+ * \brief Module used to handle logging messages.
+ *
+ * A ChimeraTK module is producing messages, that are send to the LoggingModule
+ * via the \c message variable. The message is then put into the logfile ring buffer
+ * and published in the \c LogFileTail. In addidtion the message can be put to an ostream.
+ * Available streams are:
+ * - file stream
+ * - cout/cerr
+ *
+ * You can control which stream is used by setting the targetStream varibale:
+ * 0: cout/cerr and logfile
+ * 1: logfile
+ * 2: cout/cerr
+ * 3: none
+ *
+ * The logfile is given by the client using the logFile variable.
+ */
+class LoggingModule: public ctk::ApplicationModule {
+private:
+  std::pair<ctk::VariableNetworkNode,ctk::VariableNetworkNode> getAccessorPair(const std::string &sender);
+
+  /** Map key is the feeding module */
+  std::map<std::string,Message> msg_list;
+
+  /** Update message or messageLevel from the sending module
+   * Basically the first element read by readAny() could be either the message or
+   * the messageLevel.
+   * Here the element not updated by readSAny is also read, since both are PushInput variables.
+   */
+  std::map<std::string, Message>::iterator UpdatePair(const mtca4u::TransferElementID &id);
+
+  /** Number of messages stored in the tail */
+  size_t messageCounter;
+
+  /** Broadcast message to cout/cerr and log file
+   * \param msg The mesage
+   * \param isError If true cerr is used. Else cout is used.
+   */
+  void broadcastMessage(std::string msg, bool isError = false);
+
+public:
+  using ctk::ApplicationModule::ApplicationModule;
+
+  ctk::ScalarPollInput<uint> targetStream { this, "targetStream", "",
+          "Set the tagret stream: 0 (cout/cerr+logfile), 1 (logfile), 2 (cout/cerr), 3 (none)" };
+
+  ctk::ScalarPollInput<std::string> logFile { this, "Logfile", "",
+    "Name of the external logfile. If empty messages are pushed to cout/cerr" };
+
+  ctk::ScalarPollInput<uint> tailLength { this, "maxLength", "",
+      "Maximum number of messages to be shown in the logging stream tail." };
+
+  ctk::ScalarPollInput<uint> logLevel { this, "logLevel", "",
+      "Current log level used for messages." };
+
+  ctk::ScalarOutput<std::string> logTail { this, "LogTail", "", "Tail of the logging stream.",
+      { "CS", "PROCESS", getName() } };
+
+  std::unique_ptr<std::ofstream> file; ///< Log file where to write log messages
+
+  /** Add a Module as a source to this DAQ. */
+  void addSource(Logger *logger);
+
+  /**
+   * Application core main loop.
+   */
+  void mainLoop() override;
+
+  void terminate() override;
+
+};
+
+}
+
+#endif /* MODULES_LOGGING_H_ */

Modules/src/Logging.cc

+/*
+ * Logging.cc
+ *
+ *  Created on: Apr 3, 2018
+ *      Author: zenker
+ */
+
+#include <string>
+#include <sstream>
+#include <ostream>
+#include <vector>
+
+#include "boost/date_time/posix_time/posix_time.hpp"
+#include "Logging.h"
+
+using namespace logging;
+
+std::ostream& logging::operator<<(std::ostream &os,const LogLevel &level){
+  switch(level){
+    case LogLevel::DEBUG:
+      os << "DEBUG::";
+      break;
+    case LogLevel::INFO:
+      os << "INFO::";
+      break;
+    case LogLevel::WARNING:
+      os << "WARNING::";
+      break;
+    case LogLevel::ERROR:
+      os << "ERROR::";
+      break;
+    default:
+      break;
+  }
+  return os;
+}
+
+std::string logging::getTime(){
+  std::string str;
+  str.append(boost::posix_time::to_simple_string(boost::posix_time::microsec_clock::local_time()) + " ");
+  str.append(" -> ");
+  return str;
+}
+
+Logger::Logger(ctk::Module* module){
+  message.reset(new ctk::ScalarOutput<std::string>{module, "message", "", "Message of the module to the logging System",
+      { "Logging", "OneWire", module->getName() } });
+  messageLevel.reset(new ctk::ScalarOutput<uint>{module,  "messageLevel", "", "Logging level of the message",
+      { "Logging", "OneWire", module->getName() } });
+}
+
+void Logger::sendMessage(const std::string &msg, const logging::LogLevel &level){
+  *message = msg + "\n";
+  *messageLevel = level;
+  message->write();
+  messageLevel->write();
+}
+
+void LoggingModule::broadcastMessage(std::string msg, bool isError){
+  if(msg.back() != '\n'){
+    msg.append("\n");
+  }
+  std::string tmpLog  = (std::string)logTail;
+  if( tailLength == 0 && messageCounter > 20){
+    messageCounter--;
+    tmpLog = tmpLog.substr(tmpLog.find_first_of("\n")+1, tmpLog.length());
+  } else if (tailLength > 0){
+    while(messageCounter >= tailLength){
+      messageCounter--;
+      tmpLog = tmpLog.substr(tmpLog.find_first_of("\n")+1, tmpLog.length());
+    }
+  }
+  if(targetStream == 0 || targetStream == 2){
+    if(isError)
+      std::cerr << msg;
+    else
+      std::cout << msg;
+  }
+  if(targetStream == 0 || targetStream == 1){
+    if(file->is_open()){
+      (*file) << msg.c_str();
+      file->flush();
+    }
+  }
+  tmpLog.append(msg);
+  messageCounter++;
+  logTail = tmpLog;
+  logTail.write();
+}
+
+void LoggingModule::mainLoop(){
+  file.reset(new std::ofstream());
+  messageCounter = 0;
+  std::stringstream greeter;
+  greeter << getName() << " " << getTime() << "There are " << msg_list.size() << " modules registered for logging:" << std::endl;
+  broadcastMessage(greeter.str());
+  for(auto &module : msg_list){
+    broadcastMessage(std::string("\t - ") + module.first);
+  }
+  while(1){
+    auto id = readAny();
+    auto sender = UpdatePair(id);
+    if(targetStream == 3)
+      continue;
+    LogLevel level = static_cast<LogLevel>((uint)sender->second.second);
+    LogLevel setLevel = static_cast<LogLevel>((uint)logLevel);
+    std::stringstream ss;
+    ss << level << getName() << "/" << sender->first << " " << getTime() << (std::string)sender->second.first;
+    if(targetStream == 0 || targetStream == 1){
+      if(!((std::string)logFile).empty() && !file->is_open()){
+        file->open((std::string)logFile,  std::ofstream::out | std::ofstream::app);
+        std::stringstream ss_file;
+        if(!file->is_open() && setLevel <= LogLevel::ERROR){
+          ss_file << LogLevel::ERROR << getName() << " " << getTime() << "Failed to open log file for writing: " << (std::string)logFile << std::endl;
+          broadcastMessage(ss_file.str(), true);
+        } else if (file->is_open() && setLevel <= LogLevel::INFO){
+          ss_file << LogLevel::INFO << getName() << " " << getTime() <<  "Opened log file for writing: " << (std::string)logFile << std::endl;
+          broadcastMessage(ss_file.str());
+        }
+
+      }
+    }
+    if(level >= setLevel){
+      if(level < LogLevel::ERROR)
+        broadcastMessage(ss.str());
+      else
+        broadcastMessage(ss.str(), true);
+    }
+  }
+}
+
+void LoggingModule::addSource(Logger *logger){
+  auto acc = getAccessorPair(logger->message->getOwner()->getName());
+  *logger->message.get() >> acc.first;
+  *logger->messageLevel.get() >> acc.second;
+}
+
+std::pair<ctk::VariableNetworkNode,ctk::VariableNetworkNode> LoggingModule::getAccessorPair(const std::string &sender) {
+  if(msg_list.count(sender) == 0){
+    msg_list.emplace(std::piecewise_construct, std::make_tuple(sender),std::forward_as_tuple(
+      std::piecewise_construct,
+      std::forward_as_tuple(ctk::ScalarPushInput<std::string>{this, sender + "Msg", "", ""}),
+      std::forward_as_tuple(ctk::ScalarPushInput<uint>{this, sender + "MsgLevel", "", ""})));
+  } else {
+    throw ctk::ApplicationExceptionWithID<ctk::ApplicationExceptionID::illegalVariableNetwork>("Cannot add logging for module "+sender+
+      " since logging was already added for this module.");
+  }
+  return msg_list[sender];
+}
+
+std::map<std::string, Message>::iterator LoggingModule::UpdatePair(const mtca4u::TransferElementID &id){
+  for(auto it = msg_list.begin(), iend = msg_list.end(); it != iend; it++){
+    if(it->second.first.getId() == id){
+      it->second.second.read();
+      return it;
+    }
+    if(it->second.second.getId() == id){
+      it->second.first.read();
+      return it;
+    }
+  }
+  throw ctk::ApplicationExceptionWithID<ctk::ApplicationExceptionID::illegalVariableNetwork>("Cannot find  element id"
+        "when updating logging variables.");
+}
+
+void LoggingModule::terminate(){
+  if((file.get() != nullptr) && (file->is_open()))
+    file->close();
+  ApplicationModule::terminate();
+}
+
+

cmake/Doxyfile.in

@@ -784,7 +784,8 @@ WARN_LOGFILE           =
 INPUT                  = @CMAKE_CURRENT_SOURCE_DIR@/src \
                          @CMAKE_CURRENT_SOURCE_DIR@/include \
                          @CMAKE_CURRENT_SOURCE_DIR@/Modules/src \
-                         @CMAKE_CURRENT_SOURCE_DIR@/Modules/include
+                         @CMAKE_CURRENT_SOURCE_DIR@/Modules/include \
+                         @CMAKE_CURRENT_BINARY_DIR@/main.dox
 
 # This tag can be used to specify the character encoding of the source files
 # that doxygen parses. Internally doxygen uses the UTF-8 encoding. Doxygen uses

cmake/main.dox.in

+/**
+* \mainpage
+* Module documentation:
+* - \subpage loggingdoc
+*/

tests/executables_src/testLogging.cc

+/*
+ * testLogging.cc
+ *
+ *  Created on: Apr 11, 2018
+ *      Author: zenker
+ */
+
+//#define BOOST_TEST_DYN_LINK
+#define BOOST_TEST_MODULE ProcessModuleTest
+
+#include <fstream>
+
+#include <boost/filesystem.hpp>
+#include <boost/algorithm/string.hpp>
+#include <boost/test/included/unit_test.hpp>
+#include <boost/test/test_case_template.hpp>
+#include <boost/thread.hpp>
+
+#include "Logging.h"
+using namespace logging;
+
+#include "ChimeraTK/ApplicationCore/TestFacility.h"
+
+#include <boost/test/unit_test.hpp>
+using namespace boost::unit_test_framework;
+
+/**
+ * Define a test app to test the SoftwareMasterModule.
+ */
+struct testApp : public ChimeraTK::Application {
+  testApp() : Application("test"), fileCreated(false){ }
+  ~testApp() {
+    shutdown();
+    if(fileCreated){
+      BOOST_CHECK_EQUAL(boost::filesystem::remove("/tmp/testLogging/test.log"), true);
+      BOOST_CHECK_EQUAL(boost::filesystem::remove("/tmp/testLogging/"), true);
+    }
+  }
+
+  LoggingModule log { this, "LoggingModule",
+      "LoggingModule test" };
+
+  Logger logger{&log};
+
+  ChimeraTK::ControlSystemModule cs;
+
+  void defineConnections() override{
+    cs("targetStream") >> log.targetStream;
+    cs("logLevel") >> log.logLevel;
+    cs("logFile") >> log.logFile;
+    cs("tailLength") >> log.tailLength;
+
+    log.addSource(&logger);
+    log.findTag("CS").connectTo(cs);
+
+   }
+
+  bool fileCreated;
+};
+
+BOOST_AUTO_TEST_CASE( testLogMsg) {
+  testApp app;
+  ChimeraTK::TestFacility tf;
+  tf.runApplication();
+  auto tailLength = tf.getScalar<uint>("tailLength");
+  app.logger.sendMessage("test", LogLevel::DEBUG);
+  tailLength = 1;
+  tailLength.write();
+  tf.stepApplication();
+  std::string ss  = (std::string)tf.readScalar<std::string>("LogTail");
+  BOOST_CHECK_EQUAL(ss.substr(ss.find("->")+3), std::string("test\n"));
+}
+
+BOOST_AUTO_TEST_CASE( testLogfileFails) {
+  testApp app;
+  ChimeraTK::TestFacility tf;
+
+  auto logFile = tf.getScalar<std::string>("logFile");
+  tf.runApplication();
+  logFile = std::string("/tmp/testLogging/test.log");
+  logFile.write();
+  // message not considered here but used to step through the application
+  app.logger.sendMessage("test", LogLevel::DEBUG);
+  tf.stepApplication();
+  std::string ss  = (std::string)tf.readScalar<std::string>("LogTail");
+  std::vector<std::string> strs;
+  boost::split(strs, ss, boost::is_any_of("\n"), boost::token_compress_on);
+  BOOST_CHECK_EQUAL(strs.at(2).substr(strs.at(2).find("->")+3), std::string("Failed to open log file for writing: /tmp/testLogging/test.log"));
+}
+
+BOOST_AUTO_TEST_CASE( testLogfile) {
+  testApp app;
+  ChimeraTK::TestFacility tf;
+
+  auto logFile = tf.getScalar<std::string>("logFile");
+
+  if(!boost::filesystem::is_directory("/tmp/testLogging/"))
+    boost::filesystem::create_directory("/tmp/testLogging/");
+  tf.runApplication();
+  logFile = std::string("/tmp/testLogging/test.log");
+  logFile.write();
+  // message not considered here but used to step through the application
+  app.logger.sendMessage("test", LogLevel::DEBUG);
+  tf.stepApplication();
+  std::fstream file;
+  file.open("/tmp/testLogging/test.log");
+  BOOST_CHECK_EQUAL(file.good(), true);
+  if(file.good())
+    app.fileCreated = true;
+  std::string line;
+
+  std::getline(file, line);
+  BOOST_CHECK_EQUAL(line.substr(line.find("->")+3), std::string("Opened log file for writing: /tmp/testLogging/test.log"));
+  std::getline(file, line);
+  BOOST_CHECK_EQUAL(line.substr(line.find("->")+3), std::string("test"));
+}
+
+BOOST_AUTO_TEST_CASE( testLogging) {
+  testApp app;
+  ChimeraTK::TestFacility tf;
+
+  auto logLevel = tf.getScalar<uint>("logLevel");
+  auto tailLength = tf.getScalar<uint>("tailLength");
+
+  logLevel = 0;
+  logLevel.write();
+  tailLength = 2;
+  tailLength.write();
+
+  tf.runApplication();
+  app.logger.sendMessage("1st test message", LogLevel::DEBUG);
+  tf.stepApplication();
+  app.logger.sendMessage("2nd test message", LogLevel::DEBUG);
+  tf.stepApplication();
+  auto tail = tf.readScalar<std::string>("LogTail");
+  std::vector< std::string > result;
+  boost::algorithm::split(result, tail, boost::is_any_of("\n"));
+  // result length should be 3 not 2, because new line is used to split, which results in 3 items although there are only two messages.
+  BOOST_CHECK_EQUAL(result.size(), 3);
+
+  /**** Test log level ****/
+  logLevel = 2;
+  logLevel.write();
+  app.logger.sendMessage("3rd test message", LogLevel::DEBUG);
+  tf.stepApplication();
+  tail = tf.readScalar<std::string>("LogTail");
+  boost::algorithm::split(result, tail, boost::is_any_of("\n"));
+  // should still be 3 because log level was too low!
+  BOOST_CHECK_EQUAL(result.size(), 3);
+
+  /**** Test tail length ****/
+  app.logger.sendMessage("4th test message", LogLevel::ERROR);
+  tailLength = 3;
+  tailLength.write();
+  tf.stepApplication();
+  tail = tf.readScalar<std::string>("LogTail");
+  boost::algorithm::split(result, tail, boost::is_any_of("\n"));
+  BOOST_CHECK_EQUAL(result.size(), 4);
+
+  app.logger.sendMessage("5th test message", LogLevel::ERROR);
+  tf.stepApplication();
+  tail = tf.readScalar<std::string>("LogTail");
+  boost::algorithm::split(result, tail, boost::is_any_of("\n"));
+  // should still be 4 because tailLength is 3!
+  BOOST_CHECK_EQUAL(result.size(), 4);
+}