Improved logging system

src/controller/controller.cpp

@@ -234,14 +234,42 @@ int main_loop(int argc, char **argv){
   Controller::Storage = JSON::fromFile(Controller::conf.getString("configFile"));
 
   {// spawn thread that reads stderr of process
-    int pipeErr[2];
-    if (pipe(pipeErr) >= 0){
-      dup2(pipeErr[1], STDERR_FILENO); // cause stderr to write to the pipe
-      close(pipeErr[1]);               // close the unneeded pipe file descriptor
-      Util::Procs::socketList.insert(pipeErr[0]);
-      tthread::thread msghandler(Controller::handleMsg, (void *)(((char *)0) + pipeErr[0]));
-      msghandler.detach();
+    std::string logPipe = Util::getTmpFolder()+"MstLog";
+    if (mkfifo(logPipe.c_str(), S_IWUSR | S_IRUSR | S_IRGRP | S_IROTH) != 0){
+      if (errno != EEXIST){
+        ERROR_MSG("Could not create log message pipe %s: %s", logPipe.c_str(), strerror(errno));
+      }
     }
+    int inFD = -1;
+    if ((inFD = open(logPipe.c_str(), O_RDONLY | O_NONBLOCK)) == -1){
+      ERROR_MSG("Could not open log message pipe %s: %s; falling back to unnamed pipe", logPipe.c_str(), strerror(errno));
+      int pipeErr[2];
+      if (pipe(pipeErr) >= 0){
+        dup2(pipeErr[1], STDERR_FILENO); // cause stderr to write to the pipe
+        close(pipeErr[1]);               // close the unneeded pipe file descriptor
+        //Start reading log messages from the unnamed pipe
+        Util::Procs::socketList.insert(pipeErr[0]); //Mark this FD as needing to be closed before forking
+        tthread::thread msghandler(Controller::handleMsg, (void *)(((char *)0) + pipeErr[0]));
+        msghandler.detach();
+      }
+    }else{
+      //Set the read end to blocking mode
+      int inFDflags = fcntl(inFD, F_GETFL, 0);
+      fcntl(inFD, F_SETFL, inFDflags & (~O_NONBLOCK));
+      //Start reading log messages from the named pipe
+      Util::Procs::socketList.insert(inFD); //Mark this FD as needing to be closed before forking
+      tthread::thread msghandler(Controller::handleMsg, (void *)(((char *)0) + inFD));
+      msghandler.detach();
+      //Attempt to open and redirect log messages to named pipe
+      int outFD = -1;
+      if ((outFD = open(logPipe.c_str(), O_WRONLY)) == -1){
+        ERROR_MSG("Could not open log message pipe %s for writing! %s; falling back to standard error", logPipe.c_str(), strerror(errno));
+      }else{
+        dup2(outFD, STDERR_FILENO); // cause stderr to write to the pipe
+        close(outFD);               // close the unneeded pipe file descriptor
+      }
+    }
+    setenv("MIST_CONTROL", "1", 0);//Signal in the environment that the controller handles all children
   }
 
   if (Controller::conf.getOption("debug", true).size() > 1){

src/controller/controller_storage.cpp

@@ -7,7 +7,7 @@
 #include <mist/shared_memory.h>
 #include <mist/timing.h>
 #include <mist/triggers.h> //LTS
-#include <mist/util.h>     //LTS
+#include <mist/util.h>
 #include <sys/stat.h>
 
 ///\brief Holds everything unique to the controller.
@@ -28,33 +28,18 @@ namespace Controller{
   ///\brief Store and print a log message.
   ///\param kind The type of message.
   ///\param message The message to be logged.
-  void Log(std::string kind, std::string message){
+  void Log(std::string kind, std::string message, bool noWriteToLog){
     tthread::lock_guard<tthread::mutex> guard(logMutex);
-    std::string color_time, color_msg, color_end;
-    if (Controller::isColorized){
-      color_end = "\033[0m";
-      color_time = "\033[2m";
-      color_msg = color_end;
-      if (kind == "CONF"){color_msg = "\033[0;1;37m";}
-      if (kind == "FAIL"){color_msg = "\033[0;1;31m";}
-      if (kind == "ERROR"){color_msg = "\033[0;31m";}
-      if (kind == "WARN"){color_msg = "\033[0;1;33m";}
-      if (kind == "INFO"){color_msg = "\033[0;36m";}
-    }
     JSON::Value m;
     m.append(Util::epoch());
     m.append(kind);
     m.append(message);
     Storage["log"].append(m);
     Storage["log"].shrink(100); // limit to 100 log messages
-    time_t rawtime;
-    struct tm *timeinfo;
-    char buffer[100];
-    time(&rawtime);
-    timeinfo = localtime(&rawtime);
-    strftime(buffer, 100, "%F %H:%M:%S", timeinfo);
-    std::cout << color_time << "[" << buffer << "] " << color_msg << kind << ": " << message << color_end << std::endl;
     logCounter++;
+    if (!noWriteToLog){
+      std::cerr << kind << "|MistController|" << getpid() << "||" << message << "\n";
+    }
   }
 
   ///\brief Write contents to Filename
@@ -68,29 +53,8 @@ namespace Controller{
     return File.good();
   }
 
-  /// Handles output of a Mist application, detecting and catching debug messages.
-  /// Debug messages are automatically converted into Log messages.
-  /// Closes the file descriptor on read error.
-  /// \param err File descriptor of the stderr output of the process to monitor.
   void handleMsg(void *err){
-    char buf[1024];
-    FILE *output = fdopen((long long int)err, "r");
-    while (fgets(buf, 1024, output)){
-      unsigned int i = 0;
-      while (i < 9 && buf[i] != '|' && buf[i] != 0){++i;}
-      unsigned int j = i;
-      while (j < 1024 && buf[j] != '\n' && buf[j] != 0){++j;}
-      buf[j] = 0;
-      if (i < 9){
-        buf[i] = 0;
-        Log(buf, buf + i + 1);
-      }else{
-        printf("%s", buf);
-      }
-    }
-    Log("LOG", "Logger exiting");
-    fclose(output);
-    close((long long int)err);
+    Util::logParser((long long)err, fileno(stdout), Controller::isColorized, &Log);
   }
 
   /// Writes the current config to the location set in the configFile setting.

src/controller/controller_storage.h

@@ -18,7 +18,7 @@ namespace Controller {
   extern unsigned long long logCounter; ///<Count of logged messages since boot
   
   /// Store and print a log message.
-  void Log(std::string kind, std::string message);
+  void Log(std::string kind, std::string message, bool noWriteToLog = false);
 
   /// Write contents to Filename.
   bool WriteFile(std::string Filename, std::string contents);