meta-starlingx/meta-stx-distro/recipes-security/gssproxy/files/server-Add-detailed-request-logging.patch

   1 From f413cc257c6c1e60090c72163152ae7fd2180c41 Mon Sep 17 00:00:00 2001
   2 From: Alexander Scheel <ascheel@redhat.com>
   3 Date: Fri, 4 Aug 2017 16:09:20 -0400
   4 Subject: [PATCH] [server] Add detailed request logging
   5
   6 Add request logging to track requests through gssproxy.  Requests are
   7 logged as they are read, processed, handled, and replies sent.  These
   8 are identified by buffer memory address and size.
   9
  10 Signed-off-by: Alexander Scheel <ascheel@redhat.com>
  11 Reviewed-by: Simo Sorce <simo@redhat.com>
  12 [rharwood@redhat.com: commit message cleanups, rebase]
  13 Reviewed-by: Robbie Harwood <rharwood@redhat.com>
  14 Merges: #205
  15 (cherry picked from commit 4097dafad3f276c3cf7b1255fe0540e16d59ae03)
  16 ---
  17  proxy/src/gp_rpc_process.c |  6 ++++++
  18  proxy/src/gp_socket.c      | 12 ++++++++++++
  19  proxy/src/gp_workers.c     |  5 +++++
  20  3 files changed, 23 insertions(+)
  21
  22 diff --git a/proxy/src/gp_rpc_process.c b/proxy/src/gp_rpc_process.c
  23 index 0ea17f0..eaffc55 100644
  24 --- a/proxy/src/gp_rpc_process.c
  25 +++ b/proxy/src/gp_rpc_process.c
  26 @@ -372,9 +372,12 @@ int gp_rpc_process_call(struct gp_call_ctx *gpcall,
  27      xdrmem_create(&xdr_reply_ctx, reply_buffer, MAX_RPC_SIZE, XDR_ENCODE);
  28
  29      /* decode request */
  30 +    GPDEBUGN(3, "[status] Processing request [%p (%zu)]\n", inbuf, inlen);
  31      ret = gp_rpc_decode_call(&xdr_call_ctx, &xid, &proc, &arg, &acc, &rej);
  32      if (!ret) {
  33          /* execute request */
  34 +        GPDEBUGN(3, "[status] Executing request %d (%s) from [%p (%zu)]\n",
  35 +                 proc, gp_rpc_procname(proc), inbuf, inlen);
  36          ret = gp_rpc_execute(gpcall, proc, &arg, &res);
  37          if (ret) {
  38              acc = GP_RPC_SYSTEM_ERR;
  39 @@ -388,6 +391,9 @@ int gp_rpc_process_call(struct gp_call_ctx *gpcall,
  40          /* return encoded buffer */
  41          ret = gp_rpc_return_buffer(&xdr_reply_ctx,
  42                                     reply_buffer, outbuf, outlen);
  43 +        GPDEBUGN(3, "[status] Returned buffer %d (%s) from [%p (%zu)]: "
  44 +                 "[%p (%zu)]\n", proc, gp_rpc_procname(proc), inbuf, inlen,
  45 +                 *outbuf, *outlen);
  46      }
  47      /* free resources */
  48      gp_rpc_free_xdrs(proc, &arg, &res);
  49 diff --git a/proxy/src/gp_socket.c b/proxy/src/gp_socket.c
  50 index 5064e51..8675a0e 100644
  51 --- a/proxy/src/gp_socket.c
  52 +++ b/proxy/src/gp_socket.c
  53 @@ -441,6 +441,8 @@ void gp_socket_send_data(verto_ctx *vctx, struct gp_conn *conn,
  54
  55      wbuf = calloc(1, sizeof(struct gp_buffer));
  56      if (!wbuf) {
  57 +        GPDEBUGN(3, "[status] OOM in gp_socket_send_data: %p (%zu)\n",
  58 +                 buffer, buflen);
  59          /* too bad, must kill the client connection now */
  60          gp_conn_free(conn);
  61          return;
  62 @@ -467,6 +469,8 @@ static void gp_socket_write(verto_ctx *vctx, verto_ev *ev)
  63
  64      vecs = 0;
  65
  66 +    GPDEBUGN(3, "[status] Sending data: %p (%zu)\n", wbuf->data, wbuf->size);
  67 +
  68      if (wbuf->pos == 0) {
  69          /* first write, send the buffer size as packet header */
  70          size = wbuf->size | FRAGMENT_BIT;
  71 @@ -489,6 +493,9 @@ static void gp_socket_write(verto_ctx *vctx, verto_ev *ev)
  72              gp_socket_schedule_write(vctx, wbuf);
  73          } else {
  74              /* error on socket, close and release it */
  75 +            GPDEBUGN(3, "[status] Error %d in gp_socket_write on writing for "
  76 +                     "[%p (%zu:%zu)]\n", errno, wbuf->data, wbuf->pos,
  77 +                     wbuf->size);
  78              gp_conn_free(wbuf->conn);
  79              gp_buffer_free(wbuf);
  80          }
  81 @@ -498,6 +505,8 @@ static void gp_socket_write(verto_ctx *vctx, verto_ev *ev)
  82          if (wn < (ssize_t) sizeof(size)) {
  83              /* don't bother trying to handle sockets that can't
  84               * buffer even 4 bytes */
  85 +            GPDEBUGN(3, "[status] Sending data [%p (%zu)]: failed with short "
  86 +                     "write of %d\n", wbuf->data, wbuf->size, wn);
  87              gp_conn_free(wbuf->conn);
  88              gp_buffer_free(wbuf);
  89              return;
  90 @@ -505,6 +514,9 @@ static void gp_socket_write(verto_ctx *vctx, verto_ev *ev)
  91          wn -= sizeof(size);
  92      }
  93
  94 +    GPDEBUGN(3, "[status] Sending data [%p (%zu)]: successful write of %d\n",
  95 +             wbuf->data, wbuf->size, wn);
  96 +
  97      wbuf->pos += wn;
  98      if (wbuf->size > wbuf->pos) {
  99          /* short write, reschedule */
 100 diff --git a/proxy/src/gp_workers.c b/proxy/src/gp_workers.c
 101 index d37e57c..2a33c21 100644
 102 --- a/proxy/src/gp_workers.c
 103 +++ b/proxy/src/gp_workers.c
 104 @@ -319,6 +319,7 @@ static void gp_handle_reply(verto_ctx *vctx, verto_ev *ev)
 105              break;
 106
 107          case GP_QUERY_OUT:
 108 +            GPDEBUGN(3, "[status] Handling query reply: %p (%zu)\n", q->buffer, q->buflen);
 109              gp_socket_send_data(vctx, q->conn, q->buffer, q->buflen);
 110              gp_query_free(q, false);
 111              break;
 112 @@ -381,7 +382,11 @@ static void *gp_worker_main(void *pvt)
 113          gp_debug_set_conn_id(gp_conn_get_cid(q->conn));
 114
 115          /* handle the client request */
 116 +        GPDEBUGN(3, "[status] Handling query input: %p (%zu)\n", q->buffer,
 117 +                 q->buflen);
 118          gp_handle_query(t->pool, q);
 119 +        GPDEBUGN(3 ,"[status] Handling query output: %p (%zu)\n", q->buffer,
 120 +                 q->buflen);
 121
 122          /* now get lock on main queue, to play with the reply list */
 123          /* ======> POOL LOCK */