Logging.cc

/*
 * Logging.cc
 *
 *  Created on: Apr 3, 2018
 *      Author: zenker
 */

#include "Logging.h"

#include "boost/date_time/posix_time/posix_time.hpp"

#include <fstream>
#include <ostream>
#include <sstream>
#include <string>
#include <vector>

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, const std::string& name, const std::string& description, const std::string& tag)
: VariableGroup(module, name, description),
  message(this, "message", "",
      "Message of the module to the logging System. The leading number indicates the log level "
      "(0: DEBUG, 1: INFO, 2: WARNING, 3: ERROR, 4;SILENT). A leading 5 is used internally for old messages.",
      {tag, module->getName()}),
  alias(this, "alias", "", "Alias used in the message as identifier.", {tag, module->getName()}) {}

void Logger::sendMessage(const std::string& msg, const logging::LogLevel& level) {
  if(message.isInitialised()) {
    while(!msg_buffer.empty()) {
      message = msg_buffer.front();
      message.write();
      msg_buffer.pop();
    }
    message = std::to_string(level) + msg + "\n";
    message.write();
    // set emtpy message to let the LoggingModule know that someone called writeAll() without sending a message
    message = std::to_string(logging::LogLevel::INTERNAL) + msg + "\n";
  }
  else {
    // only use the buffer until ctk initialized the process variables
    msg_buffer.push(std::to_string(level) + msg + "\n");
  }
}

void Logger::prepare() {
  // write initial value in order to bring LoggingModule to mainLoop()
  message.write();
}

LoggingModule::LoggingModule(ctk::EntityOwner* owner, const std::string& name, const std::string& description,
    ctk::HierarchyModifier hierarchyModifier, const std::unordered_set<std::string>& tags)
: ApplicationModule(owner, name, description, hierarchyModifier, tags) {
  for(auto tag : tags) {
    auto virtualLogging = getOwner()->findTag(tag);
    auto list = virtualLogging.getAccessorListRecursive();
    for(auto it = list.begin(); it != list.end(); ++it) {
      // do not add the module itself
      if(it->getOwningModule() == this) continue;
      try {
        // virtualLogging.getQualifiedName() returns the name of the app, e.g. /test and we remove that from the module
        // name , e.g. /test/MyModule
        auto moduleName =
            it->getOwningModule()->getQualifiedName().substr(virtualLogging.getQualifiedName().length() + 1);
        auto msgSource = std::find(sources.begin(), sources.end(), moduleName);
        if(msgSource == sources.end()) {
          // Create new MessageSource
          auto acc = getAccessorPair(moduleName);
          (*it) >> acc;
          std::cout << "Registered module " << it->getOwningModule()->getQualifiedName() << " for logging."
                    << std::endl;
        }
        else {
          // Connect variables that was not connected when creating the MessageSource
          // On creation either alias or the message could have been connected -> now connect the other one
          if(it->getName() == "alias") {
            (*it) >> msgSource->data.alias;
          }
          else if(it->getName() == "message") {
            (*it) >> msgSource->data.msg;
          }
        }
      }
      catch(ChimeraTK::logic_error& e) {
        std::cerr << "Failed to add logging module: " << it->getOwningModule()->getQualifiedName()
                  << " Error: " << e.what() << std::endl;
      }
    }
  }
  if(sources.empty()) std::cerr << "LoggingModule did not find any module that uses a Logger." << std::endl;
}

ctk::RegisterPath LoggingModule::prepareHierarchy(const ctk::RegisterPath& namePrefix) {
  ctk::RegisterPath result;
  // create variable group map for namePrefix if needed
  if(groupMap.find(namePrefix) == groupMap.end()) {
    // search for existing parent (if any)
    auto parentPrefix = namePrefix;
    while(groupMap.find(parentPrefix) == groupMap.end()) {
      if(parentPrefix == "/") break; // no existing parent found
      parentPrefix = std::string(parentPrefix).substr(0, std::string(parentPrefix).find_last_of("/"));
    }
    // create all not-yet-existing parents
    while(true) {
      ctk::EntityOwner* owner = this;
      if(parentPrefix != "/") owner = &groupMap[parentPrefix];
      auto stop = std::string(namePrefix).find_first_of("/", parentPrefix.length() + 1);
      if(stop == std::string::npos) stop = namePrefix.length();
      ctk::RegisterPath name = std::string(namePrefix).substr(parentPrefix.length(), stop - parentPrefix.length());
      result = parentPrefix;
      parentPrefix /= name;
      if(parentPrefix == namePrefix) {
        // do not add the last hierachy level -> will be added by the MessageSource
        break;
      }
      groupMap[parentPrefix] = ctk::VariableGroup(owner, std::string(name).substr(1), "");
    }
  }
  return result;
}

