Remove <curl_time_total: from response even when response is unexpected

p3rf Team · copybara-github · commit a52122505697 · 2023-10-03T13:33:54.000-07:00
PiperOrigin-RevId: 570481465
diff --git a/perfkitbenchmarker/data/http/poll_http_endpoint.py b/perfkitbenchmarker/data/http/poll_http_endpoint.py
@@ -1,6 +1,5 @@
 """Scripts to poll http endpoint."""
 
-import logging
 import re
 import subprocess
 import sys
@@ -13,16 +12,20 @@
 
 _ENDPOINT = flags.DEFINE_string('endpoint', None, 'Endpoint to use.')
 _MAX_RETRIES = flags.DEFINE_integer('max_retries', 0, 'Number of retries.')
-_RETRY_INTERVAL = flags.DEFINE_float('retry_interval', 0.5,
-                                     'Gap in seconds between retries.')
+_RETRY_INTERVAL = flags.DEFINE_float(
+    'retry_interval', 0.5, 'Gap in seconds between retries.'
+)
 _TIMEOUT = flags.DEFINE_integer('timeout', 600, 'Polling deadline in seconds.')
-_EXPECTED_RESPONSE = flags.DEFINE_string('expected_response', '',
-                                         'Expected response.')
+_EXPECTED_RESPONSE = flags.DEFINE_string(
+    'expected_response', '', 'Expected response.'
+)
 _EXPECTED_RESPONSE_CODE = flags.DEFINE_string(
-    'expected_response_code', r'2\d\d',
+    'expected_response_code',
+    r'2\d\d',
     'Expected http response code. Can be either a regexp or '
     'a integer in string format. '
-    'By default, any 2xx response code is valid.')
+    'By default, any 2xx response code is valid.',
+)
 _HEADERS = flags.DEFINE_list('headers', [], 'Headers applying to requests.')
 _HTTP_RESPCODE_REGEXP = r'HTTPS?/[\d\.]*\s+(\d+)'
 _CURL_METRICS = '<curl_time_total:%{time_total}>'
@@ -33,8 +36,12 @@
 FAILURE_CURL = 'curl_failure'
 FAILURE_INVALID_RESPONSE = 'invalid_response'
 FAILURE_INVALID_RESPONSE_CODE = 'invalid_response_code'
-POLL_STATUS = (POLL_SUCCEED, FAILURE_CURL,
-               FAILURE_INVALID_RESPONSE, FAILURE_INVALID_RESPONSE_CODE)
+POLL_STATUS = (
+    POLL_SUCCEED,
+    FAILURE_CURL,
+    FAILURE_INVALID_RESPONSE,
+    FAILURE_INVALID_RESPONSE_CODE,
+)
 
 
 def _generate_file_names():
@@ -53,77 +60,89 @@ def _popen(curl_cmd, stdout, stderr, shell):
   return subprocess.Popen(curl_cmd, stdout=stdout, stderr=stderr, shell=shell)
 
 
-def call_curl(endpoint, headers=None, expected_response_code=None,
-              expected_response=None):
+def call_curl(
+    endpoint, headers=None, expected_response_code=None, expected_response=None
+):
   """Curl endpoint once and return response.
 
   Args:
     endpoint: string. HTTP(S) endpoint to curl.
     headers: list. A list of strings, each representing a header.
-    expected_response_code: string. Expected http response code. Can be either
-      a string or a regex.
-    expected_response: string. Expected http response. Can be either a string
-      or a regex.
+    expected_response_code: string. Expected http response code. Can be either a
+      string or a regex.
+    expected_response: string. Expected http response. Can be either a string or
+      a regex.
 
   Returns:
-    A tuple of float, string, integer and string:
+    A tuple of float, string, string, and string:
       Float indicates latency in second of the polling attempt.
-      String indicates whether the HTTP endpoint is reachable and respond
+      First string indicates whether the HTTP endpoint is reachable and respond
         with expected responses or the reason of failure;
         List of current values are:
         [succeed, curl_failure, invalid_response_code, invalid_response]
 
-      Integer indicates the actual HTTP response code;
-      String indicates the actual HTTP response.
+      Second string is the actual HTTP response.
+      Third string is additional logged info.
   """
   poll_stats = POLL_SUCCEED
   outid, errid = _generate_file_names()
   header = ''
