From 5b903c7b428c2c7024fdfc1dffacad0b1521b750 Mon Sep 17 00:00:00 2001
From: John Spray <john.spray@redhat.com>
Date: Mon, 7 Aug 2017 07:52:42 -0400
Subject: [PATCH] mon: rate limit on health check update logging

Fixes: http://tracker.ceph.com/issues/20888
Signed-off-by: John Spray <john.spray@redhat.com>
---
 src/common/options.cc |  6 ++++
 src/mon/Monitor.cc    | 81 +++++++++++++++++++++++++++++++++++++++++--
 src/mon/Monitor.h     | 19 ++++++++++
 3 files changed, 103 insertions(+), 3 deletions(-)

diff --git a/src/common/options.cc b/src/common/options.cc
index aeb7d69a409..75fd0b10c47 100644
--- a/src/common/options.cc
+++ b/src/common/options.cc
@@ -1209,6 +1209,12 @@ std::vector<Option> get_global_options() {
     .set_default(50)
     .set_description(""),
 
+    Option("mon_health_log_update_period", Option::TYPE_INT, Option::LEVEL_DEV)
+    .set_default(5)
+    .set_description("Minimum time in seconds between log messages about "
+                     "each health check")
+    .set_min(0),
+
     Option("mon_data_avail_crit", Option::TYPE_INT, Option::LEVEL_ADVANCED)
     .set_default(5)
     .set_description(""),
diff --git a/src/mon/Monitor.cc b/src/mon/Monitor.cc
index 8fd219fc618..3cb22549d95 100755
--- a/src/mon/Monitor.cc
+++ b/src/mon/Monitor.cc
@@ -1061,6 +1061,7 @@ void Monitor::_reset()
   cancel_probe_timeout();
   timecheck_finish();
   health_events_cleanup();
+  health_check_log_times.clear();
   scrub_event_cancel();
 
   leader_since = utime_t();
@@ -2550,25 +2551,60 @@ void Monitor::log_health(
   if (!g_conf->mon_health_to_clog) {
     return;
   }
+
+  const utime_t now = ceph_clock_now();
+
   // FIXME: log atomically as part of @t instead of using clog.
   dout(10) << __func__ << " updated " << updated.checks.size()
 	   << " previous " << previous.checks.size()
 	   << dendl;
+  const auto min_log_period = g_conf->get_val<int64_t>(
+      "mon_health_log_update_period");
   for (auto& p : updated.checks) {
     auto q = previous.checks.find(p.first);
+    bool logged = false;
     if (q == previous.checks.end()) {
       // new
       ostringstream ss;
       ss << "Health check failed: " << p.second.summary << " ("
          << p.first << ")";
       clog->health(p.second.severity) << ss.str();
+
+      logged = true;
     } else {
       if (p.second.summary != q->second.summary ||
 	  p.second.severity != q->second.severity) {
-	// summary or severity changed (ignore detail changes at this level)
-	ostringstream ss;
+
+        auto status_iter = health_check_log_times.find(p.first);
+        if (status_iter != health_check_log_times.end()) {
+          if (p.second.severity == q->second.severity &&
+              now - status_iter->second.updated_at < min_log_period) {
+            // We already logged this recently and the severity is unchanged,
+            // so skip emitting an update of the summary string.
+            // We'll get an update out of tick() later if the check
+            // is still failing.
+            continue;
+          }
+        }
+
+        // summary or severity changed (ignore detail changes at this level)
+        ostringstream ss;
         ss << "Health check update: " << p.second.summary << " (" << p.first << ")";
         clog->health(p.second.severity) << ss.str();
+
+        logged = true;
+      }
+    }
+    // Record the time at which we last logged, so that we can check this
+    // when considering whether/when to print update messages.
+    if (logged) {
+      auto iter = health_check_log_times.find(p.first);
+      if (iter == health_check_log_times.end()) {
+        health_check_log_times.emplace(p.first, HealthCheckLogStatus(
+          p.second.severity, p.second.summary, now));
+      } else {
+        iter->second = HealthCheckLogStatus(
+          p.second.severity, p.second.summary, now);
       }
     }
   }
@@ -2584,6 +2620,10 @@ void Monitor::log_health(
         clog->info() << "Health check cleared: " << p.first << " (was: "
                      << p.second.summary << ")";
       }
+
+      if (health_check_log_times.count(p.first)) {
+        health_check_log_times.erase(p.first);
+      }
     }
   }
 
@@ -5443,14 +5483,49 @@ void Monitor::tick()
 {
   // ok go.
   dout(11) << "tick" << dendl;
+  const utime_t now = ceph_clock_now();
   
+  // Check if we need to emit any delayed health check updated messages
+  if (is_leader()) {
+    const auto min_period = g_conf->get_val<int64_t>(
+                              "mon_health_log_update_period");
+    for (auto& svc : paxos_service) {
+      auto health = svc->get_health_checks();
+
+      for (const auto &i : health.checks) {
+        const std::string &code = i.first;
+        const std::string &summary = i.second.summary;
+        const health_status_t severity = i.second.severity;
+
+        auto status_iter = health_check_log_times.find(code);
+        if (status_iter == health_check_log_times.end()) {
+          continue;
+        }
+
+        auto &log_status = status_iter->second;
+        bool const changed = log_status.last_message != summary
+                             || log_status.severity != severity;
+
+        if (changed && now - log_status.updated_at > min_period) {
+          log_status.last_message = summary;
+          log_status.updated_at = now;
+          log_status.severity = severity;
+
+          ostringstream ss;
+          ss << "Health check update: " << summary << " (" << code << ")";
+          clog->health(severity) << ss.str();
+        }
+      }
+    }
+  }
+
+
   for (vector<PaxosService*>::iterator p = paxos_service.begin(); p != paxos_service.end(); ++p) {
     (*p)->tick();
     (*p)->maybe_trim();
   }
   
   // trim sessions
-  utime_t now = ceph_clock_now();
   {
     Mutex::Locker l(session_map_lock);
     auto p = session_map.sessions.begin();
diff --git a/src/mon/Monitor.h b/src/mon/Monitor.h
index e61f4b99e6d..fc9772601cb 100644
--- a/src/mon/Monitor.h
+++ b/src/mon/Monitor.h
@@ -756,6 +756,25 @@ public:
     const health_check_map_t& previous,
     MonitorDBStore::TransactionRef t);
 
+protected:
+
+  class HealthCheckLogStatus {
+    public:
+    health_status_t severity;
+    std::string last_message;
+    utime_t updated_at = 0;
+    HealthCheckLogStatus(health_status_t severity_,
+                         const std::string &last_message_,
+                         utime_t updated_at_)
+      : severity(severity_),
+        last_message(last_message_),
+        updated_at(updated_at_)
+    {}
+  };
+  std::map<std::string, HealthCheckLogStatus> health_check_log_times;
+
+public:
+
   void get_cluster_status(stringstream &ss, Formatter *f);
 
   void reply_command(MonOpRequestRef op, int rc, const string &rs, version_t version);
-- 
2.39.5