From: Thomas Markwalder Date: Thu, 28 Mar 2024 20:25:22 +0000 (-0400) Subject: [#3297] Initial Packet processing implemented X-Git-Tag: Kea-2.5.8~102 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=abc2570ce37cf2ed3c433bb20d022916c585fdd3;p=thirdparty%2Fkea.git [#3297] Initial Packet processing implemented PerfMonMgr can now process packet event stacks, poplating duration store and driving alarm checking Not yet tied to pkt_send handlers src/hooks/dhcp/perfmon/monitored_duration.* DurationKey::getStatName() setSubnetId() - new functions src/hooks/dhcp/perfmon/perfmon_messages.mes PERFMON_ALARM_CLEARED PERFMON_ALARM_TRIGGERED - new messages src/hooks/dhcp/perfmon/perfmon_mgr.* PerfMonMgr::init() - new function PerfMonMgr::processPktEventStack() PerfMonMgr::reportToStatsMgr() PerfMonMgr::reportAlarm() - implemented src/hooks/dhcp/perfmon/tests/monitored_duration_unittests.cc Updated to test getStatName() src/hooks/dhcp/perfmon/tests/perfmon_mgr_unittests.cc class TestablePerfMonMgr : public PerfMonMgr - new Expanded PerfMonMgrTest with new tests functions TEST_F(PerfMonMgrTest4, testReportToStatsMgr) TEST_F(PerfMonMgrTest6, testReportToStatsMgr) TEST_F(PerfMonMgrTest4, testAddDurationSample) TEST_F(PerfMonMgrTest6, testAddDurationSample) - new tests --- diff --git a/src/hooks/dhcp/perfmon/monitored_duration.cc b/src/hooks/dhcp/perfmon/monitored_duration.cc index 906f6d7d39..9487e9bd7c 100644 --- a/src/hooks/dhcp/perfmon/monitored_duration.cc +++ b/src/hooks/dhcp/perfmon/monitored_duration.cc @@ -177,6 +177,23 @@ DurationKey::getLabel() const { return (oss.str()); }; +std::string +DurationKey::getStatName(const std::string& value_name) const { + std::ostringstream oss; + if (subnet_id_ != SUBNET_ID_GLOBAL) { + oss << "subnet-id[" << subnet_id_ << "]."; + } + + oss << "perfmon." + << getMessageTypeLabel(family_, query_type_) + << "-" + << getMessageTypeLabel(family_, response_type_) + << "." << start_event_label_ << "-" << stop_event_label_ + << "." << value_name; + + return (oss.str()); +}; + bool DurationKey::operator==(const DurationKey& other) const { return ( diff --git a/src/hooks/dhcp/perfmon/monitored_duration.h b/src/hooks/dhcp/perfmon/monitored_duration.h index 83a0db6d95..2f025e5faf 100644 --- a/src/hooks/dhcp/perfmon/monitored_duration.h +++ b/src/hooks/dhcp/perfmon/monitored_duration.h @@ -188,6 +188,13 @@ public: return (subnet_id_); } + /// @brief Set the subnet id. + /// + /// @param subnet_id new value for subnet id.x + void setSubnetId(dhcp::SubnetID subnet_id) { + subnet_id_ = subnet_id; + } + /// @brief Get a label for a family-specific message type (e.g. /// "DHCPDISCOVER", "SOLICIT") /// @@ -217,6 +224,26 @@ public: /// @return the composite label. std::string getLabel() const; + /// @brief Get the StatsMgr formatted compatible name + /// + /// @param value_name name of the specific value (e.g. "average-ms", "min-duration-ms") + /// The format of the string: + /// + /// @code + /// + /// {subnet-id[x]}.perfmon.-.-. + /// + /// Example: + /// + /// perfmon.discover-offer.socket_received-buffer_read.average-ms + /// + /// subnet[9].perfmon.discover-offer.socket_received-buffer_read.average-ms + /// + /// @endcode + /// + /// @return the statistic name. + std::string getStatName(const std::string& value_name) const; + /// @brief Validates that a query and response message type pair is sane. /// /// @param family Protocol family of the key (AF_INET or AF_INET6) diff --git a/src/hooks/dhcp/perfmon/perfmon_messages.cc b/src/hooks/dhcp/perfmon/perfmon_messages.cc index 1bb01f93dd..f3c1bdadb0 100644 --- a/src/hooks/dhcp/perfmon/perfmon_messages.cc +++ b/src/hooks/dhcp/perfmon/perfmon_messages.cc @@ -4,6 +4,8 @@ #include #include +extern const isc::log::MessageID PERFMON_ALARM_CLEARED = "PERFMON_ALARM_CLEARED"; +extern const isc::log::MessageID PERFMON_ALARM_TRIGGERED = "PERFMON_ALARM_TRIGGERED"; extern const isc::log::MessageID PERFMON_DEINIT_FAILED = "PERFMON_DEINIT_FAILED"; extern const isc::log::MessageID PERFMON_DEINIT_OK = "PERFMON_DEINIT_OK"; extern const isc::log::MessageID PERFMON_DHCP4_PKT_EVENTS = "PERFMON_DHCP4_PKT_EVENTS"; @@ -16,6 +18,8 @@ extern const isc::log::MessageID PERFMON_INIT_OK = "PERFMON_INIT_OK"; namespace { const char* values[] = { + "PERFMON_ALARM_CLEARED", "Alarm for %1 has been cleared, reported average duration %2 is now beloe low-water-ms: %3", + "PERFMON_ALARM_TRIGGERED", "Alarm for %1 has been triggered since %2, reported average duration %3 exceeds high-water-ms: %4", "PERFMON_DEINIT_FAILED", "unloading PerfMon hooks library failed: %1", "PERFMON_DEINIT_OK", "unloading PerfMon hooks library successful", "PERFMON_DHCP4_PKT_EVENTS", "query: %1 events=[%2]", diff --git a/src/hooks/dhcp/perfmon/perfmon_messages.h b/src/hooks/dhcp/perfmon/perfmon_messages.h index 3fcb213098..d87d8b722c 100644 --- a/src/hooks/dhcp/perfmon/perfmon_messages.h +++ b/src/hooks/dhcp/perfmon/perfmon_messages.h @@ -5,6 +5,8 @@ #include +extern const isc::log::MessageID PERFMON_ALARM_CLEARED; +extern const isc::log::MessageID PERFMON_ALARM_TRIGGERED; extern const isc::log::MessageID PERFMON_DEINIT_FAILED; extern const isc::log::MessageID PERFMON_DEINIT_OK; extern const isc::log::MessageID PERFMON_DHCP4_PKT_EVENTS; diff --git a/src/hooks/dhcp/perfmon/perfmon_messages.mes b/src/hooks/dhcp/perfmon/perfmon_messages.mes index 053eab13e3..78cf358d83 100644 --- a/src/hooks/dhcp/perfmon/perfmon_messages.mes +++ b/src/hooks/dhcp/perfmon/perfmon_messages.mes @@ -41,3 +41,18 @@ the log message. % PERFMON_INIT_OK loading PerfMon hooks library successful This info message indicates that the PerfMon hooks library has been loaded successfully. Enjoy! + +% PERFMON_ALARM_CLEARED Alarm for %1 has been cleared, reported average duration %2 is now beloe low-water-ms: %3 +This info message is emitted when the reported average duration for +an alarm that has been triggered has fallen below the value of its +low-water-ms parameter. The arguments detail the alarm's key and +the most recently reported average. + +% PERFMON_ALARM_TRIGGERED Alarm for %1 has been triggered since %2, reported average duration %3 exceeds high-water-ms: %4 +This warning message is emitted when the reported average duration for +an alarm exceeds its high-water-ms value. As long as the reported +averges remain above the low-water-ms value, the alarm will remain +triggered and this message will be repeated every alarm-report-secs. +Arguments detail the alarm's key, the time the alarm was first +triggered, the most recent reported average, and the high-watr-ms +value. diff --git a/src/hooks/dhcp/perfmon/perfmon_mgr.cc b/src/hooks/dhcp/perfmon/perfmon_mgr.cc index d24a548368..ca97a88e62 100644 --- a/src/hooks/dhcp/perfmon/perfmon_mgr.cc +++ b/src/hooks/dhcp/perfmon/perfmon_mgr.cc @@ -9,23 +9,38 @@ // issues related to namespaces. #include +#include #include +#include +#include +#include namespace isc { namespace perfmon { using namespace isc::data; +using namespace isc::dhcp; +using namespace isc::stats; +using namespace isc::util; using namespace boost::posix_time; PerfMonMgr::PerfMonMgr(uint16_t family_) : PerfMonConfig(family_) { - // Set defaults. + init(); +} + +void +PerfMonMgr::init() { + // Set convenience values. interval_duration_ = seconds(interval_width_secs_); alarm_report_interval_ = seconds(alarm_report_secs_); + + // Re-create the duration store. duration_store_.reset(new MonitoredDurationStore(family_, interval_duration_)); } -void PerfMonMgr::configure(const ConstElementPtr& params) { +void +PerfMonMgr::configure(const ConstElementPtr& params) { if (!params) { // User wants passive logging only. setEnableMonitoring(false); @@ -45,18 +60,74 @@ void PerfMonMgr::configure(const ConstElementPtr& params) { "PerfMonMgr::configure failed - " << ex.what()); } - // Set convenience values. - interval_duration_ = seconds(interval_width_secs_); - alarm_report_interval_ = seconds(alarm_report_secs_); - - // Re-create the duration store. - duration_store_.reset(new MonitoredDurationStore(family_, interval_duration_)); + init(); } -void PerfMonMgr::processPktEventStack(isc::dhcp::PktPtr /* query */, - isc::dhcp::PktPtr /* response */, - const isc::dhcp::SubnetID& /* subnet_id */) { - isc_throw (NotImplemented, __FILE__ << ":" << __LINE__ << ":" << __FUNCTION__); +void +PerfMonMgr::processPktEventStack(isc::dhcp::PktPtr query, + isc::dhcp::PktPtr response, + const isc::dhcp::SubnetID& subnet_id) { + if (!query) { + isc_throw(Unexpected, "processPktEventStack - query is empty!"); + } + uint16_t query_type = query->getType(); + + // Response is optional to allow for future support of responseless queries + // such as declines or releases. + uint16_t response_type; + if (!response) { + response_type = (family_ == AF_INET ? static_cast(DHCP_NOTYPE) + : static_cast(DHCPV6_NOTYPE)); + } else { + response_type = response->getType(); + } + + // Sanity check the message types. + DurationKey::validateMessagePair(family_, query_type, response_type); + + auto events = query->getPktEvents(); + if (events.size() < 2) { + isc_throw(Unexpected, "processPtkEventStack - incomplete stack, size: " + << events.size()); + } + + boost::posix_time::ptime start_time; + boost::posix_time::ptime prev_time; + std::string prev_event_label; + bool first_pass = true; + for (auto const& event : events) { + if (first_pass) { + prev_event_label = event.label_; + prev_time = event.timestamp_; + start_time = prev_time; + first_pass = false; + } else { + Duration sample = event.timestamp_ - prev_time; + DurationKeyPtr key(new DurationKey(family_, query_type, response_type, + prev_event_label, event.label_, subnet_id)); + addDurationSample(key, sample); + + // Update global duration. + if (subnet_id != SUBNET_ID_GLOBAL) { + key->setSubnetId(SUBNET_ID_GLOBAL); + addDurationSample(key, sample); + } + + prev_event_label = event.label_; + prev_time = event.timestamp_; + } + } + + // Generate composite total. + Duration sample = prev_time - start_time; + DurationKeyPtr key(new DurationKey(family_, query_type, response_type, + "composite", "total_response", subnet_id)); + addDurationSample(key, sample); + // Update global duration. + if (subnet_id != SUBNET_ID_GLOBAL) { + key->setSubnetId(SUBNET_ID_GLOBAL); + addDurationSample(key, sample); + } } void @@ -78,13 +149,52 @@ PerfMonMgr::addDurationSample(DurationKeyPtr key, const Duration& sample) { } Duration -PerfMonMgr::reportToStatsMgr(MonitoredDurationPtr /* duration */) { - isc_throw (NotImplemented, __FILE__ << ":" << __LINE__ << ":" << __FUNCTION__); +PerfMonMgr::reportToStatsMgr(MonitoredDurationPtr duration) { + if (!duration) { + isc_throw(BadValue, "reportToStatsMgr - duration is empty"); + } + + auto previous_interval = duration->getPreviousInterval(); + if (!previous_interval) { + isc_throw(BadValue, "reportToStatsMgr - duration previous interval is empty"); + } + + auto average = previous_interval->getAverageDuration(); + if (getStatsMgrReporting()) { + StatsMgr::instance().setValue(duration->getStatName("average-ms"), + static_cast(average.total_milliseconds())); + } + + /// @todo - decide if we want to report min and max values too. + + return(average); } void -PerfMonMgr::reportAlarm(AlarmPtr /* alarm */, const Duration& /* average */) { - isc_throw (NotImplemented, __FILE__ << ":" << __LINE__ << ":" << __FUNCTION__); +PerfMonMgr::reportAlarm(AlarmPtr alarm, const Duration& average) { + std::string label = alarm->getLabel(); + switch(alarm->getState()) { + case Alarm::CLEAR: + LOG_INFO(perfmon_logger, PERFMON_ALARM_CLEARED) + .arg(alarm->getLabel()) + .arg(average) + .arg(alarm->getLowWater().total_milliseconds()); + break; + + case Alarm::TRIGGERED: + LOG_WARN(perfmon_logger, PERFMON_ALARM_TRIGGERED) + .arg(alarm->getLabel()) + .arg(ptimeToText(alarm->getStosTime(), 3)) + .arg(average) + .arg(alarm->getHighWater().total_milliseconds()); + alarm->setLastHighWaterReport(); + alarm_store_->updateAlarm(alarm); + break; + + case Alarm::DISABLED: + // Shouldn't happen. We'll silently ignore for now. + break; + } } void diff --git a/src/hooks/dhcp/perfmon/perfmon_mgr.h b/src/hooks/dhcp/perfmon/perfmon_mgr.h index db73f2a2d1..4ba3bbed78 100644 --- a/src/hooks/dhcp/perfmon/perfmon_mgr.h +++ b/src/hooks/dhcp/perfmon/perfmon_mgr.h @@ -38,6 +38,10 @@ public: /// @param params map of configuration parameters to parse. void configure(const isc::data::ConstElementPtr& params); + /// @brief Sets convenience values and (re)creates the duration store. + /// Called by the constructor and also by configure(). + virtual void init(); + /// @brief Processes the event stack of a query packet. /// /// @todo DETAILS TO FOLLOW @@ -119,7 +123,7 @@ public: return (duration_store_); } -private: +protected: /// @brief Length of time a MonitoredDuration accumulates samples until reporting. Duration interval_duration_; diff --git a/src/hooks/dhcp/perfmon/tests/Makefile.am b/src/hooks/dhcp/perfmon/tests/Makefile.am index e38c046c83..21269255e7 100644 --- a/src/hooks/dhcp/perfmon/tests/Makefile.am +++ b/src/hooks/dhcp/perfmon/tests/Makefile.am @@ -43,6 +43,7 @@ perfmon_unittests_LDFLAGS = $(AM_LDFLAGS) $(CRYPTO_LDFLAGS) $(GTEST_LDFLAGS) perfmon_unittests_CXXFLAGS = $(AM_CXXFLAGS) perfmon_unittests_LDADD = $(top_builddir)/src/hooks/dhcp/perfmon/libperfmon.la +perfmon_unittests_LDADD += $(top_builddir)/src/lib/testutils/libkea-testutils.la perfmon_unittests_LDADD += $(top_builddir)/src/lib/process/libkea-process.la perfmon_unittests_LDADD += $(top_builddir)/src/lib/stats/libkea-stats.la perfmon_unittests_LDADD += $(top_builddir)/src/lib/dhcp/libkea-dhcp++.la diff --git a/src/hooks/dhcp/perfmon/tests/monitored_duration_unittests.cc b/src/hooks/dhcp/perfmon/tests/monitored_duration_unittests.cc index 8aeea12678..842902ce3a 100644 --- a/src/hooks/dhcp/perfmon/tests/monitored_duration_unittests.cc +++ b/src/hooks/dhcp/perfmon/tests/monitored_duration_unittests.cc @@ -95,7 +95,10 @@ TEST(DurationKey, basics) { EXPECT_EQ(key->getStartEventLabel(), "process_started"); EXPECT_EQ(key->getStopEventLabel(), "process_completed"); EXPECT_EQ(key->getSubnetId(), SUBNET_ID_GLOBAL); - EXPECT_EQ("DHCPDISCOVER-DHCPOFFER.process_started-process_completed.0", key->getLabel()); + EXPECT_EQ("DHCPDISCOVER-DHCPOFFER.process_started-process_completed.0", + key->getLabel()); + EXPECT_EQ("perfmon.DHCPDISCOVER-DHCPOFFER.process_started-process_completed.average-ms", + key->getStatName("average-ms")); // Create valid v6 key, verify contents and label. ASSERT_NO_THROW_LOG(key.reset(new DurationKey(AF_INET6, DHCPV6_SOLICIT, DHCPV6_ADVERTISE, @@ -107,7 +110,10 @@ TEST(DurationKey, basics) { EXPECT_EQ(key->getStartEventLabel(), "mt_queued"); EXPECT_EQ(key->getStopEventLabel(), "process_started"); EXPECT_EQ(key->getSubnetId(), 77); - EXPECT_EQ("SOLICIT-ADVERTISE.mt_queued-process_started.77", key->getLabel()); + EXPECT_EQ("SOLICIT-ADVERTISE.mt_queued-process_started.77", + key->getLabel()); + EXPECT_EQ("subnet-id[77].perfmon.SOLICIT-ADVERTISE.mt_queued-process_started.average-ms", + key->getStatName("average-ms")); // Make sure constructor catches an insane message pairing. ASSERT_THROW_MSG(key.reset(new DurationKey(AF_INET6, DHCPV6_ADVERTISE, DHCPV6_SOLICIT, diff --git a/src/hooks/dhcp/perfmon/tests/perfmon_mgr_unittests.cc b/src/hooks/dhcp/perfmon/tests/perfmon_mgr_unittests.cc index 62f2dbe021..3d1c80fb61 100644 --- a/src/hooks/dhcp/perfmon/tests/perfmon_mgr_unittests.cc +++ b/src/hooks/dhcp/perfmon/tests/perfmon_mgr_unittests.cc @@ -8,6 +8,8 @@ #include #include #include +#include +#include #include #include @@ -19,7 +21,9 @@ using namespace isc; using namespace isc::data; using namespace isc::dhcp; using namespace isc::perfmon; +using namespace isc::stats; using namespace isc::test; +using namespace isc::dhcp::test; using namespace boost::posix_time; namespace { @@ -37,42 +41,168 @@ TEST(PerfMonMgr, constructor) { EXPECT_EQ(mgr->getFamily(), AF_INET6); } +/// @brief Derivation of PerfMonMgr that uses milliseconds for intervals. +class TestablePerfMonMgr : public PerfMonMgr { +public: + /// @brief Constructor. + /// + /// @param family Protocol family AF_INET or AF_INET6. + explicit TestablePerfMonMgr(uint16_t family) + : PerfMonMgr(family) { + } + + /// @brief Destructor. + virtual ~TestablePerfMonMgr() = default; + + /// @brief Override base class so we can use milliseconds. + virtual void init() { + // Set convenience values. + interval_duration_ = milliseconds(interval_width_secs_); + alarm_report_interval_ = milliseconds(alarm_report_secs_); + + // Re-create the duration store. + duration_store_.reset(new MonitoredDurationStore(family_, interval_duration_)); + } +}; + /// @brief Test fixture for testing PerfMonMgr -class PerfMonMgrTest : public ::testing::Test { +class PerfMonMgrTest : public LogContentTest { public: /// @brief Constructor. explicit PerfMonMgrTest(uint16_t family) : family_(family) { + StatsMgr::instance(); + StatsMgr::instance().removeAll(); + StatsMgr::instance().setMaxSampleCountAll(1); } /// @brief Destructor. virtual ~PerfMonMgrTest() = default; + /// @brief Re-creates and then configures the PerfMonMgr instance with a + /// given configuration. + /// + /// @param config JSON configuration text + void createMgr(const std::string& config) { + mgr_.reset(new TestablePerfMonMgr(family_)); + ConstElementPtr json_elements; + json_elements = Element::fromJSON(config); + mgr_->configure(json_elements); + } + + /// @brief Compares an Alarm to the version stored in the Alarm store. + /// + /// @param line_no source line of the invocation. + /// @param before[in/out] pointer to the "before" alarm. It is updated + /// to the stored Alarm prior to return. + /// @param exp_state expected Alarm::STATE of the stored Alarm. + /// @param should_report true if the stored alarm's high_water_last_report + /// should be more recent than that of the before alarm. + void beforeAndAfterAlarm(int line_no, AlarmPtr& before, Alarm::State exp_state, + bool should_report) { + std::ostringstream oss; + oss << "beforeAndAfterAlarm at line " << line_no << " failed"; + SCOPED_TRACE(oss.str()); + + // Retrieve the Alarm from the store. + AlarmPtr after; + ASSERT_NO_THROW_LOG(after = mgr_->getAlarmStore()->getAlarm(before)); + ASSERT_TRUE(after); + ASSERT_EQ(exp_state, after->getState()); + + if (exp_state == before->getState()) { + // State should not have changed. + ASSERT_EQ(before->getStosTime(), after->getStosTime()); + switch(exp_state) { + case Alarm::CLEAR: + ASSERT_EQ(after->getLastHighWaterReport(), PktEvent::EMPTY_TIME()); + break; + case Alarm::TRIGGERED: + if (should_report) { + ASSERT_LT(before->getLastHighWaterReport(), after->getLastHighWaterReport()); + } else { + ASSERT_EQ(before->getLastHighWaterReport(), after->getLastHighWaterReport()); + } + break; + case Alarm::DISABLED: + // No use case for this (yet). + break; + } + + } else { + // State should have changed. + ASSERT_LT(before->getStosTime(), after->getStosTime()); + switch(exp_state) { + case Alarm::CLEAR: + ASSERT_EQ(after->getLastHighWaterReport(), PktEvent::EMPTY_TIME()); + break; + case Alarm::TRIGGERED: + if (should_report) { + ASSERT_EQ(before->getLastHighWaterReport(), PktEvent::EMPTY_TIME()); + ASSERT_LE(after->getStosTime(), after->getLastHighWaterReport()); + } else { + ASSERT_EQ(before->getLastHighWaterReport(), after->getLastHighWaterReport()); + } + break; + case Alarm::DISABLED: + // No use case for this (yet). + break; + } + + } + + before = after; + } + + /// @brief Check the content of a stored MonitoredDuration. + /// + /// @param line_no source line of the invocation + /// @param key DurationKey of the target duration + /// @param exp_current_total_ms expected value of the current interval's total_duration_ + /// @param exp_previous true if the duration should have previous interval, defaults to false + /// @param exp_previous_total_ms expected value of the previous interval's total_duration_ + void checkDuration(int line_no, DurationKeyPtr key, uint64_t exp_current_total_ms, + bool exp_previous = false, uint64_t exp_previous_total_ms = 0) { + std::ostringstream oss; + oss << "checkDuration at line " << line_no << " failed"; + SCOPED_TRACE(oss.str()); + MonitoredDurationPtr mond; + ASSERT_NO_THROW(mond = mgr_->getDurationStore()->getDuration(key)); + ASSERT_TRUE(mond); + if (!exp_previous) { + ASSERT_FALSE(mond->getPreviousInterval()); + } else { + ASSERT_TRUE(mond->getPreviousInterval()); + EXPECT_EQ(milliseconds(exp_previous_total_ms), mond->getPreviousInterval()->getTotalDuration()); + } + + ASSERT_TRUE(mond->getCurrentInterval()); + EXPECT_EQ(milliseconds(exp_current_total_ms), mond->getCurrentInterval()->getTotalDuration()); + } + /// @brief Verifies PerfMonConfig constructors and accessors. void testBasics() { - PerfMonMgrPtr mgr; - // Verify that an invalid family is caught. - ASSERT_THROW_MSG(mgr.reset(new PerfMonMgr(777)), BadValue, + ASSERT_THROW_MSG(mgr_.reset(new PerfMonMgr(777)), BadValue, "PerfmonConfig: family must be AF_INET or AF_INET6"); // Verify initial values. - ASSERT_NO_THROW_LOG(mgr.reset(new PerfMonMgr(family_))); - ASSERT_TRUE(mgr); - EXPECT_FALSE(mgr->getEnableMonitoring()); - EXPECT_EQ(mgr->getIntervalDuration(), seconds(60)); - EXPECT_TRUE(mgr->getStatsMgrReporting()); - EXPECT_EQ(mgr->getAlarmReportInterval(), seconds(300)); + ASSERT_NO_THROW_LOG(mgr_.reset(new PerfMonMgr(family_))); + ASSERT_TRUE(mgr_); + EXPECT_FALSE(mgr_->getEnableMonitoring()); + EXPECT_EQ(mgr_->getIntervalDuration(), seconds(60)); + EXPECT_TRUE(mgr_->getStatsMgrReporting()); + EXPECT_EQ(mgr_->getAlarmReportInterval(), seconds(300)); // Alarm store should exist but be empty. - EXPECT_TRUE(mgr->getAlarmStore()); - EXPECT_EQ(mgr->getAlarmStore()->getFamily(), family_); - AlarmCollectionPtr alarms = mgr->getAlarmStore()->getAll(); + EXPECT_TRUE(mgr_->getAlarmStore()); + EXPECT_EQ(mgr_->getAlarmStore()->getFamily(), family_); + AlarmCollectionPtr alarms = mgr_->getAlarmStore()->getAll(); ASSERT_EQ(alarms->size(), 0); // Duration store should exist but be empty. - EXPECT_TRUE(mgr->getDurationStore()); - EXPECT_EQ(mgr->getDurationStore()->getFamily(), family_); - MonitoredDurationCollectionPtr durations = mgr->getDurationStore()->getAll(); + EXPECT_TRUE(mgr_->getDurationStore()); + EXPECT_EQ(mgr_->getDurationStore()->getFamily(), family_); + MonitoredDurationCollectionPtr durations = mgr_->getDurationStore()->getAll(); ASSERT_EQ(durations->size(), 0); } @@ -100,22 +230,17 @@ public: }] })"; - // Convert JSON texts to Element map. - ConstElementPtr json_elements; - ASSERT_NO_THROW_LOG(json_elements = Element::fromJSON(valid_config)); - - PerfMonMgrPtr mgr(new PerfMonMgr(family_)); - ASSERT_NO_THROW_LOG(mgr->configure(json_elements)); + ASSERT_NO_THROW_LOG(createMgr(valid_config)); - EXPECT_FALSE(mgr->getEnableMonitoring()); - EXPECT_EQ(mgr->getIntervalDuration(), seconds(5)); - EXPECT_FALSE(mgr->getStatsMgrReporting()); - EXPECT_EQ(mgr->getAlarmReportInterval(), seconds(600)); + EXPECT_FALSE(mgr_->getEnableMonitoring()); + EXPECT_EQ(mgr_->getIntervalDuration(), seconds(5)); + EXPECT_FALSE(mgr_->getStatsMgrReporting()); + EXPECT_EQ(mgr_->getAlarmReportInterval(), seconds(600)); // AlarmStore should have one alarm. - EXPECT_TRUE(mgr->getAlarmStore()); - EXPECT_EQ(mgr->getAlarmStore()->getFamily(), family_); - AlarmCollectionPtr alarms = mgr->getAlarmStore()->getAll(); + EXPECT_TRUE(mgr_->getAlarmStore()); + EXPECT_EQ(mgr_->getAlarmStore()->getFamily(), family_); + AlarmCollectionPtr alarms = mgr_->getAlarmStore()->getAll(); ASSERT_EQ(alarms->size(), 1); DurationKeyPtr key(new DurationKey(family_, 0, 0, "process-started", "process-completed", 70)); @@ -127,9 +252,9 @@ public: EXPECT_EQ(alarm->getLowWater(), milliseconds(25)); // Duration store should exist but be empty. - EXPECT_TRUE(mgr->getDurationStore()); - EXPECT_EQ(mgr->getDurationStore()->getFamily(), family_); - MonitoredDurationCollectionPtr durations = mgr->getDurationStore()->getAll(); + EXPECT_TRUE(mgr_->getDurationStore()); + EXPECT_EQ(mgr_->getDurationStore()->getFamily(), family_); + MonitoredDurationCollectionPtr durations = mgr_->getDurationStore()->getAll(); ASSERT_EQ(durations->size(), 0); } @@ -144,35 +269,211 @@ public: "alarms": "bogus" })"; - // Convert JSON texts to Element map. - ConstElementPtr json_elements; - ASSERT_NO_THROW_LOG(json_elements = Element::fromJSON(invalid_config)); - - PerfMonMgrPtr mgr(new PerfMonMgr(family_)); - ASSERT_THROW_MSG(mgr->configure(json_elements), DhcpConfigError, + ASSERT_THROW_MSG(createMgr(invalid_config), DhcpConfigError, "PerfMonMgr::configure failed - " "'alarms' parameter is not a list"); - EXPECT_FALSE(mgr->getEnableMonitoring()); - EXPECT_EQ(mgr->getIntervalDuration(), seconds(60)); - EXPECT_TRUE(mgr->getStatsMgrReporting()); - EXPECT_EQ(mgr->getAlarmReportInterval(), seconds(300)); + EXPECT_FALSE(mgr_->getEnableMonitoring()); + EXPECT_EQ(mgr_->getIntervalDuration(), seconds(60)); + EXPECT_TRUE(mgr_->getStatsMgrReporting()); + EXPECT_EQ(mgr_->getAlarmReportInterval(), seconds(300)); // Alarm store should exist but be empty. - EXPECT_TRUE(mgr->getAlarmStore()); - EXPECT_EQ(mgr->getAlarmStore()->getFamily(), family_); - AlarmCollectionPtr alarms = mgr->getAlarmStore()->getAll(); + EXPECT_TRUE(mgr_->getAlarmStore()); + EXPECT_EQ(mgr_->getAlarmStore()->getFamily(), family_); + AlarmCollectionPtr alarms = mgr_->getAlarmStore()->getAll(); ASSERT_EQ(alarms->size(), 0); // Duration store should exist but be empty. - EXPECT_TRUE(mgr->getDurationStore()); - EXPECT_EQ(mgr->getDurationStore()->getFamily(), family_); - MonitoredDurationCollectionPtr durations = mgr->getDurationStore()->getAll(); + EXPECT_TRUE(mgr_->getDurationStore()); + EXPECT_EQ(mgr_->getDurationStore()->getFamily(), family_); + MonitoredDurationCollectionPtr durations = mgr_->getDurationStore()->getAll(); ASSERT_EQ(durations->size(), 0); } + /// @brief Exercises PerfMonMgr::reportToStatsMgr(). + void testReportToStatsMgr() { + // Minimal valid configuration. + std::string valid_config = + R"({ + "enable-monitoring": true, + "interval-width-secs": 5, + "stats-mgr-reporting": true + })"; + + ASSERT_NO_THROW_LOG(createMgr(valid_config)); + + MonitoredDurationPtr mond; + ASSERT_THROW_MSG(mgr_->reportToStatsMgr(mond), BadValue, + "reportToStatsMgr - duration is empty"); + + ASSERT_NO_THROW_LOG( + mond.reset(new MonitoredDuration(family_, 0, 0, + "process-started", "process-completed", + 70, seconds(60)))); + + ASSERT_THROW_MSG(mgr_->reportToStatsMgr(mond), BadValue, + "reportToStatsMgr - duration previous interval is empty"); + + mond->addSample(milliseconds(100)); + mond->addSample(milliseconds(250)); + mond->expireCurrentInterval(); + + Duration average; + ASSERT_NO_THROW_LOG(average = mgr_->reportToStatsMgr(mond)); + EXPECT_EQ(milliseconds(175), average); + + auto obs = StatsMgr::instance().getObservation(mond->getStatName("average-ms")); + ASSERT_TRUE(obs); + EXPECT_EQ(175, obs->getInteger().first); + + StatsMgr::instance().removeAll(); + mgr_->setStatsMgrReporting(false); + + ASSERT_NO_THROW_LOG(average = mgr_->reportToStatsMgr(mond)); + EXPECT_EQ(milliseconds(175), average); + obs = StatsMgr::instance().getObservation(mond->getStatName("average-ms")); + ASSERT_FALSE(obs); + } + + /// @brief Exercises PerfMonMgr::addDurationSample(). + void testAddDurationSample() { + // Minimal valid configuration. + std::string valid_config = + R"({ + "enable-monitoring": true, + "interval-width-secs": 100, + "stats-mgr-reporting": true, + "alarm-report-secs": 200, + "alarms": [{ + "duration-key": { + "query-type": "*", + "response-type": "*", + "start-event": "process-started", + "stop-event": "process-completed", + "subnet-id": 70 + }, + "enable-alarm": true, + "high-water-ms": 50, + "low-water-ms": 25 + }] + })"; + + ASSERT_NO_THROW_LOG(createMgr(valid_config)); + + // Make a duration key to match the alarm. + DurationKeyPtr key; + ASSERT_NO_THROW_LOG( + key.reset(new DurationKey(family_, 0, 0, "process-started", + "process-completed", 70))); + + // Verify the alarm exists but is CLEAR since the duration has not yet reported. + AlarmPtr before_alarm; + ASSERT_NO_THROW_LOG(before_alarm = mgr_->getAlarmStore()->getAlarm(key)); + ASSERT_TRUE(before_alarm); + EXPECT_EQ(Alarm::CLEAR, before_alarm->getState()); + + // 1. Add two samples to the duratson inside the current interval + // This should create the duration in the store. Note both samples above + // high-water-ms. + ASSERT_NO_THROW_LOG(mgr_->addDurationSample(key, milliseconds(75))); + ASSERT_NO_THROW_LOG(mgr_->addDurationSample(key, milliseconds(85))); + + // Duration should exist in the store with a current total of 160 ms. + // It should not yet have a previous interval. + checkDuration(__LINE__, key, 160, false); + + // Verify the alarm should still be CLEAR since we have not yet completed the interval. + AlarmPtr after_alarm; + beforeAndAfterAlarm(__LINE__, before_alarm, after_alarm, Alarm::CLEAR, false); + + // No stats should have been reported. + EXPECT_EQ(0, StatsMgr::instance().count()); + + // Sleep 100ms second to make sure the current interval duration elapses. + usleep(100 * 1000); + + // 2. Add a new sample after the current interval duration elapses. + // This should cause the duration to be reported and the alarm to trigger. + ASSERT_NO_THROW_LOG(mgr_->addDurationSample(key, milliseconds(95))); + + // Duration should have a current total of 95 ms, and a previous total of 160. + checkDuration(__LINE__, key, 95, true, 160); + + // Should have one stat reported with a average value of 80. + EXPECT_EQ(1, StatsMgr::instance().count()); + auto obs = StatsMgr::instance().getObservation(key->getStatName("average-ms")); + ASSERT_TRUE(obs); + EXPECT_EQ(80, obs->getInteger().first); + + // The alarm should have triggered and reported. + beforeAndAfterAlarm(__LINE__, before_alarm, after_alarm, Alarm::TRIGGERED, true); + addString("reported average duration 00:00:00.080000 exceeds high-water-ms: 50"); + + // Sleep 100ms second to make sure the current interval duration elapses. + usleep(100 * 1000); + + // 3. Add another above high water sample. + ASSERT_NO_THROW_LOG(mgr_->addDurationSample(key, milliseconds(100))); + + // Duration should have a current total of 100 ms, and a previous total of 95. + checkDuration(__LINE__, key, 100, true, 95); + + // The Alarm should still be TRIGGERED since the newly completed interval is + // above high water. The alarm should not report because the reporting + // interval has not elapsed. + beforeAndAfterAlarm(__LINE__, before_alarm, after_alarm, Alarm::TRIGGERED, false); + + // Sleep 100ms second to make sure the current interval duration elapses. + usleep(100 * 1000); + + // 4. Add a below low water duration. This should close the current interval. + ASSERT_NO_THROW_LOG(mgr_->addDurationSample(key, milliseconds(10))); + + // Duration should have a current total of 10ms, and a previous total of 100. + checkDuration(__LINE__, key, 10, true, 100); + + // The Alarm should still be TRIGGERED since the newly completed interval is + // above high water. The alarm should report again because the reporting + // interval has elapsed. + beforeAndAfterAlarm(__LINE__, before_alarm, after_alarm, Alarm::TRIGGERED, true); + addString("reported average duration 00:00:00.100000 exceeds high-water-ms: 50"); + + // Should have one stat reported with a value of 100. + EXPECT_EQ(1, StatsMgr::instance().count()); + obs = StatsMgr::instance().getObservation(key->getStatName("average-ms")); + ASSERT_TRUE(obs); + EXPECT_EQ(100, obs->getInteger().first); + + // Sleep 100ms second to make sure the current interval duration elapses. + usleep(100 * 1000); + + // 5. Add another below low water duration. This should close the current interval. + ASSERT_NO_THROW_LOG(mgr_->addDurationSample(key, milliseconds(15))); + + // Duration should have a current total of 15 ms, and a previous total of 10. + checkDuration(__LINE__, key, 15, true, 10); + + // The Alarm should now be CLEAR since the newly completed interval is + // below high water. The alarm should low-water report. + beforeAndAfterAlarm(__LINE__, before_alarm, after_alarm, Alarm::CLEAR, false); + addString("reported average duration 00:00:00.010000 is now beloe low-water-ms: 25"); + + // Should have one stat reported with a value of 10. + EXPECT_EQ(1, StatsMgr::instance().count()); + obs = StatsMgr::instance().getObservation(key->getStatName("average-ms")); + ASSERT_TRUE(obs); + EXPECT_EQ(10, obs->getInteger().first); + + // Lastly, verify the log entries. + EXPECT_TRUE(checkFile()); + } + /// @brief Protocol family AF_INET or AF_INET6 uint16_t family_; + + /// @brief PerfMonMgr instance used in test functions. + PerfMonMgrPtr mgr_; }; /// @brief Test fixture for testing PerfMonConfig for DHCPV4. @@ -221,4 +522,20 @@ TEST_F(PerfMonMgrTest6, invalidConfig) { testInvalidConfig(); } +TEST_F(PerfMonMgrTest4, testReportToStatsMgr) { + testReportToStatsMgr(); +} + +TEST_F(PerfMonMgrTest6, testReportToStatsMgr) { + testReportToStatsMgr(); +} + +TEST_F(PerfMonMgrTest4, testAddDurationSample) { + testAddDurationSample(); +} + +TEST_F(PerfMonMgrTest6, testAddDurationSample) { + testAddDurationSample(); +} + } // end of anonymous namespace