rgw: simple request logging

Signed-off-by: Yehuda Sadeh <yehuda@hq.newdream.net>

diff --git a/src/rgw/rgw_common.cc b/src/rgw/rgw_common.cc
index a0554f65821535eb3f080219cf5b00d8bff3e91a..966a08a65ba60dc12279311e0f24e11f44c86216 100644 (file)
--- a/src/rgw/rgw_common.cc
+++ b/src/rgw/rgw_common.cc
@@ -102,6 +102,7 @@ req_state::req_state(struct RGWEnv *e) : acl(NULL), os_auth_token(NULL), os_user
   object = NULL;
   bucket_name = NULL;
   has_bad_meta = false;
+  method = NULL;
 }
 
 req_state::~req_state() {

diff --git a/src/rgw/rgw_common.h b/src/rgw/rgw_common.h
index df5556d3b5982c866b2844ffb27a41905c2844a5..bacb5022fb6cef8b2aa58479982d2d316e552f72 100644 (file)
--- a/src/rgw/rgw_common.h
+++ b/src/rgw/rgw_common.h
@@ -569,6 +569,8 @@ struct req_state {
 
    void *obj_ctx;
 
+   string dialect;
+
    req_state(struct RGWEnv *e);
    ~req_state();
 };

diff --git a/src/rgw/rgw_main.cc b/src/rgw/rgw_main.cc
index 5e9ba6a1a471ca58eed9074661d1da28fcd3c2b2..e003af347d2ac7260d31748fd3b7370095f96a8b 100644 (file)
--- a/src/rgw/rgw_main.cc
+++ b/src/rgw/rgw_main.cc
@@ -64,66 +64,97 @@ static void godown_alarm(int signum)
   _exit(0);
 }
 
