rgw/notification: add rgw notification specific debug log subsystem.

decorate the events with event details while logging.

Signed-off-by: kchheda3 <kchheda3@bloomberg.net>
(cherry picked from commit 429967917b4f9b5f71214fa3c7718e780728249b)

diff --git a/doc/rados/troubleshooting/log-and-debug.rst b/doc/rados/troubleshooting/log-and-debug.rst
index 1a4c51f7c55d609227421d83aa472e0b9dcd96b5..81bc320e6ae1aac29ed606e5301a566a6778562a 100644 (file)
--- 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 deefc61d3d83b22fb69b805225188db082f14bf5..65a8c7f56ea31a5357b7ac459877df5ae5e7fe5a 100644 (file)
--- 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 3983ed9d26e638f8876e96cc13324a2c431f3c5b..bba1ddcf7dd8a9129edc0290140f0d836cac7eaa 100644 (file)
--- 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 8f05f59163ac56cab2f06285bf95794e84268459..46351c0d578aa4c8916879e3ba3848b170661d73 100644 (file)
--- 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 774855e5da057deb76cba747ad2ea83ea3f8f4a1..fad120bf2ed9b3507ae2a8318505ce4a25a0e365 100644 (file)
--- 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 0bc92346530faf297e071f575f2cf7886357684a..c331f5767cd8ab72381a4148127160df823d6d99 100644 (file)
--- 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 b3437c6685eda82768b81580d6ca20f64eaefbea..1363e2092893070df2e252699380f10432a38314 100644 (file)
--- 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 <chrono>
 
-#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 805afaf2c5bf7d53c0dc7b934dee9f4b0b9399ec..893db72223372bf3a58266686372b8229ca6c412 100644 (file)
--- a/src/rgw/rgw_amqp.cc
+++ b/src/rgw/rgw_amqp.cc
@@ -20,7 +20,7 @@
 #include "common/dout.h"
 #include <openssl/ssl.h>
 
-#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 e944cd05f81586be03c0e131af234e1bb8f0aef7..7420e68c2644865945916073dffa9e20f29e4b05 100644 (file)
--- a/src/rgw/rgw_kafka.cc
+++ b/src/rgw/rgw_kafka.cc
@@ -16,7 +16,7 @@
 #include <boost/lockfree/queue.hpp>
 #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