From: kchheda3 Date: Wed, 6 Mar 2024 23:13:57 +0000 (-0500) Subject: rgw/notification: add rgw notification specific debug log subsystem. X-Git-Tag: v19.2.3~311^2~3 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=bc2bca96222ecdc9c55ab2b0a6d1619fb44da7a5;p=ceph.git rgw/notification: add rgw notification specific debug log subsystem. decorate the events with event details while logging. Signed-off-by: kchheda3 (cherry picked from commit 429967917b4f9b5f71214fa3c7718e780728249b) --- diff --git a/doc/rados/troubleshooting/log-and-debug.rst b/doc/rados/troubleshooting/log-and-debug.rst index 1a4c51f7c55d..81bc320e6ae1 100644 --- a/doc/rados/troubleshooting/log-and-debug.rst +++ b/doc/rados/troubleshooting/log-and-debug.rst @@ -302,6 +302,8 @@ to their default level or to a level suitable for normal operations. +--------------------------+-----------+--------------+ | ``rgw lifecycle`` | 1 | 5 | +--------------------------+-----------+--------------+ +| ``rgw notification`` | 1 | 5 | ++--------------------------+-----------+--------------+ | ``javaclient`` | 1 | 5 | +--------------------------+-----------+--------------+ | ``asok`` | 1 | 5 | diff --git a/qa/suites/crimson-rados/perf/settings/optimized.yaml b/qa/suites/crimson-rados/perf/settings/optimized.yaml index deefc61d3d83..65a8c7f56ea3 100644 --- a/qa/suites/crimson-rados/perf/settings/optimized.yaml +++ b/qa/suites/crimson-rados/perf/settings/optimized.yaml @@ -55,6 +55,7 @@ overrides: debug rgw: "0/0" debug rgw sync: "0/0" debug rgw lifecycle: "0/0" + debug rgw notification: "0/0" debug civetweb: "0/0" debug javaclient: "0/0" debug asok: "0/0" diff --git a/qa/suites/perf-basic/settings/optimized.yaml b/qa/suites/perf-basic/settings/optimized.yaml index 3983ed9d26e6..bba1ddcf7dd8 100644 --- a/qa/suites/perf-basic/settings/optimized.yaml +++ b/qa/suites/perf-basic/settings/optimized.yaml @@ -59,6 +59,7 @@ overrides: debug rgw: "0/0" debug rgw sync: "0/0" debug rgw lifecycle: "0/0" + debug rgw notification: "0/0" debug civetweb: "0/0" debug javaclient: "0/0" debug asok: "0/0" diff --git a/qa/suites/rados/perf/settings/optimized.yaml b/qa/suites/rados/perf/settings/optimized.yaml index 8f05f59163ac..46351c0d578a 100644 --- a/qa/suites/rados/perf/settings/optimized.yaml +++ b/qa/suites/rados/perf/settings/optimized.yaml @@ -55,6 +55,7 @@ overrides: debug rgw: "0/0" debug rgw sync: "0/0" debug rgw lifecycle: "0/0" + debug rgw notification: "0/0" debug civetweb: "0/0" debug javaclient: "0/0" debug asok: "0/0" diff --git a/qa/suites/rgw/multisite/overrides.yaml b/qa/suites/rgw/multisite/overrides.yaml index 774855e5da05..fad120bf2ed9 100644 --- a/qa/suites/rgw/multisite/overrides.yaml +++ b/qa/suites/rgw/multisite/overrides.yaml @@ -7,6 +7,7 @@ overrides: debug rgw: 20 debug rgw sync: 20 debug rgw lifecycle: 20 + debug rgw notification: 20 rgw crypt s3 kms backend: testing rgw crypt s3 kms encryption keys: testkey-1=YmluCmJvb3N0CmJvb3N0LWJ1aWxkCmNlcGguY29uZgo= rgw crypt require ssl: false diff --git a/src/common/subsys.h b/src/common/subsys.h index 0bc92346530f..c331f5767cd8 100644 --- a/src/common/subsys.h +++ b/src/common/subsys.h @@ -66,6 +66,7 @@ SUBSYS(rgw_access, 1, 5) SUBSYS(rgw_dbstore, 1, 5) SUBSYS(rgw_flight, 1, 5) SUBSYS(rgw_lifecycle, 1, 5) +SUBSYS(rgw_notification, 1, 5) SUBSYS(javaclient, 1, 5) SUBSYS(asok, 1, 5) SUBSYS(throttle, 1, 1) diff --git a/src/rgw/driver/rados/rgw_notify.cc b/src/rgw/driver/rados/rgw_notify.cc index b3437c6685ed..1363e2092893 100644 --- a/src/rgw/driver/rados/rgw_notify.cc +++ b/src/rgw/driver/rados/rgw_notify.cc @@ -21,9 +21,20 @@ #include "common/dout.h" #include -#define dout_subsys ceph_subsys_rgw +#define dout_subsys ceph_subsys_rgw_notification namespace rgw::notify { + +static inline std::ostream& operator<<(std::ostream& out, + const event_entry_t& e) { + return out << "notification id: '" << e.event.configurationId + << "', topic: '" << e.arn_topic + << "', endpoint: '" << e.push_endpoint + << "', bucket_owner: '" << e.event.bucket_ownerIdentity + << "', bucket: '" << e.event.bucket_name + << "', object: '" << e.event.object_key + << "', event type: '" << e.event.eventName << "'"; +} struct persistency_tracker { ceph::coarse_real_time last_retry_time {ceph::coarse_real_clock::zero()}; @@ -58,18 +69,6 @@ void publish_commit_completion(rados_completion_t completion, void* arg) { } }; -static inline std::ostream& operator<<(std::ostream& out, - const event_entry_t& e) { - return out << "notification id: '" << e.event.configurationId - << "', topic: '" << e.arn_topic - << "', endpoint: '" << e.push_endpoint - << "', bucket_owner: '" << e.event.bucket_ownerIdentity - << "', bucket: '" << e.event.bucket_name - << "', object: '" << e.event.object_key - << "', event type: '" << e.event.eventName << "'"; -} - - class Manager : public DoutPrefixProvider { bool shutdown = false; const uint32_t queues_update_period_ms; @@ -222,15 +221,12 @@ private: if ( (topic_persistency_ttl != 0 && event_entry.creation_time != ceph::coarse_real_clock::zero() && time_now - event_entry.creation_time > std::chrono::seconds(topic_persistency_ttl)) || ( topic_persistency_max_retries != 0 && entry_persistency_tracker.retires_num > topic_persistency_max_retries) ) { - ldpp_dout(this, 1) << "Expiring entry for topic= " - << event_entry.arn_topic << " bucket_owner= " - << event_entry.event.bucket_ownerIdentity - << " bucket= " << event_entry.event.bucket_name - << " object_name= " << event_entry.event.object_key - << " entry retry_number=" + ldpp_dout(this, 1) << "WARNING: Expiring entry marker: " << entry.marker + << " for event with " << event_entry + << " entry retry_number: " << entry_persistency_tracker.retires_num - << " creation_time=" << event_entry.creation_time - << " time_now=" << time_now << dendl; + << " creation_time: " << event_entry.creation_time + << " time_now: " << time_now << dendl; return EntryProcessingResult::Expired; } if (time_now - entry_persistency_tracker.last_retry_time < std::chrono::seconds(topic_persistency_sleep_duration) ) { @@ -275,12 +271,15 @@ private: auto ret = rgw_rados_operate(this, rados_store.getRados()->get_notif_pool_ctx(), queue_name, &op, yield); if (ret == -ENOENT) { // queue was deleted - ldpp_dout(this, 5) << "INFO: queue: " - << queue_name << ". was removed. cleanup will stop" << dendl; + ldpp_dout(this, 10) << "INFO: queue: " << queue_name + << ". was removed. cleanup will stop" << dendl; return; } if (ret == -EBUSY) { - ldpp_dout(this, 5) << "WARNING: queue: " << queue_name << " ownership moved to another daemon. processing will stop" << dendl; + ldpp_dout(this, 10) + << "WARNING: queue: " << queue_name + << " ownership moved to another daemon. processing will stop" + << dendl; return; } if (ret < 0) { @@ -398,13 +397,16 @@ private: if (ret == -ENOENT) { // queue was deleted topics_persistency_tracker.erase(queue_name); - ldpp_dout(this, 5) << "INFO: queue: " - << queue_name << ". was removed. processing will stop" << dendl; + ldpp_dout(this, 10) << "INFO: queue: " << queue_name + << ". was removed. processing will stop" << dendl; return; } if (ret == -EBUSY) { topics_persistency_tracker.erase(queue_name); - ldpp_dout(this, 5) << "WARNING: queue: " << queue_name << " ownership moved to another daemon. processing will stop" << dendl; + ldpp_dout(this, 10) + << "WARNING: queue: " << queue_name + << " ownership moved to another daemon. processing will stop" + << dendl; return; } if (ret < 0) { @@ -523,11 +525,15 @@ private: auto ret = rgw_rados_operate(this, rados_ioctx, queue_name, &op, yield); if (ret == -ENOENT) { // queue was deleted - ldpp_dout(this, 5) << "INFO: queue: " << queue_name << ". was removed. processing will stop" << dendl; + ldpp_dout(this, 10) << "INFO: queue: " << queue_name + << ". was removed. processing will stop" << dendl; return; } if (ret == -EBUSY) { - ldpp_dout(this, 5) << "WARNING: queue: " << queue_name << " ownership moved to another daemon. processing will stop" << dendl; + ldpp_dout(this, 10) + << "WARNING: queue: " << queue_name + << " ownership moved to another daemon. processing will stop" + << dendl; return; } if (ret < 0) { @@ -1250,23 +1256,16 @@ int publish_commit(rgw::sal::Object* obj, const auto ret = push_endpoint->send(event_entry.event, res.yield); if (ret < 0) { ldpp_dout(dpp, 1) - << "ERROR: push to endpoint " << topic.cfg.dest.push_endpoint - << " bucket: " << event_entry.event.bucket_name - << " bucket_owner: " << event_entry.event.bucket_ownerIdentity - << " object_name: " << event_entry.event.object_key - << " failed. error: " << ret << dendl; + << "ERROR: failed to push sync notification event with error: " + << ret << " for event with " << event_entry << dendl; if (perfcounter) perfcounter->inc(l_rgw_pubsub_push_failed); return ret; } if (perfcounter) perfcounter->inc(l_rgw_pubsub_push_ok); } catch (const RGWPubSubEndpoint::configuration_error& e) { - ldpp_dout(dpp, 1) << "ERROR: failed to create push endpoint: " - << topic.cfg.dest.push_endpoint - << " bucket: " << event_entry.event.bucket_name - << " bucket_owner: " - << event_entry.event.bucket_ownerIdentity - << " object_name: " << event_entry.event.object_key - << ". error: " << e.what() << dendl; + ldpp_dout(dpp, 1) << "ERROR: failed to create push endpoint for sync " + "notification event with error: " + << e.what() << " event with " << event_entry << dendl; if (perfcounter) perfcounter->inc(l_rgw_pubsub_push_failed); return -EINVAL; } diff --git a/src/rgw/rgw_amqp.cc b/src/rgw/rgw_amqp.cc index 805afaf2c5bf..893db7222337 100644 --- a/src/rgw/rgw_amqp.cc +++ b/src/rgw/rgw_amqp.cc @@ -20,7 +20,7 @@ #include "common/dout.h" #include -#define dout_subsys ceph_subsys_rgw +#define dout_subsys ceph_subsys_rgw_notification // TODO investigation, not necessarily issues: // (1) in case of single threaded writer context use spsc_queue diff --git a/src/rgw/rgw_kafka.cc b/src/rgw/rgw_kafka.cc index e944cd05f815..7420e68c2644 100644 --- a/src/rgw/rgw_kafka.cc +++ b/src/rgw/rgw_kafka.cc @@ -16,7 +16,7 @@ #include #include "common/dout.h" -#define dout_subsys ceph_subsys_rgw +#define dout_subsys ceph_subsys_rgw_notification // this is the inverse of rd_kafka_errno2err // see: https://github.com/confluentinc/librdkafka/blob/master/src/rdkafka.c