Skip to content

Commit

Permalink
Merge pull request #390 from JeffersonLab/nbrei_logger_improvements
Browse files Browse the repository at this point in the history 
Make JLogMessage consistent with JStreamLog
  • Loading branch information
@nathanwbrei
nathanwbrei authored Dec 5, 2024
2 parents abdb575 + d9e6cd4 commit c216891
Show file tree
Hide file tree
Showing 4 changed files with 99 additions and 60 deletions.
79 changes: 26 additions & 53 deletions src/libraries/JANA/JLogger.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,6 @@
#include <time.h>



struct JLogger {
enum class Level { TRACE, DEBUG, INFO, WARN, ERROR, FATAL, OFF };
Level level;
Expand All @@ -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";
Expand All @@ -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);

Expand All @@ -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 << "[?????] ";
Expand All @@ -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)

Expand Down
12 changes: 6 additions & 6 deletions src/plugins/janacontrol/JControlZMQ.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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;
}
Expand All @@ -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;
}
Expand Down
2 changes: 1 addition & 1 deletion src/programs/unit_tests/CMakeLists.txt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,7 @@ set(TEST_SOURCES
Utils/JTablePrinterTests.cc
Utils/JStatusBitsTests.cc
Utils/JCallGraphRecorderTests.cc

Utils/JLoggerTests.cc
)

if (${USE_PODIO})
Expand Down
66 changes: 66 additions & 0 deletions src/programs/unit_tests/Utils/JLoggerTests.cc
View file
Original file line number Diff line number Diff line change
@@ -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;
}

0 comments on commit c216891

Please sign in to comment.