+struct RGWRequest
+{
+  FCGX_Request fcgx;
+  uint64_t id;
+  struct req_state *s;
+  string req_str;
+
+  RGWRequest() : id(0), s(NULL) {}
+
+  ~RGWRequest() {
+    delete s;
+  }
+ 
+  req_state *init_state(RGWEnv *env) { 
+    s = new req_state(env);
+    return s;
+  }
+
+  void log(struct req_state *s, const char *msg) {
+    if (s->method && req_str.size() == 0) {
+      req_str = s->method;
+      req_str.append(" ");
+      req_str.append(s->request_uri);
+    }
+    dout(1) << "req" << id << ":" << s->dialect << ":" << req_str << ":" << msg << dendl;
+  }
+};
+
 class RGWProcess {
-  deque<FCGX_Request *> m_fcgx_queue;
+  deque<RGWRequest *> m_req_queue;
   ThreadPool m_tp;
 
-  struct RGWWQ : public ThreadPool::WorkQueue<FCGX_Request> {
+  struct RGWWQ : public ThreadPool::WorkQueue<RGWRequest> {
     RGWProcess *process;
     RGWWQ(RGWProcess *p, time_t timeout, time_t suicide_timeout, ThreadPool *tp)
-      : ThreadPool::WorkQueue<FCGX_Request>("RGWWQ", timeout, suicide_timeout, tp), process(p) {}
+      : ThreadPool::WorkQueue<RGWRequest>("RGWWQ", timeout, suicide_timeout, tp), process(p) {}
 
-    bool _enqueue(FCGX_Request *req) {
-      process->m_fcgx_queue.push_back(req);
+    bool _enqueue(RGWRequest *req) {
+      process->m_req_queue.push_back(req);
       perfcounter->inc(l_rgw_qlen);
-      dout(20) << "enqueued request fcgx=" << hex << req << dec << dendl;
+      dout(20) << "enqueued request req=" << hex << req << dec << dendl;
       _dump_queue();
       return true;
     }
-    void _dequeue(FCGX_Request *req) {
+    void _dequeue(RGWRequest *req) {
       assert(0);
     }
     bool _empty() {
-      return process->m_fcgx_queue.empty();
+      return process->m_req_queue.empty();
     }
-    FCGX_Request *_dequeue() {
-      if (process->m_fcgx_queue.empty())
+    RGWRequest *_dequeue() {
+      if (process->m_req_queue.empty())
        return NULL;
-      FCGX_Request *req = process->m_fcgx_queue.front();
-      process->m_fcgx_queue.pop_front();
-      dout(20) << "dequeued request fcgx=" << hex << req << dec << dendl;
+      RGWRequest *req = process->m_req_queue.front();
+      process->m_req_queue.pop_front();
+      dout(20) << "dequeued request req=" << hex << req << dec << dendl;
       _dump_queue();
       perfcounter->inc(l_rgw_qlen, -1);
       return req;
     }
-    void _process(FCGX_Request *fcgx) {
+    void _process(RGWRequest *req) {
       perfcounter->inc(l_rgw_qactive);
-      process->handle_request(fcgx);
+      process->handle_request(req);
       perfcounter->inc(l_rgw_qactive, -1);
     }
     void _dump_queue() {
-      deque<FCGX_Request *>::iterator iter;
-      if (process->m_fcgx_queue.size() == 0) {
+      deque<RGWRequest *>::iterator iter;
+      if (process->m_req_queue.size() == 0) {
         dout(20) << "RGWWQ: empty" << dendl;
         return;
       }
       dout(20) << "RGWWQ:" << dendl;
-      for (iter = process->m_fcgx_queue.begin(); iter != process->m_fcgx_queue.end(); ++iter) {
-        dout(20) << "fcgx: " << hex << *iter << dec << dendl;
+      for (iter = process->m_req_queue.begin(); iter != process->m_req_queue.end(); ++iter) {
+        dout(20) << "req: " << hex << *iter << dec << dendl;
       }
     }
     void _clear() {
-      assert(process->m_fcgx_queue.empty());
+      assert(process->m_req_queue.empty());
     }
   } req_wq;
 
+  uint64_t max_req_id;
+
 public:
   RGWProcess(CephContext *cct, int num_threads)
     : m_tp(cct, "RGWProcess::m_tp", num_threads),
       req_wq(this, g_conf->rgw_op_thread_timeout,
-            g_conf->rgw_op_thread_suicide_timeout, &m_tp) {}
+            g_conf->rgw_op_thread_suicide_timeout, &m_tp),
+      max_req_id(0) {}
   void run();
-  void handle_request(FCGX_Request *fcgx);
+  void handle_request(RGWRequest *req);
 };
 
 void RGWProcess::run()
@@ -145,14 +176,15 @@ void RGWProcess::run()
   m_tp.start();
 
   for (;;) {
-    FCGX_Request *fcgx = new FCGX_Request;
-    dout(10) << "allocated request fcgx=" << hex << fcgx << dec << dendl;
-    FCGX_InitRequest(fcgx, s, 0);
-    int ret = FCGX_Accept_r(fcgx);
+    RGWRequest *req = new RGWRequest;
+    req->id = ++max_req_id;
+    dout(10) << "allocated request req=" << hex << req << dec << dendl;
+    FCGX_InitRequest(&req->fcgx, s, 0);
+    int ret = FCGX_Accept_r(&req->fcgx);
     if (ret < 0)
       break;
 
-    req_wq.queue(fcgx);
+    req_wq.queue(req);
   }
 
   m_tp.stop();
@@ -164,59 +196,67 @@ static int call_log_intent(void *ctx, rgw_obj& obj, RGWIntentEvent intent)
   return rgw_log_intent(s, obj, intent);
 }
 
-void RGWProcess::handle_request(FCGX_Request *fcgx)
+void RGWProcess::handle_request(RGWRequest *req)
 {
+  FCGX_Request *fcgx = &req->fcgx;
   RGWRESTMgr rest;
   int ret;
   RGWEnv rgw_env;
 
-  dout(0) << "====== starting new request fcgx=" << hex << fcgx << dec << " =====" << dendl;
+  dout(0) << "====== starting new request req=" << hex << req << dec << " =====" << dendl;
   perfcounter->inc(l_rgw_req);
 
   rgw_env.init(fcgx->envp);
 
-  struct req_state *s = new req_state(&rgw_env);
+  struct req_state *s = req->init_state(&rgw_env);
   s->obj_ctx = rgwstore->create_context(s);
   rgwstore->set_intent_cb(s->obj_ctx, call_log_intent);
 
+  req->log(s, "initializing");
+
   RGWOp *op = NULL;
   int init_error = 0;
   RGWHandler *handler = rest.get_handler(s, fcgx, &init_error);
-
   if (init_error != 0) {
     abort_early(s, init_error);
     goto done;
   }
 
+  req->log(s, "getting op");
   op = handler->get_op();
   if (!op) {
     abort_early(s, -ERR_METHOD_NOT_ALLOWED);
     goto done;
   }
 
+  req->log(s, "authorizing");
   ret = handler->authorize();
   if (ret < 0) {
     dout(10) << "failed to authorize request" << dendl;
     abort_early(s, ret);
     goto done;
   }
+
   if (s->user.suspended) {
     dout(10) << "user is suspended, uid=" << s->user.user_id << dendl;
     abort_early(s, -ERR_USER_SUSPENDED);
     goto done;
   }
+  req->log(s, "reading permissions");
   ret = handler->read_permissions(op);
   if (ret < 0) {
     abort_early(s, ret);
     goto done;
   }
 
+  req->log(s, "verifying op permissions");
   ret = op->verify_permission();
   if (ret < 0) {
     abort_early(s, ret);
     goto done;
   }
 
+  req->log(s, "verifying op params");
   ret = op->verify_params();
   if (ret < 0) {
     abort_early(s, ret);
@@ -226,6 +266,7 @@ void RGWProcess::handle_request(FCGX_Request *fcgx)
   if (s->expect_cont)
     dump_continue(s);
 
+  req->log(s, "executing");
   op->execute();
 done:
   rgw_log_op(s);
@@ -234,11 +275,10 @@ done:
 
   handler->put_op(op);
   rgwstore->destroy_context(s->obj_ctx);
-  delete s;
   FCGX_Finish_r(fcgx);
-  delete fcgx;
+  delete req;
 
-  dout(0) << "====== req done fcgx=" << hex << fcgx << dec << " http_status=" << http_ret << " ======" << dendl;
+  dout(0) << "====== req done req=" << hex << req << dec << " http_status=" << http_ret << " ======" << dendl;
 }
 
 class C_InitTimeout : public Context {

diff --git a/src/rgw/rgw_op.h b/src/rgw/rgw_op.h
index 8caba9b1ea9c3f51b94cc78476e2d597653896ec..c536f89425de372a5e4b1c667e99c0f877031dc3 100644 (file)
--- a/src/rgw/rgw_op.h
+++ b/src/rgw/rgw_op.h
@@ -37,6 +37,7 @@ public:
   virtual bool prefetch_data() { return false; }
   virtual int verify_permission() = 0;
   virtual void execute() = 0;
+  virtual const char *name() = 0;
 };
 
 class RGWGetObj : public RGWOp {
@@ -101,6 +102,8 @@ public:
 
   virtual int get_params() = 0;
   virtual int send_response(void *handle) = 0;
+
+  virtual const char *name() { return "get_obj"; }
 };
 
 class RGWListBuckets : public RGWOp {
@@ -120,6 +123,8 @@ public:
 
   virtual int get_params()= 0;
   virtual void send_response() = 0;
+
+  virtual const char *name() { return "list_buckets"; }
 };
 
 class RGWStatAccount : public RGWOp {
@@ -145,6 +150,7 @@ public:
   void execute();
 
   virtual void send_response() = 0;
+  virtual const char *name() { return "stat_account"; }
 };
 
 class RGWListBucket : public RGWOp {
@@ -183,6 +189,7 @@ public:
 
   virtual int get_params() = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "list_bucket"; }
 };
 
 class RGWStatBucket : public RGWOp {
@@ -203,6 +210,7 @@ public:
   void execute();
 
   virtual void send_response() = 0;
+  virtual const char *name() { return "stat_bucket"; }
 };
 
 class RGWCreateBucket : public RGWOp {
@@ -219,6 +227,7 @@ public:
     ret = 0;
   }
   virtual void send_response() = 0;
+  virtual const char *name() { return "create_bucket"; }
 };
 
 class RGWDeleteBucket : public RGWOp {
@@ -236,6 +245,7 @@ public:
   void execute();
 
   virtual void send_response() = 0;
+  virtual const char *name() { return "delete_bucket"; }
 };
 
 class RGWPutObjProcessor
@@ -287,6 +297,7 @@ public:
   virtual int get_params() = 0;
   virtual int get_data(bufferlist& bl) = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "put_obj"; }
 };
 
 class RGWPutObjMetadata : public RGWOp {
@@ -305,6 +316,7 @@ public:
 
   virtual int get_params() = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "put_obj_metadata"; }
 };
 
 class RGWDeleteObj : public RGWOp {
@@ -322,6 +334,7 @@ public:
   void execute();
 
   virtual void send_response() = 0;
+  virtual const char *name() { return "delete_obj"; }
 };
 
 class RGWCopyObj : public RGWOp {
@@ -379,6 +392,7 @@ public:
 
   virtual int get_params() = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "copy_obj"; }
 };
 
 class RGWGetACLs : public RGWOp {
@@ -398,6 +412,7 @@ public:
   void execute();
 
   virtual void send_response() = 0;
+  virtual const char *name() { return "get_acls"; }
 };
 
 class RGWPutACLs : public RGWOp {
@@ -420,6 +435,7 @@ public:
 
   virtual int get_params() = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "put_acls"; }
 };
 
 class RGWInitMultipart : public RGWOp {
@@ -440,6 +456,7 @@ public:
 
   virtual int get_params() = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "init_multipart"; }
 };
 
 class RGWCompleteMultipart : public RGWOp {
@@ -466,6 +483,7 @@ public:
 
   virtual int get_params() = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "complete_multipart"; }
 };
 
 class RGWAbortMultipart : public RGWOp {
@@ -483,6 +501,7 @@ public:
   void execute();
 
   virtual void send_response() = 0;
+  virtual const char *name() { return "abort_multipart"; }
 };
 
 class RGWListMultipart : public RGWOp {
@@ -511,6 +530,7 @@ public:
 
   virtual int get_params() = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "list_multipart"; }
 };
 
 #define MP_META_SUFFIX ".meta"
