Change in vdsm[ovirt-4.0]: rpc: Log RPC call summary on info level

Thursday, 30 June 2016

Hello Piotr Kliczewski, Nir Soffer,

I'd like you to do a code review.  Please visit

    https://gerrit.ovirt.org/59998

to review the following change.

Change subject: rpc: Log RPC call summary on info level
......................................................................

rpc: Log RPC call summary on info level

We currently log relatively detailed information about all RPC calls.

This information is logged on the debug level.  We are going to switch
to the info logging level sometimes in future and then information about
RPC calls won't be logged anymore.  But we still want to see some very
basic information about the RPC calls, such as that they were performed
and how much time they took.

This patch adds the corresponding logging.  We additionally add the
response to the context at a single place as a preparation for the
following patch that logs the response.

Change-Id: Idde2f1ba7394f16770543f5ca13411e8c2339cc6
Bug-Url: https://bugzilla.redhat.com/1351247
Backport-To: 4.0
Signed-off-by: Milan Zamazal <mzamazal(a)redhat.com&gt;
Reviewed-on: https://gerrit.ovirt.org/59080
Reviewed-by: Nir Soffer <nsoffer(a)redhat.com&gt;
Reviewed-by: Piotr Kliczewski <piotr.kliczewski(a)gmail.com&gt;
Continuous-Integration: Jenkins CI
---
M lib/vdsm/rpc/bindingxmlrpc.py
M lib/yajsonrpc/__init__.py
2 files changed, 26 insertions(+), 11 deletions(-)


  git pull ssh://gerrit.ovirt.org:29418/vdsm refs/changes/98/59998/1

diff --git a/lib/vdsm/rpc/bindingxmlrpc.py b/lib/vdsm/rpc/bindingxmlrpc.py
index 2c4765a..732918f 100644
--- a/lib/vdsm/rpc/bindingxmlrpc.py
+++ b/lib/vdsm/rpc/bindingxmlrpc.py
@@ -302,6 +302,8 @@
     def _registerFunctions(self):
         def wrapIrsMethod(f):
             def wrapper(*args, **kwargs):
+                start_time = utils.monotonic_time()
+
                 fmt = ""
                 logargs = []
 
@@ -321,6 +323,10 @@
                 except:
                     self.log.error("Unexpected exception", exc_info=True)
                     return errCode['unexpected']
+                finally:
+                    self.log.info("RPC call %s finished in %.2f seconds",
+                                  f.__name__,
+                                  utils.monotonic_time() - start_time)
 
             wrapper.__name__ = f.__name__
             wrapper.__doc__ = f.__doc__
@@ -1191,6 +1197,7 @@
 
 def wrapApiMethod(f):
     def wrapper(*args, **kwargs):
+        start_time = utils.monotonic_time()
         try:
             logLevel = logging.DEBUG
             suppress_args = f.__name__ in ('fenceNode',)
@@ -1260,6 +1267,10 @@
         except:
             f.__self__.cif.log.error("unexpected error", exc_info=True)
             return errCode['unexpected']
+        finally:
+            f.__self__.cif.log.info("RPC call %s finished in %.2f seconds",
+                                    f.__name__,
+                                    utils.monotonic_time() - start_time)
     wrapper.__name__ = f.__name__
     wrapper.__doc__ = f.__doc__
     return wrapper
diff --git a/lib/yajsonrpc/__init__.py b/lib/yajsonrpc/__init__.py
index 71db724..ff8e4ae 100644
--- a/lib/yajsonrpc/__init__.py
+++ b/lib/yajsonrpc/__init__.py
@@ -501,6 +501,14 @@
             self._counter = 0
 
     def _serveRequest(self, ctx, req):
+        start_time = monotonic_time()
+        response = self._handle_request(req, ctx.server_address)
+        self.log.info("RPC call %s finished in %.2f seconds",
+                      req.method, monotonic_time() - start_time)
+        if response is not None:
+            ctx.requestDone(response)
+
+    def _handle_request(self, req, server_address):
         self._attempt_log_stats()
         logLevel = logging.DEBUG
 
@@ -510,8 +518,7 @@
             self.log.info("In recovery, ignoring '%s' in bridge with
%s",
                           req.method, req.params)
             # TODO: take the response from the exception instead of via errCode
-            ctx.requestDone(JsonRpcResponse(errCode['recovery'], None, req.id))
-            return
+            return JsonRpcResponse(errCode['recovery'], None, req.id)
 
         self.log.log(logLevel, "Calling '%s' in bridge with %s",
                      req.method, req.params)
@@ -519,32 +526,29 @@
             method = self._bridge.dispatch(req.method)
         except JsonRpcMethodNotFoundError as e:
             if req.isNotification():
-                return
+                return None
 
-            ctx.requestDone(JsonRpcResponse(None, e, req.id))
-            return
+            return JsonRpcResponse(None, e, req.id)
 
         try:
             params = req.params
-            self._bridge.register_server_address(ctx.server_address)
+            self._bridge.register_server_address(server_address)
             if isinstance(req.params, list):
                 res = method(*params)
             else:
                 res = method(**params)
             self._bridge.unregister_server_address()
         except JsonRpcError as e:
-            ctx.requestDone(JsonRpcResponse(None, e, req.id))
+            return JsonRpcResponse(None, e, req.id)
         except Exception as e:
             self.log.exception("Internal server error")
-            ctx.requestDone(JsonRpcResponse(None,
-                                            JsonRpcInternalError(str(e)),
-                                            req.id))
+            return JsonRpcResponse(None, JsonRpcInternalError(str(e)), req.id)
         else:
             self.log.log(logLevel, "Return '%s' in bridge with %s",
                          req.method, res)
             if isinstance(res, Suppressed):
                 res = res.value
-            ctx.requestDone(JsonRpcResponse(res, None, req.id))
+            return JsonRpcResponse(res, None, req.id)
 
     @traceback(on=log.name)
     def serve_requests(self):


-- 
To view, visit https://gerrit.ovirt.org/59998
To unsubscribe, visit https://gerrit.ovirt.org/settings

Gerrit-MessageType: newchange
Gerrit-Change-Id: Idde2f1ba7394f16770543f5ca13411e8c2339cc6
Gerrit-PatchSet: 1
Gerrit-Project: vdsm
Gerrit-Branch: ovirt-4.0
Gerrit-Owner: Milan Zamazal <mzamazal(a)redhat.com&gt;
Gerrit-Reviewer: Nir Soffer <nsoffer(a)redhat.com&gt;
Gerrit-Reviewer: Piotr Kliczewski <piotr.kliczewski(a)gmail.com&gt;
    

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011