+  logs = ''
   if headers:
     header = '-H %s ' % ' '.join(headers)
 
   curl_cmd = 'curl -w "{metrics}" -v {header}"{endpoint}"'.format(
-      metrics=_CURL_METRICS,
-      header=header,
-      endpoint=endpoint)
+      metrics=_CURL_METRICS, header=header, endpoint=endpoint
+  )
   with open(outid, 'w+') as stdout:
     with open(errid, 'w+') as stderr:
-      p = _popen(
-          curl_cmd, stdout=stdout, stderr=stderr, shell=True)
+      p = _popen(curl_cmd, stdout=stdout, stderr=stderr, shell=True)
       retcode = p.wait()
   http_resp_code = None
   with open(errid, 'r') as stderr:
     http_stderr = stderr.read()
     for line in http_stderr.split('\n'):
       match = re.search(_HTTP_RESPCODE_REGEXP, line)
-      if match:
+      if expected_response_code and match:
         http_resp_code = match.group(1)
         if re.search(expected_response_code, http_resp_code) is None:
           poll_stats = FAILURE_INVALID_RESPONSE_CODE
   if retcode:
     poll_stats = FAILURE_CURL
     http_resp_code = '-1'
-    logging.info(
-        'Error: received non-zero return code running %s, stderr: %s',
-        curl_cmd, http_stderr)
+    logs += (
+        f'Error: received non-zero return code running {curl_cmd}, '
+        f'stderr: {http_stderr};'
+    )
   latency = 0
   with open(outid, 'r') as stdout:
     http_stdout = stdout.read()
     if expected_response and (
-        re.search(expected_response, http_stdout) is None):
+        re.search(expected_response, http_stdout) is None
+    ):
       poll_stats = FAILURE_INVALID_RESPONSE
-    else:
-      match = re.search(_CURL_METRICS_REGEXP, http_stdout)
-      if match:
-        latency = float(match.group(1))
-        # Remove <curl_time_total:##> from the response.
-        http_stdout = http_stdout.split(match.group(0))[0]
-
-    return latency or -1, poll_stats, int(http_resp_code), http_stdout
-
-
-def poll(endpoint, headers=None, max_retries=0, retry_interval=0.5,
-         timeout=600, expected_response_code=None, expected_response=None):
+    match = re.search(_CURL_METRICS_REGEXP, http_stdout)
+    if match:
+      latency = float(match.group(1))
+      # Remove <curl_time_total:##> from the response.
+      http_stdout = http_stdout.split(match.group(0))[0]
+
+    logs += (
+        f'call_curl values - latency: {latency}, pass/fail: {poll_stats}, '
+        f'response code: {http_resp_code}, stdout: {http_stdout};'
+    )
+    return latency or -1, poll_stats, http_stdout, logs
+
+
+def poll(
+    endpoint,
+    headers=None,
+    max_retries=0,
+    retry_interval=0.5,
+    timeout=600,
+    expected_response_code=None,
+    expected_response=None,
+):
   """Poll HTTP endpoint until expected response code is received or time out.
 
   Args:
@@ -132,54 +151,62 @@ def poll(endpoint, headers=None, max_retries=0, retry_interval=0.5,
     max_retries: int. Indicates how many retires before give up.
     retry_interval: float. Indicates interval in sec between retries.
     timeout: int. Deadline before giving up.
-    expected_response_code: string. Expected http response code. Can be either
-      a string or a regex.
-    expected_response: string. Expected http response. Can be either a string
-      or a regex.
+    expected_response_code: string. Expected http response code. Can be either a
+      string or a regex.
+    expected_response: string. Expected http response. Can be either a string or
+      a regex.
 
   Returns:
-    A tuple of float, float, string, string:
-      First float indicates total time spent in seconds polling before
-        giving up or succeed.
-      Second float indicates latency for successful polls. If polling failed,
+    A tuple of float, string, string, and string:
+      Float indicates latency for successful polls. If polling failed,
         latency is default to -1.
-      String indicates if HTTP(S) endpoint is reachable and responds with
+      First string indicates if HTTP(S) endpoint is reachable and responds with
         expected response and code, or reasons of failure.
-      String represents actual response.
+      Second string represents actual response.
+      Third string has additional debugging info worth logging.
   """
   start = _get_time()
   end = start
   latency = 0
   attempt = 0
   poll_stats = None