void LoggingModule::broadcastMessage(std::string msg, const 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 " << sources.size()
          << " modules registered for logging:" << std::endl;
  broadcastMessage(greeter.str());
  for(auto module = sources.begin(); module != sources.end(); module++) {
    broadcastMessage(std::string("\t - ") + module->sendingModule);
    id_list[module->data.msg.getId()] = &(*module);
  }
  auto group = readAnyGroup();
  std::string msg;
  MessageSource* currentSender;
  LogLevel level;

  while(1) {
    // we skip the initial value since it is empty anyway and set in Logger::prepare
    auto id = group.readAny();
    if(id_list.count(id) == 0) {
      throw ChimeraTK::logic_error("Cannot find  element id"
                                   "when updating logging variables.");
    }
    try {
      currentSender = id_list.at(id);
      msg = (std::string)(currentSender->data.msg);
    }
    catch(std::out_of_range& e) {
      throw ChimeraTK::logic_error("Cannot find  element id"
                                   "when updating logging variables.");
    }
    try {
      level = static_cast<LogLevel>(std::strtoul(&msg.at(0), NULL, 0));
    }
    catch(std::out_of_range& e) {
      throw ChimeraTK::logic_error("Cannot find  message level"
                                   "when updating logging variables.");
    }
    // if log level is INTERANEL someone called writeAll() in a module containing the Logger -> ignore
    if(level == LogLevel::INTERNAL) {
      continue;
    }
    if(targetStream == 4) continue;
    LogLevel setLevel = static_cast<LogLevel>((uint)logLevel);
    std::string tmpStr = msg;
    // remove message level
    tmpStr = tmpStr.substr(1, tmpStr.size());
    std::stringstream ss;
    if(((std::string)currentSender->data.alias).empty()) {
      ss << level << getName() << ":" << currentSender->sendingModule << " " << getTime() << tmpStr;
    }
    else {
      ss << level << getName() << ":" << (std::string)currentSender->data.alias << " " << getTime() << tmpStr;
    }
    if(targetStream == 0 || targetStream == 1) {
      if(!((std::string)logFile).empty() && !file->is_open()) {
        std::stringstream ss_file;
        file->open((std::string)logFile, std::ofstream::out | std::ofstream::app);
        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);
    }
  }
}

ctk::VariableNetworkNode LoggingModule::getAccessorPair(const ctk::RegisterPath& namePrefix) {
  auto it = std::find_if(sources.begin(), sources.end(),
      boost::bind(&MessageSource::sendingModule, boost::placeholders::_1) == (std::string)namePrefix);
  if(it == sources.end()) {
    auto result = prepareHierarchy(namePrefix);
    if(result == "/") {
      sources.emplace_back(MessageSource{namePrefix, this});
    }
    else {
      sources.emplace_back(MessageSource{namePrefix, &groupMap[result]});
    }
  }
  else {
    throw ChimeraTK::logic_error(
        "Cannot add logging for module " + namePrefix + " since logging was already added for this module.");
  }
  return sources.back().data.msg;
}

void LoggingModule::terminate() {
  if((file.get() != nullptr) && (file->is_open())) file->close();
  ApplicationModule::terminate();
}

void LoggingModule::findTagAndAppendToModule(ctk::VirtualModule& virtualParent, const std::string& tag,
    bool eliminateAllHierarchies, bool eliminateFirstHierarchy, bool negate, ctk::VirtualModule& root) const {
  // Change behaviour to exclude the auto-generated inputs which are connected to the data sources. Otherwise those
  // variables might get published twice to the control system, if findTag(".*") is used to connect the entire
  // application to the control system.
  // This is a temporary solution. In future, instead the inputs should be generated at the same place in the
  // hierarchy as the source variable, and the connetion should not be made by the module itself. This currently would
  // be complicated to implement, since it is difficult to find the correct virtual name for the variables.

  struct MyVirtualModule : ctk::VirtualModule {
    using ctk::VirtualModule::VirtualModule;
    using ctk::VirtualModule::findTagAndAppendToModule;
  };

  MyVirtualModule tempParent("tempRoot", "", ModuleType::ApplicationModule);
  MyVirtualModule tempRoot("tempRoot", "", ModuleType::ApplicationModule);
  ctk::EntityOwner::findTagAndAppendToModule(
      tempParent, "_logging_internal", eliminateAllHierarchies, eliminateFirstHierarchy, true, tempRoot);
  tempParent.findTagAndAppendToModule(virtualParent, tag, false, true, negate, root);
  tempRoot.findTagAndAppendToModule(root, tag, false, true, negate, root);
}