From ceac077637d147b54abeeb4f0154bf152ba13138 Mon Sep 17 00:00:00 2001 From: Mihai Moldovan Date: Sat, 30 Sep 2017 16:58:16 +0200 Subject: nxcomp: add basic logging_test utility in test subdirectory. Needs more sophisticated features to actually test stuff correctly. --- nxcomp/.gitignore | 4 + nxcomp/Makefile.am | 2 +- nxcomp/configure.ac | 1 + nxcomp/test/Makefile.am | 22 +++++ nxcomp/test/logging_test.cpp | 224 +++++++++++++++++++++++++++++++++++++++++++ nxcomp/test/logging_test.h | 121 +++++++++++++++++++++++ 6 files changed, 373 insertions(+), 1 deletion(-) create mode 100644 nxcomp/test/Makefile.am create mode 100644 nxcomp/test/logging_test.cpp create mode 100644 nxcomp/test/logging_test.h diff --git a/nxcomp/.gitignore b/nxcomp/.gitignore index 019202342..1d00b755b 100644 --- a/nxcomp/.gitignore +++ b/nxcomp/.gitignore @@ -19,3 +19,7 @@ m4/lt~obsolete.m4 nxcomp.pc src/Makefile src/Makefile.in +test/.deps/ +test/Makefile +test/Makefile.in +test/logging_test diff --git a/nxcomp/Makefile.am b/nxcomp/Makefile.am index ae5991c3d..c1f6226bc 100644 --- a/nxcomp/Makefile.am +++ b/nxcomp/Makefile.am @@ -1,4 +1,4 @@ -SUBDIRS = src +SUBDIRS = src test pkgconfig_DATA = nxcomp.pc diff --git a/nxcomp/configure.ac b/nxcomp/configure.ac index a61db32c1..3ae81f0d1 100644 --- a/nxcomp/configure.ac +++ b/nxcomp/configure.ac @@ -108,6 +108,7 @@ AC_ARG_ENABLE([valgrind], AC_CONFIG_FILES([ Makefile src/Makefile +test/Makefile nxcomp.pc ]) diff --git a/nxcomp/test/Makefile.am b/nxcomp/test/Makefile.am new file mode 100644 index 000000000..412b8ea94 --- /dev/null +++ b/nxcomp/test/Makefile.am @@ -0,0 +1,22 @@ +NULL = + +noinst_PROGRAMS = logging_test +EXTRA_DIST = logging_test + +AM_CPPFLAGS = -I$(top_srcdir)/src +AM_CXXFLAGS = \ + @PTHREAD_CFLAGS@ \ + $(NULL) + +logging_test_SOURCES = logging_test.cpp +logging_test_LDADD = \ + $(top_srcdir)/src/.libs/libXcomp.a \ + @PTHREAD_LIBS@ \ + $(NULL) + +logging_test_LDFLAGS = \ + $(PTHREAD_LDFLAGS) \ + $(NULL) + +check: all + ./logging_test diff --git a/nxcomp/test/logging_test.cpp b/nxcomp/test/logging_test.cpp new file mode 100644 index 000000000..7e2d7d213 --- /dev/null +++ b/nxcomp/test/logging_test.cpp @@ -0,0 +1,224 @@ +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "logging_test.h" + +Faulty_Logger faulty_logger; +NXLog good_logger; + +void print_sigmask () { + sigset_t orig_mask; + sigemptyset (&orig_mask); + + pthread_sigmask (SIG_SETMASK, NULL, &orig_mask); + + bool empty = true; + for (std::size_t i = 0; i < NSIG; ++i) { + if (sigismember (&orig_mask, i)) { + nxdbg_good << "Signal i (" << i << ") in signal mask." << std::endl; + empty = false; + } + } + + if (empty) { + nxdbg_good << "Signal mask empty."; + } +} + +void* log_task (void* /* unused */) { + /* print_sigmask (); */ + + for (std::size_t i = 0; i < 10; ++i) { + nxinfo << "Log message " << i << std::endl; + } +} + +void sig_handler (int signo) { + nxinfo << "Received signal " << signo << std::endl; +} + +void setup_faulty_logger () { + faulty_logger.log_level (true); + faulty_logger.log_unix_time (false); + faulty_logger.log_time (true); + faulty_logger.log_location (true); + faulty_logger.log_thread_id (true); + faulty_logger.level (NXDEBUG); +} + +void setup_good_logger () { + good_logger.log_level (true); + good_logger.log_unix_time (false); + good_logger.log_time (true); + good_logger.log_location (true); + good_logger.log_thread_id (true); + good_logger.level (NXDEBUG); +} + +pthread_t spawn_thread () { + pthread_t thread_id; + int pthread_ret; + + sigset_t block_mask, orig_mask; + sigemptyset (&orig_mask); + sigfillset (&block_mask); + + pthread_sigmask (SIG_BLOCK, &block_mask, &orig_mask); + + pthread_ret = pthread_create (&thread_id, NULL, log_task, NULL); + + pthread_sigmask (SIG_SETMASK, &orig_mask, NULL); + + return (thread_id); +} + +void install_signal_handler () { + struct sigaction sa; + sa.sa_handler = sig_handler; + sigemptyset (&sa.sa_mask); + sa.sa_flags = SA_RESTART; + + if (-1 == sigaction (SIGUSR1, &sa, NULL)) { + nxerr_good << "Unable to install signal handler!" << std::endl; + } + else { + nxdbg_good << "Signal handler registered successfully for SIGUSR1." << std::endl; + } +} + +void killing_process_work (pid_t parent_pid) { + /* Seed PRNG. */ + std::srand (std::time (0)); + + for (std::size_t i = 0; i < 25; ++i) { + /* Sleep for 4 seconds + some random number up to a second. */ + std::size_t rand_add = (std::rand () % 1000000); + usleep (4000000 + rand_add); + + /* Send SIGUSR1 to parent process. */ + nxdbg_good << "Sending SIGUSR1 (" << SIGUSR1 << ") to parent_pid (" << parent_pid << ")" << std::endl; + + if (kill (parent_pid, SIGUSR1)) { + int saved_errno = errno; + nxerr_good << "Failed to deliver signal to parent, aborting." << std::endl; + nxerr_good << "Error " << saved_errno << ": " << strerror (saved_errno) << std::endl; + exit (EXIT_FAILURE); + } + } + + exit (EXIT_SUCCESS); +} + +void killing_process_init (int argc, char **argv) { + /* We're in the "killing process". */ + pid_t parent_pid = getppid (); + + setup_good_logger (); + + for (std::size_t i = 0; i < argc; ++i) { + nxdbg_good << "argv[" << i << "]: " << argv[i] << std::endl; + } + + char *end = NULL; + + errno = 0; + long parent_pid_check = std::strtol (argv[1], &end, 0); + + if ((errno == ERANGE) && (parent_pid_check == LONG_MAX)) { + /* Overflow, handle gracefully. */ + parent_pid_check = 1; + } + + if ((errno == ERANGE) && (parent_pid_check == LONG_MIN)) { + /* Underflow, handle gracefully. */ + parent_pid_check = 1; + } + + if (*end) { + /* Conversion error (for inputs like "X", end will point to X.) */ + parent_pid_check = 1; + } + + if (parent_pid != parent_pid_check) { + nxinfo_good << "Parent PID verification via first argument failed, trusting getppid ()." << std::endl; + } + + killing_process_work (parent_pid); +} + +int main (int argc, char **argv) { + if (argc > 1) { + killing_process_init (argc, argv); + } + else { + /* That's the main process. */ + + /* First, fork and create the "killing process". */ + pid_t pid = fork (); + + if (0 == pid) { + /* Child process. */ + pid_t parent_pid = getppid (); + + /* Prepare to pass-through parent PID. */ + std::stringstream ss; + ss << parent_pid; + + std::vector new_argv; + new_argv.push_back (std::string (argv[0])); + new_argv.push_back (ss.str ()); + + std::vector new_argv_c_str; + for (std::vector::iterator it = new_argv.begin (); it != new_argv.end (); ++it) { + const char *elem = (*it).c_str (); + new_argv_c_str.push_back (strndup (elem, std::strlen (elem))); + } + + /* Add null pointer as last element. */ + new_argv_c_str.push_back (0); + + /* Relaunch, with argv[1] containing the ppid. */ + if (0 != execvp (new_argv_c_str.front (), &(new_argv_c_str.front ()))) { + const int saved_errno = errno; + std::cerr << "Failed to start \"killing process\"! Panic!" << std::endl; + std::cerr << "System error: " << std::strerror (saved_errno) << std::endl; + exit (EXIT_FAILURE); + } + } + else if (0 > pid) { + const int saved_errno = errno; + std::cerr << "Error while forking main process! Panic!" << std::endl; + std::cerr << "System error: " << std::strerror (saved_errno) << std::endl; + exit (EXIT_FAILURE); + } + else { + /* Main process. */ + /* Falls through to general code below. */ + } + } + + setup_faulty_logger (); + + pthread_t thread_id = spawn_thread (); + + setup_good_logger (); + + install_signal_handler (); + + /* print_sigmask (); */ + + log_task (NULL); + + pthread_join (thread_id, NULL); + + exit (EXIT_SUCCESS); +} diff --git a/nxcomp/test/logging_test.h b/nxcomp/test/logging_test.h new file mode 100644 index 000000000..239fbfe2b --- /dev/null +++ b/nxcomp/test/logging_test.h @@ -0,0 +1,121 @@ +#ifndef LOGGING_TEST_H +#define LOGGING_TEST_H + +#include + +#define INTERNAL_LOGGING_TEST +#include "Log.h" + +class Faulty_Logger : public NXLog { + /* Copied from base class, inserted "fault" within critical section. */ + using NXLog::flush; + void flush(per_thread_data *pdt) + { + sigset_t orig_signal_mask, + tmp_signal_mask; + sigemptyset(&orig_signal_mask); + + sigfillset(&tmp_signal_mask); + + pthread_sigmask(SIG_BLOCK, &tmp_signal_mask, &orig_signal_mask); + + if (!pdt->buffer.empty ()) { + const std::string str = pdt->buffer.top()->str(); + + if (!str.empty()) + { + pthread_mutex_lock(&output_lock_); + usleep (3000000); + (*stream()) << str; + pthread_mutex_unlock(&output_lock_); + } + + pdt->buffer.pop(); + } + + pthread_sigmask(SIG_SETMASK, &orig_signal_mask, NULL); + } + + template + friend Faulty_Logger& operator<<(Faulty_Logger& out, const T& value); + + friend Faulty_Logger& operator<< (Faulty_Logger& out, const NXLogStamp& value); +}; + +template +Faulty_Logger& operator<<(Faulty_Logger& out, const T& value) { + if ( out.will_log() ) { + if ( out.synchronized() ) { + // In synchronized mode, we buffer data until a newline, std::flush, or the buffer + // gets full. Then we dump the whole thing at once to the output stream, synchronizing + // with a mutex. + Faulty_Logger::per_thread_data *pdt = out.get_data(); + assert (!pdt->buffer.empty ()); + usleep (1000000); + (*pdt->buffer.top()) << value; + + if ( ss_length(pdt->buffer.top()) >= out.thread_buffer_size_ || has_newline(value) ) + out.flush(); + } + else { + // In async mode we just dump data on the output stream as-is. + // Multithreaded code will have ugly output. + *(out.stream()) << value; + } + } + + return out; +} + +Faulty_Logger& operator<< (Faulty_Logger& out, const NXLogStamp& value) +{ + out.current_level( value.level() ); + out.current_file( value.file() ); + + // Writing an NXLogStamp to the stream indicates the start of a new entry. + // If there's any content in the buffer, create a new entry in the output + // queue. + if ( out.synchronized() ) + out.new_stack_entry(); + + out << out.stamp_to_string(value); + + return out; +} + +#undef nxdbg +#undef nxinfo +#undef nxwarn +#undef nxerr +#undef nxfatal + +#define nxdbg faulty_logger << nxstamp(NXDEBUG) +#define nxinfo faulty_logger << nxstamp(NXINFO) +#define nxwarn faulty_logger << nxstamp(NXWARNING) +#define nxerr faulty_logger << nxstamp(NXERROR) +#define nxfatal faulty_logger << nxstamp(NXFATAL) + +#define nxdbg_good good_logger << nxstamp(NXDEBUG) +#define nxinfo_good good_logger << nxstamp(NXINFO) +#define nxwarn_good good_logger << nxstamp(NXWARNING) +#define nxerr_good good_logger << nxstamp(NXERROR) +#define nxfatal_good good_logger << nxstamp(NXFATAL) + +/* Helper functions used by all component. */ +void print_sigmask (); +void setup_faulty_logger (); +void setup_good_logger (); + +/* Functions used by both main and auxiliary threads. */ +void* log_task (void* /* unused */); + +/* Functions used in main thread only. */ +pthread_t spawn_thread (); +void install_signal_handler (); +void sig_handler (int signo); + +/* Functions used by "killing" process. */ +void killing_process_init (int argc, char **argv); +void killing_process_work (pid_t parent_pid); + +#endif /* !defined (LOGGING_TEST_H) */ -- cgit v1.2.3