+  resp = ''
+  logs = ''
   while end - start < timeout and attempt <= max_retries:
-    attempt_latency, poll_stats, _, resp = call_curl(endpoint, headers,
-                                                     expected_response_code,
-                                                     expected_response)
+    attempt_latency, poll_stats, resp, logs = call_curl(
+        endpoint, headers, expected_response_code, expected_response
+    )
     if poll_stats != POLL_SUCCEED:
       time.sleep(retry_interval)
       end = _get_time()
       attempt += 1
     else:
       latency = attempt_latency
       break
-  return _get_time() - start - latency, latency or -1, poll_stats, resp
+  logs += f'Time before request started: {_get_time() - start - latency};'
+  return latency or -1, poll_stats, resp, logs
 
 
 def main():
   if not _ENDPOINT.value:
-    logging.info('Invalid arguments, no endpoint provided.')
+    print(
+        -1, 'INVALID_ARGUMENTS', '', 'Invalid arguments, no endpoint provided.'
+    )
     return 1
   print(
-      poll(_ENDPOINT.value, _HEADERS.value, _MAX_RETRIES.value,
-           _RETRY_INTERVAL.value, _TIMEOUT.value, _EXPECTED_RESPONSE_CODE.value,
-           _EXPECTED_RESPONSE.value))
+      poll(
+          _ENDPOINT.value,
+          _HEADERS.value,
+          _MAX_RETRIES.value,
+          _RETRY_INTERVAL.value,
+          _TIMEOUT.value,
+          _EXPECTED_RESPONSE_CODE.value,
+          _EXPECTED_RESPONSE.value,
+      )
+  )
   return 0
 
 
 if __name__ == '__main__':
   FLAGS(sys.argv)
-  logging.basicConfig(
-      level=logging.INFO,
-      format='%(asctime)-15s %(message)s')
   sys.exit(main())
diff --git a/perfkitbenchmarker/linux_packages/http_poller.py b/perfkitbenchmarker/linux_packages/http_poller.py
@@ -35,7 +35,7 @@ def AptInstall(vm):
   _Install(vm)
 
 
-_SUCCEED_RESP = 'succeed'
+_SUCCESS = 'succeed'
 _FAILURE_INVALID_RESPONSE = 'invalid_response'
 
 
@@ -105,15 +105,15 @@ def Run(self, vm, endpoint,
         endpoint, headers, retries, retry_interval, timeout,
         expected_response_code, expected_response)
     out, _ = vm.RemoteCommand(cmd)
