Add logger

libspawner/CMakeLists.txt

@@ -28,6 +28,7 @@ set(HEADERS
     inc/hexdump.h
     inc/multibyte.h
     inc/multipipe.h
+    inc/logger.h
     inc/options.h
     inc/report.h
     inc/restrictions.h
@@ -48,6 +49,7 @@ set(SOURCES
     src/hexdump.cpp
     src/multibyte.cpp
     src/multipipe.cpp
+    src/logger.cpp
     src/options.cpp
     src/report.cpp
     src/restrictions.cpp

libspawner/inc/logger.h

@@ -0,0 +1,39 @@
+#ifndef LOGGER_H
+#define LOGGER_H
+
+//#define DEBUG
+
+#ifdef DEBUG
+#define LOG(...) logger::log(logger::get_log_header(__FILE__, __LINE__), __VA_ARGS__)
+#else
+#define LOG(...)
+#endif
+
+#include <iostream>
+#include <sstream>
+#include <string>
+#include <utility>
+
+class logger {
+    static std::stringstream log_data;
+
+public:
+    static long long start_time;
+    static long long get_time();
+    static std::string get_log_header(const char* filename, int line);
+
+    static void log();
+
+    template <typename First, typename... Rest>
+    static void log(First&& first, Rest&&... rest);
+
+    static void print();
+};
+
+template<typename First, typename ...Rest>
+void logger::log(First && first, Rest && ...rest) {
+    log_data << std::forward<First>(first) << " ";
+    log(std::forward<Rest>(rest)...);
+}
+
+#endif // LOGGER_H

libspawner/src/error.cpp

@@ -1,4 +1,5 @@
 #include "error.h"
+#include "logger.h"
 #include "platform.h"
 
 #include <cstring>
@@ -10,6 +11,7 @@ bool do_we_panic_();
 void exec_on_panic_action_();
 
 void panic_(const std::string& error_message, const char* filename, int line_number) {
+    logger::print();
     std::stringstream error_text;
     const char *fn = filename + strlen(filename);
     while (fn > filename && fn[-1] != '\\' && fn[-1] != '/') --fn;

libspawner/src/logger.cpp

@@ -0,0 +1,43 @@
+#include "logger.h"
+
+#include <chrono>
+#include <cstdlib>
+
+using namespace std::chrono;
+
+static const int header_fixed_len = 25;
+static const int time_fixed_len = 5;
+
+std::stringstream logger::log_data;
+
+long long logger::start_time = 0;
+
+long long logger::get_time() {
+    return duration_cast<milliseconds>(system_clock::now().time_since_epoch()).count();
+}
+
+std::string logger::get_log_header(const char* filename, int line) {
+    std::string header = filename;
+    auto ll = header.find_last_of('\\');
+    if (ll == std::string::npos) { ll = header.find_last_of('/');}
+    if (ll != std::string::npos) { header = header.substr(ll + 1);}
+    header += ":" + std::to_string(line) + ":";
+    auto len = header_fixed_len - header.length();
+    std::string fixed_end = " " + std::string(len > 0 ? len : 0, '.') + " ";
+    std::string ms = std::to_string(get_time() - start_time);
+    auto time_len = time_fixed_len - ms.length();
+    std::string fixed_time_head = std::string(time_len > 0 ? time_len : 0, ' ');
+    return fixed_time_head + ms + "  " + header + fixed_end;
+}
+
+void logger::log() {
+    log_data << std::endl;
+}
+
+void logger::print() {
+    std::string all_data = log_data.str();
+    if (!all_data.empty()) {
+        std::cerr << "  time\tfile:line\t\tdata" << std::endl;
+        std::cerr << all_data;
+    }
+}

libspawner/src/multipipe.cpp

@@ -3,6 +3,7 @@
 #include <chrono>
 
 #include "error.h"
+#include "logger.h"
 
 using std::chrono::milliseconds;
 using std::this_thread::sleep_for;
@@ -42,6 +43,7 @@ void multipipe::set_new_line_checking() {
 }
 
 void multipipe::listen() {
+    LOG("listen", id);
     if (mode != read_mode && core_pipe->is_readable())
         return;
 
@@ -102,6 +104,7 @@ void multipipe::write(const char* bytes, size_t count, set<int>& src) {
 }
 
 void multipipe::close_and_notify() {
+    LOG("close and notify", id);
     flush();
 
     auto childs = this->sinks;

libspawner/src/posix/runner.cpp

@@ -7,6 +7,7 @@
 #include <fcntl.h>
 
 #include "inc/error.h"
+#include "logger.h"
 
 #include "runner.h"
 
@@ -216,6 +217,7 @@ void runner::waitpid_body() {
         pid_t w = waitpid(proc_pid, &status,
             WUNTRACED | WCONTINUED);
         if (WIFSIGNALED(status)) {
+            LOG("signaled", get_index());
             // "signalled" means abnormal/terminate
 #ifdef WCOREDUMP
             process_status = process_finished_abnormally;
@@ -225,14 +227,17 @@ void runner::waitpid_body() {
 
             runner_signal = (signal_t)WTERMSIG(status);
         } else if (WIFEXITED(status)) {
+            LOG("exited", get_index());
             process_status = process_finished_normal;
             exit_code = WEXITSTATUS(status);
         } else if (WIFSTOPPED(status)) {
+            LOG("stopped", get_index());
             if (resume_requested) {
                 resume();
             }
             process_status = process_suspended;
         } else if (WIFCONTINUED(status)) {
+            LOG("continued", get_index());
             resume_requested = false;
             process_status = process_still_active;
         }
@@ -280,6 +285,7 @@ void runner::suspend() {
     suspend_mutex.lock();
     if (get_process_status() == process_still_active) {
         int err = kill(proc_pid, SIGSTOP);
+        LOG("suspend", get_index(), err);
     }
     suspend_mutex.unlock();
 }
@@ -289,6 +295,7 @@ void runner::resume() {
     if (get_process_status() == process_suspended) {
         resume_requested = true;
         int err = kill(proc_pid, SIGCONT);
+        LOG("resume", get_index(), err);
     }
     suspend_mutex.unlock();
 }

libspawner/src/posix/system_pipe.cpp

@@ -7,6 +7,7 @@
 #include <sys/file.h>
 
 #include "error.h"
+#include "logger.h"
 
 system_pipe::system_pipe(bool flush, pipe_type t) {
     autoflush = flush;
@@ -105,6 +106,7 @@ size_t system_pipe::read(char* bytes, size_t count) {
             read_mutex.unlock();
             PANIC(strerror(errno));
         }
+        LOG("read", bytes_read);
         read_mutex.unlock();
     }
 
@@ -121,6 +123,7 @@ size_t system_pipe::write(const char* bytes, size_t count) {
             write_mutex.unlock();
             PANIC(strerror(errno));
         }
+        LOG("written", bytes_written);
         write_mutex.unlock();
     }
 
@@ -132,12 +135,15 @@ size_t system_pipe::write(const char* bytes, size_t count) {
 
 void system_pipe::flush() {
     write_mutex.lock();
-    if (is_writable())
+    if (is_writable()) {
         fsync(output_handle);
+        LOG("flushed");
+    }
     write_mutex.unlock();
 }
 
 void system_pipe::close(pipe_mode mode) {
+    LOG("close");
     if (mode == read_mode && is_readable()) {
         read_mutex.lock();
         if (is_file()) {

src/main.cpp

@@ -5,6 +5,7 @@
 
 #include "sp.h"
 #include "inc/compatibility.h"
+#include "inc/logger.h"
 #include "spawner_base.h"
 #include "spawner_old.h"
 #include "spawner_new.h"
@@ -147,6 +148,7 @@ BOOL WINAPI CtrlHandlerRoutine(DWORD dwCtrlType) {
 #endif
 
 int main(int argc, char *argv[]) {
+    logger::start_time = logger::get_time();
     handler = new command_handler_c();
     // TODO: codestyle: replace \)\r\n\{ with \) \{\r\n
     // Suppress msg window on abort; TODO: check if it's ms spec
@@ -172,5 +174,6 @@ int main(int argc, char *argv[]) {
         delete handler;
         handler = nullptr;
     }
+    logger::print();
     return 0;
 }

src/spawner_new.cpp

@@ -2,6 +2,9 @@
 
 #include <iostream>
 
+#include "inc/logger.h"
+
+
 spawner_new_c::spawner_new_c(settings_parser_c &parser)
     : parser(parser)
     , spawner_base_c()
@@ -416,6 +419,7 @@ bool spawner_new_c::init_runner() {
 
 void spawner_new_c::run() {
     begin_report();
+    LOG("initialize...");
     for (auto i : runners) {
         i->run_process_async();
     }
@@ -430,6 +434,7 @@ void spawner_new_c::run() {
     for (auto i : runners) {
         i->get_pipe(std_stream_input)->check_parents();
     }
+    LOG("initialized");
     for (auto i : runners) {
         i->wait_for();
     }