Skip to content

Commit

Permalink
Merge pull request #27 from ethz-asl/fix/timed-logging
Browse files Browse the repository at this point in the history 
Fixed LOG_TIMED and ROS_INFO_THROTTLE macros in MODE_GLOG
  • Loading branch information
@4c3y
4c3y authored Apr 17, 2024
2 parents 59b2f2d + 9342236 commit b190abd
Show file tree
Hide file tree
Showing 7 changed files with 522 additions and 36 deletions.
3 changes: 3 additions & 0 deletions CMakeLists.txt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -89,6 +89,7 @@ if (GLOG_FOUND AND catkin_FOUND AND LPP_BUILD_TESTS)
test/glog/test_glog_if_every_n.cc
test/glog/test_glog_log_string.cc
test/glog/test_glog_rosprintf.cc
test/glog/test_glog_timed.cc
test/glog/test_glog_vlog.cc)

target_include_directories(${GLOG_TESTS} PRIVATE ${LPP_INCLUDE_DIRECTORIES} test/glog)
Expand All @@ -105,6 +106,7 @@ if (GLOG_FOUND AND catkin_FOUND AND LPP_BUILD_TESTS)
test/lpp/test_lpp_if_every_n.cc
test/lpp/test_lpp_log_string.cc
test/lpp/test_lpp_rosprintf.cc
test/lpp/test_lpp_timed.cc
test/lpp/test_lpp_vlog.cc)

target_include_directories(${LPP_TESTS} PRIVATE ${LPP_INCLUDE_DIRECTORIES} test/lpp)
Expand Down Expand Up @@ -138,6 +140,7 @@ if (GLOG_FOUND AND catkin_FOUND AND LPP_BUILD_TESTS)
test/roslog/test_roslog_if_every_n.cc
test/roslog/test_roslog_log_string.cc
test/roslog/test_roslog_rosprintf.cc
test/roslog/test_roslog_timed.cc
test/roslog/test_roslog_vlog.cc)

target_include_directories(${ROSLOG_TESTS} PRIVATE ${LPP_INCLUDE_DIRECTORIES} test/roslog)
Expand Down
149 changes: 114 additions & 35 deletions include/log++.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -278,10 +278,15 @@ inline void LOG_INIT([[maybe_unused]] char *argv, [[maybe_unused]] const std::fu
#define LOG_1(severity) COMPACT_GOOGLE_LOG_ ## severity.stream()

#ifndef LOG_EVERY_T
#define LPP_INTL_LOG_EVERY_T(severity, t) LPP_WARN("LOG_EVERY_T is only defined in GLOG v0.6 or newer. File name and line numbers will be invalid in the log output.") \
LPP_INTL::InternalPolicyLog<float>(LPP_GET_KEY(), t, toBase(severity), LPP_INTL::PolicyType::TIMED)

#define LOG_EVERY_T(severity, t) LPP_WARN("LOG_EVERY_T is only defined in GLOG v0.6 or newer.") \
LPP_INTL::InternalPolicyLog(LPP_GET_KEY(), t, toBase(LPP_INTL::GlogSeverity::severity), LPP_INTL::PolicyType::TIMED)
LPP_INTL::InternalPolicyLog<float>(LPP_GET_KEY(), t, toBase(LPP_INTL::GlogSeverity::severity), LPP_INTL::PolicyType::TIMED)
#endif

#define LPP_INTL_DLOG_EVERY_T(severity, t) LPP_WARN("File name and line numbers will be invalid in the log output.") LOG_EVERY_T(severity, t)

#ifndef DLOG_EVERY_T
#define DLOG_EVERY_T(severity, t) LPP_WARN("DLOG_EVERY_T is a Log++ extension") \
LPP_INTL::LppGlogExtensionLog(LPP_GET_KEY(), t, LPP_INTL::GlogSeverity::severity, LPP_INTL::PolicyType::TIMED, [](const std::string& str) {LOG_1(severity) << str;})
Expand Down Expand Up @@ -321,6 +326,15 @@ else if constexpr(LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::E) {
else if constexpr(LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::F) {LOG_FIRST_N(FATAL, n) << x;} \
} while(0)

#define LOG_TIMED(severity, t, x) do { \
if constexpr(LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::I \
|| LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::W \
|| LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::E \
|| LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::F \
|| LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::D \
){LPP_INTL_LOG_EVERY_T(LppSeverity::severity, t) << x;} \
} while(0)

