Fix VIM REST API missing end_headers() causing empty responses

The VIM compute REST API error paths (404, 400, 204) call send_response() without end_headers(). In python3, response headers are only appended to an internal buffer; end_headers() is what flushes them to the socket. The dispatcher's done() method, which used to be the finaliser, was reduced to a no-op in [1]. The net effect is that zero bytes are written before the connection is closed: nova-api-proxy's httplib raises RemoteDisconnected, and eventlet synthesises an empty HTTP 500 for the client where nova itself would have returned a 404 with a JSON body. The same defect affects every handler path that omits an explicit end_headers(), including the delayed-response paths in _action_request_complete() that pass no headers, so the max-concurrent 503 and the ageout auto-accept 202 also send nothing. On the delayed path finish() early-returns and done() was the only remaining cleanup, so those requests have also been leaking sockets since [1]. Restore RestAPIRequestDispatcher.done() as the single point of response finalisation: - Override end_headers() and guard it with a new _headers_ended flag, so handlers that already call it explicitly are unaffected and a second call cannot append a stray CRLF into the body. - done() always calls end_headers(), and additionally calls _done() when the response was delayed, which is the only opportunity to release that socket. Also in the compute plugin, add the done() call that the invalid-URL early return was missing, and return nova-compatible JSON error bodies for 400 and 404 so that a client sees the same shape whether the action was intercepted by the proxy or passed through to nova: {"itemNotFound": {"code": 404, "message": "..."}} The 404 message text is aligned with nova's byte for byte, including its trailing period. Writing an error body puts a socket write on paths that previously wrote nothing, so the write is guarded against a client that has already disconnected; without the guard a dropped client would produce the kind of IOError traceback that [1] set out to remove. Relatedly, _action_request_complete() flushed the headers only when the relayed response carried headers of its own, and wrote the body afterwards. Now that done() flushes, a caller passing a body but no headers would have put that body on the wire ahead of the header block. The flush is now unconditional and precedes the body. No current caller passes a body without headers, but the ordering is no longer left to chance. Finally, WritableLogger.write() hardcoded a DEBUG call while __init__ accepted a level argument it never used, which hid the eventlet WSGI traceback behind the proxy's default INFO level. write() now logs at the configured level. Not changed: - Socket teardown on the non-delayed path stays in finish(). wfile must remain open until http.server's handle_one_request() has completed its own wfile.flush(), which is the constraint [1] was addressing; done() only adds the header flush there. - No safety-net end_headers() was added to finish(). done() is the load-bearing mechanism and every handler calls it. On the only path that could reach finish() with unflushed state - a request that matched no handler, so no status line was ever buffered - end_headers() would emit a bare CRLF, turning a clean zero-byte close into a malformed response. - The 204 path stays bodyless, as a 204 must not carry a body. - The HTTP/1.0 status line is unchanged. RestAPIServer assigns the handler's 'protocol' attribute while http.server reads 'protocol_version'; that mismatch has keep-alive implications and is a separate concern. - VIM instance lookup semantics are unchanged. A UUID absent from the VIM table still gets a 404 rather than being passed through to nova; making nova authoritative for unknown instances is a separate change. References: [1] bb99182 "Debian: Eliminate nfv IOError logs during api calls" [2] 1e475dc "Debian: Fix nova actions", which fixed only the relayed-response path [3] https://docs.python.org/3/library/http.server.html BaseHTTPRequestHandler.end_headers Test Plan: AIO-SX, stx-openstack applied: PASS - POST {"pause": {}} for an unknown server uuid through nova-api-proxy returns 404 with Content-Type application/json and a 111 byte itemNotFound body; before the change the same request returned 500 with Content-Length 0 and an empty body PASS - differential control: the same request with a "lock" action, which the proxy does not intercept and therefore routes to nova-api, returns a byte-identical response body PASS - raw socket to the VIM compute REST API port returns 227 bytes for the 404 path, 207 for the invalid-url 400, 187 for the no-action 400 and 64 for the bodyless 204; every one of those returned 0 bytes and a clean FIN before the change PASS - nova-api-proxy now logs the relayed response body for the intercepted request, which previously produced no log line at all SKIP** - max-concurrent 503 on the delayed-response path SKIP** - ageout auto-accept 202 on the delayed-response path SKIP** - pause/unpause of an existing instance Unit tests: PASS - tox -c nfv/tox.ini -e py39 -- test_nfvi_compute_rest_api (15 new tests, covering the 404, 400, 204 and invalid-url paths, the delayed 503 and 202 paths, relay of a nova response, end_headers() idempotency, that done() releases the socket only on the delayed path, that a client disconnect mid-response neither raises nor leaks the request, and that a relayed body never precedes the header block) Regression: PASS - GET on the VIM infrastructure REST API, a handler that already called end_headers(), returns the same 154 bytes with exactly one header terminator PASS - no dispatcher errors in nfv-vim.log after the change; the only tracebacks present are pre-existing and appear in equal numbers before it PASS - tox -e linters PASS - tox -c nfv/tox.ini -e pep8 PASS - tox -c nfv/tox.ini -e pylint (10.00/10) PASS - tox -c nfv/tox.ini -e black PASS - tox -c nfv/tox.ini -e py39 (511 tests, 510 passed, 1 pre-existing skip) PASS - tox -c nfv/tox.ini -e cover PASS - tox -c nova-api-proxy/tox.ini -e pep8 PASS - tox -c nova-api-proxy/tox.ini -e pylint (10.00/10) PASS - tox -c nova-api-proxy/tox.ini -e black ** The delayed-response paths require the instance to be present in the VIM instance table, and pause/unpause requires a running instance. The test system had no working nova-compute, so these three items were exercised by the new unit tests only. Closes-Bug: 2163671 Change-Id: I6e070ed1c33bb88349ee4501679c7ea1b3690b90 Signed-off-by: Reese Norris <reese.norris@windriver.com>
2026-08-18 13:55:17 -04:00
1 parent e4df194656
commit 69f526fe35
@@ -26,6 +26,43 @@ from nfv_vim.nfvi.objects import v1 as nfvi_objs

 DLOG = debug.debug_get_logger("nfv_plugins.nfvi_plugins.compute_api")

