From 26f22d220a2c37e5030aca24ee0e438a9b47c765 Mon Sep 17 00:00:00 2001
From: "J. Eric Ivancich" <ivancich@redhat.com>
Date: Thu, 14 Feb 2019 20:30:46 -0500
Subject: [PATCH] rgw: resolve bugs and clean up garbage collection code

Does a number of things to clean up rgw gc code:

  * adds additional logging to make future debugging easier.
  * resolves bug where the truncated flag was not always set correctly
    in gc_iterate_entries
  * resolves bug where marker in RGWGC::process was not advanced
  * resolves bug in which gc entries with a zero-length chain
    were not trimmed
  * resolves bug where same gc entry tag was added to list for
    deletion multiple times

Fixes: http://tracker.ceph.com/issues/38454

Signed-off-by: J. Eric Ivancich <ivancich@redhat.com>
(cherry picked from commit 73d7d36)

Conflicts:
	src/rgw/rgw_gc.cc dout() vs ldpp_dout()

Note: This was a clean cherry-pick from Mimic, which already resolved
      dout() vs ldpp_dout() conficts.

Signed-off-by: Dan Hill <daniel.hill@canonical.com>
(cherry picked from commit a598ccce2e)
---
 src/cls/rgw/cls_rgw.cc |  66 ++++++++++++-----
 src/common/options.cc  |   4 +-
 src/rgw/rgw_gc.cc      | 162 +++++++++++++++++++++++++++++------------
 3 files changed, 164 insertions(+), 68 deletions(-)

diff --git a/src/cls/rgw/cls_rgw.cc b/src/cls/rgw/cls_rgw.cc
index f56c7f55a5961..9f0b1e3243ab2 100644
--- a/src/cls/rgw/cls_rgw.cc
+++ b/src/cls/rgw/cls_rgw.cc
@@ -3212,23 +3212,36 @@ static int gc_update_entry(cls_method_context_t hctx, uint32_t expiration_secs,
       return ret;
     }
   }
+
+  // calculate time and time key
   info.time = ceph::real_clock::now();
   info.time += make_timespan(expiration_secs);
+  string time_key;
+  get_time_key(info.time, &time_key);
+
+  if (info.chain.objs.empty()) {
+    CLS_LOG(0,
+	    "WARNING: %s setting GC log entry with zero-length chain, "
+	    "tag='%s', timekey='%s'",
+	    __func__, info.tag.c_str(), time_key.c_str());
+  }
+
   ret = gc_omap_set(hctx, GC_OBJ_NAME_INDEX, info.tag, &info);
   if (ret < 0)
     return ret;
 
-  string key;
-  get_time_key(info.time, &key);
-  ret = gc_omap_set(hctx, GC_OBJ_TIME_INDEX, key, &info);
+  ret = gc_omap_set(hctx, GC_OBJ_TIME_INDEX, time_key, &info);
   if (ret < 0)
     goto done_err;
 
   return 0;
 
 done_err:
-  CLS_LOG(0, "ERROR: gc_set_entry error info.tag=%s, ret=%d\n", info.tag.c_str(), ret);
+
+  CLS_LOG(0, "ERROR: gc_set_entry error info.tag=%s, ret=%d\n",
+	  info.tag.c_str(), ret);
   gc_omap_remove(hctx, GC_OBJ_NAME_INDEX, info.tag);
+
   return ret;
 }
 
@@ -3285,16 +3298,22 @@ static int rgw_cls_gc_defer_entry(cls_method_context_t hctx, bufferlist *in, buf
   return gc_defer_entry(hctx, op.tag, op.expiration_secs);
 }
 