#ifndef MODE_DEFAULT
#define ROS_DEBUG(...) DLOG(INFO) << LPP_INTL::formatToString(__VA_ARGS__)
#define ROS_DEBUG_STREAM(x) DLOG(INFO) << x
Expand Down Expand Up @@ -349,6 +363,17 @@ else if constexpr(LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::F) {
#define ROS_WARN_ONCE(...) LOG_FIRST_N(WARNING, 1) << LPP_INTL::formatToString(__VA_ARGS__)
#define ROS_ERROR_ONCE(...) LOG_FIRST_N(ERROR, 1) << LPP_INTL::formatToString(__VA_ARGS__)
#define ROS_FATAL_ONCE(...) LOG_FIRST_N(FATAL, 1) << LPP_INTL::formatToString(__VA_ARGS__)

#define ROS_DEBUG_THROTTLE(n, ...) LPP_INTL_DLOG_EVERY_T(INFO, n) << LPP_INTL::formatToString(__VA_ARGS__);
#define ROS_DEBUG_STREAM_THROTTLE(n, x) LPP_INTL_DLOG_EVERY_T(INFO, n) << x
#define ROS_INFO_THROTTLE(n, ...) LPP_INTL_LOG_EVERY_T(LppSeverity::I, n) << LPP_INTL::formatToString(__VA_ARGS__);
#define ROS_INFO_STREAM_THROTTLE(n, x) LPP_INTL_LOG_EVERY_T(LppSeverity::I, n) << x
#define ROS_WARN_THROTTLE(n, ...) LPP_INTL_LOG_EVERY_T(LppSeverity::W, n) << LPP_INTL::formatToString(__VA_ARGS__);
#define ROS_WARN_STREAM_THROTTLE(n, x) LPP_INTL_LOG_EVERY_T(LppSeverity::W, n) << x
#define ROS_ERROR_THROTTLE(n, ...) LPP_INTL_LOG_EVERY_T(LppSeverity::E, n) << LPP_INTL::formatToString(__VA_ARGS__);
#define ROS_ERROR_STREAM_THROTTLE(n, x) LPP_INTL_LOG_EVERY_T(LppSeverity::E, n) << x
#define ROS_FATAL_THROTTLE(n, ...) LPP_INTL_LOG_EVERY_T(LppSeverity::F, n) << LPP_INTL::formatToString(__VA_ARGS__);
#define ROS_FATAL_STREAM_THROTTLE(n, x) LPP_INTL_LOG_EVERY_T(LppSeverity::F, n) << x
#endif

#pragma clang diagnostic pop
Expand All @@ -365,9 +390,9 @@ else if constexpr(LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::F) {
#endif

#if defined MODE_ROSLOG || defined MODE_LPP || defined MODE_DEFAULT
#define LOG_EVERY(severity, n, x) LPP_INTL::InternalLogCount::getInstance().update(LPP_GET_KEY(), n, LPP_INTL::InternalLog() << x, toBase(LPP_INTL::LppSeverity::severity), LPP_INTL::PolicyType::EVERY_N) // NOLINT(bugprone-macro-parentheses)
#define LOG_FIRST(severity, n, x) LPP_INTL::InternalLogCount::getInstance().update(LPP_GET_KEY(), n, LPP_INTL::InternalLog() << x, toBase(LPP_INTL::LppSeverity::severity), LPP_INTL::PolicyType::FIRST_N) // NOLINT(bugprone-macro-parentheses)
#define LOG_TIMED(severity, n, x) LPP_INTL::InternalLogCount::getInstance().update(LPP_GET_KEY(), n, LPP_INTL::InternalLog() << x, toBase(LPP_INTL::LppSeverity::severity), LPP_INTL::PolicyType::TIMED) // NOLINT(bugprone-macro-parentheses)
#define LOG_EVERY(severity, n, x) LPP_INTL::InternalLogCount::getInstance().update<unsigned int, LPP_INTL::PolicyType::EVERY_N>(LPP_GET_KEY(), n, LPP_INTL::InternalLog() << x, toBase(LPP_INTL::LppSeverity::severity)) // NOLINT(bugprone-macro-parentheses)
#define LOG_FIRST(severity, n, x) LPP_INTL::InternalLogCount::getInstance().update<unsigned int, LPP_INTL::PolicyType::FIRST_N>(LPP_GET_KEY(), n, LPP_INTL::InternalLog() << x, toBase(LPP_INTL::LppSeverity::severity)) // NOLINT(bugprone-macro-parentheses)
#define LOG_TIMED(severity, t, x) LPP_INTL::InternalLogCount::getInstance().update<float, LPP_INTL::PolicyType::TIMED>(LPP_GET_KEY(), t, LPP_INTL::InternalLog() << x, toBase(LPP_INTL::LppSeverity::severity)) // NOLINT(bugprone-macro-parentheses)
#endif

#if defined MODE_ROSLOG || defined MODE_LPP || MODE_NOLOG
Expand All @@ -383,15 +408,17 @@ else if constexpr(LPP_INTL::LppSeverity::severity == LPP_INTL::LppSeverity::F) {
#endif //defined MODE_ROSLOG || defined MODE_LPP || MODE_NOLOG

#if defined MODE_ROSLOG || defined MODE_LPP
#define LOG_EVERY_N(severity, n) LPP_INTL::InternalPolicyLog(LPP_GET_KEY(), n, LPP_INTL::toBase(LPP_INTL::GlogSeverity::severity), LPP_INTL::PolicyType::EVERY_N)
#define LOG_EVERY_N(severity, n) LPP_INTL::InternalPolicyLog<unsigned int>(LPP_GET_KEY(), n, LPP_INTL::toBase(LPP_INTL::GlogSeverity::severity), LPP_INTL::PolicyType::EVERY_N)
#define LOG_EVERY_T(severity, t) LPP_WARN("LOG_EVERY_T is only defined in GLOG v0.6 or newer.") LPP_INTL::InternalPolicyLog<float>(LPP_GET_KEY(), t, LPP_INTL::toBase(LPP_INTL::GlogSeverity::severity), LPP_INTL::PolicyType::TIMED)
#define LOG_IF_EVERY_N(severity, condition, n) if (condition) LOG_EVERY_N(severity, n)
#define LOG_FIRST_N(severity, n) LPP_INTL::InternalPolicyLog(LPP_GET_KEY(), n, LPP_INTL::toBase(LPP_INTL::GlogSeverity::severity), LPP_INTL::PolicyType::FIRST_N)
#define LOG_FIRST_N(severity, n) LPP_INTL::InternalPolicyLog<unsigned int>(LPP_GET_KEY(), n, LPP_INTL::toBase(LPP_INTL::GlogSeverity::severity), LPP_INTL::PolicyType::FIRST_N)

#define DLOG(severity) LPP_ASSERT_GLOG(LPP_INTL::GlogSeverity::severity); LPP_INTL::InternalLog(LPP_INTL::BaseSeverity::DEBUG)
#define DLOG_EVERY_N(severity, n) LPP_ASSERT_GLOG(LPP_INTL::GlogSeverity::severity); LPP_INTL::InternalPolicyLog(LPP_GET_KEY(), n, LPP_INTL::BaseSeverity::DEBUG, LPP_INTL::PolicyType::EVERY_N)
#define DLOG_EVERY_N(severity, n) LPP_ASSERT_GLOG(LPP_INTL::GlogSeverity::severity); LPP_INTL::InternalPolicyLog<unsigned int>(LPP_GET_KEY(), n, LPP_INTL::BaseSeverity::DEBUG, LPP_INTL::PolicyType::EVERY_N)
#define DLOG_EVERY_T(severity, t) LPP_WARN("DLOG_FIRST_N is a Log++ extension"); LPP_ASSERT_GLOG(LPP_INTL::GlogSeverity::severity); LPP_INTL::InternalPolicyLog<float>(LPP_GET_KEY(), t, LPP_INTL::BaseSeverity::DEBUG, LPP_INTL::PolicyType::TIMED)
#define DLOG_FIRST_N(severity, n) LPP_WARN("DLOG_FIRST_N is a Log++ extension"); LPP_ASSERT_GLOG(LPP_INTL::GlogSeverity::severity); \
LPP_INTL::InternalPolicyLog(LPP_GET_KEY(), n, LPP_INTL::BaseSeverity::DEBUG, LPP_INTL::PolicyType::FIRST_N)
#define DLOG_IF_EVERY_N(severity, condition, n) LPP_ASSERT_GLOG(LPP_INTL::GlogSeverity::severity); if (condition) LPP_INTL::InternalPolicyLog(LPP_GET_KEY(), n, LPP_INTL::BaseSeverity::DEBUG, LPP_INTL::PolicyType::EVERY_N)
LPP_INTL::InternalPolicyLog<unsigned int>(LPP_GET_KEY(), n, LPP_INTL::BaseSeverity::DEBUG, LPP_INTL::PolicyType::FIRST_N)
#define DLOG_IF_EVERY_N(severity, condition, n) LPP_ASSERT_GLOG(LPP_INTL::GlogSeverity::severity); if (condition) LPP_INTL::InternalPolicyLog<unsigned int>(LPP_GET_KEY(), n, LPP_INTL::BaseSeverity::DEBUG, LPP_INTL::PolicyType::EVERY_N)
#define LOG_STRING(severity, ptr) LPP_ASSERT_GLOG(LPP_INTL::GlogSeverity::severity); LPP_INTL::InternalGlogLogStringLog(toBase(LPP_INTL::GlogSeverity::severity), ptr)

#undef VLOG_IS_ON
Expand Down Expand Up @@ -432,6 +459,17 @@ LPP_INTL::InternalPolicyLog(LPP_GET_KEY(), n, LPP_INTL::BaseSeverity::DEBUG, LPP
#define ROS_ERROR_ONCE(...) LOG_FIRST(E, 1, LPP_INTL::formatToString(__VA_ARGS__))
#define ROS_FATAL_ONCE(...) LOG_FIRST(F, 1, LPP_INTL::formatToString(__VA_ARGS__))

#define ROS_DEBUG_THROTTLE(period, ...) LOG_TIMED(D, period, LPP_INTL::formatToString(__VA_ARGS__))
#define ROS_DEBUG_STREAM_THROTTLE(period, x) LOG_TIMED(D, period, x)
#define ROS_INFO_THROTTLE(period, ...) LOG_TIMED(I, period, LPP_INTL::formatToString(__VA_ARGS__))
#define ROS_INFO_STREAM_THROTTLE(period, x) LOG_TIMED(I, period, x)
#define ROS_WARN_THROTTLE(period, ...) LOG_TIMED(W, period, LPP_INTL::formatToString(__VA_ARGS__))
#define ROS_WARN_STREAM_THROTTLE(period, x) LOG_TIMED(W, period, x)
#define ROS_ERROR_THROTTLE(period, ...) LOG_TIMED(E, period, LPP_INTL::formatToString(__VA_ARGS__))
#define ROS_ERROR_STREAM_THROTTLE(period, x) LOG_TIMED(E, period, x)
#define ROS_FATAL_THROTTLE(period, ...) LOG_TIMED(F, period, LPP_INTL::formatToString(__VA_ARGS__))
#define ROS_FATAL_STREAM_THROTTLE(period, x) LOG_TIMED(F, period, x)

#define LOG_IF(severity, cond) if (cond) LPP_INTL::InternalLog(GlogSeverity::severity)
#define LOG_1(severity) LPP_INTL::InternalLog(LPP_INTL::GlogSeverity::severity)
#endif
Expand Down Expand Up @@ -594,6 +632,25 @@ class InternalLog {
#endif
#if defined MODE_LPP || defined MODE_DEFAULT
lpp::internal::logging.call(severity_, ss.str());
#endif
#if defined MODE_GLOG
switch (severity_) {
case BaseSeverity::DEBUG:
LOG(INFO) << ss.str();
break;
case BaseSeverity::INFO:
LOG(INFO) << ss.str();
break;
case BaseSeverity::WARN:
LOG(WARNING) << ss.str();
break;
case BaseSeverity::ERROR:
LOG(ERROR) << ss.str();
break;
case BaseSeverity::FATAL:
LOG(FATAL) << ss.str();
break;
}
#endif
}

Expand All @@ -617,21 +674,31 @@ class InternalCondLog : public InternalLog {
};


class LogPolicy {
class LogPolicyBase {
public:
virtual void update() = 0;
[[nodiscard]] virtual bool shouldLog() const = 0;
virtual void onLog() {};
virtual ~LogPolicy() = default;
protected:
explicit LogPolicy(int max) : max_(max) {}
int counter_{0};
int max_{0};
};

class OccasionPolicy : public LogPolicy {
template<typename T>
class LogPolicy : public LogPolicyBase {
public:
explicit LogPolicy(T max) : max_(max) {}
protected:
T max_{0};
};

class CountableLogPolicy : public LogPolicy<unsigned int> {
public:
explicit CountableLogPolicy(unsigned int max) : LogPolicy(max) {}
protected:
unsigned int counter_{0};
};

class OccasionPolicy : public CountableLogPolicy {
public:
explicit OccasionPolicy(int max) : LogPolicy(max) {
explicit OccasionPolicy(unsigned int max) : CountableLogPolicy(max) {
counter_ = max_;
}

Expand All @@ -649,13 +716,14 @@ class OccasionPolicy : public LogPolicy {
return should_log_;
}

virtual ~OccasionPolicy() = default;
private:
bool should_log_{false};
};

class FirstNOccurrencesPolicy : public LogPolicy {
class FirstNOccurrencesPolicy : public CountableLogPolicy {
public:
explicit FirstNOccurrencesPolicy(int max) : LogPolicy(max) {}
explicit FirstNOccurrencesPolicy(unsigned int max) : CountableLogPolicy(max) {}
inline void update() override {
if (!is_n_occurences_reached) {
counter_++;
Expand All @@ -670,22 +738,23 @@ class FirstNOccurrencesPolicy : public LogPolicy {
return !is_n_occurences_reached;
}

virtual ~FirstNOccurrencesPolicy() = default;
private:
bool is_n_occurences_reached = false;
};

using namespace std::chrono;

class TimePolicy : public LogPolicy {
class TimePolicy : public LogPolicy<float> {
public:
explicit TimePolicy(int max) : LogPolicy(max) {};
explicit TimePolicy(float max) : LogPolicy(max) {};

inline void update() override {
now_ = duration_cast<microseconds>(system_clock::now().time_since_epoch()).count();
}

[[nodiscard]] inline bool shouldLog() const override {
if (now_ >= last_ + (max_ * 1000000)) {
if (now_ >= last_ + static_cast<long>(max_ * 1000000.f)) {
return true;
}
return false;
Expand All @@ -695,6 +764,7 @@ class TimePolicy : public LogPolicy {
last_ = now_;
}

virtual ~TimePolicy() = default;
private:
long now_{0};
long last_{0};
Expand All @@ -706,11 +776,12 @@ enum PolicyType {
TIMED
};

typedef std::shared_ptr<LogPolicy> LogPolicyPtr;
typedef std::shared_ptr<LogPolicyBase> LogPolicyPtr;

class LogPolicyFactory {
public:
static LogPolicyPtr create(PolicyType policy_type, int max) {
template<typename T>
static LogPolicyPtr create(PolicyType policy_type, T max) {
switch (policy_type) {
case FIRST_N: return std::make_shared<FirstNOccurrencesPolicy>(max);
case EVERY_N: return std::make_shared<OccasionPolicy>(max);
Expand All @@ -735,16 +806,23 @@ class InternalLogCount {
return instance;
}

template<typename T, PolicyType policyType>
inline void update(const std::string &key,
int max,
T max,
const InternalLog &internal_log,
const BaseSeverity base_severity,
PolicyType policy_type) {
update(key, max, internal_log.ss.str(), base_severity, policy_type);
const BaseSeverity base_severity) {
//Check if T is a float and only allow it for PolicyType::TIMED
static_assert(std::is_same<T, unsigned int>::value || std::is_same<T, float>::value, "Only int or float is allowed for T");

if constexpr (std::is_same<T, float>::value) {
static_assert(policyType == PolicyType::TIMED, "Only PolicyType::TIMED can be used with float");
}
update(key, max, internal_log.ss.str(), base_severity, policyType);
}

template<typename T>
inline void update(const std::string &key,
int max,
T max,
const std::string &log_msg,
const BaseSeverity base_severity,
PolicyType policy_type) {
Expand All @@ -755,8 +833,9 @@ class InternalLogCount {
mtx_.unlock();
}

template<typename T>
inline void updatePolicy(const std::string &key,
int max,
T max,
const std::string &log_msg,
BaseSeverity base_severity,
PolicyType policy_type) {
Expand Down Expand Up @@ -836,10 +915,10 @@ class InternalGlogLogStringLog : public InternalLog {
std::vector<std::string>* vecptr_;
};


template<typename T>
class InternalPolicyLog : public InternalLog {
public:
InternalPolicyLog(std::string key, int n, BaseSeverity base_severity, PolicyType policy_type) :
InternalPolicyLog(std::string key, T n, BaseSeverity base_severity, PolicyType policy_type) :
InternalLog(base_severity), key_(std::move(key)), n_(n),
policy_type_(policy_type) {
should_print_ = false;
Expand All @@ -854,13 +933,13 @@ class InternalPolicyLog : public InternalLog {
protected:
bool should_update_{true};
std::string key_{};
int n_{};
T n_{};
PolicyType policy_type_{};
};

class LppGlogExtensionLog : public InternalPolicyLog {
class LppGlogExtensionLog : public InternalPolicyLog<unsigned int> {
public:
LppGlogExtensionLog(std::string key, int n, GlogSeverity glog_severity, PolicyType policy_type,
LppGlogExtensionLog(std::string key, unsigned int n, GlogSeverity glog_severity, PolicyType policy_type,
std::function<void(const std::string &str)> fn) :
InternalPolicyLog(std::move(key), n, toBase(glog_severity), policy_type), fn_(std::move(fn)) {
should_print_ = false;
Expand Down
8 changes: 7 additions & 1 deletion test/common/async_tests.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,8 @@

enum CompareType {
EQUAL,
IS_SUBSTRING
IS_SUBSTRING,
REMOVE_NUMBERS_FROM_STRING
};

enum StreamType {
Expand Down Expand Up @@ -128,6 +129,7 @@ class TestResult {
switch (compare_type) {
case EQUAL:return compareEquality(output, expected_output);
case IS_SUBSTRING: return compareSubstring(output, expected_output);
case REMOVE_NUMBERS_FROM_STRING: return compareRemoveNumbersFromString(output, expected_output);
default:return false;
}
}
Expand All @@ -143,6 +145,10 @@ class TestResult {
return output == expected_output;
};

static inline bool compareRemoveNumbersFromString(const std::string &output, const std::string &expected_output) {
return expected_output == removeNumbersFromString(output);
}

inline void insert(const std::string &test_name, bool test_status) {
test_results.insert({test_name, test_status});
}
Expand Down
13 changes: 13 additions & 0 deletions test/default/test_default_timed.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,19 @@ std::vector<AsyncTest> generateTests() {
};
}

TEST(default_timed, lpp_syntax_floating_point_time) {
for (int i = 0; i < 5; i++) {

std::string output = LPP_CAPTURE_STDOUT(LOG_TIMED(I, 0.1, "Test" << 123));
if (i % 2 == 0) {
ASSERT_TRUE(isSubstring(output, "I"));
ASSERT_TRUE(isSubstring(output, "Test123"));
}
//sleep 0.1s
std::this_thread::sleep_for(std::chrono::milliseconds(50));
}
}

TEST(default_timed, lpp_syntax_severity_debug) {
ASSERT_TRUE(TestResult::getInstance().get(GET_CLASS_NAME(*this, nullptr)));
}
Expand Down
Loading

0 comments on commit b190abd

Please sign in to comment.