+# The nova api names its error bodies after the http status code, see
+# nova.api.openstack.wsgi.Fault._fault_names. Only the codes that this
+# plugin can produce are listed here.
+NOVA_FAULT_NAMES = {
+    httplib.BAD_REQUEST: "badRequest",
+    httplib.NOT_FOUND: "itemNotFound",
+}
+
+
+def nova_error_body(http_status_code, message):
+    """Build a nova compatible JSON error response body, encoded as bytes."""
+
+    fault_name = NOVA_FAULT_NAMES.get(http_status_code, "computeFault")
+    body = {fault_name: {"code": http_status_code, "message": message}}
+    return json.dumps(body).encode()
+
+
+def send_error_response(request_dispatch, http_status_code, message):
+    """Send a nova compatible JSON error response and finish the request."""
+
+    http_body = nova_error_body(http_status_code, message)
+    # The reason phrase is left at the standard one for the status code, as
+    # nova does; the detail belongs in the response body.
+    request_dispatch.send_response(http_status_code)
+    request_dispatch.send_header("Content-Type", "application/json")
+    request_dispatch.send_header("Content-Length", str(len(http_body)))
+    try:
+        request_dispatch.end_headers()
+        request_dispatch.wfile.write(http_body)
+    except socket.error as e:
+        # The client can disconnect while waiting for the response.
+        DLOG.error("Send response for %s failed, error=%s" % (request_dispatch.path, e))
+
+    # Called even if the send failed, as the delayed path releases the socket
+    # from here.
+    request_dispatch.done()
+

 def hypervisor_get_admin_state(status):
    """Convert the nfvi hypervisor status to a hypervisor administrative state."""
@@ -842,7 +879,9 @@ class NFVIComputeAPI(nfvi.api.v1.NFVIComputeAPI):
                        for key, value in http_headers:
                            if "Server" != key and "Date" != key:
                                request_dispatch.send_header(key, value)
-                        request_dispatch.end_headers()
+                    # Flush the headers before any body is written, whether or
+                    # not the relayed response carried headers of its own.
+                    request_dispatch.end_headers()
                    if http_body is not None:
                        if hasattr(http_body, "encode"):
                            http_body = http_body.encode()
