Add inspection modes to Python client library (#1418)

* Add inspection modes to Python client library

* Reset sandbox & debug globals

* Update based on reviews

* Add auth logging

Co-authored-by: george <[email protected]>

---------

Co-authored-by: george <[email protected]>

Author: rzats

dev/local/setup.cfg

@@ -24,6 +24,7 @@ packages =
     delphi.epidata.acquisition.twtr
     delphi.epidata.acquisition.wiki
     delphi.epidata.client
+    delphi.epidata.common
     delphi.epidata.server
     delphi.epidata.server.admin
     delphi.epidata.server.admin.templates

integrations/client/test_delphi_epidata.py

@@ -3,6 +3,7 @@
 # standard library
 import time
 from json import JSONDecodeError
+from requests.models import Response
 from unittest.mock import MagicMock, patch
 
 # first party
@@ -41,6 +42,8 @@ def localSetUp(self):
     # use the local instance of the Epidata API
     Epidata.BASE_URL = 'http://delphi_web_epidata/epidata'
     Epidata.auth = ('epidata', 'key')
+    Epidata.debug = False
+    Epidata.sandbox = False
 
     # use the local instance of the epidata database
     secrets.db.host = 'delphi_database_epidata'
@@ -221,6 +224,82 @@ def test_retry_request(self, get):
                        {'result': 0, 'message': 'error: Expecting value: line 1 column 1 (char 0)'}
                        )
 
+  @patch('requests.post')
+  @patch('requests.get')
+  def test_debug(self, get, post):
+    """Test that in debug mode request params are correctly logged."""
+    class MockResponse:
+      def __init__(self, content, status_code):
+          self.content = content
+          self.status_code = status_code
+      def raise_for_status(self): pass
+
+    Epidata.debug = True
+
+    try:
+      with self.subTest(name='test multiple GET'):
+        with self.assertLogs('delphi_epidata_client', level='INFO') as logs:
+          get.reset_mock()
+          get.return_value = MockResponse(b'{"key": "value"}', 200)
+          Epidata._request_with_retry("test_endpoint1", params={"key1": "value1"})
+          Epidata._request_with_retry("test_endpoint2", params={"key2": "value2"})
+
+        output = logs.output
+        self.assertEqual(len(output), 4) # [request, response, request, response]
+        self.assertIn("Sending GET request", output[0])
+        self.assertIn("\"url\": \"http://delphi_web_epidata/epidata/test_endpoint1/\"", output[0])
+        self.assertIn("\"params\": {\"key1\": \"value1\"}", output[0])
+        self.assertIn("Received response", output[1])
+        self.assertIn("\"status_code\": 200", output[1])
+        self.assertIn("\"len\": 16", output[1])
+        self.assertIn("Sending GET request", output[2])
+        self.assertIn("\"url\": \"http://delphi_web_epidata/epidata/test_endpoint2/\"", output[2])
+        self.assertIn("\"params\": {\"key2\": \"value2\"}", output[2])
+        self.assertIn("Received response", output[3])
+        self.assertIn("\"status_code\": 200", output[3])
+        self.assertIn("\"len\": 16", output[3])
+
+      with self.subTest(name='test GET and POST'):
+        with self.assertLogs('delphi_epidata_client', level='INFO') as logs:
+          get.reset_mock()
+          get.return_value = MockResponse(b'{"key": "value"}', 414)
+          post.reset_mock()
+          post.return_value = MockResponse(b'{"key": "value"}', 200)
+          Epidata._request_with_retry("test_endpoint3", params={"key3": "value3"})
+
+        output = logs.output
+        self.assertEqual(len(output), 3) # [request, response, request, response]
+        self.assertIn("Sending GET request", output[0])
+        self.assertIn("\"url\": \"http://delphi_web_epidata/epidata/test_endpoint3/\"", output[0])
+        self.assertIn("\"params\": {\"key3\": \"value3\"}", output[0])
+        self.assertIn("Received 414 response, retrying as POST request", output[1])
+        self.assertIn("\"url\": \"http://delphi_web_epidata/epidata/test_endpoint3/\"", output[1])
+        self.assertIn("\"params\": {\"key3\": \"value3\"}", output[1])
+        self.assertIn("Received response", output[2])
+        self.assertIn("\"status_code\": 200", output[2])
+        self.assertIn("\"len\": 16", output[2])
+    finally: # make sure this global is always reset
+      Epidata.debug = False
+
+  @patch('requests.post')
+  @patch('requests.get')
+  def test_sandbox(self, get, post):
+    """Test that in debug + sandbox mode request params are correctly logged, but no queries are sent."""
+    Epidata.debug = True
+    Epidata.sandbox = True
+    try:
+      with self.assertLogs('delphi_epidata_client', level='INFO') as logs:
+        Epidata.covidcast('src', 'sig', 'day', 'county', 20200414, '01234')
+      output = logs.output
+      self.assertEqual(len(output), 1)
+      self.assertIn("Sending GET request", output[0])
+      self.assertIn("\"url\": \"http://delphi_web_epidata/epidata/covidcast/\"", output[0])
+      get.assert_not_called()
+      post.assert_not_called()
+    finally: # make sure these globals are always reset
+      Epidata.debug = False
+      Epidata.sandbox = False
+
   def test_geo_value(self):
     """test different variants of geo types: single, *, multi."""
 

src/client/delphi_epidata.py

@@ -10,12 +10,15 @@
 
 # External modules
 import requests
+import time
 import asyncio
 from tenacity import retry, stop_after_attempt
 
 from aiohttp import ClientSession, TCPConnector, BasicAuth
 from importlib.metadata import version, PackageNotFoundError
 
+from delphi.epidata.common.logger import get_structured_logger
+
 # Obtain package version for the user-agent. Uses the installed version by
 # preference, even if you've installed it and then use this script independently
 # by accident.
@@ -49,6 +52,10 @@ class Epidata:
 
     client_version = _version
 
+    logger = get_structured_logger('delphi_epidata_client')
+    debug = False # if True, prints extra logging statements
+    sandbox = False # if True, will not execute any queries
+
     # Helper function to cast values and/or ranges to strings
     @staticmethod
     def _listitem(value):
@@ -71,9 +78,25 @@ def _list(values):
     def _request_with_retry(endpoint, params={}):
         """Make request with a retry if an exception is thrown."""
         request_url = f"{Epidata.BASE_URL}/{endpoint}/"
+        if Epidata.debug:
+            Epidata.logger.info("Sending GET request", url=request_url, params=params, headers=_HEADERS, auth=Epidata.auth)
+        if Epidata.sandbox:
+            resp = requests.Response()
+            resp._content = b'true'
+            return resp
+        start_time = time.time()
         req = requests.get(request_url, params, auth=Epidata.auth, headers=_HEADERS)
         if req.status_code == 414:
+            if Epidata.debug:
+                Epidata.logger.info("Received 414 response, retrying as POST request", url=request_url, params=params, headers=_HEADERS)
             req = requests.post(request_url, params, auth=Epidata.auth, headers=_HEADERS)
+        if Epidata.debug:
+            Epidata.logger.info(
+                "Received response",
+                status_code=req.status_code,
+                len=len(req.content),
+                time=round(time.time() - start_time, 4)
+            )
         # handle 401 and 429
         req.raise_for_status()
         return req