Merge pull request #46 from ONSdigital/889_HTTP_Logging

889 HTTP logging

dpytools/logging/logger.py

@@ -4,9 +4,19 @@
 from datetime import datetime, timezone
 from typing import Dict, List, Optional
 
+import requests
 import structlog
 
-from dpytools.logging.utility import create_error_dict, level_to_severity
+from dpytools.logging.utility import (
+    calculate_duration_in_nanoseconds,
+    create_error_dict,
+    get_domain,
+    get_end_date,
+    get_port,
+    get_scheme,
+    get_start_date,
+    level_to_severity,
+)
 
 
 class DpLogger:
@@ -63,12 +73,30 @@ def _log(
         error: Optional[List] = None,
         data: Optional[Dict] = None,
         raw: str = None,
+        response : Optional[requests.Response] = None,
     ):
         data_dict = data if data is not None else {}
         data_dict["level"] = logging.getLevelName(level)
 
         # match dp logging structue
         # https://github.com/ONSdigital/dp-standards/blob/main/LOGGING_STANDARDS.md
+
+        if response is not None:
+            r_dict = {
+                "method": response.request.method,
+                "scheme": get_scheme(response.url),
+                "host": get_domain(response.url),
+                "port": get_port(response.url),
+                "path": response.request.path_url,
+                "status_code" : response.status_code,
+                "started_at":get_start_date(response.headers["Date"]),
+                "ended_at":get_end_date(response.elapsed, response.headers["Date"]),
+                "duration": calculate_duration_in_nanoseconds(response.elapsed, response.headers["Date"]),
+                "response_content_length":len(response.content)
+                }
+        else:
+            r_dict = None
+
         log_event = {
             "severity": level_to_severity(level),
             "event": event,
@@ -77,6 +105,7 @@ def _log(
             "trace_id": "not-implemented",
             "span_id": "not-implemented",
             "data": data_dict,
+            "response_dict" : r_dict,
             "raw": raw,
             "errors": create_error_dict(error) if error is not None else None,
         }
@@ -86,17 +115,17 @@ def _log(
         if self.flush_stdout_after_log_entry is True:
             sys.stdout.flush()
 
-    def debug(self, event: str, raw: str = None, data: Dict = None):
+    def debug(self, event: str, raw: str = None, data: Dict = None, response: requests.Response = None):
         """
         Log at the debug level.
 
         event: the thing that's happened, a simple short english statement
         raw  : a raw string of any log messages captured for a third party library
         data : arbitrary key-value pairs that may be of use in providing context
         """
-        self._log(event, 10, raw=raw, data=data)
+        self._log(event, 10, raw=raw, data=data, response=response)
 
-    def info(self, event: str, raw: str = None, data: Dict = None):
+    def info(self, event: str, raw: str = None, data: Dict = None, response: requests.Response = None):
         """
         Log at the info level.
 
@@ -106,17 +135,17 @@ def info(self, event: str, raw: str = None, data: Dict = None):
         """
         self._log(event, 20, raw=raw, data=data)
 
-    def warning(self, event: str, raw: str = None, data: Dict = None):
+    def warning(self, event: str, raw: str = None, data: Dict = None, response: requests.Response = None):
         """
         Log at the warning level.
 
         event: the thing that's happened, a simple short english statement
         raw  : a raw string of any log messages captured for a third party library
         data : arbitrary key-value pairs that may be of use in providing context
         """
-        self._log(event, 30, raw=raw, data=data)
+        self._log(event, 30, raw=raw, data=data, response=response)
 
-    def error(self, event: str, error: Exception, raw: str = None, data: Dict = None):
+    def error(self, event: str, error: Exception, raw: str = None, data: Dict = None, response: requests.Response = None):
         """
         Log at the error level.
 
@@ -125,10 +154,10 @@ def error(self, event: str, error: Exception, raw: str = None, data: Dict = None
         raw  : a raw string of any log messages captured for a third party library
         data : arbitrary key-value pairs that may be of use in providing context
         """
-        self._log(event, 40, error=error, raw=raw, data=data)
+        self._log(event, 40, error=error, raw=raw, data=data, response=response)
 
     def critical(
-        self, event: str, error: Exception, raw: str = None, data: Dict = None
+        self, event: str, error: Exception, raw: str = None, data: Dict = None, response: requests.Response = None
     ):
         """
         IMPORTANT: You should only be logging at the critical level during
@@ -142,4 +171,4 @@ def critical(
         raw  : a raw string of any log messages captured for a third party library
         data : arbitrary key-value pairs that may be of use in providing context
         """
-        self._log(event, 50, error=error, raw=raw, data=data)
+        self._log(event, 50, error=error, raw=raw, data=data, response=response)

dpytools/logging/utility.py

@@ -1,6 +1,10 @@
 import sys
 import traceback
+from datetime import datetime, timedelta
 from typing import Dict, List
+from urllib.parse import urlparse
+
+from requests import Response
 
 
 def level_to_severity(level: int) -> int:
@@ -50,3 +54,72 @@ def create_error_dict(error: Exception) -> List[Dict]:
 
     # Listify in keeping with expected DP logging structures
     return [error_dict]
+
+def get_scheme(url: str) -> str:
+    """This function will return the scheme from the provided url."""
+
+    index = url.find('/')
+    scheme = url[0:index-1]
+    return scheme
+
+def get_domain(url: str) -> str:
+    """This function will return the domain name from the provided url."""
+    #Parsing url to extract the domain name
+    parsed_url = urlparse(url)
+
+    #Getting the domain name
+    domain = parsed_url.netloc.split(':')[0]
+    return domain
+
+def get_port(url: str) ->int:
+    """This function will return the port number form the provided url."""
+    #Parsing url
+    parsed_url = urlparse(url)
+
+    #checking if the port was give if not checking scheme for port number
+    if parsed_url.port is None:
+        if parsed_url.scheme == "http":
+            return 80
+        else:
+            return 443
+    else:
+        return parsed_url.port
+
+def get_start_date(date: str) ->str:
+
+    strp_time = datetime.strptime(date, '%a, %d %b %Y %H:%M:%S GMT')
+
+    return strp_time.isoformat() + "Z"
+
+def get_end_date(time_delta: timedelta, date: str) ->str:
+    """This function will calculate the end_date by adding the duration to the start date."""
+
+    strp_time = datetime.strptime(date, '%a, %d %b %Y %H:%M:%S GMT')
+    td = timedelta(microseconds=time_delta.microseconds)
+
+    end_date = strp_time + td
+
+    return end_date.isoformat() + "Z"
+
+def calculate_duration_in_nanoseconds(time_delta: timedelta, date: str)->int:
+    """This function will convert the duration from Miliseconds to Nanoseconds."""
+
+    strp_time = datetime.strptime(date, '%a, %d %b %Y %H:%M:%S GMT')
+    td = timedelta(microseconds=time_delta.microseconds)
+
+    end_date = strp_time + td
+
+    duration = end_date - strp_time
+
+    return duration.microseconds * 1000 
+
+def get_content_length(res: Response)->int:
+    """
+    This function will try to get the 'Content-Lenght'
+    if there is noone it will return a default 0.
+    """
+    try:
+        content_length = res.headers["Content-Length"]
+        return int(content_length)
+    except KeyError:
+        return 0