@@ -3565,7 +3604,11 @@ class NFVIComputeAPI(nfvi.api.v1.NFVIComputeAPI):
        content = request_dispatch.rfile.read(content_len)
        if "action" != request_dispatch.path.split("/")[-1]:
            DLOG.error("Invalid url %s received" % request_dispatch.path)
-            request_dispatch.send_response(httplib.BAD_REQUEST)
+            send_error_response(
+                request_dispatch,
+                httplib.BAD_REQUEST,
+                "Invalid url, expecting a server action request",
+            )
            return

        path_items = request_dispatch.path.split("/")
@@ -3620,9 +3663,10 @@ class NFVIComputeAPI(nfvi.api.v1.NFVIComputeAPI):
                        DLOG.error(
                            "Callback failed for instance_uuid=%s." % instance_uuid
                        )
-                        err_msg = "Instance %s could not be found" % instance_uuid
+                        err_msg = "Instance %s could not be found." % instance_uuid
                        http_response = httplib.NOT_FOUND
            else:
+                err_msg = "No server action specified"
                http_response = httplib.BAD_REQUEST
        else:
            http_response = httplib.NO_CONTENT
@@ -3639,8 +3683,15 @@ class NFVIComputeAPI(nfvi.api.v1.NFVIComputeAPI):
                request_dispatch.response_delayed()
                self._ageout_action_requests()
        else:
-            request_dispatch.send_response(http_response, message=err_msg)
-            request_dispatch.done()
+            if httplib.NO_CONTENT == http_response:
+                # A 204 response must not carry a message body. done()
+                # flushes the buffered headers, so no explicit
+                # end_headers() is needed here, unlike the error paths
+                # that go through send_error_response().
+                request_dispatch.send_response(http_response)
+                request_dispatch.done()
+            else:
+                send_error_response(request_dispatch, http_response, err_msg)
            self._request_times.pop()
            del self._requests[request_uuid]

@@ -41,6 +41,7 @@ class RestAPIRequestDispatcher(BaseHTTPServer.BaseHTTPRequestHandler):
    def __init__(self, request, client_address, server):
        self._is_shutdown = False
        self._response_delayed = False
