From d46603c97e6f5116193cb4f7207dc44c09abd2a0 Mon Sep 17 00:00:00 2001
From: Alexander Scheel <ascheel@redhat.com>
Date: Aug 22 2017 19:17:15 +0000
Subject: [server] Add detailed request logging


Add request logging to track requests through gssproxy.  Requests are
logged as they are read, processed, handled, and replies sent.  These
are identified by buffer memory address and size.

Signed-off-by: Alexander Scheel <ascheel@redhat.com>
Reviewed-by: Simo Sorce <simo@redhat.com>
[rharwood@redhat.com: commit message cleanups, rebase]
Reviewed-by: Robbie Harwood <rharwood@redhat.com>
Merges: #205

---

diff --git a/src/gp_rpc_process.c b/src/gp_rpc_process.c
index 0ea17f0..eaffc55 100644
--- a/src/gp_rpc_process.c
+++ b/src/gp_rpc_process.c
@@ -372,9 +372,12 @@ int gp_rpc_process_call(struct gp_call_ctx *gpcall,
     xdrmem_create(&xdr_reply_ctx, reply_buffer, MAX_RPC_SIZE, XDR_ENCODE);
 
     /* decode request */
+    GPDEBUGN(3, "[status] Processing request [%p (%zu)]\n", inbuf, inlen);
     ret = gp_rpc_decode_call(&xdr_call_ctx, &xid, &proc, &arg, &acc, &rej);
     if (!ret) {
         /* execute request */
+        GPDEBUGN(3, "[status] Executing request %d (%s) from [%p (%zu)]\n",
+                 proc, gp_rpc_procname(proc), inbuf, inlen);
         ret = gp_rpc_execute(gpcall, proc, &arg, &res);
         if (ret) {
             acc = GP_RPC_SYSTEM_ERR;
@@ -388,6 +391,9 @@ int gp_rpc_process_call(struct gp_call_ctx *gpcall,
         /* return encoded buffer */
         ret = gp_rpc_return_buffer(&xdr_reply_ctx,
                                    reply_buffer, outbuf, outlen);
+        GPDEBUGN(3, "[status] Returned buffer %d (%s) from [%p (%zu)]: "
+                 "[%p (%zu)]\n", proc, gp_rpc_procname(proc), inbuf, inlen,
+                 *outbuf, *outlen);
     }
     /* free resources */
     gp_rpc_free_xdrs(proc, &arg, &res);
diff --git a/src/gp_socket.c b/src/gp_socket.c
index 2198514..7a19ee5 100644
--- a/src/gp_socket.c
+++ b/src/gp_socket.c
@@ -487,6 +487,8 @@ void gp_socket_send_data(verto_ctx *vctx, struct gp_conn *conn,
 
     wbuf = calloc(1, sizeof(struct gp_buffer));
     if (!wbuf) {
+        GPDEBUGN(3, "[status] OOM in gp_socket_send_data: %p (%zu)\n",
+                 buffer, buflen);
         /* too bad, must kill the client connection now */
         gp_conn_free(conn);
         return;
@@ -513,6 +515,8 @@ static void gp_socket_write(verto_ctx *vctx, verto_ev *ev)
 
     vecs = 0;
 
+    GPDEBUGN(3, "[status] Sending data: %p (%zu)\n", wbuf->data, wbuf->size);
+
     if (wbuf->pos == 0) {
         /* first write, send the buffer size as packet header */
         size = wbuf->size | FRAGMENT_BIT;
@@ -535,6 +539,9 @@ static void gp_socket_write(verto_ctx *vctx, verto_ev *ev)
             gp_socket_schedule_write(vctx, wbuf);
         } else {
             /* error on socket, close and release it */
+            GPDEBUGN(3, "[status] Error %d in gp_socket_write on writing for "
+                     "[%p (%zu:%zu)]\n", errno, wbuf->data, wbuf->pos,
+                     wbuf->size);
             gp_conn_free(wbuf->conn);
             gp_buffer_free(wbuf);
         }
@@ -544,6 +551,8 @@ static void gp_socket_write(verto_ctx *vctx, verto_ev *ev)
         if (wn < (ssize_t) sizeof(size)) {
             /* don't bother trying to handle sockets that can't
              * buffer even 4 bytes */
+            GPDEBUGN(3, "[status] Sending data [%p (%zu)]: failed with short "
+                     "write of %d\n", wbuf->data, wbuf->size, wn);
             gp_conn_free(wbuf->conn);
             gp_buffer_free(wbuf);
             return;
@@ -551,6 +560,9 @@ static void gp_socket_write(verto_ctx *vctx, verto_ev *ev)
         wn -= sizeof(size);
     }
 
+    GPDEBUGN(3, "[status] Sending data [%p (%zu)]: successful write of %d\n",
+             wbuf->data, wbuf->size, wn);
+
     wbuf->pos += wn;
     if (wbuf->size > wbuf->pos) {
         /* short write, reschedule */
diff --git a/src/gp_workers.c b/src/gp_workers.c
index d37e57c..2a33c21 100644
--- a/src/gp_workers.c
+++ b/src/gp_workers.c
@@ -319,6 +319,7 @@ static void gp_handle_reply(verto_ctx *vctx, verto_ev *ev)
             break;
 
         case GP_QUERY_OUT:
+            GPDEBUGN(3, "[status] Handling query reply: %p (%zu)\n", q->buffer, q->buflen);
             gp_socket_send_data(vctx, q->conn, q->buffer, q->buflen);
             gp_query_free(q, false);
             break;
@@ -381,7 +382,11 @@ static void *gp_worker_main(void *pvt)
         gp_debug_set_conn_id(gp_conn_get_cid(q->conn));
 
         /* handle the client request */
+        GPDEBUGN(3, "[status] Handling query input: %p (%zu)\n", q->buffer,
+                 q->buflen);
         gp_handle_query(t->pool, q);
+        GPDEBUGN(3 ,"[status] Handling query output: %p (%zu)\n", q->buffer,
+                 q->buflen);
 
         /* now get lock on main queue, to play with the reply list */
         /* ======> POOL LOCK */