From 20e9121fdcf414dc5e8c258208ffecf64dc1d241 Mon Sep 17 00:00:00 2001 From: "J. Eric Ivancich" Date: Thu, 17 Mar 2022 17:05:10 -0400 Subject: [PATCH] rgw: bucket index transaction instrumentation clean-ups Add a series of clean-ups to the instrumentation code. Keep this as a separate commit so it will be easier to reconcile other code streams. Signed-off-by: J. Eric Ivancich --- src/cls/rgw/cls_rgw.cc | 118 ++++++++++++++++++++++------------------- src/rgw/rgw_rados.cc | 53 ++++++++++-------- 2 files changed, 94 insertions(+), 77 deletions(-) diff --git a/src/cls/rgw/cls_rgw.cc b/src/cls/rgw/cls_rgw.cc index b103b8a1a3519..f83432fc6399a 100644 --- a/src/cls/rgw/cls_rgw.cc +++ b/src/cls/rgw/cls_rgw.cc @@ -856,6 +856,14 @@ static int read_key_entry(cls_method_context_t hctx, const cls_rgw_obj_key& key, string *idx, rgw_bucket_dir_entry *entry, bool special_delete_marker_name = false); +static std::string modify_op_str(RGWModifyOp op) { + return std::string(to_string(op)); +} + +static std::string modify_op_str(uint8_t op) { + return modify_op_str((RGWModifyOp) op); +} + int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist *out) { const ConfigProxy& conf = cls_get_config(hctx); @@ -865,7 +873,7 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist const bool bitx_inst = conf->rgw_bucket_index_transaction_instrumentation; - CLS_LOG_BITX(bitx_inst, 1, "ENTERING %s for object oid=%s key=%s", + CLS_LOG_BITX(bitx_inst, 10, "ENTERING %s for object oid=%s key=%s", __func__, oi.soid.oid.name.c_str(), oi.soid.get_key().c_str()); // decode request @@ -885,8 +893,8 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist } CLS_LOG_BITX(bitx_inst, 1, - "INFO: %s: request: op=%d name=%s instance=%s tag=%s", __func__, - op.op, op.key.name.c_str(), op.key.instance.c_str(), op.tag.c_str()); + "INFO: %s: request: op=%s name=%s tag=%s", __func__, + modify_op_str(op.op).c_str(), op.key.to_string().c_str(), op.tag.c_str()); // get on-disk state std::string idx; @@ -895,8 +903,8 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist int rc = read_key_entry(hctx, op.key, &idx, &entry); if (rc < 0 && rc != -ENOENT) { CLS_LOG_BITX(bitx_inst, 1, - "ERROR: %s could not read key entry, key=%s(%s), rc=%d", - __func__, op.key.name.c_str(), op.key.instance.c_str(), rc); + "ERROR: %s could not read key entry, key=%s, rc=%d", + __func__, op.key.to_string().c_str(), rc); return rc; } @@ -917,8 +925,9 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist info.state = CLS_RGW_STATE_PENDING_MODIFY; info.op = op.op; CLS_LOG_BITX(bitx_inst, 20, - "INFO: %s: inserting tag %s op %c into pending map for entry %s", - __func__, op.tag, info.op, entry.key.to_string().c_str()); + "INFO: %s: inserting tag %s op %s into pending map for entry %s", + __func__, op.tag.c_str(), modify_op_str(info.op).c_str(), + entry.key.to_string().c_str()); entry.pending_map.insert(pair(op.tag, info)); // write out new key to disk @@ -926,19 +935,18 @@ int rgw_bucket_prepare_op(cls_method_context_t hctx, bufferlist *in, bufferlist encode(entry, info_bl); CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: setting map entry at key=%s", - __func__, idx.c_str()); + __func__, escape_str(idx).c_str()); rc = cls_cxx_map_set_val(hctx, idx, &info_bl); if (rc < 0) { CLS_LOG_BITX(bitx_inst, 1, "ERROR: %s could not set value for key, key=%s, rc=%d", - __func__, idx.c_str(), rc); + __func__, escape_str(idx).c_str(), rc); return rc; } - - CLS_LOG_BITX(bitx_inst, 1, "EXITING %s, returning 0", __func__); + CLS_LOG_BITX(bitx_inst, 10, "EXITING %s, returning 0", __func__); return 0; -} +} // rgw_bucket_prepare_op static void unaccount_entry(rgw_bucket_dir_header& header, rgw_bucket_dir_entry& entry) @@ -1079,7 +1087,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist const bool bitx_inst = conf->rgw_bucket_index_transaction_instrumentation; - CLS_LOG_BITX(bitx_inst, 1, "ENTERING %s for object oid=%s key=%s", + CLS_LOG_BITX(bitx_inst, 10, "ENTERING %s for object oid=%s key=%s", __func__, oi.soid.oid.name.c_str(), oi.soid.get_key().c_str()); // decode request @@ -1093,16 +1101,17 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist } CLS_LOG_BITX(bitx_inst, 1, - "INFO: %s: request: op=%d name=%s instance=%s ver=%lu:%llu tag=%s", + "INFO: %s: request: op=%s name=%s ver=%lu:%llu tag=%s", __func__, - op.op, op.key.name.c_str(), op.key.instance.c_str(), + modify_op_str(op.op).c_str(), op.key.to_string().c_str(), (unsigned long)op.ver.pool, (unsigned long long)op.ver.epoch, op.tag.c_str()); rgw_bucket_dir_header header; int rc = read_bucket_header(hctx, &header); if (rc < 0) { - CLS_LOG_BITX(bitx_inst, 1, "ERROR: %s: failed to read header", __func__); + CLS_LOG_BITX(bitx_inst, 1, "ERROR: %s: failed to read header, rc=%d", + __func__, rc); return -EINVAL; } @@ -1119,8 +1128,8 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist ondisk = false; } else if (rc < 0) { CLS_LOG_BITX(bitx_inst, 1, - "ERROR: %s: read key entry failed, key=%s(%s), rc=%d", - __func__, op.key.name.c_str(), op.key.instance.c_str(), rc); + "ERROR: %s: read key entry failed, key=%s, rc=%d", + __func__, op.key.to_string().c_str(), rc); return rc; } @@ -1133,7 +1142,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist auto pinter = entry.pending_map.find(op.tag); if (pinter == entry.pending_map.end()) { CLS_LOG_BITX(bitx_inst, 1, - "ERROR: %s: couldn't find tag for pending operation with tag:\"%s\"", + "ERROR: %s: couldn't find tag for pending operation with tag %s", __func__, op.tag.c_str()); return -EINVAL; } @@ -1148,7 +1157,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist } else if (op.ver.pool == entry.ver.pool && op.ver.epoch && op.ver.epoch <= entry.ver.epoch) { CLS_LOG_BITX(bitx_inst, 20, - "%s: skipping request, old epoch", __func__); + "INFO: %s: skipping request, old epoch", __func__); op.op = CLS_RGW_OP_CANCEL; } @@ -1164,14 +1173,14 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist // we removed this tag from pending_map so need to write the changes CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: setting map entry at key=%s", - __func__, idx.c_str()); + __func__, escape_str(idx).c_str()); bufferlist new_key_bl; encode(entry, new_key_bl); rc = cls_cxx_map_set_val(hctx, idx, &new_key_bl); if (rc < 0) { CLS_LOG_BITX(bitx_inst, 1, "ERROR: %s: unable to set map val, key=%s, rc=%d", - __func__, idx.c_str(), rc); + __func__, escape_str(idx).c_str(), rc); return rc; } } @@ -1182,23 +1191,23 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: delete op, key=%s", - __func__, idx.c_str()); + __func__, escape_str(idx).c_str()); entry.meta = op.meta; if (!ondisk) { // no entry to erase CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: key=%s not on disk, no action", - __func__, idx.c_str()); + __func__, escape_str(idx).c_str()); log_op = false; } else if (!entry.pending_map.size()) { CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: removing map entry with key=%s", - __func__, idx.c_str()); + __func__, escape_str(idx).c_str()); rc = cls_cxx_map_remove_key(hctx, idx); if (rc < 0) { CLS_LOG_BITX(bitx_inst, 1, "ERROR: %s: unable to remove map key, key=%s, rc=%d", - __func__, idx.c_str(), rc); + __func__, escape_str(idx).c_str(), rc); return rc; } } else { @@ -1207,12 +1216,12 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist encode(entry, new_key_bl); CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: setting map entry at key=%s", - __func__, idx.c_str()); + __func__, escape_str(idx).c_str()); rc = cls_cxx_map_set_val(hctx, idx, &new_key_bl); if (rc < 0) { CLS_LOG_BITX(bitx_inst, 1, "ERROR: %s: unable to set map val, key=%s, rc=%d", - __func__, idx.c_str(), rc); + __func__, escape_str(idx).c_str(), rc); return rc; } } @@ -1220,7 +1229,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist else if (op.op == CLS_RGW_OP_ADD) { CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: add op, key=%s", - __func__, idx.c_str()); + __func__, escape_str(idx).c_str()); // unaccount overwritten entry unaccount_entry(header, entry); @@ -1239,12 +1248,12 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist encode(entry, new_key_bl); CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: setting map entry at key=%s", - __func__, idx.c_str()); + __func__, escape_str(idx).c_str()); rc = cls_cxx_map_set_val(hctx, idx, &new_key_bl); if (rc < 0) { CLS_LOG_BITX(bitx_inst, 1, - "ERROR: %s: unable to log index operation, key=%s(%s), tag=%s, rc=%d", - __func__, op.key.name.c_str(), op.key.instance.c_str(), op.tag.c_str(), rc); + "ERROR: %s: unable to set map value at key=%s, rc=%d", + __func__, escape_str(idx).c_str(), rc); return rc; } } // CLS_RGW_OP_ADD @@ -1256,25 +1265,24 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist &op.zones_trace); if (rc < 0) { CLS_LOG_BITX(bitx_inst, 0, - "%s: log_index_operation failed with rc=%d", + "ERROR: %s: log_index_operation failed with rc=%d", __func__, rc); return rc; } } - CLS_LOG(20, "rgw_bucket_complete_op(): remove_objs.size()=%d", - (int)op.remove_objs.size()); + CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: remove_objs.size()=%d", + __func__, (int)op.remove_objs.size()); for (const auto& remove_key : op.remove_objs) { CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: completing object remove key=%s", - __func__, remove_key.to_string().c_str()); + __func__, escape_str(remove_key.to_string()).c_str()); rc = complete_remove_obj(hctx, header, remove_key, default_log_op); if (rc < 0) { CLS_LOG_BITX(bitx_inst, 1, "WARNING: %s: complete_remove_obj, failed to remove entry, " - "name=%s instance=%s read_index_entry ret=%d, continuing", - __func__, remove_key.name.c_str(), - remove_key.instance.c_str(), rc); + "name=%s read_index_entry ret=%d, continuing", + __func__, escape_str(remove_key.to_string()).c_str(), rc); continue; // part cleanup errors are not fatal } } // remove loop @@ -1288,7 +1296,7 @@ int rgw_bucket_complete_op(cls_method_context_t hctx, bufferlist *in, bufferlist __func__, rc); } - CLS_LOG_BITX(bitx_inst, 20, + CLS_LOG_BITX(bitx_inst, 10, "EXITING %s: returning %d", __func__, rc); return rc; } // rgw_bucket_complete_op @@ -2276,7 +2284,7 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx, const bool bitx_inst = conf->rgw_bucket_index_transaction_instrumentation; - CLS_LOG_BITX(bitx_inst, 1, "ENTERING %s for object oid=%s key=%s", + CLS_LOG_BITX(bitx_inst, 10, "ENTERING %s for object oid=%s key=%s", __func__, oi.soid.oid.name.c_str(), oi.soid.get_key().c_str()); bufferlist header_bl; @@ -2361,7 +2369,7 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx, // these pending entries will prevent us from applying suggested changes real_time cur_time = real_clock::now(); auto iter = cur_disk.pending_map.begin(); - while(iter != cur_disk.pending_map.end()) { + while (iter != cur_disk.pending_map.end()) { auto cur_iter = iter++; // IMPORTANT, cur_iter might be invalidated if (cur_time > (cur_iter->second.timestamp + timespan(tag_timeout))) { CLS_LOG_BITX(bitx_inst, 0, @@ -2370,16 +2378,16 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx, __func__, cur_iter->first.c_str(), cur_iter->second.state, - std::string(to_string((RGWModifyOp) iter->second.op)).c_str()); + modify_op_str(iter->second.op).c_str()); cur_disk.pending_map.erase(cur_iter); } } // while } // if CLS_LOG_BITX(bitx_inst, 20, - "INFO: %s: cur_disk.pending_map.empty()=%d op=%c cur_disk.exists=%d " + "INFO: %s: op=%c cur_disk.pending_map.empty()=%d cur_disk.exists=%d " "cur_disk.index_ver=%d cur_change.exists=%d cur_change.index_ver=%d", - __func__, cur_disk.pending_map.empty(), op, cur_disk.exists, + __func__, op, cur_disk.pending_map.empty(), cur_disk.exists, (int)cur_disk.index_ver, cur_change.exists, (int)cur_change.index_ver); @@ -2394,7 +2402,8 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx, CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: cur_disk.pending_map is empty", __func__); if (cur_disk.exists) { rgw_bucket_category_stats& old_stats = header.stats[cur_disk.meta.category]; - CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: stats.num_entries: %ld -> %ld", __func__, old_stats.num_entries, old_stats.num_entries - 1); + CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: stats.num_entries: %ld -> %ld", + __func__, old_stats.num_entries, old_stats.num_entries - 1); old_stats.num_entries--; old_stats.total_size -= cur_disk.meta.accounted_size; old_stats.total_size_rounded -= cls_rgw_get_rounded_size(cur_disk.meta.accounted_size); @@ -2406,9 +2415,8 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx, switch(op) { case CEPH_RGW_REMOVE: CLS_LOG_BITX(bitx_inst, 10, - "INFO: %s: CEPH_RGW_REMOVE name=%s instance=%s encoded=%s", - __func__, cur_change.key.name.c_str(), - cur_change.key.instance.c_str(), + "INFO: %s: CEPH_RGW_REMOVE name=%s encoded=%s", + __func__, escape_str(cur_change.key.to_string()).c_str(), escape_str(cur_change_key).c_str()); CLS_LOG_BITX(bitx_inst, 20, @@ -2432,8 +2440,8 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx, break; case CEPH_RGW_UPDATE: CLS_LOG_BITX(bitx_inst, 10, - "INFO: %s: CEPH_RGW_UPDATE name=%s instance=%s stats.num_entries: %ld -> %ld", - __func__, cur_change.key.name.c_str(), cur_change.key.instance.c_str(), + "INFO: %s: CEPH_RGW_UPDATE name=%s stats.num_entries: %ld -> %ld", + __func__, escape_str(cur_change.key.to_string()).c_str(), stats.num_entries, stats.num_entries + 1); stats.num_entries++; @@ -2447,7 +2455,7 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx, CLS_LOG_BITX(bitx_inst, 20, "INFO: %s: setting map entry at key=%s", - __func__, cur_change.key.name.c_str()); + __func__, escape_str(cur_change.key.to_string()).c_str()); ret = cls_cxx_map_set_val(hctx, cur_change_key, &cur_state_bl); if (ret < 0) { CLS_LOG_BITX(bitx_inst, 0, "ERROR: %s: unable to set value for key, key=%s, error=%d", @@ -2468,19 +2476,19 @@ int rgw_dir_suggest_changes(cls_method_context_t hctx, } // while (!in_iter.end()) if (header_changed) { - CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: header changed, writing", __func__); + CLS_LOG_BITX(bitx_inst, 10, "INFO: %s: bucket header changed, writing", __func__); int ret = write_bucket_header(hctx, &header); if (ret < 0) { CLS_LOG_BITX(bitx_inst, 0, "ERROR: %s: failed to write bucket header ret=%d", __func__, ret); } else { - CLS_LOG_BITX(bitx_inst, 1, "EXITING %s, returning %d", __func__, ret); + CLS_LOG_BITX(bitx_inst, 10, "EXITING %s, returning %d", __func__, ret); } return ret; } - CLS_LOG_BITX(bitx_inst, 1, "EXITING %s, returning 0", __func__); + CLS_LOG_BITX(bitx_inst, 10, "EXITING %s, returning 0", __func__); return 0; } // rgw_dir_suggest_changes diff --git a/src/rgw/rgw_rados.cc b/src/rgw/rgw_rados.cc index 68d99a08738cb..d9bc8d1e8d854 100644 --- a/src/rgw/rgw_rados.cc +++ b/src/rgw/rgw_rados.cc @@ -895,11 +895,22 @@ void RGWIndexCompletionManager::process() r = store->guard_reshard(&dpp, &bs, c->obj, bucket_info, [&](RGWRados::BucketShard *bs) -> int { + const bool bitx = ctx()->_conf->rgw_bucket_index_transaction_instrumentation; + ldout_bitx(bitx, ctx(), 10) << + "ENTERING " << __func__ << ": bucket-shard=" << bs << + " obj=" << c->obj << " tag=" << c->tag << + " op=" << c->op << ", remove_objs=" << c->remove_objs << dendl_bitx; + ldout_bitx(bitx, ctx(), 25) << + "BACKTRACE: " << __func__ << ": " << ClibBackTrace(1) << dendl_bitx; + librados::ObjectWriteOperation o; cls_rgw_guard_bucket_resharding(o, -ERR_BUSY_RESHARDING); cls_rgw_bucket_complete_op(o, c->op, c->tag, c->ver, c->key, c->dir_meta, &c->remove_objs, c->log_op, c->bilog_op, &c->zones_trace); - return bs->bucket_obj.operate(&dpp, &o, null_yield); + int ret = bs->bucket_obj.operate(&dpp, &o, null_yield); + ldout_bitx(bitx, ctx(), 10) << + "EXITING " << __func__ << ": ret=" << dendl_bitx; + return ret; }); if (r < 0) { ldpp_dout(&dpp, 0) << "ERROR: " << __func__ << "(): bucket index completion failed, obj=" << c->obj << " r=" << r << dendl; @@ -8376,7 +8387,7 @@ int RGWRados::cls_obj_prepare_op(const DoutPrefixProvider *dpp, BucketShard& bs, { const bool bitx = cct->_conf->rgw_bucket_index_transaction_instrumentation; ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": bucket-shard=" << bs << " obj=" << obj << " tag=" << tag << " op=" << op << dendl_bitx; - ldout_bitx(bitx, cct, 10) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx; + ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx; rgw_zone_set zones_trace; if (_zones_trace) { @@ -8402,7 +8413,7 @@ int RGWRados::cls_obj_complete_op(BucketShard& bs, const rgw_obj& obj, RGWModify ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": bucket-shard=" << bs << " obj=" << obj << " tag=" << tag << " op=" << op << ", remove_objs=" << (remove_objs ? *remove_objs : std::list()) << dendl_bitx; - ldout_bitx(bitx, cct, 10) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx; + ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx; ObjectWriteOperation o; rgw_bucket_dir_entry_meta dir_meta; @@ -8535,17 +8546,16 @@ int RGWRados::cls_bucket_list_ordered(const DoutPrefixProvider *dpp, * namespaced entries */ ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": " << bucket_info.bucket << - " start_after=\"" << start_after.name << - "[" << start_after.instance << - "]\", prefix=\"" << prefix << + " start_after=\"" << start_after.to_string() << + "\", prefix=\"" << prefix << ", delimiter=\"" << delimiter << "\", shard_id=" << shard_id << - "\" num_entries=" << num_entries << + "\", num_entries=" << num_entries << ", list_versions=" << list_versions << ", expansion_factor=" << expansion_factor << ", force_check_filter is " << (force_check_filter ? "set" : "unset") << dendl_bitx; - ldout_bitx(bitx, cct, 20) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx; + ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx; m.clear(); @@ -8773,7 +8783,7 @@ int RGWRados::cls_bucket_list_ordered(const DoutPrefixProvider *dpp, librados::Rados::aio_create_completion(nullptr, nullptr); ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << - " doing dir_suggest on " << miter.first << dendl_bitx; + ": doing dir_suggest on " << miter.first << dendl_bitx; ioctx.aio_operate(miter.first, c, &o); c->release(); } @@ -8851,7 +8861,7 @@ int RGWRados::cls_bucket_list_unordered(const DoutPrefixProvider *dpp, "\", num_entries=" << num_entries << ", list_versions=" << list_versions << (force_check_filter ? "set" : "unset") << dendl_bitx; - ldout_bitx(bitx, cct, 20) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx; + ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx; ent_list.clear(); static MultipartMetaFilter multipart_meta_filter; @@ -8936,7 +8946,7 @@ int RGWRados::cls_bucket_list_unordered(const DoutPrefixProvider *dpp, r = rgw_rados_operate(dpp, ioctx, oid, &op, nullptr, null_yield); if (r < 0) { ldpp_dout(dpp, 0) << "ERROR: " << __func__ << - " error in rgw_rados_operate (bucket list op), r=" << r << dendl; + ": error in rgw_rados_operate (bucket list op), r=" << r << dendl; return r; } @@ -8953,12 +8963,12 @@ int RGWRados::cls_bucket_list_unordered(const DoutPrefixProvider *dpp, librados::IoCtx sub_ctx; sub_ctx.dup(ioctx); ldout_bitx(bitx, cct, 20) << "INFO: " << __func__ << - " calling check_disk_state bucket=" << bucket_info.bucket << + ": calling check_disk_state bucket=" << bucket_info.bucket << " entry=" << dirent.key << dendl_bitx; r = check_disk_state(dpp, sub_ctx, bucket_info, dirent, dirent, updates[oid], y); if (r < 0 && r != -ENOENT) { ldpp_dout(dpp, 0) << "ERROR: " << __func__ << - " error in check_disk_state, r=" << r << dendl; + ": error in check_disk_state, r=" << r << dendl; return r; } } else { @@ -9113,8 +9123,8 @@ int RGWRados::remove_objs_from_index(const DoutPrefixProvider *dpp, RGWBucketInf { const bool bitx = cct->_conf->rgw_bucket_index_transaction_instrumentation; ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": bucket=" << bucket_info.bucket << - " entry_key_list.size()=" << entry_key_list.size() << dendl_bitx; - ldout_bitx(bitx, cct, 20) << "BACKTRACE: " << __func__ << ": " << BackTrace(0) << dendl_bitx; + " oid_list.size()=" << oid_list.size() << dendl_bitx; + ldout_bitx(bitx, cct, 25) << "BACKTRACE: " << __func__ << ": " << ClibBackTrace(0) << dendl_bitx; RGWSI_RADOS::Pool index_pool; string dir_oid; @@ -9132,7 +9142,6 @@ int RGWRados::remove_objs_from_index(const DoutPrefixProvider *dpp, RGWBucketInf entry.key = *iter; ldout_bitx(bitx, cct, 5) << "INFO: " << __func__ << ": encoding removal of bucket=" << bucket_info.bucket << - " shard=" << shard << " entry=" << entry.key << " in updates" << dendl_bitx; entry.ver.epoch = (uint64_t)-1; // ULLONG_MAX, needed to that objclass doesn't skip out request updates.append(CEPH_RGW_REMOVE | suggest_flag); @@ -9145,7 +9154,7 @@ int RGWRados::remove_objs_from_index(const DoutPrefixProvider *dpp, RGWBucketInf bufferlist out; r = index_pool.ioctx().exec(dir_oid, RGW_CLASS, RGW_DIR_SUGGEST_CHANGES, updates, out); - ldout_bitx(bitx, cct, 20) << + ldout_bitx(bitx, cct, 10) << "EXITING " << __func__ << " and returning " << r << dendl_bitx; return r; } @@ -9159,7 +9168,7 @@ int RGWRados::check_disk_state(const DoutPrefixProvider *dpp, optional_yield y) { const bool bitx = cct->_conf->rgw_bucket_index_transaction_instrumentation; - ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << " bucket=" << + ldout_bitx(bitx, cct, 10) << "ENTERING " << __func__ << ": bucket=" << bucket_info.bucket << " dir_entry=" << list_state.key << dendl_bitx; std::unique_ptr bucket; @@ -9188,11 +9197,11 @@ int RGWRados::check_disk_state(const DoutPrefixProvider *dpp, list_state.pending_map.clear(); // we don't need this and it inflates size if (!list_state.is_delete_marker() && !astate->exists) { - ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << " disk state exists" << dendl_bitx; + ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << ": disk state exists" << dendl_bitx; /* object doesn't exist right now -- hopefully because it's * marked as !exists and got deleted */ if (list_state.exists) { - ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << " index list state exists" << dendl_bitx; + ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << ": index list state exists" << dendl_bitx; /* FIXME: what should happen now? Work out if there are any * non-bad ways this could happen (there probably are, but annoying * to handle!) */ @@ -9201,7 +9210,7 @@ int RGWRados::check_disk_state(const DoutPrefixProvider *dpp, // encode a suggested removal of that key list_state.ver.epoch = io_ctx.get_last_version(); list_state.ver.pool = io_ctx.get_id(); - ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << " encoding remove of " << list_state.key << " on suggested_updates" << dendl_bitx; + ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << ": encoding remove of " << list_state.key << " on suggested_updates" << dendl_bitx; cls_rgw_encode_suggestion(CEPH_RGW_REMOVE | suggest_flag, list_state, suggested_updates); return -ENOENT; } @@ -9283,7 +9292,7 @@ int RGWRados::check_disk_state(const DoutPrefixProvider *dpp, list_state.exists = true; ldout_bitx(bitx, cct, 10) << "INFO: " << __func__ << - " encoding update of " << list_state.key << " on suggested_updates" << dendl_bitx; + ": encoding update of " << list_state.key << " on suggested_updates" << dendl_bitx; cls_rgw_encode_suggestion(CEPH_RGW_UPDATE | suggest_flag, list_state, suggested_updates); ldout_bitx(bitx, cct, 10) << "EXITING " << __func__ << dendl_bitx; -- 2.39.5