Adding pre-stage log on api request

Currently jumpgate only logs api response with a post-stage logging
handler, it's a limitation for real-time debugging if the handling of
api request was blocked or needs a while to process, operator or
developer needs to know what api is hanlding there now and which api
request the log belongs to that the main handling logic logged, so this
change added a pre-stage logging for api request.

etc/jumpgate.conf

@@ -3,7 +3,7 @@ enabled_services = identity, compute, image, volume, network, baremetal
 log_level = INFO
 admin_token = ADMIN
 secret_key = SET ME TO SOMETHING
-request_hooks = jumpgate.common.hooks.admin_token, jumpgate.common.hooks.auth_token, jumpgate.common.hooks.sl.client
+request_hooks = jumpgate.common.hooks.log, jumpgate.common.hooks.admin_token, jumpgate.common.hooks.auth_token, jumpgate.common.hooks.sl.client
 response_hooks = jumpgate.common.hooks.log
 default_domain = jumpgate.com
 

jumpgate/common/hooks/log.py

@@ -5,9 +5,19 @@
 LOG = logging.getLogger(__name__)
 
 
+@hooks.request_hook(True)
+def log_request(req, resp, kwargs):
+    LOG.info('REQ: %s %s %s %s [ReqId: %s]',
+             req.method,
+             req.path,
+             req.query_string,
+             kwargs,
+             req.env['REQUEST_ID'])
+
+
 @hooks.response_hook(True)
-def log_request(req, resp):
-    LOG.info('%s %s %s %s [ReqId: %s]',
+def log_response(req, resp):
+    LOG.info('RESP: %s %s %s %s [ReqId: %s]',
              req.method,
              req.path,
              req.query_string,

tests/jumpgate-tests/common/hooks/test_hooks.py

@@ -4,6 +4,7 @@
 from jumpgate.common.exceptions import InvalidTokenError
 from jumpgate.common.hooks.core import hook_format, hook_set_uuid
 from jumpgate.common.hooks.log import log_request
+from jumpgate.common.hooks.log import log_response
 from jumpgate.common.hooks.admin_token import admin_token
 from jumpgate.common.hooks.auth_token import validate_token
 
@@ -49,10 +50,27 @@ def test_log_request(self, log):
         req.env = {'REQUEST_ID': '123456'}
         resp = MagicMock()
         resp.status = '200 OK'
-        log_request(req, resp)
+        log_request(req, resp, {'key': 'value'})
 
         log.info.assert_called_with(
-            '%s %s %s %s [ReqId: %s]',
+            'REQ: %s %s %s %s [ReqId: %s]',
+            'GET', '/', 'something=value', {'key': 'value'}, '123456')
+
+
+class TestHookLogResponse(unittest.TestCase):
+    @patch('jumpgate.common.hooks.log.LOG')
+    def test_log_response(self, log):
+        req = MagicMock()
+        req.method = 'GET'
+        req.path = '/'
+        req.query_string = 'something=value'
+        req.env = {'REQUEST_ID': '123456'}
+        resp = MagicMock()
+        resp.status = '200 OK'
+        log_response(req, resp)
+
+        log.info.assert_called_with(
+            'RESP: %s %s %s %s [ReqId: %s]',
             'GET', '/', 'something=value', '200 OK', '123456')