@@ -623,6 +643,7 @@ public:
 
   virtual int get_params() = 0;
   virtual void send_response() = 0;
+  virtual const char *name() { return "list_bucket_multiparts"; }
 };
 
 class RGWHandler {

diff --git a/src/rgw/rgw_rest_s3.cc b/src/rgw/rgw_rest_s3.cc
index 309e2a8ddf29e836f457c3e5f006d67f21954427..b111908db54eadce3d0027b1d123e109d1abadf4 100644 (file)
--- a/src/rgw/rgw_rest_s3.cc
+++ b/src/rgw/rgw_rest_s3.cc
@@ -536,6 +536,8 @@ int RGWHandler_REST_S3::init(struct req_state *state, FCGX_Request *fcgx)
 
   state->copy_source = state->env->get("HTTP_X_AMZ_COPY_SOURCE");
 
+  state->dialect = "s3";
+
   return RGWHandler_REST::init(state, fcgx);
 }
 

diff --git a/src/rgw/rgw_rest_swift.cc b/src/rgw/rgw_rest_swift.cc
index 3856fdfaba3f728a2be314517350e89ca97f5a72..099a7ec4e2b7f9459a0c33bdb43c1a0a1ad74f6f 100644 (file)
--- a/src/rgw/rgw_rest_swift.cc
+++ b/src/rgw/rgw_rest_swift.cc
@@ -518,5 +518,7 @@ int RGWHandler_REST_SWIFT::init(struct req_state *state, FCGX_Request *fcgx)
 {
   state->copy_source = state->env->get("HTTP_X_COPY_FROM");
 
+  state->dialect = "swift";
+
   return RGWHandler_REST::init(state, fcgx);
 }

