diff --git a/lib/util.cpp b/lib/util.cpp index f52f2ee5..2f74ec70 100644 --- a/lib/util.cpp +++ b/lib/util.cpp @@ -5,6 +5,7 @@ #include "bitfields.h" #include "defines.h" #include "timing.h" +#include "procs.h" #include // errno, ENOENT, EEXIST #include #include @@ -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){ diff --git a/lib/util.h b/lib/util.h index 841b2901..9d0c560e 100644 --- a/lib/util.h +++ b/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: diff --git a/src/analysers/mist_analyse.cpp b/src/analysers/mist_analyse.cpp index 1957b2dd..cde3b32a 100644 --- a/src/analysers/mist_analyse.cpp +++ b/src/analysers/mist_analyse.cpp @@ -1,8 +1,10 @@ #include ANALYSERHEADER #include #include +#include int main(int argc, char *argv[]){ + Util::redirectLogsIfNeeded(); Util::Config conf(argv[0]); ANALYSERTYPE::init(conf); if (conf.parseArgs(argc, argv)){ diff --git a/src/controller/controller.cpp b/src/controller/controller.cpp index 556a04e6..3f8ddc63 100644 --- a/src/controller/controller.cpp +++ b/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){ diff --git a/src/controller/controller_storage.cpp b/src/controller/controller_storage.cpp index 0f3d9176..781d8053 100644 --- a/src/controller/controller_storage.cpp +++ b/src/controller/controller_storage.cpp @@ -5,6 +5,8 @@ #include #include #include +#include +#include #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 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. diff --git a/src/controller/controller_storage.h b/src/controller/controller_storage.h index 1c5994dc..13081752 100644 --- a/src/controller/controller_storage.h +++ b/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); diff --git a/src/input/mist_in.cpp b/src/input/mist_in.cpp index dd4f206c..92e68b62 100644 --- a/src/input/mist_in.cpp +++ b/src/input/mist_in.cpp @@ -1,6 +1,8 @@ #include INPUTTYPE +#include int main(int argc, char * argv[]) { + Util::redirectLogsIfNeeded(); Util::Config conf(argv[0]); mistIn conv(&conf); return conv.boot(argc, argv); diff --git a/src/output/mist_out.cpp b/src/output/mist_out.cpp index a75aefcc..b5d02796 100644 --- a/src/output/mist_out.cpp +++ b/src/output/mist_out.cpp @@ -2,6 +2,7 @@ #include #include #include +#include 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)) { diff --git a/src/utils/util_amf.cpp b/src/utils/util_amf.cpp index b7b44e4e..223ad5f1 100644 --- a/src/utils/util_amf.cpp +++ b/src/utils/util_amf.cpp @@ -7,9 +7,11 @@ #include #include #include +#include #include int main(int argc, char **argv){ + Util::redirectLogsIfNeeded(); Util::Config conf(argv[0]); JSON::Value opt; opt["arg_num"] = 1ll; diff --git a/src/utils/util_rax.cpp b/src/utils/util_rax.cpp index 96a9eae4..5cdb0f4a 100644 --- a/src/utils/util_rax.cpp +++ b/src/utils/util_rax.cpp @@ -3,6 +3,7 @@ #include int main(int argc, char ** argv){ + Util::redirectLogsIfNeeded(); if (argc < 1){ FAIL_MSG("Usage: %s MEMORY_PAGE_NAME"); return 1;