wsgi: bad request syntax response missing txn-id

When a client sends a malformed http request our server returns a valid http error response with Connection: close and closes the connection.
We want to include a transaction-id and ensure we log details about about the "bad request syntax"

Change-Id: Ic0ee1e4fd4d434d442fcffa68da77e862b37d4c6

swift/common/http_protocol.py

@@ -16,11 +16,16 @@
 from eventlet import wsgi, websocket
 import six
 
+from swift.common.utils import generate_trans_id
+from swift.common.http import HTTP_NO_CONTENT, HTTP_RESET_CONTENT, \
+    HTTP_NOT_MODIFIED
 
 if six.PY2:
     from eventlet.green import httplib as http_client
+    from cgi import escape
 else:
     from eventlet.green.http import client as http_client
+    from html import escape
 
 
 class SwiftHttpProtocol(wsgi.HttpProtocol):
@@ -52,7 +57,7 @@ class SwiftHttpProtocol(wsgi.HttpProtocol):
             self.server.log.info('ERROR WSGI: ' + f, *a)
 
     class MessageClass(wsgi.HttpProtocol.MessageClass):
-        '''Subclass to see when the client didn't provide a Content-Type'''
+        """Subclass to see when the client didn't provide a Content-Type"""
         # for py2:
         def parsetype(self):
             if self.typeheader is None:
@@ -61,7 +66,7 @@ class SwiftHttpProtocol(wsgi.HttpProtocol):
 
         # for py3:
         def get_default_type(self):
-            '''If the client didn't provide a content type, leave it blank.'''
+            """If the client didn't provide a content type, leave it blank."""
             return ''
 
     def parse_request(self):
@@ -241,6 +246,74 @@ class SwiftHttpProtocol(wsgi.HttpProtocol):
                 self.conn_state[2] = wsgi.STATE_IDLE
         return got
 
