Fix bytes_sent bugs.

log bytes sent/received.
add cct to bufferingfilter
add cct to RGWRestfulIO
AccountingFilter - save cct for debugging output
implement AccountingFilter::complete_request() - account for bytes reported here.
BufferingFilter<T>::complete_request() - ignore counts from send_content_length() complete_header();

Code quality note:
this patch makes "cct" available for a lot of newly added debug
statements.  The debug statements are mostly not very useful (and should
go away in the future) - *But* the "cct" logic should be redone and
incorporated into some base class (such RestfulClient) so that it is
possible to easily add in debug statements such as these in the future.

Fixes: http://tracker.ceph.com/issues/19870
Signed-off-by: Marcus Watts <mwatts@redhat.com>
(cherry picked from commit 0172aab860abe324923a392baf51f956a65b64a5)

diff --git a/src/rgw/rgw_asio_frontend.cc b/src/rgw/rgw_asio_frontend.cc
index 5fc1deec42e4b323d7281e2e14db2dc43647386d..ee6be6256a5ba69b588c612a517b4d190eeee5db 100644 (file)
--- a/src/rgw/rgw_asio_frontend.cc
+++ b/src/rgw/rgw_asio_frontend.cc
@@ -111,11 +111,11 @@ static void handle_connection(RGWProcessEnv& env, tcp::socket socket,
     rgw::asio::ClientIO real_client{socket, parser, buffer};
 
     auto real_client_io = rgw::io::add_reordering(
-                            rgw::io::add_buffering(
+                            rgw::io::add_buffering(cct,
                               rgw::io::add_chunking(
                                 rgw::io::add_conlen_controlling(
                                   &real_client))));
-    RGWRestfulIO client(&real_client_io);
+    RGWRestfulIO client(cct, &real_client_io);
     process_request(env.store, env.rest, &req, env.uri_prefix,
                     *env.auth_registry, &client, env.olog);
 

diff --git a/src/rgw/rgw_civetweb_frontend.cc b/src/rgw/rgw_civetweb_frontend.cc
index 4b1fd766cbfaa13175d7889f55ad96a86d8b4cc7..8cf7a20b0dc0110f355f95ecb633a0c651de3919 100644 (file)
--- a/src/rgw/rgw_civetweb_frontend.cc
+++ b/src/rgw/rgw_civetweb_frontend.cc
@@ -24,11 +24,11 @@ int RGWCivetWebFrontend::process(struct mg_connection*  const conn)
 
   RGWCivetWeb cw_client(conn);
   auto real_client_io = rgw::io::add_reordering(
-                          rgw::io::add_buffering(
+                          rgw::io::add_buffering(dout_context,
                             rgw::io::add_chunking(
                               rgw::io::add_conlen_controlling(
                                 &cw_client))));
-  RGWRestfulIO client_io(&real_client_io);
+  RGWRestfulIO client_io(dout_context, &real_client_io);
 
   RGWRequest req(env.store->get_new_req_id());
   int ret = process_request(env.store, env.rest, &req, env.uri_prefix,

diff --git a/src/rgw/rgw_client_io.h b/src/rgw/rgw_client_io.h
index d06eaea3c2d16bdae092ba9cfccbfb352030ea23..8579b2383526956dee5774136cf2786b8d6c9121 100644 (file)
--- a/src/rgw/rgw_client_io.h
+++ b/src/rgw/rgw_client_io.h
@@ -339,8 +339,8 @@ class RGWRestfulIO : public rgw::io::AccountingFilter<rgw::io::RestfulClient*> {
 public:
   ~RGWRestfulIO() override = default;
 
-  RGWRestfulIO(rgw::io::RestfulClient* engine)
-    : AccountingFilter<rgw::io::RestfulClient*>(std::move(engine)) {
+  RGWRestfulIO(CephContext *_cx, rgw::io::RestfulClient* engine)
+    : AccountingFilter<rgw::io::RestfulClient*>(_cx, std::move(engine)) {
   }
 
   void add_filter(std::shared_ptr<DecoratedRestfulClient> new_filter) {

diff --git a/src/rgw/rgw_client_io_filters.h b/src/rgw/rgw_client_io_filters.h
index 0862f33d3ef570a9d29471bd5e2efba09c9bbedc..04761fc782905236a4fdbcb5fcc72993fcc38769 100644 (file)
--- a/src/rgw/rgw_client_io_filters.h
+++ b/src/rgw/rgw_client_io_filters.h
@@ -20,20 +20,24 @@ class AccountingFilter : public DecoratedRestfulClient<T>,
   bool enabled;
   uint64_t total_sent;
   uint64_t total_received;
+  CephContext *cct;
 
 public:
   template <typename U>
-  AccountingFilter(U&& decoratee)
+  AccountingFilter(CephContext *cct, U&& decoratee)
     : DecoratedRestfulClient<T>(std::forward<U>(decoratee)),
       enabled(false),
       total_sent(0),
-      total_received(0) {
+      total_received(0), cct(cct) {
   }
 
   size_t send_status(const int status,
                      const char* const status_name) override {
     const auto sent = DecoratedRestfulClient<T>::send_status(status,
                                                              status_name);
+    lsubdout(cct, rgw, 30) << "AccountingFilter::send_status: e="
+        << (enabled ? "1" : "0") << ", sent=" << sent << ", total="
+        << total_sent << dendl;
     if (enabled) {
       total_sent += sent;
     }
@@ -42,6 +46,9 @@ public:
 
   size_t send_100_continue() override {
     const auto sent = DecoratedRestfulClient<T>::send_100_continue();
+    lsubdout(cct, rgw, 30) << "AccountingFilter::send_100_continue: e="
+        << (enabled ? "1" : "0") << ", sent=" << sent << ", total="
+        << total_sent << dendl;
     if (enabled) {
       total_sent += sent;
     }
@@ -51,6 +58,9 @@ public:
   size_t send_header(const boost::string_ref& name,
                      const boost::string_ref& value) override {
     const auto sent = DecoratedRestfulClient<T>::send_header(name, value);
+    lsubdout(cct, rgw, 30) << "AccountingFilter::send_header: e="
+        << (enabled ? "1" : "0") << ", sent=" << sent << ", total="
+        << total_sent << dendl;
     if (enabled) {
       total_sent += sent;
     }
@@ -59,6 +69,9 @@ public:
 
   size_t send_content_length(const uint64_t len) override {
     const auto sent = DecoratedRestfulClient<T>::send_content_length(len);
+    lsubdout(cct, rgw, 30) << "AccountingFilter::send_content_length: e="
+        << (enabled ? "1" : "0") << ", sent=" << sent << ", total="
+        << total_sent << dendl;
     if (enabled) {
       total_sent += sent;
     }
@@ -67,6 +80,9 @@ public:
 
   size_t send_chunked_transfer_encoding() override {
     const auto sent = DecoratedRestfulClient<T>::send_chunked_transfer_encoding();
+    lsubdout(cct, rgw, 30) << "AccountingFilter::send_chunked_transfer_encoding: e="
+        << (enabled ? "1" : "0") << ", sent=" << sent << ", total="
+        << total_sent << dendl;
     if (enabled) {
       total_sent += sent;
     }
@@ -75,6 +91,9 @@ public:
 
   size_t complete_header() override {
     const auto sent = DecoratedRestfulClient<T>::complete_header();
+    lsubdout(cct, rgw, 30) << "AccountingFilter::complete_header: e="
+        << (enabled ? "1" : "0") << ", sent=" << sent << ", total="
+        << total_sent << dendl;
     if (enabled) {
       total_sent += sent;
     }
@@ -83,6 +102,8 @@ public:
 
   size_t recv_body(char* buf, size_t max) override {
     const auto received = DecoratedRestfulClient<T>::recv_body(buf, max);
+    lsubdout(cct, rgw, 30) << "AccountingFilter::recv_body: e="
+        << (enabled ? "1" : "0") << ", received=" << received << dendl;
     if (enabled) {
       total_received += received;
     }
@@ -92,6 +113,20 @@ public:
   size_t send_body(const char* const buf,
                    const size_t len) override {
     const auto sent = DecoratedRestfulClient<T>::send_body(buf, len);
+    lsubdout(cct, rgw, 30) << "AccountingFilter::send_body: e="
+        << (enabled ? "1" : "0") << ", sent=" << sent << ", total="
+        << total_sent << dendl;
+    if (enabled) {
+      total_sent += sent;
+    }
+    return sent;
+  }
+
+  size_t complete_request() override {
+    const auto sent = DecoratedRestfulClient<T>::complete_request();
+    lsubdout(cct, rgw, 30) << "AccountingFilter::complete_request: e="
+        << (enabled ? "1" : "0") << ", sent=" << sent << ", total="
+        << total_sent << dendl;
     if (enabled) {
       total_sent += sent;
     }
@@ -108,6 +143,8 @@ public:
 
   void set_account(bool enabled) override {
     this->enabled = enabled;
+    lsubdout(cct, rgw, 30) << "AccountingFilter::set_account: e="
+        << (enabled ? "1" : "0") << dendl;
   }
 };
 
@@ -122,13 +159,14 @@ protected:
 
   bool has_content_length;
   bool buffer_data;
+  CephContext *cct;
 
 public:
   template <typename U>
-  BufferingFilter(U&& decoratee)
+  BufferingFilter(CephContext *cct, U&& decoratee)
     : DecoratedRestfulClient<T>(std::forward<U>(decoratee)),
       has_content_length(false),
-      buffer_data(false) {
+      buffer_data(false), cct(cct) {
   }
 
   size_t send_content_length(const uint64_t len) override;
@@ -144,6 +182,9 @@ size_t BufferingFilter<T>::send_body(const char* const buf,
 {
   if (buffer_data) {
     data.append(buf, len);
+
+    lsubdout(cct, rgw, 30) << "BufferingFilter<T>::send_body: defer count = "
+        << len << dendl;
     return 0;
   }
 
@@ -170,6 +211,8 @@ size_t BufferingFilter<T>::complete_header()
   if (! has_content_length) {
     /* We will dump everything in complete_request(). */
     buffer_data = true;
+    lsubdout(cct, rgw, 30) << "BufferingFilter<T>::complete_header: has_content_length="
+        << (has_content_length ? "1" : "0") << dendl;
     return 0;
   }
 
@@ -182,8 +225,16 @@ size_t BufferingFilter<T>::complete_request()
   size_t sent = 0;
 
   if (! has_content_length) {
+    /* It is not correct to count these bytes here,
+     * because they can only be part of the header.
+     * Therefore force count to 0.
+     */
     sent += DecoratedRestfulClient<T>::send_content_length(data.length());
     sent += DecoratedRestfulClient<T>::complete_header();
+    lsubdout(cct, rgw, 30) <<
+        "BufferingFilter::complete_request: !has_content_length: IGNORE: sent="
+        << sent << dendl;
+    sent = 0;
   }
 
   if (buffer_data) {
@@ -195,14 +246,18 @@ size_t BufferingFilter<T>::complete_request()
     }
     data.clear();
     buffer_data = false;
+    lsubdout(cct, rgw, 30) << "BufferingFilter::complete_request: buffer_data: sent="
+        << sent << dendl;
   }
 
   return sent + DecoratedRestfulClient<T>::complete_request();
 }
 
 template <typename T> static inline
-BufferingFilter<T> add_buffering(T&& t) {
-  return BufferingFilter<T>(std::forward<T>(t));
+BufferingFilter<T> add_buffering(
+CephContext *cct,
+T&& t) {
+  return BufferingFilter<T>(cct, std::forward<T>(t));
 }
 
 

diff --git a/src/rgw/rgw_fcgi_process.cc b/src/rgw/rgw_fcgi_process.cc
index 332cde29719f3517268e0b887611ecd7f5c98d98..3d6eac2b5dde3f3851193bb21714740ab68ceeda 100644 (file)
--- a/src/rgw/rgw_fcgi_process.cc
+++ b/src/rgw/rgw_fcgi_process.cc
@@ -118,10 +118,10 @@ void RGWFCGXProcess::handle_request(RGWRequest* r)
 
   RGWFCGX fcgxfe(req->fcgx);
   auto real_client_io = rgw::io::add_reordering(
-                          rgw::io::add_buffering(
+                          rgw::io::add_buffering(cct,
                             rgw::io::add_chunking(
                               &fcgxfe)));
-  RGWRestfulIO client_io(&real_client_io);
+  RGWRestfulIO client_io(cct, &real_client_io);
 
  
   int ret = process_request(store, rest, req, uri_prefix,

diff --git a/src/rgw/rgw_loadgen_process.cc b/src/rgw/rgw_loadgen_process.cc
index fef37f805bac9cca414756d006c6344f38089944..13a344e3b46946dc2ae0b39cf86abbfa215b2e00 100644 (file)
--- a/src/rgw/rgw_loadgen_process.cc
+++ b/src/rgw/rgw_loadgen_process.cc
@@ -131,7 +131,7 @@ void RGWLoadGenProcess::handle_request(RGWRequest* r)
   env.sign(access_key);
 
   RGWLoadGenIO real_client_io(&env);
-  RGWRestfulIO client_io(&real_client_io);
+  RGWRestfulIO client_io(cct, &real_client_io);
 
   int ret = process_request(store, rest, req, uri_prefix,
                             *auth_registry, &client_io, olog);

diff --git a/src/rgw/rgw_log.cc b/src/rgw/rgw_log.cc
index 7bceab0aa689636031a1eef3f075fad869116a91..588aa0a26fde84b8b626c0864ed5977f06fb7129 100644 (file)
--- a/src/rgw/rgw_log.cc
+++ b/src/rgw/rgw_log.cc
@@ -221,6 +221,11 @@ static void log_usage(struct req_state *s, const string& op_name)
   if (!s->is_err())
     data.successful_ops = 1;
 
+  ldout(s->cct, 30) << "log_usage: bucket_name=" << bucket_name
+       << " tenant=" << s->bucket_tenant
+       << ", bytes_sent=" << bytes_sent << ", bytes_received="
+       << bytes_received << ", success=" << data.successful_ops << dendl;
+
   entry.add(op_name, data);
 
   utime_t ts = ceph_clock_now();