-    _, latency, resp, ret = ast.literal_eval(out)
-    if resp == _FAILURE_INVALID_RESPONSE:
+    latency, ret, resp, _ = ast.literal_eval(out)
+    if ret == _FAILURE_INVALID_RESPONSE:
       logging.debug(
           'Failure polling endpoint %s. Received unexpected response %s != '
           'expected %s.',
-          endpoint, ret, expected_response)
-    elif float(latency) == -1 or resp != _SUCCEED_RESP:
+          endpoint, resp, expected_response)
+    elif float(latency) == -1 or ret != _SUCCESS:
       logging.debug(
           'Unexpected response or unable to reach endpoint %s, resp: %s',
           endpoint, resp)
     return PollingResponse(
-        success=resp == _SUCCEED_RESP, response=ret, latency=latency)
+        success=resp == _SUCCESS, response=resp, latency=latency)
diff --git a/tests/poll_http_endpoint_test.py b/tests/poll_http_endpoint_test.py
@@ -43,44 +43,49 @@ def setUp(self):
           '400 request fails',
           '< HTTP/1.1 400 Bad Request',
           'invalid_response_code',
-          400,
       ),
-      ('200 request passes', '< HTTP/1.1 200 OK'
-       , 'succeed', 200),
+      ('200 request passes', '< HTTP/1.1 200 OK', 'succeed'),
   )
   def test_call_curl_response_types(
-      self, response_stderr, expected_response_type, expected_response_code
+      self, response_stderr, expected_response_type
   ):
     self.mock_subprocess.side_effect = fake_subprocess_popen_output(
         'hello world<curl_time_total:0.5>', response_stderr
     )
-    latency, response_type, response_code, response = (
-        poll_http_endpoint.call_curl(
-            'http://site.com', expected_response_code=r'2\d\d'
-        )
+    latency, response_type, response, _ = poll_http_endpoint.call_curl(
+        'http://site.com', expected_response_code=r'2\d\d'
     )
     self.assertEqual(response_type, expected_response_type)
-    self.assertEqual(response_code, expected_response_code)
     self.assertAlmostEqual(latency, 0.5)
     self.assertEqual(response, 'hello world')
 
+  def test_call_curl_unexpected_no_response(self):
+    self.mock_subprocess.side_effect = fake_subprocess_popen_output(
+        '<curl_time_total:0.5>', '< HTTP/1.1 400 Bad Request'
+    )
+    latency, _, response, _ = poll_http_endpoint.call_curl(
+        'http://site.com', expected_response='foo'
+    )
+    self.assertAlmostEqual(latency, 0.5)
+    self.assertEqual(response, '')
+
   @parameterized.named_parameters(
       ('response match', 'succeed', 'hello world'),
       ('response not match', 'invalid_response', 'hi folks'),
   )
   def test_call_curl_matching_expected_response(
-      self, response_type, expected_response
+      self, expected_response_type, expected_response
   ):
     self.mock_subprocess.side_effect = fake_subprocess_popen_output(
         'hello world<curl_time_total:0.5>', '< HTTP/1.1 200 OK'
     )
-    _, response_type, response_code, _ = poll_http_endpoint.call_curl(
+    _, response_type, response, _ = poll_http_endpoint.call_curl(
         'http://site.com',
         expected_response_code=r'2\d\d',
         expected_response=expected_response,
     )
-    self.assertEqual(response_type, response_type)
-    self.assertEqual(response_code, 200)
+    self.assertEqual(expected_response_type, response_type)
+    self.assertEqual(response, 'hello world')
 
   @parameterized.named_parameters(
       (
@@ -108,7 +113,7 @@ def test_poll(
     self.mock_subprocess.side_effect = fake_subprocess_popen_output(
         'hello world<curl_time_total:0.5>', response_stderr
     )
-    _, latency, response_type, response = poll_http_endpoint.poll(
+    latency, response_type, response, _ = poll_http_endpoint.poll(
         'http://site.com',
         expected_response_code=r'2\d\d',
         max_retries=2,
@@ -123,7 +128,7 @@ def test_poll_fails_with_timeout(self):
         mock.patch.object(
             poll_http_endpoint,
             'call_curl',
-            return_value=(1, 'invalid_response_code', '', 'hello'),
+            return_value=('invalid_response_code', '', 'hello', ''),
         )
     )
     self.enter_context(
