Improved logging system

lib/util.cpp

@@ -5,6 +5,7 @@
 #include "bitfields.h"
 #include "defines.h"
 #include "timing.h"
+#include "procs.h"
 #include <errno.h> // errno, ENOENT, EEXIST
 #include <iostream>
 #include <stdio.h>
@@ -197,6 +198,137 @@ namespace Util{
     return true;
   }
 
+
+  static int true_stderr = 2;
+  static int log_pipe = -1;
+  //Local-only helper function.
+  //Detects tty on stdin to decide whether or not colours should be used.
+  static void handleMsg(void *nul){
+    Util::logParser(log_pipe, true_stderr, isatty(true_stderr));
+  }
+
+  /// Redirects stderr to log parser, writes log parser to the old stderr.
+  /// Does nothing if the MIST_CONTROL environment variable is set.
+  void redirectLogsIfNeeded(){
+    //The controller sets this environment variable.
+    //We don't do anything if set, since the controller wants the messages raw.
+    if (getenv("MIST_CONTROL")){return;}
+    setenv("MIST_CONTROL", "1", 1);
+    //Okay, we're stand-alone, lets do some parsing!
+    true_stderr = dup(STDERR_FILENO);
+    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
+      log_pipe = pipeErr[0];
+      //Start reading log messages from the unnamed pipe
+      Util::Procs::socketList.insert(log_pipe); //Mark this FD as needing to be closed before forking
+      Util::Procs::socketList.insert(true_stderr); //Mark this FD as needing to be closed before forking
+      tthread::thread msghandler(handleMsg, (void *)0);
+      msghandler.detach();
+    }
+  }
+
+  /// Parses log messages from the given file descriptor in, printing them to out, optionally calling the given callback for each valid message.
+  /// Closes the file descriptor on read error
+  void logParser(int in, int out, bool colored, void callback(std::string, std::string, bool)){
+    char buf[1024];
+    FILE *output = fdopen(in, "r");
+    char *color_time, *color_msg, *color_end, *CONF_msg, *FAIL_msg, *ERROR_msg, *WARN_msg, *INFO_msg;
+    if (colored){
+      color_end = (char*)"\033[0m";
+      if (getenv("MIST_COLOR_END")){color_end = getenv("MIST_COLOR_END");}
+      color_time = (char*)"\033[2m";
+      if (getenv("MIST_COLOR_TIME")){color_time = getenv("MIST_COLOR_TIME");}
+      CONF_msg = (char*)"\033[0;1;37m";
+      if (getenv("MIST_COLOR_CONF")){CONF_msg = getenv("MIST_COLOR_CONF");}
+      FAIL_msg = (char*)"\033[0;1;31m";
+      if (getenv("MIST_COLOR_FAIL")){FAIL_msg = getenv("MIST_COLOR_FAIL");}
+      ERROR_msg = (char*)"\033[0;31m";
+      if (getenv("MIST_COLOR_ERROR")){ERROR_msg = getenv("MIST_COLOR_ERROR");}
+      WARN_msg = (char*)"\033[0;1;33m";
+      if (getenv("MIST_COLOR_WARN")){WARN_msg = getenv("MIST_COLOR_WARN");}
+      INFO_msg = (char*)"\033[0;36m";
+      if (getenv("MIST_COLOR_INFO")){INFO_msg = getenv("MIST_COLOR_INFO");}
+    }else{
+      color_end = (char*)"";
+      color_time = (char*)"";
+      CONF_msg = (char*)"";
+      FAIL_msg = (char*)"";
+      ERROR_msg = (char*)"";
+      WARN_msg = (char*)"";
+      INFO_msg = (char*)"";
+    }
+    while (fgets(buf, 1024, output)){
+      unsigned int i = 0;
+      char * kind = buf;//type of message, at begin of string
+      char * progname = 0;
+      char * progpid = 0;
+      char * lineno = 0;
+      char * message = 0;
+      while (i < 9 && buf[i] != '|' && buf[i] != 0){++i;}
+      if (buf[i] == '|'){
+        buf[i] = 0;//insert null byte
+        ++i;
+        progname = buf+i;//progname starts here
+      }
+      while (i < 30 && buf[i] != '|' && buf[i] != 0){++i;}
+      if (buf[i] == '|'){
+        buf[i] = 0;//insert null byte
+        ++i;
+        progpid = buf+i;//progpid starts here
+      }
+      while (i < 40 && buf[i] != '|' && buf[i] != 0){++i;}
+      if (buf[i] == '|'){
+        buf[i] = 0;//insert null byte
+        ++i;
+        lineno = buf+i;//lineno starts here
+      }
+      while (i < 80 && buf[i] != '|' && buf[i] != 0){++i;}
+      if (buf[i] == '|'){
+        buf[i] = 0;//insert null byte
+        ++i;
+        message = buf+i;//message starts here
+      }
+      //find end of line, insert null byte
+      unsigned int j = i;
+      while (j < 1024 && buf[j] != '\n' && buf[j] != 0){++j;}
+      buf[j] = 0;
+      //print message
+      if (message){
+        if (callback){callback(kind, message, true);}
+        color_msg = color_end;
+        if (colored){
+          if (!strcmp(kind, "CONF")){color_msg = CONF_msg;}
+          if (!strcmp(kind, "FAIL")){color_msg = FAIL_msg;}
+          if (!strcmp(kind, "ERROR")){color_msg = ERROR_msg;}
+          if (!strcmp(kind, "WARN")){color_msg = WARN_msg;}
+          if (!strcmp(kind, "INFO")){color_msg = INFO_msg;}
+        }
+        time_t rawtime;
+        struct tm *timeinfo;
+        char buffer[100];
+        time(&rawtime);
+        timeinfo = localtime(&rawtime);
+        strftime(buffer, 100, "%F %H:%M:%S", timeinfo);
+        dprintf(out, "%s[%s] ", color_time, buffer);
+        if (strlen(progname) && strlen(progpid)){
+          dprintf(out, "%s (%s) ", progname, progpid);
+        }
+        dprintf(out, "%s%s: %s%s", color_msg, kind, message, color_end);
+        if (strlen(lineno)){
+          dprintf(out, " (%s) ", lineno);
+        }
+        dprintf(out, "\n", lineno);
+      }else{
+        //could not be parsed as log string - print the whole thing
+        dprintf(out, "%s\n", buf);
+      }
+    }
+    fclose(output);
+    close(in);
+  }
+
   /// If waitReady is true (default), waits for isReady() to return true in 50ms sleep increments.
   RelAccX::RelAccX(char *data, bool waitReady){
     if (!data){

lib/util.h

@@ -32,6 +32,9 @@ namespace Util{
 
   };
 
+  void logParser(int in, int out, bool colored, void callback(std::string, std::string, bool) = 0);
+  void redirectLogsIfNeeded();
+
   /// Holds type, size and offset for RelAccX class internal data fields.
   class RelAccXFieldData{
   public:

src/analysers/mist_analyse.cpp

@@ -1,8 +1,10 @@
 #include ANALYSERHEADER
 #include <mist/config.h>
 #include <mist/defines.h>
+#include <mist/util.h>
 
 int main(int argc, char *argv[]){
+  Util::redirectLogsIfNeeded();
   Util::Config conf(argv[0]);
   ANALYSERTYPE::init(conf);
   if (conf.parseArgs(argc, argv)){

src/controller/controller.cpp

@@ -191,14 +191,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

@@ -5,6 +5,8 @@
 #include <mist/timing.h>
 #include <mist/shared_memory.h>
 #include <mist/defines.h>
+#include <mist/util.h>
+#include <sys/stat.h>
 #include "controller_storage.h"
 #include "controller_capabilities.h"
 
@@ -24,32 +26,17 @@ 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;
+    Storage["log"].shrink(100); // limit to 100 log messages
+    if (!noWriteToLog){
+      std::cerr << kind << "|MistController|" << getpid() << "||" << message << "\n";
+    }
   }
 
   ///\brief Write contents to Filename
@@ -63,33 +50,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);
+  void handleMsg(void *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

@@ -15,7 +15,7 @@ namespace Controller {
   extern bool isColorized;///< True if we colorize the output
   
   /// 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);

src/input/mist_in.cpp

@@ -1,6 +1,8 @@
 #include INPUTTYPE 
+#include <mist/util.h>
 
 int main(int argc, char * argv[]) {
+  Util::redirectLogsIfNeeded();
   Util::Config conf(argv[0]);
   mistIn conv(&conf);
   return conv.boot(argc, argv);

src/output/mist_out.cpp

@@ -2,6 +2,7 @@
 #include <mist/config.h>
 #include <mist/socket.h>
 #include <mist/defines.h>
+#include <mist/util.h>
 
 int spawnForked(Socket::Connection & S){
   mistOut tmp(S);
@@ -9,6 +10,7 @@ int spawnForked(Socket::Connection & S){
 }
 
 int main(int argc, char * argv[]) {
+  Util::redirectLogsIfNeeded();
   Util::Config conf(argv[0]);
   mistOut::init(&conf);
   if (conf.parseArgs(argc, argv)) {

src/utils/util_amf.cpp

@@ -7,9 +7,11 @@
 #include <mist/amf.h>
 #include <mist/config.h>
 #include <mist/defines.h>
+#include <mist/util.h>
 #include <string>
 
 int main(int argc, char **argv){
+  Util::redirectLogsIfNeeded();
   Util::Config conf(argv[0]);
   JSON::Value opt;
   opt["arg_num"] = 1ll;

src/utils/util_rax.cpp

@@ -3,6 +3,7 @@
 #include <mist/shared_memory.h>
 
 int main(int argc, char ** argv){
+  Util::redirectLogsIfNeeded();
   if (argc < 1){
     FAIL_MSG("Usage: %s MEMORY_PAGE_NAME");
     return 1;