Fix InternalClient to drain response body if the request fails

If we don't drain the body, the proxy logging in the internal client
pipeline will log 499 client disconnect instead of actual error response
code.

For error responses, we try to do the most helpful thing using swob's
closing and caching response body attribute.  For non-error responses
which are returned to the client, we endeavour to keep the app_iter
intact and unconsumed, trusting expecting the caller to do the right
thing is the only reasonable interface.  We must cleanly close any WSGI
app_iter which we do not return to the client regardless of status code
and allow the logging of the 499 if needed.

Closes-Bug: #1675650
Change-Id: I455b5c38074ad0e72aa5e0b05771e193208905eb

swift/common/internal_client.py

@@ -22,14 +22,13 @@ from six.moves import urllib
 import struct
 from sys import exc_info, exit
 import zlib
-from swift import gettext_ as _
 from time import gmtime, strftime, time
 from zlib import compressobj
 
 from swift.common.exceptions import ClientException
 from swift.common.http import HTTP_NOT_FOUND, HTTP_MULTIPLE_CHOICES
 from swift.common.swob import Request
-from swift.common.utils import quote
+from swift.common.utils import quote, closing_if_possible
 from swift.common.wsgi import loadapp, pipeline_property
 
 if six.PY3:
@@ -199,10 +198,22 @@ class InternalClient(object):
                 exc_type, exc_value, exc_traceback = exc_info()
             # sleep only between tries, not after each one
             if attempt < self.request_tries - 1:
+                if resp:
+                    # always close any resp.app_iter before we discard it
+                    with closing_if_possible(resp.app_iter):
+                        # for non 2XX requests it's safe and useful to drain
+                        # the response body so we log the correct status code
+                        if resp.status_int // 100 != 2:
+                            for iter_body in resp.app_iter:
+                                pass
                 sleep(2 ** (attempt + 1))
         if resp:
-            raise UnexpectedResponse(
-                _('Unexpected response: %s') % resp.status, resp)
+            msg = 'Unexpected response: %s' % resp.status
+            if resp.status_int // 100 != 2 and resp.body:
+                # provide additional context (and drain the response body) for
+                # non 2XX responses
+                msg += ' (%s)' % resp.body
+            raise UnexpectedResponse(msg, resp)
         if exc_type:
             # To make pep8 tool happy, in place of raise t, v, tb:
             six.reraise(exc_type(*exc_value.args), None, exc_traceback)

test/unit/common/middleware/helpers.py

@@ -28,9 +28,9 @@ from test.unit import FakeLogger, FakeRing
 
 
 class LeakTrackingIter(object):
-    def __init__(self, inner_iter, fake_swift, path):
+    def __init__(self, inner_iter, mark_closed, path):
         self.inner_iter = inner_iter
-        self.fake_swift = fake_swift
+        self.mark_closed = mark_closed
         self.path = path
 
     def __iter__(self):
@@ -38,7 +38,7 @@ class LeakTrackingIter(object):
             yield x
 
     def close(self):
-        self.fake_swift.mark_closed(self.path)
+        self.mark_closed(self.path)
 
 
 FakeSwiftCall = namedtuple('FakeSwiftCall', ['method', 'path', 'headers'])
@@ -173,7 +173,7 @@ class FakeSwift(object):
                 conditional_etag=conditional_etag)
         wsgi_iter = resp(env, start_response)
         self.mark_opened(path)
-        return LeakTrackingIter(wsgi_iter, self, path)
+        return LeakTrackingIter(wsgi_iter, self.mark_closed, path)
 
     def mark_opened(self, path):
         self._unclosed_req_paths[path] += 1

test/unit/common/test_internal_client.py

@@ -19,6 +19,7 @@ import unittest
 import zlib
 from textwrap import dedent
 import os
+from itertools import izip_longest
 
 import six
 from six import StringIO
@@ -28,9 +29,11 @@ from test.unit import FakeLogger
 from swift.common import exceptions, internal_client, swob
 from swift.common.header_key_dict import HeaderKeyDict
 from swift.common.storage_policy import StoragePolicy
+from swift.common.middleware.proxy_logging import ProxyLoggingMiddleware
 
-from test.unit import with_tempdir, write_fake_ring, patch_policies
-from test.unit.common.middleware.helpers import FakeSwift
+from test.unit import with_tempdir, write_fake_ring, patch_policies, \
+    DebugLogger
+from test.unit.common.middleware.helpers import FakeSwift, LeakTrackingIter
 
 if six.PY3:
     from eventlet.green.urllib import request as urllib2
@@ -434,6 +437,74 @@ class TestInternalClient(unittest.TestCase):
             self.assertEqual(client.env['PATH_INFO'], path)
             self.assertEqual(client.env['HTTP_X_TEST'], path)
 
+    def test_make_request_error_case(self):
+        class InternalClient(internal_client.InternalClient):
+            def __init__(self):
+                self.logger = DebugLogger()
+                # wrap the fake app with ProxyLoggingMiddleware
+                self.app = ProxyLoggingMiddleware(
+                    self.fake_app, {}, self.logger)
+                self.user_agent = 'some_agent'
+                self.request_tries = 3
+
+            def fake_app(self, env, start_response):
+                body = 'fake error response'
+                start_response('409 Conflict',
+                               [('Content-Length', str(len(body)))])
+                return [body]
+
+        client = InternalClient()
+        with self.assertRaises(internal_client.UnexpectedResponse), \
+                mock.patch('swift.common.internal_client.sleep'):
+            client.make_request('DELETE', '/container', {}, (200,))
+
+        for logline in client.logger.get_lines_for_level('info'):
+            # add spaces before/after 409 because it can match with
+            # something like timestamp
+            self.assertIn(' 409 ', logline)
+
+    def test_make_request_acceptable_status_not_2xx(self):
+        closed_paths = []
+
+        def mark_closed(path):
+            closed_paths.append(path)
+
+        class InternalClient(internal_client.InternalClient):
+            def __init__(self):
+                self.logger = DebugLogger()
+                # wrap the fake app with ProxyLoggingMiddleware
+                self.app = ProxyLoggingMiddleware(
+                    self.fake_app, {}, self.logger)
+                self.user_agent = 'some_agent'
+                self.request_tries = 3
+
+            def fake_app(self, env, start_response):
+                body = 'fake error response'
+                start_response('200 Ok', [('Content-Length', str(len(body)))])
+                return LeakTrackingIter((c for c in body),
+                                        mark_closed, env['PATH_INFO'])
+
+        client = InternalClient()
+        with self.assertRaises(internal_client.UnexpectedResponse) as ctx, \
+                mock.patch('swift.common.internal_client.sleep'):
+            # This is obvious strange tests to expect only 400 Bad Request
+            # but this test intended to avoid extra body drain if it's
+            # correct object body with 2xx.
+            client.make_request('GET', '/cont/obj', {}, (400,))
+        self.assertEqual(closed_paths, ['/cont/obj'] * 2)
+        # swob's body resp property will call close
+        self.assertEqual(ctx.exception.resp.body, 'fake error response')
+        self.assertEqual(closed_paths, ['/cont/obj'] * 3)
+
+        # Retries like this will cause 499 because internal_client won't
+        # automatically consume (potentially large) 2XX responses.
+        expected = (' 499 ', ' 499 ', ' 200 ')
+        loglines = client.logger.get_lines_for_level('info')
+        for expected, logline in izip_longest(expected, loglines):
+            if not expected:
+                self.fail('Unexpected extra log line: %r' % logline)
+            self.assertIn(expected, logline)
+
     def test_make_request_codes(self):
         class InternalClient(internal_client.InternalClient):
             def __init__(self):