From b0521e8165389515b6f8290a652d7db241f84af8 Mon Sep 17 00:00:00 2001 From: Vadim Troshchinskiy Date: Thu, 22 Dec 2016 09:57:47 +0100 Subject: New logging implementation Features: * Works without ifdefs * Configurable with commandline arguments * Log level configurable per file * Thread safe --- nxcomp/src/Log.cpp | 121 ++++++++++++ nxcomp/src/Log.h | 500 +++++++++++++++++++++++++++++++++++++++++++++++++ nxcomp/src/Loop.cpp | 97 ++++++++++ nxcomp/src/Makefile.am | 1 + 4 files changed, 719 insertions(+) create mode 100644 nxcomp/src/Log.cpp create mode 100644 nxcomp/src/Log.h diff --git a/nxcomp/src/Log.cpp b/nxcomp/src/Log.cpp new file mode 100644 index 000000000..3ff47aea8 --- /dev/null +++ b/nxcomp/src/Log.cpp @@ -0,0 +1,121 @@ +/**************************************************************************/ +/* */ +/* Copyright (c) 2001, 2011 NoMachine (http://www.nomachine.com) */ +/* Copyright (c) 2008-2014 Oleksandr Shneyder */ +/* Copyright (c) 2014-2016 Ulrich Sibiller */ +/* Copyright (c) 2014-2016 Mihai Moldovan */ +/* Copyright (c) 2011-2016 Mike Gabriel */ +/* Copyright (c) 2015-2016 Qindel Group (http://www.qindel.com) */ +/* */ +/* NXCOMP, NX protocol compression and NX extensions to this software */ +/* are copyright of the aforementioned persons and companies. */ +/* */ +/* Redistribution and use of the present software is allowed according */ +/* to terms specified in the file LICENSE.nxcomp which comes in the */ +/* source distribution. */ +/* */ +/* All rights reserved. */ +/* */ +/* NOTE: This software has received contributions from various other */ +/* contributors, only the core maintainers and supporters are listed as */ +/* copyright holders. Please contact us, if you feel you should be listed */ +/* as copyright holder, as well. */ +/* */ +/**************************************************************************/ + + +#include +#include +#include +#include +#include + +#include "Log.h" + +NXLog nx_log; + + +bool NXLog::will_log() const +{ + std::map::const_iterator item = per_file_levels_.find(current_file()); + + if ( item != per_file_levels_.end() ) + { + return current_level() <= item->second; + } + else + { + return current_level() <= level(); + } +} + + +std::string NXLog::stamp_to_string(const NXLogStamp& stamp) const +{ + std::ostringstream oss; + + static const char* level_names[] = { + "FATAL", + "ERROR", + "WARN ", + "INFO ", + "DEBUG" + }; + + if ( log_level() ) + oss << ((stamp.level() >=0 && stamp.level() < NXLOG_LEVEL_COUNT ) ? level_names[stamp.level()] : "???") << " "; + + if ( log_time() ) + { + struct timeval timestamp = stamp.timestamp(); + struct tm timeinfo; + + localtime_r(×tamp.tv_sec, &timeinfo); + + if ( log_unix_time() ) + { + oss << timestamp.tv_sec; + } + else + { + #if __cplusplus >= 201103L && (!defined(__GNUC__) || __GNUC__ >= 5) + oss << " " << std::put_time(&timeinfo, "%Y/%m/%d %H:%M:%S"); + #else + oss << timestamp.tv_sec; + #endif + } + + oss << "." << std::setw(3) << std::setfill('0') << (int)(timestamp.tv_usec / 1000) << " "; + } + + if ( log_location() ) + oss << stamp.file() << "/" << stamp.function() << ":" << stamp.line() << " "; + + if ( log_thread_id() ) + { + if ( thread_name().empty() ) + oss << pthread_self() << " "; + else + oss << "[" << thread_name() << "] "; + } + + return oss.str(); +} + +NXLog& operator<< (NXLog& 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, we flush it to finalize the previous + // log entry. + if ( out.synchronized() ) + out.flush(); + + + out << out.stamp_to_string(value); + + return out; +} + diff --git a/nxcomp/src/Log.h b/nxcomp/src/Log.h new file mode 100644 index 000000000..f4ee66e1f --- /dev/null +++ b/nxcomp/src/Log.h @@ -0,0 +1,500 @@ +/**************************************************************************/ +/* */ +/* Copyright (c) 2001, 2011 NoMachine (http://www.nomachine.com) */ +/* Copyright (c) 2008-2014 Oleksandr Shneyder */ +/* Copyright (c) 2014-2016 Ulrich Sibiller */ +/* Copyright (c) 2014-2016 Mihai Moldovan */ +/* Copyright (c) 2011-2016 Mike Gabriel */ +/* Copyright (c) 2015-2016 Qindel Group (http://www.qindel.com) */ +/* */ +/* NXCOMP, NX protocol compression and NX extensions to this software */ +/* are copyright of the aforementioned persons and companies. */ +/* */ +/* Redistribution and use of the present software is allowed according */ +/* to terms specified in the file LICENSE.nxcomp which comes in the */ +/* source distribution. */ +/* */ +/* All rights reserved. */ +/* */ +/* NOTE: This software has received contributions from various other */ +/* contributors, only the core maintainers and supporters are listed as */ +/* copyright holders. Please contact us, if you feel you should be listed */ +/* as copyright holder, as well. */ +/* */ +/**************************************************************************/ + + +#ifndef NXLog_H +#define NXLog_H + +#include +#include +#include +#include + +#include +#include +#include + +/** Log severity level */ +enum NXLogLevel +{ + NXFATAL, + NXERROR, + NXWARNING, + NXINFO, + NXDEBUG, + NXLOG_LEVEL_COUNT +}; + + +/** + * Log timestamp class + * + * Stores the timestamp, file, function, line number and log level. + * Acts as a manipulator on the NXLog class, telling it a new log + * severity level. For instance: + * + * nx_log << NXLogStamp(...,NXINFO) + * + * Tells nx_log that now NXINFO type messages are being logged. This + * will be applied until a new NXLogStamp with a different level + * is sent to the NXLog. + */ +class NXLogStamp +{ + private: + std::string file_; + std::string function_; + size_t line_; + NXLogLevel level_; + struct timeval timestamp_; + + public: + /** File where the event occurred */ + std::string file() const + { + return file_; + } + + /** Function where the event occurred */ + std::string function() const + { + return function_; + } + + /** Line where the event occurred */ + size_t line() const + { + return line_; + } + + /** Severity level of the event */ + NXLogLevel level() const + { + return level_; + } + + /** Time of the event */ + struct timeval timestamp() const + { + return timestamp_; + } + + + NXLogStamp(const char *file, const char *function, int line, NXLogLevel level) + { + file_ = std::string(file); + function_ = std::string(function); + line_ = line; + level_ = level; + gettimeofday(×tamp_, NULL); + } + +}; + + +/** + * Log class + * + * Logs events to a stream, filters by file/level + */ +class NXLog +{ + NXLogLevel level_; + + std::ostream *stream_; + std::map< std::string, NXLogLevel > per_file_levels_; + bool synchronized_; + size_t thread_buffer_size_; + pthread_mutex_t output_lock_; + pthread_key_t tls_key_; + + bool log_level_; + bool log_time_; + bool log_unix_time_; + bool log_location_; + bool log_thread_id_; + + typedef struct per_thread_data_s + { + NXLogLevel current_level; + std::string* current_file; + std::string* thread_name; + std::stringstream* buffer; + NXLog* log_obj; + } per_thread_data; + + + static void free_thread_data(void* arg) + { + per_thread_data *pdt = (per_thread_data*)arg; + + if ( !pdt ) + return; + + if ( pdt->log_obj ) { + // Ensure the buffer is flushed before thread deletion + pdt->log_obj->flush(pdt); + } + + delete pdt->current_file; + delete pdt->thread_name; + delete pdt->buffer; + delete pdt; + } + + per_thread_data* get_data_int() const + { + per_thread_data *ret = NULL; + + if ( (ret = (per_thread_data*)pthread_getspecific(tls_key_)) == NULL ) + { + ret = new per_thread_data; + ret->current_level = NXDEBUG; + ret->buffer = new std::stringstream(); + ret->current_file = new std::string(); + ret->thread_name = new std::string(); + ret->log_obj = const_cast(this); + pthread_setspecific(tls_key_, ret); + } + + return ret; + } + + per_thread_data* get_data() + { + return get_data_int(); + } + + const per_thread_data* get_data() const + { + return get_data_int(); + } + + /** Convert NXLogStamp to string according to the current configuration */ + std::string stamp_to_string(const NXLogStamp& stamp) const; + + /** + * Internal flush function + * + * When a thread is being terminated and free_thread_data gets called, + * the TLS key gets set to NULL before the call to free_thread_data, + * and the destructor function gets the old value. + * + * This means that get_data() stops working correctly, and we need + * to be able to pass the old pointer. + */ + void flush(per_thread_data *pdt) + { + const std::string str = pdt->buffer->str(); + + if (!str.empty()) + { + pthread_mutex_lock(&output_lock_); + (*stream()) << str; + pthread_mutex_unlock(&output_lock_); + pdt->buffer->str(""); + } + } + + + public: + NXLog() + { + stream_ = &std::cerr; + level_ = NXDEBUG; + synchronized_ = true; + thread_buffer_size_ = 1024; + log_level_ = false; + log_time_ = false; + log_unix_time_ = false; + log_location_ = false; + log_thread_id_ = false; + + if ( pthread_key_create(&tls_key_, free_thread_data) != 0 ) + { + std::cerr << "pthread_key_create failed" << std::endl; + abort(); + } + + } + + ~NXLog() + { + per_thread_data *pdt = get_data(); + + // Flush any remaining output and delete TLS data + free_thread_data(pdt); + + pthread_key_delete(tls_key_); + } + + /** Minimum severity level to output */ + NXLogLevel level() const + { + return level_; + } + + void level(NXLogLevel level) + { + level_ = level; + } + + + /** Current severity level */ + NXLogLevel current_level() const + { + return get_data()->current_level; + } + + void current_level(NXLogLevel level) + { + get_data()->current_level = level; + } + + /** Source file from which messages are currently originating */ + std::string current_file() const + { + return *get_data()->current_file; + } + + void current_file(std::string val) + { + *get_data()->current_file = val; + } + + std::ostream* stream() const + { + return stream_; + } + + void stream(std::ostream *stream) + { + flush(); + stream_ = stream; + } + + bool synchronized() const { + return synchronized_; + } + + void synchronized(bool val) { + synchronized_ = val; + } + + bool log_level() const + { + return log_level_; + } + + void log_level(bool val) + { + log_level_ = val; + } + + bool log_time() const + { + return log_time_; + } + + void log_time(bool val) + { + log_time_ = val; + } + + bool log_unix_time() const + { + return log_unix_time_; + } + + void log_unix_time(bool val) + { + log_unix_time_ = val; + } + + bool log_location() const + { + return log_location_; + } + + void log_location(bool val) + { + log_location_ = val; + } + + bool log_thread_id() const + { + return log_thread_id_; + } + + void log_thread_id(bool val) + { + log_thread_id_ = val; + } + + + void flush() + { + per_thread_data *pdt = get_data(); + flush(pdt); + } + + std::string thread_name() const + { + return *get_data()->thread_name; + } + + void thread_name(std::string str) + { + *get_data()->thread_name = str; + } + + void thread_name(const char *str) + { + *get_data()->thread_name = str; + } + + /** + * True if a message sent to the NXLog object will be sent to the output + * + * This considers two things: + * + * If there's a per-file log level, then it is used + * Otherwise the global log level is used. + * + * If the log level permits the current message to be output, then the + * return value is true. + */ + bool will_log() const; + + + /** + * This catches std::flush + */ + NXLog& operator<<(std::ostream& (*F)(std::ostream&)) + { + if ( will_log() ) + { + if ( synchronized() ) + { + per_thread_data *pdt = get_data(); + (*pdt->buffer) << F; + flush(); + } + else + { + *(stream()) << F; + } + } + + return *this; + } + + template + friend NXLog& operator<<(NXLog& out, const T& value); + + friend NXLog& operator<< (NXLog& out, const NXLogStamp& value); +}; + + +extern NXLog nx_log; + + +#define nxstamp(l) NXLogStamp(__FILE__, __func__, __LINE__, l) + + +#define nxdbg nx_log << nxstamp(NXDEBUG) +#define nxinfo nx_log << nxstamp(NXINFO) +#define nxwarn nx_log << nxstamp(NXWARNING) +#define nxerr nx_log << nxstamp(NXERROR) +#define nxfatal nx_log << nxstamp(NXFATAL) + + +NXLog& operator<< (NXLog& out, const NXLogStamp& value); + + +template +bool has_newline(T value) +{ + return false; +} + +template +static bool has_newline(char *value) +{ + return strstr(value, "\n") != NULL; +} + +template +static bool has_newline(char value) +{ + return value == '\n'; +} + +template +static bool has_newline(std::string &value) +{ + return value.find_first_of("\n") != std::string::npos; +} + +static size_t ss_length(std::stringstream *ss) +{ + size_t pos = ss->tellg(); + size_t ret = 0; + ss->seekg(0, std::ios::end); + ret = ss->tellg(); + ss->seekg(pos, std::ios::beg); + return ret; +} + +template +NXLog& operator<<(NXLog& 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. + NXLog::per_thread_data *pdt = out.get_data(); + (*pdt->buffer) << value; + + if ( ss_length(pdt->buffer) >= 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; +} + +#endif diff --git a/nxcomp/src/Loop.cpp b/nxcomp/src/Loop.cpp index 4292e7b9a..681a5a1ef 100644 --- a/nxcomp/src/Loop.cpp +++ b/nxcomp/src/Loop.cpp @@ -101,6 +101,7 @@ typedef int socklen_t; #include "Message.h" #include "ChannelEndPoint.h" +#include "Log.h" // // System specific defines. @@ -9339,6 +9340,102 @@ int ParseCommandLineOptions(int argc, const char **argv) return -1; } + case 'd': + { + if ( argi+1 >= argc ) + { + PrintUsageInfo(nextArg, 0); + return -1; + } + + int level = 0; + errno = 0; + level = strtol(argv[argi+1], NULL, 10); + + if ( errno && (level == 0) ) + { + cerr << "Warning: Failed to parse log level. Ignoring option." << std::endl; + } + if ( level < 0 ) + { + cerr << "Warning: Log level must be a positive integer. Ignoring option." << std::endl; + level = nx_log.level(); + } + else if ( level >= NXLOG_LEVEL_COUNT ) + { + cerr << "Warning: Log level is greater than the maximum " << NXLOG_LEVEL_COUNT-1 << ". Setting to the maximum." << std::endl; + level = NXLOG_LEVEL_COUNT-1; + } + + nx_log.level( (NXLogLevel)level ); + + argi++; + break; + + } + case 'o': + { + if ( argi + 1 >= argc ) + { + PrintUsageInfo(nextArg, 0); + return -1; + } + + std::ofstream *logfile = new std::ofstream(); + + // Unbuffered output + logfile->rdbuf()->pubsetbuf(0, 0); + logfile->open(argv[argi+1], std::ofstream::app); + + if ( logfile->is_open() ) + { + nx_log.stream(logfile); + } + else + { + cerr << "Failed to open log file " << argv[argi+1] << endl; + return -1; + } + + argi++; + break; + } + case 'f': + { + if ( argi + 1 >= argc ) + { + PrintUsageInfo(nextArg, 0); + return -1; + } + + const char *format = argv[argi+1]; + size_t pos = 0; + + nx_log.log_level(false); + nx_log.log_time(false); + nx_log.log_unix_time(false); + nx_log.log_location(false); + nx_log.log_thread_id(false); + + for(pos =0;pos