+        self._headers_ended = False

        # Call old-style class __init__
        BaseHTTPServer.BaseHTTPRequestHandler.__init__(
@@ -59,6 +60,13 @@ class RestAPIRequestDispatcher(BaseHTTPServer.BaseHTTPRequestHandler):
            if "server" != keyword.lower():
                BaseHTTPServer.BaseHTTPRequestHandler.send_header(self, keyword, value)

+    def end_headers(self):
+        """Override end_headers so that it can safely be called more than once."""
+
+        if not self._is_shutdown and not self._headers_ended:
+            self._headers_ended = True
+            BaseHTTPServer.BaseHTTPRequestHandler.end_headers(self)
+
    def send_response(self, code, message=None):
        """Override send_response."""

@@ -78,8 +86,22 @@ class RestAPIRequestDispatcher(BaseHTTPServer.BaseHTTPRequestHandler):
        DLOG.error(format, *args)

    def done(self):
-        # todo:abailey  Remove the calls to 'done' in the plugins
-        DLOG.debug("Deprecated: 'done' method no longer supported")
+        """Finalize the response.
+
+        Flushes the buffered headers to the socket, and on the delayed
+        response path also releases the socket, since finish() has already
+        returned without doing so.
+        """
+
+        if not self._is_shutdown:
+            # In python3 send_response and send_header only buffer the
+            # headers, end_headers is what writes them to the socket.
+            self.end_headers()
+
+            if self._response_delayed:
+                # finish has already returned without cleaning up, so this
+                # is the only remaining opportunity to release the socket.
+                self._done()

    def _done(self):
        """Finished with processing the request."""
@@ -0,0 +1,440 @@
+#
+# Copyright (c) 2026 Wind River Systems, Inc.
+#
+# SPDX-License-Identifier: Apache-2.0
+#
+import http.client as httplib
+import json
+import sys
+from unittest import mock
+
+from nfv_common import timers
+from nfv_unit_tests.tests import testcase
+
+sys.modules["fm_core"] = mock.Mock()
+
+# pylint: disable-next=C0413
+from nfv_plugins.nfvi_plugins.nfvi_compute_api import (  # noqa: H306,E402
+    NFVIComputeAPI,
+)
+
+# pylint: disable-next=C0413
+from nfv_plugins.nfvi_plugins.openstack.rest_api import (  # noqa: H306,E402
+    RestAPIRequestDispatcher,
+)
+
+INSTANCE_UUID = "deadbeef-dead-beef-dead-beefdeadbeef"
+TENANT_UUID = "11111111111111111111111111111111"
+ACTION_PATH = "/v2.1/%s/servers/%s/action" % (TENANT_UUID, INSTANCE_UUID)
+
+# The status line is emitted as HTTP/1.0 because RestAPIServer assigns the
+# handler's 'protocol' attribute while http.server reads 'protocol_version'.
+# That pre-existing mismatch is out of scope here, so the tests assert the
+# version that is actually produced.
+HTTP_VERSION = "HTTP/1.0"
+
+
+class FakeSocketFile:
+    """A wfile/rfile stand-in that retains everything written to it.
+
+    io.BytesIO discards its buffer on close, and the delayed-response path
+    closes wfile, so the bytes on the wire have to be recorded separately.
+    """
+
+    def __init__(self, data=b"", raise_on_write=False):
+        self.data = data
+        self.written = b""
+        self.closed = False
+        self.raise_on_write = raise_on_write
+
+    def read(self, amount=None):
+        if amount is None:
+            amount = len(self.data)
+        result = self.data[:amount]
+        self.data = self.data[amount:]
+        return result
+
+    def write(self, data):
+        if self.raise_on_write:
+            raise BrokenPipeError("connection reset by peer")
+        self.written += data
+        return len(data)
+
+    def writelines(self, lines):
+        for line in lines:
+            self.write(line)
+
+    def flush(self):
+        pass
+
+    def close(self):
+        self.closed = True
+
+
+def make_dispatcher(path=ACTION_PATH, body=b""):
+    """Build a dispatcher without running the socket-bound lifecycle.
+
+    BaseHTTPRequestHandler.__init__ reads and dispatches a request as a side
+    effect of construction, so the object is built directly and given only
+    the attributes the response path touches.
+    """
+    dispatcher = object.__new__(RestAPIRequestDispatcher)
+    dispatcher._is_shutdown = False
+    dispatcher._response_delayed = False
+    dispatcher._headers_ended = False
+    dispatcher.path = path
+    dispatcher.command = "POST"
+    dispatcher.request_version = "HTTP/1.1"
+    dispatcher.requestline = "POST %s HTTP/1.1" % path
+    dispatcher.client_address = ("127.0.0.1", 45678)
+    dispatcher.headers = {"content-length": str(len(body))}
+    dispatcher.rfile = FakeSocketFile(body)
+    dispatcher.wfile = FakeSocketFile()
+    dispatcher.request = mock.Mock()
+    return dispatcher
+
+
+class TestNFVIComputeRestAPI(testcase.NFVTestCase):
+    """Verify that the compute rest-api error paths put bytes on the wire."""
+
+    def setUp(self):
+        super().setUp()
+        # send_response logs the request line to stderr via log_message.
+        patcher = mock.patch.object(RestAPIRequestDispatcher, "log_request")
+        patcher.start()
+        self.addCleanup(patcher.stop)
+        self.plugin_api = NFVIComputeAPI()
+
+    @staticmethod
+    def status_line(http_status_code):
+        """Build the status line the dispatcher is expected to emit."""
+
+        return (
+            "%s %d %s\r\n"
+            % (HTTP_VERSION, http_status_code, httplib.responses[http_status_code])
+        ).encode()
+
+    def assert_single_header_terminator(self, dispatcher):
+        """Assert the header block was terminated exactly once."""
+
+        self.assertEqual(1, dispatcher.wfile.written.count(b"\r\n\r\n"))
+
+    def assert_json_error_body(self, dispatcher, fault_name, http_status_code, message):
+        """Assert a nova compatible JSON error body was written."""
+
+        header_block, _, http_body = dispatcher.wfile.written.partition(b"\r\n\r\n")
+        self.assertIn(b"Content-Type: application/json", header_block)
+        self.assertIn(
+            ("Content-Length: %d" % len(http_body)).encode(),
+            header_block,
+        )
+        self.assertEqual(
+            {fault_name: {"code": http_status_code, "message": message}},
+            json.loads(http_body),
+        )
+
+    # -----------------------------------------------------------------------
+    # Non-delayed error paths.
+    # -----------------------------------------------------------------------
+
+    def test_instance_action_not_found_writes_response(self):
+        """A 404 for an unknown instance reaches the wire with a json body."""
+
+        self.plugin_api.register_instance_action_callback(
+            lambda instance_uuid, action_data: False
+        )
+        dispatcher = make_dispatcher(body=b'{"pause": {}}')
+
+        self.plugin_api.instance_action_rest_api_post_handler(dispatcher)
+
+        err_msg = "Instance %s could not be found." % INSTANCE_UUID
+        self.assertTrue(
+            dispatcher.wfile.written.startswith(self.status_line(httplib.NOT_FOUND))
+        )
+        self.assert_single_header_terminator(dispatcher)
+        self.assert_json_error_body(
+            dispatcher, "itemNotFound", httplib.NOT_FOUND, err_msg
+        )
+        # The bookkeeping is released and the socket teardown is left to
+        # finish(), which the caller of the handler has not reached yet.
+        self.assertEqual({}, self.plugin_api._requests)
+        self.assertEqual(0, len(self.plugin_api._request_times))
+        self.assertFalse(dispatcher.wfile.closed)
+
+    def test_instance_action_no_action_writes_response(self):
+        """A body carrying no action produces a 400 on the wire."""
+
+        dispatcher = make_dispatcher(body=b"{}")
+
+        self.plugin_api.instance_action_rest_api_post_handler(dispatcher)
+
+        err_msg = "No server action specified"
+        self.assertTrue(
+            dispatcher.wfile.written.startswith(self.status_line(httplib.BAD_REQUEST))
+        )
+        self.assert_single_header_terminator(dispatcher)
+        self.assert_json_error_body(
+            dispatcher, "badRequest", httplib.BAD_REQUEST, err_msg
+        )
+
+    def test_instance_action_empty_body_writes_response(self):
+        """An empty request body produces a bodyless 204 on the wire."""
+
+        dispatcher = make_dispatcher(body=b"")
+
+        self.plugin_api.instance_action_rest_api_post_handler(dispatcher)
+
+        self.assertTrue(
+            dispatcher.wfile.written.startswith(self.status_line(httplib.NO_CONTENT))
+        )
+        self.assert_single_header_terminator(dispatcher)
+        # A 204 must not carry a message body.
+        self.assertTrue(dispatcher.wfile.written.endswith(b"\r\n\r\n"))
+        self.assertNotIn(b"Content-Type", dispatcher.wfile.written)
+
+    def test_instance_action_invalid_url_writes_response(self):
+        """The invalid-url early return produces a 400 on the wire."""
+
+        dispatcher = make_dispatcher(
+            path="/v2.1/%s/servers/%s" % (TENANT_UUID, INSTANCE_UUID),
+            body=b'{"pause": {}}',
+        )
+
+        self.plugin_api.instance_action_rest_api_post_handler(dispatcher)
+
+        err_msg = "Invalid url, expecting a server action request"
+        self.assertTrue(
+            dispatcher.wfile.written.startswith(self.status_line(httplib.BAD_REQUEST))
+        )
+        self.assert_single_header_terminator(dispatcher)
+        self.assert_json_error_body(
+            dispatcher, "badRequest", httplib.BAD_REQUEST, err_msg
+        )
+        # The early return happens before any request bookkeeping.
+        self.assertEqual({}, self.plugin_api._requests)
+
+    def test_instance_action_client_disconnect_is_not_fatal(self):
+        """A client that disconnects mid-response does not raise."""
+
+        self.plugin_api.register_instance_action_callback(
+            lambda instance_uuid, action_data: False
+        )
+        dispatcher = make_dispatcher(body=b'{"pause": {}}')
+        dispatcher.wfile = FakeSocketFile(raise_on_write=True)
+
+        # The write failure is logged and swallowed rather than escaping into
+        # http.server, which would log a traceback for every dropped client.
+        self.plugin_api.instance_action_rest_api_post_handler(dispatcher)
+
+        self.assertEqual(b"", dispatcher.wfile.written)
+        # The bookkeeping is still released, so the request does not leak.
+        self.assertEqual({}, self.plugin_api._requests)
+        self.assertEqual(0, len(self.plugin_api._request_times))
+
+    # -----------------------------------------------------------------------
+    # Delayed-response paths. These cannot be driven from a live system
+    # unless an instance is known to the vim, so they are only covered here.
+    # -----------------------------------------------------------------------
+
+    def _register_delayed_request(self, request_uuid, age_in_ms=0):
+        """Register a request that is awaiting a delayed response."""
+
+        dispatcher = make_dispatcher(body=b'{"pause": {}}')
+        dispatcher.response_delayed()
+        self.plugin_api._requests[request_uuid] = dispatcher
+        self.plugin_api._request_times.append(
+            (request_uuid, timers.get_monotonic_timestamp_in_ms() - age_in_ms)
+        )
+        return dispatcher
+
+    def test_max_concurrent_requests_writes_response(self):
+        """The max-concurrent 503 reaches the wire and releases the socket."""
+
+        dispatcher = self._register_delayed_request("request-503")
+        self.plugin_api._max_concurrent_action_requests = 0
+
+        self.plugin_api._ageout_action_requests()
+
+        self.assertTrue(
+            dispatcher.wfile.written.startswith(
+                self.status_line(httplib.SERVICE_UNAVAILABLE)
+            )
+        )
+        self.assert_single_header_terminator(dispatcher)
+        self.assertEqual({}, self.plugin_api._requests)
+        # On the delayed path finish() has already returned without cleaning
+        # up, so done() has to release the socket itself.
+        self.assertTrue(dispatcher.wfile.closed)
+        self.assertTrue(dispatcher._is_shutdown)
+
+    def test_ageout_auto_accept_writes_response(self):
+        """The ageout 202 reaches the wire and releases the socket."""
+
+        wait_in_ms = self.plugin_api._max_action_request_wait_in_secs * 1000
+        dispatcher = self._register_delayed_request(
+            "request-202", age_in_ms=wait_in_ms + 1000
+        )
+
+        self.plugin_api._ageout_action_requests()
+
+        self.assertTrue(
+            dispatcher.wfile.written.startswith(self.status_line(httplib.ACCEPTED))
+        )
+        self.assert_single_header_terminator(dispatcher)
+        self.assertEqual({}, self.plugin_api._requests)
+        self.assertTrue(dispatcher.wfile.closed)
+        self.assertTrue(dispatcher._is_shutdown)
+
+    def test_action_request_complete_relays_nova_response(self):
+        """A relayed nova response is not corrupted by the added end_headers."""
+
+        dispatcher = self._register_delayed_request("request-200")
+        http_body = b'{"server": {}}'
+
+        self.plugin_api._action_request_complete(
+            "request-200",
+            httplib.OK,
+            http_headers=[
+                ("Server", "suppressed"),
+                ("Date", "suppressed"),
+                ("Content-Type", "application/json"),
+                ("Content-Length", str(len(http_body))),
+            ],
+            http_body=http_body,
+        )
+
+        header_block, _, written_body = dispatcher.wfile.written.partition(b"\r\n\r\n")
+        self.assert_single_header_terminator(dispatcher)
+        self.assertEqual(http_body, written_body)
+        self.assertIn(b"Content-Type: application/json", header_block)
+        self.assertNotIn(b"Server: suppressed", header_block)
+        self.assertTrue(dispatcher.wfile.closed)
+
+    def test_action_request_complete_writes_headers_before_body(self):
+        """A body is never written ahead of the header block.
+
+        A relayed response can carry a body without headers, and the header
+        flush moved into done(), so the flush has to happen before the body
+        rather than after it.
+        """
+
+        dispatcher = self._register_delayed_request("request-500")
+        http_body = b'{"computeFault": {}}'
+
+        self.plugin_api._action_request_complete(
+            "request-500",
+            httplib.INTERNAL_SERVER_ERROR,
+            http_headers=None,
+            http_body=http_body,
+        )
+
+        header_block, _, written_body = dispatcher.wfile.written.partition(b"\r\n\r\n")
+        self.assert_single_header_terminator(dispatcher)
+        self.assertTrue(
+            header_block.startswith(
+                self.status_line(httplib.INTERNAL_SERVER_ERROR).rstrip(b"\r\n")
+            )
+        )
+        self.assertEqual(http_body, written_body)
+
+
+class TestRestAPIRequestDispatcher(testcase.NFVTestCase):
+    """Verify the dispatcher-level response finalisation."""
+
+    def setUp(self):
+        super().setUp()
+        patcher = mock.patch.object(RestAPIRequestDispatcher, "log_request")
+        patcher.start()
+        self.addCleanup(patcher.stop)
+
+    def test_done_flushes_buffered_headers(self):
+        """done() writes the headers that send_response only buffered."""
+
+        dispatcher = make_dispatcher()
+        dispatcher.send_response(httplib.NOT_FOUND)
+        # In python3 send_response only appends to the header buffer.
+        self.assertEqual(b"", dispatcher.wfile.written)
+
+        dispatcher.done()
+
+        self.assertTrue(dispatcher.wfile.written.startswith(b"HTTP/1.0 404 "))
+        self.assertTrue(dispatcher.wfile.written.endswith(b"\r\n\r\n"))
+
+    def test_done_does_not_close_socket_when_not_delayed(self):
+        """done() leaves the socket to finish() on the non-delayed path."""
+
+        dispatcher = make_dispatcher()
+        dispatcher.send_response(httplib.NOT_FOUND)
+
+        dispatcher.done()
+
+        self.assertFalse(dispatcher.wfile.closed)
+        self.assertFalse(dispatcher._is_shutdown)
+        dispatcher.request.shutdown.assert_not_called()
+
+        # finish() is what tears the socket down, once http.server is done
+        # with wfile.
+        dispatcher.finish()
+
+        self.assertTrue(dispatcher.wfile.closed)
+        self.assertTrue(dispatcher._is_shutdown)
+
+    def test_done_closes_socket_when_delayed(self):
+        """done() releases the socket on the delayed path, where finish() will not."""
+
+        dispatcher = make_dispatcher()
+        dispatcher.response_delayed()
+        dispatcher.send_response(httplib.SERVICE_UNAVAILABLE)
+
+        dispatcher.done()
+
+        self.assertTrue(dispatcher.wfile.written.startswith(b"HTTP/1.0 503 "))
+        self.assertTrue(dispatcher.wfile.closed)
+        self.assertTrue(dispatcher._is_shutdown)
+
+        # finish() early-returns on this path and must not double up.
+        dispatcher.finish()
+
+        self.assertEqual(1, dispatcher.request.shutdown.call_count)
+
+    def test_end_headers_is_idempotent(self):
+        """An explicit end_headers() followed by done() does not corrupt the body."""
+
+        dispatcher = make_dispatcher()
+        http_body = b'{"itemNotFound": {}}'
+        dispatcher.send_response(httplib.NOT_FOUND)
+        dispatcher.send_header("Content-Type", "application/json")
+        dispatcher.send_header("Content-Length", str(len(http_body)))
+        dispatcher.end_headers()
+        dispatcher.wfile.write(http_body)
+
+        dispatcher.done()
+
+        self.assertEqual(1, dispatcher.wfile.written.count(b"\r\n\r\n"))
+        self.assertTrue(dispatcher.wfile.written.endswith(http_body))
+
+    def test_end_headers_after_shutdown_writes_nothing(self):
+        """end_headers() is inert once the socket has been released."""
+
+        dispatcher = make_dispatcher()
+        dispatcher.response_delayed()
+        dispatcher.send_response(httplib.ACCEPTED)
+        dispatcher.done()
+        written = dispatcher.wfile.written
+
+        dispatcher.end_headers()
+        dispatcher.done()
+
+        self.assertEqual(written, dispatcher.wfile.written)
+
+    def test_send_header_suppresses_server_header(self):
+        """The Server header is still suppressed through the new flush path."""
+
+        dispatcher = make_dispatcher()
+        dispatcher.send_response(httplib.OK)
+        dispatcher.send_header("Server", "should-not-appear")
+
+        dispatcher.done()
+
+        self.assertNotIn(b"should-not-appear", dispatcher.wfile.written)
+        self.assertIn(b"Date: ", dispatcher.wfile.written)
@@ -93,7 +93,7 @@ class WritableLogger:
        self.level = level

    def write(self, msg):
-        self.logger.debug(msg.rstrip())
+        self.logger.log(self.level, msg.rstrip())


 class Server: