diff --git a/src/libraries/JANA/JLogger.h b/src/libraries/JANA/JLogger.h index df02124a5..b027dd0f7 100644 --- a/src/libraries/JANA/JLogger.h +++ b/src/libraries/JANA/JLogger.h @@ -14,7 +14,6 @@ #include - struct JLogger { enum class Level { TRACE, DEBUG, INFO, WARN, ERROR, FATAL, OFF }; Level level; @@ -40,9 +39,11 @@ struct JLogger { void ShowThreadstamp(bool show) {show_threadstamp = show; } }; + static JLogger default_cout_logger = JLogger(JLogger::Level::TRACE, &std::cout, "JANA"); static JLogger default_cerr_logger = JLogger(JLogger::Level::TRACE, &std::cerr, "JERR"); + inline std::ostream& operator<<(std::ostream& s, JLogger::Level l) { switch (l) { case JLogger::Level::TRACE: return s << "trace"; @@ -55,25 +56,20 @@ inline std::ostream& operator<<(std::ostream& s, JLogger::Level l) { } } -/// -struct JLogMessage { - - /// Message terminator - struct End {}; - const JLogger& logger; - JLogger::Level level; - std::ostringstream builder; +class JLogMessage : public std::stringstream { +private: + std::string m_prefix; +public: + JLogMessage(const std::string& prefix="") : m_prefix(prefix){ + } - JLogMessage(const JLogger& logger = default_cout_logger, - JLogger::Level level = JLogger::Level::INFO) - : logger(logger), level(level) { - + JLogMessage(const JLogger& logger, JLogger::Level level) { + std::ostringstream builder; if (logger.show_timestamp) { auto now = std::chrono::system_clock::now(); std::time_t current_time = std::chrono::system_clock::to_time_t(now); - tm tm_buf; localtime_r(¤t_time, &tm_buf); @@ -86,8 +82,8 @@ struct JLogMessage { switch (level) { case JLogger::Level::TRACE: builder << "[trace] "; break; case JLogger::Level::DEBUG: builder << "[debug] "; break; - case JLogger::Level::INFO: builder << "[info] "; break; - case JLogger::Level::WARN: builder << "[warn] "; break; + case JLogger::Level::INFO: builder << " [info] "; break; + case JLogger::Level::WARN: builder << " [warn] "; break; case JLogger::Level::ERROR: builder << "[error] "; break; case JLogger::Level::FATAL: builder << "[fatal] "; break; default: builder << "[?????] "; @@ -96,56 +92,33 @@ struct JLogMessage { if (logger.show_threadstamp) { builder << std::this_thread::get_id() << " "; } - if (logger.show_group) { - builder << "[" << logger.group << "] "; + if (logger.show_group && !logger.group.empty()) { + builder << logger.group << " > "; } + m_prefix = builder.str(); } - // Helper function for truncating long strings to keep our log readable - // This should probably live somewhere else - std::string ltrunc(std::string original, size_t desired_length) { - auto n = original.length(); - if (n <= desired_length) return original; - return "\u2026" + original.substr(n - desired_length, desired_length - 1); + virtual ~JLogMessage() { + std::string line; + std::ostringstream oss; + while (std::getline(*this, line)) { + oss << m_prefix << line << std::endl; + } + std::cout << oss.str(); + std::cout.flush(); + this->str(""); + this->clear(); } }; -/// Stream operators - -template -inline JLogMessage operator<<(JLogger& l, const T& t) { - JLogMessage m(l); - m.builder << t; - return m; -} - -template -inline JLogMessage& operator<<(JLogMessage& m, const T& t) { - m.builder << t; - return m; -} - -template -inline JLogMessage&& operator<<(JLogMessage&& m, const T& t) { - m.builder << t; - return std::move(m); -} - -inline void operator<<(JLogMessage&& m, JLogMessage::End const&) { - std::ostream& dest = *m.logger.destination; - m.builder << std::endl; - dest << m.builder.str(); - dest.flush(); -} - /// Macros #define LOG JLogMessage() #define LOG_IF(predicate) if (predicate) JLogMessage() -#define LOG_END JLogMessage::End(); +#define LOG_END std::endl #define LOG_AT_LEVEL(logger, msglevel) if ((logger).level <= msglevel) JLogMessage((logger), msglevel) diff --git a/src/plugins/janacontrol/JControlZMQ.cc b/src/plugins/janacontrol/JControlZMQ.cc index f370ec54d..d843c2117 100644 --- a/src/plugins/janacontrol/JControlZMQ.cc +++ b/src/plugins/janacontrol/JControlZMQ.cc @@ -86,7 +86,7 @@ JControlZMQ::JControlZMQ(JApplication *app, int port):_japp(app), _port(port) { // This is called from jcontrol plugin's InitPlugin() routine - LOG << "Launching JControlZMQ thread ..." << LOG_END + LOG << "Launching JControlZMQ thread ..." << LOG_END; // Create new zmq context, get the current host name, and launch server thread _zmq_context = zmq_ctx_new(); @@ -110,10 +110,10 @@ JControlZMQ::~JControlZMQ() // Tell server thread to quit and wait for it to finish _done =true; if(_thr != nullptr) { - LOG << "Joining JControlZMQ thread ..." << LOG_END + LOG << "Joining JControlZMQ thread ..." << LOG_END; _thr->join(); delete _thr; - LOG << "JControlZMQ thread joined." << LOG_END + LOG << "JControlZMQ thread joined." << LOG_END; } // Delete the zmq context @@ -132,7 +132,7 @@ void JControlZMQ::ServerLoop() /// indefinitely until the internal _done member is set to true. /// Currently, that is done only by calling the destructor. - LOG << "JControlZMQ server starting ..." << LOG_END + LOG << "JControlZMQ server starting ..." << LOG_END; // This just makes it easier to identify this thread while debugging. // Linux and Mac OS X use different calling signatures for pthread_setname_np @@ -148,7 +148,7 @@ void JControlZMQ::ServerLoop() void *responder = zmq_socket( _zmq_context, ZMQ_REP ); auto ret = zmq_bind( responder, bind_str); if( ret != 0 ){ - LOG << "JControlZMQ: Unable to bind zeroMQ control socket " << _port << "!" << LOG_END + LOG << "JControlZMQ: Unable to bind zeroMQ control socket " << _port << "!" << LOG_END; perror("zmq_bind"); return; } @@ -164,7 +164,7 @@ void JControlZMQ::ServerLoop() std::this_thread::sleep_for(std::chrono::milliseconds(250)); continue; }else{ - LOG << "JControlZMQ: ERROR listening on control socket: errno=" << errno << LOG_END + LOG << "JControlZMQ: ERROR listening on control socket: errno=" << errno << LOG_END; _done = true; continue; } diff --git a/src/programs/unit_tests/CMakeLists.txt b/src/programs/unit_tests/CMakeLists.txt index bc5284b17..720938748 100644 --- a/src/programs/unit_tests/CMakeLists.txt +++ b/src/programs/unit_tests/CMakeLists.txt @@ -39,7 +39,7 @@ set(TEST_SOURCES Utils/JTablePrinterTests.cc Utils/JStatusBitsTests.cc Utils/JCallGraphRecorderTests.cc - + Utils/JLoggerTests.cc ) if (${USE_PODIO}) diff --git a/src/programs/unit_tests/Utils/JLoggerTests.cc b/src/programs/unit_tests/Utils/JLoggerTests.cc new file mode 100644 index 000000000..23bc3d221 --- /dev/null +++ b/src/programs/unit_tests/Utils/JLoggerTests.cc @@ -0,0 +1,66 @@ + +#include +#include +#include + + +TEST_CASE("JLogMessage_DestructorOrdering") { + + { + JLogMessage m("JANA: "); + // This will destruct immediately, but only because it's in its own scope + m << "1. This is a test"; + REQUIRE(m.str() == "1. This is a test"); + + m << std::endl << " which continues on the second line"; + REQUIRE(m.str() == "1. This is a test\n which continues on the second line"); + } + + std::cout << std::endl; + + JLogger logger {JLogger::Level::WARN, &std::cout, "jana"}; + logger.show_group = true; + if (logger.level >= JLogger::Level::WARN) { + JLogMessage msg(logger, JLogger::Level::INFO); + msg << "2. This will print at level INFO and include" << std::endl; + msg << " multiple lines and the group name 'jana'" << std::endl; + msg << " It will destruct immediately because it is inside an if-block"; + } + + std::cout << std::endl; + + if (logger.level >= JLogger::Level::WARN) JLogMessage("jaanaa >> ") << "3. This destructs immediately even without enclosing braces"; + + std::cout << std::endl; + + JLogMessage("Silly: ") << "4. This message will destruct immediately because it is an rvalue"; + + std::cout << std::endl; + + std::cout << "6. This should be the last thing printed, assuming our destructors behave" << std::endl; + +} + +TEST_CASE("JLogMessage_Newlines") { + + JLogMessage("jaanaa> ") << "1. This message has a trailing newline in the code but shouldn't in the output" << std::endl; + JLogMessage("jaanaa> ") << "2. This message has no trailing newline in either the code or the output"; + + std::cout << "--------" << std::endl; + std::cout << "The following line should just be log metadata with no log message" << std::endl; + JLogMessage("jaanaa> ") << std::endl; + std::cout << "--------" << std::endl; + + JLogMessage("jaanaa> ") << "There should be a line of just log metadata below this one" << std::endl << std::endl; + JLogMessage("jaanaa> ") << "This should be the last line prefixed with 'jaanaa'."; + + JLogger logger {JLogger::Level::DEBUG, &std::cout, "jana"}; + + LOG_INFO(logger) << "This message has a trailing newline in the code but shouldn't in the output" << std::endl; + LOG_INFO(logger) << "This message has a trailing newline in the code but shouldn't in the output" << LOG_END; + + LOG_INFO(logger) << "This message has a trailing newline containing log metadata" << std::endl << std::endl; + LOG_INFO(logger) << "This message has a trailing newline containing log metadata" << LOG_END << LOG_END; + LOG_INFO(logger) << "This message has a trailing newline containing log metadata " << std::endl << LOG_END; +} +