Make JLogMessage consistent with JStreamLog

src/libraries/JANA/JLogger.h

@@ -14,7 +14,6 @@
 #include <time.h>
 
 
-
 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(&current_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 <typename T>
-inline JLogMessage operator<<(JLogger& l, const T& t) {
-    JLogMessage m(l);
-    m.builder << t;
-    return m;
-}
-
-template<typename T>
-inline JLogMessage& operator<<(JLogMessage& m, const T& t) {
-    m.builder << t;
-    return m;
-}
-
-template<typename T>
-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)
 

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;
 			}

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})

src/programs/unit_tests/Utils/JLoggerTests.cc

@@ -0,0 +1,66 @@
+
+#include <catch.hpp>
+#include <iostream>
+#include <JANA/JLogger.h>
+
+
+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;
+}
+