diff --git a/dev/local/setup.cfg b/dev/local/setup.cfg index 7295590c8..b0e16d0cd 100644 --- a/dev/local/setup.cfg +++ b/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 diff --git a/integrations/client/test_delphi_epidata.py b/integrations/client/test_delphi_epidata.py index 2af923b2b..02a1a9275 100644 --- a/integrations/client/test_delphi_epidata.py +++ b/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.""" diff --git a/src/client/delphi_epidata.py b/src/client/delphi_epidata.py index 22fd4d4e2..bc8a2441c 100644 --- a/src/client/delphi_epidata.py +++ b/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