Added logging for Request/Response Body and Headers (#491)

* implemented before and after request to log details from http invocation

* moved test under logging folder + added tests for new implementation

* fixed import after moving the test file in previous commit + fixed logging related tests

* fixed typing declaration

* added info to the logged json for request/response + allow to specify no_log_paths

* added mechanims to pass lambda event info to pcm flask context

* removed unused import

* added tests for valid cases

* removed 'type' key from logged info + renamed no_logs_path to urls_deny_list

* removed apigw request id from response + removed localproxy to carry the request id inside the app

* adjusted test

Co-authored-by: Marco Basile <[email protected]>

Author: BarcoMasile

api/logging/__init__.py

@@ -1,4 +1,6 @@
-from .logger import DefaultLogger
+from flask import Flask, request
+
+from api.logging.http_info import log_request_body_and_headers, log_response_body_and_headers
 
 VALID_LOG_LEVELS = {'debug', 'info', 'warning', 'error', 'critical'}
 
@@ -19,7 +21,30 @@ def parse_log_entry(_logger, entry):
 
     return lowercase_level, message, extra
 
+
 def push_log_entry(_logger, level, message, extra):
     """ Logs a single log entry at the specified level """
     logging_fun = getattr(_logger, level, None)
-    logging_fun(message, extra=extra)
+    logging_fun(message, extra=extra)
+
+
+class RequestResponseLogging:
+    def __init__(self, logger, app: Flask = None, urls_deny_list=['/logs']):
+        self.logger = logger
+        self.urls_deny_list = urls_deny_list
+        if app:
+            self.init_app(app)
+
+    def init_app(self, app):
+
+        def log_request():
+            if request.path not in self.urls_deny_list:
+                log_request_body_and_headers(self.logger, request)
+
+        def log_response(response = None):
+            if request.path not in self.urls_deny_list:
+                log_response_body_and_headers(self.logger, response)
+            return response
+
+        app.before_request(log_request)
+        app.after_request(log_response)

api/logging/http_info.py

@@ -0,0 +1,44 @@
+from typing import Union
+
+from flask import Request, Response
+
+
+def log_request_body_and_headers(_logger, request: Request):
+    details = __get_http_info(request)
+    details['path'] = request.path
+    if request.args:
+        details['params'] = request.args
+
+    if 'serverless.event' in request.environ:
+        env = request.environ.get('serverless.event')
+        if 'requestContext' in env and 'requestId' in env.get('requestContext'):
+            details['apigw-request-id'] = env.get('requestContext').get('requestId')
+
+    _logger.info(details)
+
+
+def log_response_body_and_headers(_logger, response: Response):
+    details = __get_http_info(response)
+    _logger.info(details)
+
+
+def __get_http_info(r: Union[Request,Response]) -> dict:
+    headers = __filter_headers(r.headers)
+    details = {'headers': headers}
+
+    try:
+        body = r.json
+        if body:
+            details['body'] = body
+    except:
+        pass
+
+    return details
+
+
+def __filter_headers(headers: dict):
+    """ utility function to remove sensitive information from request headers """
+    _headers = dict(headers)
+    _headers.pop('Cookie', None)
+    _headers.pop('X-CSRF-Token', None)
+    return _headers

api/tests/logging/test_logger.py

@@ -0,0 +1,127 @@
+from unittest.mock import MagicMock
+
+from flask import Response
+
+from api.logging import RequestResponseLogging, log_request_body_and_headers, log_response_body_and_headers
+from api.logging.logger import DefaultLogger
+import logging
+
+
+def test_logger_level_prod():
+  """
+  Given a DefaultLogger
+    When not running local
+      It should set log level to INFO
+  """
+
+  logger = DefaultLogger(is_running_local=False)
+  assert logger.logger.getEffectiveLevel() == logging.INFO
+
+
+def test_logger_level_dev():
+  """
+  Given a DefaultLogger
+    When is running local
+      It should set log level to DEBUG
+  """
+
+  logger = DefaultLogger(is_running_local=True)
+  assert logger.logger.getEffectiveLevel() == logging.DEBUG
+
+
+def test_request_response_logging_extension(app):
+    """
+    Given a Flask app
+      when using the RequestResponseLogging extension
+        it should present a log_request before func and a log_response after_func
+    """
+    RequestResponseLogging(app)
+
+    before_func_names = __get_function_name_list(app.before_request_funcs)
+    after_func_names = __get_function_name_list(app.after_request_funcs)
+
+    assert 'log_request' in before_func_names
+    assert 'log_response' in after_func_names
+
+def test_request_response_logging_execution_urls_deny_list(app, mocker):
+    """
+        Given a Flask app
+          when using the RequestResponseLogging extension
+          when invoking a path from the specified no_logs_path
+            it should not call the log_request_body_and_headers and log_response_body_and_headers functions
+        """
+
+    mock_log_request = mocker.patch('api.logging.http_info.log_request_body_and_headers')
+    mock_log_response = mocker.patch('api.logging.http_info.log_response_body_and_headers')
+
+    RequestResponseLogging(app)
+
+    with app.test_request_context('/logs'):
+        app.preprocess_request()
+        app.process_response(Response('fake-response'))
+
+    mock_log_request.assert_not_called()
+    mock_log_response.assert_not_called()
+
+def test_request_response_logging_execution(app, mocker):
+    """
+        Given a Flask app
+          when using the RequestResponseLogging extension
+          when invoking a path
+            it should call the log_request_body_and_headers and log_response_body_and_headers functions
+        """
+    mock_log_request = mocker.patch('api.logging.log_request_body_and_headers')
+    mock_log_response = mocker.patch('api.logging.log_response_body_and_headers')
+
+    RequestResponseLogging(app)
+
+    with app.test_request_context('/'):
+        app.preprocess_request()
+        app.process_response(Response('fake-response'))
+
+    mock_log_request.assert_called_once()
+    mock_log_response.assert_called_once()
+
+def __get_function_name_list(functions):
+    return list(fun.__name__ for app_name, funcs in functions.items() for fun in funcs)
+
+
+class MockRequest:
+    headers = {'int_value': 100}
+    args = {'region': 'eu-west-1'}
+    json = {'username': '[email protected]'}
+    path = '/fake-path'
+    environ = {
+        'serverless.event': {
+            'requestContext': {
+                'requestId': 'apigw-request-id'
+            }
+        }
+    }
+
+
+def test_log_request_body_and_headers():
+    mock_logger = MagicMock(wraps=DefaultLogger(True))
+    log_request_body_and_headers(mock_logger, MockRequest())
+
+    expected_details = {
+        'headers': {'int_value': 100},
+        'body': {'username': '[email protected]'},
+        'path': '/fake-path',
+        'params': {'region': 'eu-west-1'},
+        'apigw-request-id': 'apigw-request-id'
+    }
+
+    mock_logger.info.assert_called_once_with(expected_details)
+
+
+def test_log_response_body_and_headers():
+    mock_logger = MagicMock(wraps=DefaultLogger(True))
+    log_response_body_and_headers(mock_logger, MockRequest())
+
+    expected_details = {
+        'headers': {'int_value': 100},
+        'body': {'username': '[email protected]'}
+    }
+
+    mock_logger.info.assert_called_once_with(expected_details)

api/tests/test_logger.py

@@ -12,7 +12,7 @@ def test_push_log_controller_with_valid_json_no_extra(client, caplog, mock_disab
     response = client.post('/logs', json=request_body)
 
     assert response.status_code == 200
-    assert trim_log(caplog) == expected_log
+    assert expected_log in trim_log(caplog)
 
 
 def test_push_log_controller_with_valid_json_with_extra(client, caplog, mock_disable_auth, mock_csrf_needed):
@@ -24,4 +24,4 @@ def test_push_log_controller_with_valid_json_with_extra(client, caplog, mock_dis
     response = client.post('/logs', json=request_body)
 
     assert response.status_code == 200
-    assert trim_log(caplog) == expected_log
+    assert expected_log in trim_log(caplog)

api/tests/test_push_log.py

@@ -3,7 +3,7 @@
 import pytest
 
 from api.PclusterApiHandler import revoke_cognito_refresh_token
-from api.logging import DefaultLogger
+from api.logging.logger import DefaultLogger
 
 
 @pytest.fixture

api/tests/test_revoke_cognito_refresh_token.py

@@ -15,8 +15,9 @@
 from flask import Flask, Response, request, send_from_directory
 import requests
 
+from api.pcm_globals import PCMGlobals, logger
 from api.exception import ExceptionHandler
-from api.pcm_globals import PCMGlobals
+from api.logging import RequestResponseLogging
 from api.security import SecurityHeaders
 
 # needed to only allow tests to disable auth
@@ -99,6 +100,7 @@ def build_flask_app(name):
 
     SecurityHeaders(app, running_local=is_running_local)
     ExceptionHandler(app, running_local=is_running_local)
+    RequestResponseLogging(app=app, logger=logger)
 
     return app
 

api/utils.py

@@ -14,6 +14,7 @@
 
 import app
 import logging
+
 from awslambda.serverless_wsgi import handle_request
 
 # Initialize as a global to re-use across Lambda invocations