diff --git a/src/rgw/rgw_swift_auth.cc b/src/rgw/rgw_swift_auth.cc
index 9b4c2099ea7e9a56b65cea6ab1d4c09b9fc1b035..8a05c7f8673ba2876dee91acb97b29d88f0e5c8d 100644 (file)
--- a/src/rgw/rgw_swift_auth.cc
+++ b/src/rgw/rgw_swift_auth.cc
@@ -216,6 +216,13 @@ done:
   end_header(s);
 }
 
+int RGWHandler_SWIFT_Auth::init(struct req_state *state, FCGX_Request *fcgx)
+{
+  state->dialect = "swift-auth";
+
+  return RGWHandler::init(state, fcgx);
+}
+
 int RGWHandler_SWIFT_Auth::authorize()
 {
   return 0;

diff --git a/src/rgw/rgw_swift_auth.h b/src/rgw/rgw_swift_auth.h
index 677a0f4152e0bc43e58b8d336589aaf3c19d45ea..efed101cdd3709066e21faefeaa60c53e7517968 100644 (file)
--- a/src/rgw/rgw_swift_auth.h
+++ b/src/rgw/rgw_swift_auth.h
@@ -14,6 +14,7 @@ public:
 
   int verify_permission() { return 0; }
   void execute();
+  virtual const char *name() { return "swift_auth_get"; }
 };
 
 class RGWHandler_SWIFT_Auth : public RGWHandler {
@@ -23,6 +24,7 @@ public:
   RGWOp *get_op();
   void put_op(RGWOp *op);
 
+  int init(struct req_state *state, FCGX_Request *fcgx);
   int authorize();
   int read_permissions(RGWOp *op) { return 0; }
 };