-static int gc_iterate_entries(cls_method_context_t hctx, const string& marker, bool expired_only,
-                              string& key_iter, uint32_t max_entries, bool *truncated,
-                              int (*cb)(cls_method_context_t, const string&, cls_rgw_gc_obj_info&, void *),
+static int gc_iterate_entries(cls_method_context_t hctx,
+			      const string& marker,
+			      bool expired_only,
+                              string& out_marker,
+			      uint32_t max_entries,
+			      bool *truncated,
+                              int (*cb)(cls_method_context_t,
+					const string&,
+					cls_rgw_gc_obj_info&,
+					void *),
                               void *param)
 {
-  CLS_LOG(10, "gc_iterate_range");
+  CLS_LOG(10, "gc_iterate_entries");
 
   map<string, bufferlist> keys;
   string filter_prefix, end_key;
-  uint32_t i = 0;
   string key;
 
   if (truncated)
@@ -3318,18 +3337,20 @@ static int gc_iterate_entries(cls_method_context_t hctx, const string& marker, b
 
   string filter;
 
-  int ret = cls_cxx_map_get_vals(hctx, start_key, filter, max_entries, &keys, truncated);
+  int ret = cls_cxx_map_get_vals(hctx, start_key, filter, max_entries,
+				 &keys, truncated);
   if (ret < 0)
     return ret;
 
-
   map<string, bufferlist>::iterator iter = keys.begin();
-  if (iter == keys.end())
+  if (iter == keys.end()) {
+    // if keys empty must not come back as truncated
+    ceph_assert(!truncated || !(*truncated));
     return 0;
+  }
 
-  uint32_t num_keys = keys.size();
-
-  for (; iter != keys.end(); ++iter, ++i) {
+  const string* last_key = nullptr; // last key processed, for end-marker
+  for (; iter != keys.end(); ++iter) {
     const string& key = iter->first;
     cls_rgw_gc_obj_info e;
 
@@ -3341,8 +3362,11 @@ static int gc_iterate_entries(cls_method_context_t hctx, const string& marker, b
       return 0;
     }
 
-    if (!key_in_index(key, GC_OBJ_TIME_INDEX))
+    if (!key_in_index(key, GC_OBJ_TIME_INDEX)) {
+      if (truncated)
+	*truncated = false;
       return 0;
+    }
 
     ret = gc_record_decode(iter->second, e);
     if (ret < 0)
@@ -3351,10 +3375,14 @@ static int gc_iterate_entries(cls_method_context_t hctx, const string& marker, b
     ret = cb(hctx, key, e, param);
     if (ret < 0)
       return ret;
+    last_key = &(iter->first); // update when callback successful
+  }
 
-    if (i == num_keys - 1) {
-      key_iter = key;
-    }
+  // set the out marker if either caller does not capture truncated or
+  // if they do capture and we are truncated
+  if (!truncated || *truncated) {
+    assert(last_key);
+    out_marker = *last_key;
   }
 
   return 0;
diff --git a/src/common/options.cc b/src/common/options.cc
index 527d08f93e167..1911f40ef1dac 100644
--- a/src/common/options.cc
+++ b/src/common/options.cc
@@ -5205,7 +5205,7 @@ std::vector<Option> get_rgw_options() {
 
     Option("rgw_gc_obj_min_wait", Option::TYPE_INT, Option::LEVEL_ADVANCED)
     .set_default(2_hr)
-    .set_description("Garabge collection object expiration time")
+    .set_description("Garbage collection object expiration time")
     .set_long_description(
        "The length of time (in seconds) that the RGW collector will wait before purging "
        "a deleted object's data. RGW will not remove object immediately, as object could "
@@ -5220,7 +5220,7 @@ std::vector<Option> get_rgw_options() {
         "Garbage collection thread in RGW process holds a lease on its data shards. These "
         "objects contain the information about the objects that need to be removed. RGW "
         "takes a lease in order to prevent multiple RGW processes from handling the same "
-        "objects concurrently. This time signifies that maximum amount of time that RGW "
+        "objects concurrently. This time signifies that maximum amount of time (in seconds) that RGW "
         "is allowed to hold that lease. In the case where RGW goes down uncleanly, this "
         "is the amount of time where processing of that data shard will be blocked.")
     .add_see_also({"rgw_gc_max_objs", "rgw_gc_obj_min_wait", "rgw_gc_processor_period", "rgw_gc_max_concurrent_io"}),
diff --git a/src/rgw/rgw_gc.cc b/src/rgw/rgw_gc.cc
index bd4474a6b9106..aa245314cfc8f 100644
--- a/src/rgw/rgw_gc.cc
+++ b/src/rgw/rgw_gc.cc
@@ -9,6 +9,7 @@
 #include "auth/Crypto.h"
 
 #include <list>
+#include <sstream>
 
 #define dout_context g_ceph_context
 #define dout_subsys ceph_subsys_rgw
@@ -163,13 +164,15 @@ public:
                                                   remove_tags(cct->_conf->rgw_gc_max_objs) {
     max_aio = cct->_conf->rgw_gc_max_concurrent_io;
   }
+
   ~RGWGCIOManager() {
     for (auto io : ios) {
       io.c->release();
     }
   }
 
-  int schedule_io(IoCtx *ioctx, const string& oid, ObjectWriteOperation *op, int index, const string& tag) {
+  int schedule_io(IoCtx *ioctx, const string& oid, ObjectWriteOperation *op,
+		  int index, const string& tag) {
     while (ios.size() > max_aio) {
       if (gc->going_down()) {
         return 0;
@@ -194,32 +197,44 @@ public:
     int ret = io.c->get_return_value();
     io.c->release();
 
-    auto& rt = remove_tags[io.index];
-
     if (ret == -ENOENT) {
       ret = 0;
     }
 
     if (io.type == IO::IndexIO) {
       if (ret < 0) {
-        ldout(cct, 0) << "WARNING: gc cleanup of tags on gc shard index=" << io.index << " returned error, ret=" << ret << dendl;
+        ldout(cct, 0) << "WARNING: gc cleanup of tags on gc shard index=" <<
+	  io.index << " returned error, ret=" << ret << dendl;
       }
       goto done;
     }
 
     if (ret < 0) {
-      ldout(cct, 0) << "WARNING: could not remove oid=" << io.oid << ", ret=" << ret << dendl;
+      ldout(cct, 0) << "WARNING: gc could not remove oid=" << io.oid <<
+	", ret=" << ret << dendl;
       goto done;
     }
 
-    rt.push_back(io.tag);
-    if (rt.size() > (size_t)cct->_conf->rgw_gc_max_trim_chunk) {
-      flush_remove_tags(io.index, rt);
-    }
-done:
+    schedule_tag_removal(io.index, io.tag);
+
+  done:
     ios.pop_front();
   }
 
+  void schedule_tag_removal(int index, string tag) {
+    auto& rt = remove_tags[index];
+
+    // since every element of a chain tries to add the same tag, and
+    // since chains are handled sequentially, check to make sure it's
+    // not already on the list
+    if (rt.empty() || rt.back() != tag) {
+      rt.push_back(tag);
+      if (rt.size() >= (size_t)cct->_conf->rgw_gc_max_trim_chunk) {
+	flush_remove_tags(index, rt);
+      }
+    }
+  }
+
   void drain_ios() {
     while (!ios.empty()) {
       if (gc->going_down()) {
@@ -241,15 +256,39 @@ done:
     index_io.type = IO::IndexIO;
     index_io.index = index;
 
+    // use lambda to assemble list, so it will only get executed if
+    // we're at the appropirate logging level
+    auto lister = [&rt]() -> std::string {
+      std::stringstream out;
+      bool first = true;
+
+      for (const auto& s : rt) {
+	if (first) {
+	  first = false;
+	} else {
+	  out << ", ";
+	}
+	out << s;
+      }
+
+      return out.str();
+    };
+
+    ldout(cct, 20) << __func__ <<
+      " removing entries from gc log shard index=" << index << ", size=" <<
+      rt.size() << ", entries=[" << lister() << "]" << dendl;
+
     int ret = gc->remove(index, rt, &index_io.c);
     rt.clear();
     if (ret < 0) {
-      /* we already cleared list of tags, this prevents us from ballooning in case of
-       * a persistent problem
+      /* we already cleared list of tags, this prevents us from
+       * ballooning in case of a persistent problem
        */
-      ldout(cct, 0) << "WARNING: failed to remove tags on gc shard index=" << index << " ret=" << ret << dendl;
+      ldout(cct, 0) << "WARNING: failed to remove tags on gc shard index=" <<
+	index << " ret=" << ret << dendl;
       return;
     }
+
     ios.push_back(index_io);
   }
 
@@ -260,11 +299,15 @@ done:
       ++index;
     }
   }
-};
+}; // class RGWGCIOManger
 
 int RGWGC::process(int index, int max_secs, bool expired_only,
                    RGWGCIOManager& io_manager)
 {
+  ldout(cct, 20) << "RGWGC::process entered with GC index_shard=" <<
+    index << ", max_secs=" << max_secs << ", expired_only=" <<
+    expired_only << dendl;
+
   rados::cls::lock::Lock l(gc_index_lock_name);
   utime_t end = ceph_clock_now();
 
@@ -281,7 +324,8 @@ int RGWGC::process(int index, int max_secs, bool expired_only,
 
   int ret = l.lock_exclusive(&store->gc_pool_ctx, obj_names[index]);
   if (ret == -EBUSY) { /* already locked by another gc processor */
-    dout(10) << "RGWGC::process() failed to acquire lock on " << obj_names[index] << dendl;
+    dout(10) << "RGWGC::process failed to acquire lock on " <<
+      obj_names[index] << dendl;
     return 0;
   }
   if (ret < 0)
@@ -294,7 +338,14 @@ int RGWGC::process(int index, int max_secs, bool expired_only,
   do {
     int max = 100;
     std::list<cls_rgw_gc_obj_info> entries;
-    ret = cls_rgw_gc_list(store->gc_pool_ctx, obj_names[index], marker, max, expired_only, entries, &truncated, next_marker);
+
+    ret = cls_rgw_gc_list(store->gc_pool_ctx, obj_names[index], marker, max,
+			  expired_only, entries, &truncated, next_marker);
+    ldout(cct, 20) <<
+      "RGWGC::process cls_rgw_gc_list returned with returned:" << ret <<
+      ", entries.size=" << entries.size() << ", truncated=" << truncated <<
+      ", next_marker='" << next_marker << "'" << dendl;
+
     if (ret == -ENOENT) {
       ret = 0;
       goto done;
@@ -302,57 +353,75 @@ int RGWGC::process(int index, int max_secs, bool expired_only,
     if (ret < 0)
       goto done;
 
+    marker = next_marker;
+
     string last_pool;
     std::list<cls_rgw_gc_obj_info>::iterator iter;
     for (iter = entries.begin(); iter != entries.end(); ++iter) {
       cls_rgw_gc_obj_info& info = *iter;
+
+      ldout(cct, 20) << "RGWGC::process iterating over entry tag='" <<
+	info.tag << "', time=" << info.time << ", chain.objs.size()=" <<
+	info.chain.objs.size() << dendl;
+
       std::list<cls_rgw_obj>::iterator liter;
       cls_rgw_obj_chain& chain = info.chain;
 
       utime_t now = ceph_clock_now();
-      if (now >= end)
+      if (now >= end) {
         goto done;
+      }
 
-      for (liter = chain.objs.begin(); liter != chain.objs.end(); ++liter) {
-        cls_rgw_obj& obj = *liter;
-
-        if (obj.pool != last_pool) {
-          delete ctx;
-          ctx = new IoCtx;
-	  ret = rgw_init_ioctx(store->get_rados_handle(), obj.pool, *ctx);
-	  if (ret < 0) {
-	    last_pool = "";
-	    dout(0) << "ERROR: failed to create ioctx pool=" << obj.pool << dendl;
-	    continue;
+      if (chain.objs.empty()) {
+        io_manager.schedule_tag_removal(index, info.tag);
+      } else {
+	for (liter = chain.objs.begin(); liter != chain.objs.end(); ++liter) {
+	  cls_rgw_obj& obj = *liter;
+
+	  if (obj.pool != last_pool) {
+	    delete ctx;
+	    ctx = new IoCtx;
+	    ret = rgw_init_ioctx(store->get_rados_handle(), obj.pool, *ctx);
+	    if (ret < 0) {
+	      last_pool = "";
+	      dout(0) << "ERROR: failed to create ioctx pool=" <<
+		obj.pool << dendl;
+	      continue;
+	    }
+	    last_pool = obj.pool;
 	  }
-          last_pool = obj.pool;
-        }
 
-        ctx->locator_set_key(obj.loc);
+	  ctx->locator_set_key(obj.loc);
 
-        const string& oid = obj.key.name; /* just stored raw oid there */
+	  const string& oid = obj.key.name; /* just stored raw oid there */
 
-	dout(5) << "gc::process: removing " << obj.pool << ":" << obj.key.name << dendl;
-	ObjectWriteOperation op;
-	cls_refcount_put(op, info.tag, true);
+	  dout(5) << "RGWGC::process removing " << obj.pool <<
+	    ":" << obj.key.name << dendl;
+	  ObjectWriteOperation op;
+	  cls_refcount_put(op, info.tag, true);
 
-        ret = io_manager.schedule_io(ctx, oid, &op, index, info.tag);
-        if (ret < 0) {
-          ldout(store->ctx(), 0) << "WARNING: failed to schedule deletion for oid=" << oid << dendl;
-        }
-
-        if (going_down()) // leave early, even if tag isn't removed, it's ok
-          goto done;
-      }
-    }
+	  ret = io_manager.schedule_io(ctx, oid, &op, index, info.tag);
+	  if (ret < 0) {
+	    dout(0) <<
+	      "WARNING: failed to schedule deletion for oid=" << oid << dendl;
+	  }
+	  if (going_down()) {
+	    // leave early, even if tag isn't removed, it's ok since it
+	    // will be picked up next time around
+	    goto done;
+	  }
+	} // chains loop
+      } // else -- chains not empty
+    } // entries loop
   } while (truncated);
 
 done:
-  /* we don't drain here, because if we're going down we don't want to hold the system
-   * if backend is unresponsive
+  /* we don't drain here, because if we're going down we don't want to
+   * hold the system if backend is unresponsive
    */
   l.unlock(&store->gc_pool_ctx, obj_names[index]);
   delete ctx;
+
   return 0;
 }
 
@@ -437,4 +506,3 @@ void RGWGC::GCWorker::stop()
   Mutex::Locker l(lock);
   cond.Signal();
 }
-
-- 
2.39.5