+    def send_error(self, code, message=None, explain=None):
+        """Send and log an error reply, we are overriding the cpython parent
+        class method, so we can have logger generate txn_id's for error
+        response from wsgi since we are at the edge of the proxy server.
+        This sends an error response (so it must be called before any output
+        has been generated), logs the error, and finally sends a piece of HTML
+        explaining the error to the user.
+
+        :param code:    an HTTP error code
+                   3 digits
+        :param message: a simple optional 1 line reason phrase.
+                   *( HTAB / SP / VCHAR / %x80-FF )
+                   defaults to short entry matching the response code
+        :param explain: a detailed message defaults to the long entry
+                   matching the response code.
+        """
+
+        try:
+            shortmsg, longmsg = self.responses[code]
+        except KeyError:
+            shortmsg, longmsg = '???', '???'
+        if message is None:
+            message = shortmsg
+        if explain is None:
+            explain = longmsg
+
+        try:
+            # assume we have a LogAdapter
+            txn_id = self.server.app.logger.txn_id  # just in case it was set
+        except AttributeError:
+            # turns out we don't have a LogAdapter, so go direct
+            txn_id = generate_trans_id('')
+            self.log_error("code %d, message %s, (txn: %s)", code,
+                           message, txn_id)
+        else:
+            # we do have a LogAdapter, but likely not yet a txn_id
+            txn_id = txn_id or generate_trans_id('')
+            self.server.app.logger.txn_id = txn_id
+            self.log_error("code %d, message %s", code, message)
+        self.send_response(code, message)
+        self.send_header('Connection', 'close')
+
+        # Message body is omitted for cases described in:
+        #  - RFC7230: 3.3. 1xx, 204(No Content), 304(Not Modified)
+        #  - RFC7231: 6.3.6. 205(Reset Content)
+        body = None
+        exclude_status = (HTTP_NO_CONTENT,
+                          HTTP_RESET_CONTENT,
+                          HTTP_NOT_MODIFIED)
+        if (code >= 200 and
+                code not in exclude_status):
+            # HTML encode to prevent Cross Site Scripting attacks
+            # (see bug https://bugs.python.org/issue1100201)
+            content = (self.error_message_format % {
+                'code': code,
+                'message': escape(message, quote=False),
+                'explain': escape(explain, quote=False)
+            })
+            body = content.encode('UTF-8', 'replace')
+            self.send_header("Content-Type", self.error_content_type)
+            self.send_header('Content-Length', str(len(body)))
+            self.send_header('X-Trans-Id', txn_id)
+            self.send_header('X-Openstack-Request-Id', txn_id)
+        self.end_headers()
+
+        if self.command != 'HEAD' and body:
+            self.wfile.write(body)
+
 
 class SwiftHttpProxiedProtocol(SwiftHttpProtocol):
     """
@@ -271,7 +344,6 @@ class SwiftHttpProxiedProtocol(SwiftHttpProtocol):
         # ourselves and our gateway proxy before processing the client
         # protocol request.  Hopefully the operator will know what to do!
         msg = 'Invalid PROXY line %r' % connection_line
-        self.log_message(msg)
         # Even assuming HTTP we don't even known what version of HTTP the
         # client is sending?  This entire endeavor seems questionable.
         self.request_version = self.default_request_version

test/functional/test_protocol.py

@@ -0,0 +1,53 @@
+#!/usr/bin/python
+
+# Copyright (c) 2010-2012 OpenStack Foundation
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#    http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or
+# implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import unittest
+
+from test.functional import check_response, retry, SkipTest
+import test.functional as tf
+
+
+def setUpModule():
+    tf.setup_package()
+
+
+def tearDownModule():
+    tf.teardown_package()
+
+
+class TestHttpProtocol(unittest.TestCase):
+    existing_metadata = None
+
+    def test_invalid_path_info(self):
+        if tf.skip:
+            raise SkipTest
+
+        def get(url, token, parsed, conn):
+            path = "/info asdf"
+            conn.request('GET', path, '', {'X-Auth-Token': token})
+            return check_response(conn)
+
+        resp = retry(get)
+        resp.read()
+
+        self.assertEqual(resp.status, 412)
+        self.assertIsNotNone(resp.getheader('X-Trans-Id'))
+        self.assertIsNotNone(resp.getheader('X-Openstack-Request-Id'))
+        self.assertIn('tx', resp.getheader('X-Trans-Id'))
+        self.assertIn('tx', resp.getheader('X-Openstack-Request-Id'))
+        self.assertEqual(resp.getheader('X-Openstack-Request-Id'),
+                         resp.getheader('X-Trans-Id'))

test/unit/common/test_http_protocol.py

@@ -19,8 +19,10 @@ import json
 import mock
 import types
 import unittest
-import eventlet.wsgi
+import eventlet.wsgi as wsgi
 import six
+
+from test.debug_logger import debug_logger
 from swift.common import http_protocol, swob
 
 
@@ -129,13 +131,15 @@ class ProtocolTest(unittest.TestCase):
 
         # If we let the WSGI server close rfile/wfile then we can't access
         # their contents any more.
+        self.logger = debug_logger('proxy')
         with mock.patch.object(wfile, 'close', lambda: None), \
                 mock.patch.object(rfile, 'close', lambda: None):
-            eventlet.wsgi.server(
+            wsgi.server(
                 fake_listen_socket, app or self.app,
                 protocol=self.protocol_class,
                 custom_pool=FakePool(),
-                log_output=False,  # quiet the test run
+                log=self.logger,
+                log_output=True,
             )
         return wfile.getvalue()
 
@@ -229,9 +233,60 @@ class TestSwiftHttpProtocolSomeMore(ProtocolTest):
             b"\r\n"
         ))
         lines = [l for l in bytes_out.split(b"\r\n") if l]
+        info_lines = self.logger.get_lines_for_level('info')
         self.assertEqual(
             lines[0], b"HTTP/1.1 400 Bad request syntax ('ONLY-METHOD')")
         self.assertIn(b"Bad request syntax or unsupported method.", lines[-1])
+        self.assertIn(b"X-Trans-Id", lines[6])
+        self.assertIn(b"X-Openstack-Request-Id", lines[7])
+        self.assertIn("wsgi starting up", info_lines[0])
+        self.assertIn("ERROR WSGI: code 400", info_lines[1])
+        self.assertIn("txn:", info_lines[1])
+
+    def test_bad_request_server_logging(self):
+        with mock.patch('swift.common.http_protocol.generate_trans_id',
+                        return_value='test-trans-id'):
+            bytes_out = self._run_bytes_through_protocol(
+                b"ONLY-METHOD\r\n"
+                b"Server: example.com\r\n"
+                b"\r\n"
+            )
+        lines = [l for l in bytes_out.split(b"\r\n") if l]
+        self.assertEqual(
+            lines[0], b"HTTP/1.1 400 Bad request syntax ('ONLY-METHOD')")
+        self.assertIn(b"Bad request syntax or unsupported method.", lines[-1])
+        self.assertIn(b"X-Trans-Id: test-trans-id", lines[6])
+        self.assertIn(b"X-Openstack-Request-Id: test-trans-id", lines[7])
+        info_lines = self.logger.get_lines_for_level('info')
+        self.assertEqual(
+            "ERROR WSGI: code 400, message "
+            "Bad request syntax ('ONLY-METHOD'), (txn: test-trans-id)",
+            info_lines[1])
+
+    def test_bad_request_app_logging(self):
+        app_logger = debug_logger()
+        app = mock.MagicMock()
+        app.logger = app_logger
+        with mock.patch('swift.common.http_protocol.generate_trans_id',
+                        return_value='test-trans-id'):
+            bytes_out = self._run_bytes_through_protocol((
+                b"ONLY-METHOD\r\n"
+                b"Server: example.com\r\n"
+                b"\r\n"
+            ), app=app)
+        lines = [l for l in bytes_out.split(b"\r\n") if l]
+        self.assertEqual(
+            lines[0], b"HTTP/1.1 400 Bad request syntax ('ONLY-METHOD')")
+        self.assertIn(b"Bad request syntax or unsupported method.", lines[-1])
+        self.assertIn(b"X-Trans-Id: test-trans-id", lines[6])
+        self.assertIn(b"X-Openstack-Request-Id: test-trans-id", lines[7])
+        self.assertEqual(1, len(app_logger.records.get('ERROR', [])))
+        self.assertIn(
+            "ERROR WSGI: code 400, message Bad request syntax ('ONLY-METHOD') "
+            "(txn: test-trans-id)",
+            app_logger.records.get('ERROR')[0])
+        # but we can at least assert that the logger txn_id was set
+        self.assertEqual('test-trans-id', app_logger.txn_id)
 
     def test_leading_slashes(self):
         bytes_out = self._run_bytes_through_protocol((
@@ -379,15 +434,29 @@ class TestProxyProtocol(ProtocolTest):
         self.assertEqual(addr_lines, [b"https is on (scheme https)"] * 2)
 
     def test_missing_proxy_line(self):
-        bytes_out = self._run_bytes_through_protocol(
+        with mock.patch('swift.common.http_protocol.generate_trans_id',
-            # whoops, no PROXY line here
+                        return_value='test-bad-req-trans-id'):
-            b"GET /someurl HTTP/1.0\r\n"
+            bytes_out = self._run_bytes_through_protocol(
-            b"User-Agent: something or other\r\n"
+                # whoops, no PROXY line here
-            b"\r\n"
+                b"GET /someurl HTTP/1.0\r\n"
-        )
+                b"User-Agent: something or other\r\n"
+                b"\r\n"
+            )
 
         lines = [l for l in bytes_out.split(b"\r\n") if l]
-        self.assertIn(b"400 Invalid PROXY line", lines[0])
+        info_lines = self.logger.get_lines_for_level('info')
+
+        self.assertEqual(
+            lines[0],
+            b"HTTP/1.1 400 Invalid PROXY line 'GET /someurl HTTP/1.0\\r\\n'")
+        self.assertIn(b"X-Trans-Id: test-bad-req-trans-id", lines[6])
+        self.assertIn(b"X-Openstack-Request-Id: test-bad-req-trans-id",
+                      lines[7])
+        self.assertEqual(
+            "ERROR WSGI: code 400, message Invalid PROXY line "
+            "'GET /someurl HTTP/1.0\\r\\n', "
+            "(txn: test-bad-req-trans-id)",
+            info_lines[1])
 
     def test_malformed_proxy_lines(self):
         for bad_line in [b'PROXY jojo',
@@ -396,7 +465,12 @@ class TestProxyProtocol(ProtocolTest):
                          ]:
             bytes_out = self._run_bytes_through_protocol(bad_line)
             lines = [l for l in bytes_out.split(b"\r\n") if l]
+            info_lines = self.logger.get_lines_for_level('info')
             self.assertIn(b"400 Invalid PROXY line", lines[0])
+            self.assertIn(b"X-Trans-Id", lines[6])
+            self.assertIn(b"X-Openstack-Request-Id", lines[7])
+            self.assertIn("wsgi starting up", info_lines[0])
+            self.assertIn("txn:", info_lines[1])
 
     def test_unknown_client_addr(self):
         # For "UNKNOWN", the rest of the line before the CRLF may be omitted by