Skip to content

Bug: subprocess test client background logging can exhaust the PIPE buffer and begin failing silently #4573

@ftsartek

Description

@ftsartek

Description

At a certain state of unconsumed log output from a subprocess app (stderr/stdout go to the PIPE buffer) the client will begin to fail with no indication of why. Logging does not seem to trigger this, but anything printed within a handler (or for example the output of SQLAlchemy's echo parameter) can fill the pipe and result in silent failure. This might be a Linux kernel limitation and not applicable to other platforms (or they might have their own limits).

Using an abstracted subprocess test client with the output piped to DEVNULL (or in my extended testing, a file) resolves this issue.

As it stands, the log output isn't actually used (but it can be useful, which is another downfall of the subprocess client - when the app fails to start or encounters an error that is obfuscated by the lack of stdout/stderr feedback.

The MCVE uses litestar[standard] and pytest with the following pyproject:

[project]
name = "mcve"
version = "0.1.0"
description = "Litestar subprocess MCVE"
readme = "README.md"
requires-python = ">=3.13"
dependencies = [
    "litestar[standard,uvicorn]>=2.19.0",
    "pytest>=9.0.2",
]


[tool.pytest.ini_options]
anyio_mode = "auto"

A few suggested options to fix:

  1. Change the default output to subprocess.DEVNULL - the output doesn't get used anyway so this should be harmless.
  2. Provide an option to override the default output in run_app and by extension subprocess_async_client which allows the user to set an alternative to subprocess.PIPE. This has the added benefit, if it's a client-accessible buffer, of making the app output accessible to the client.
  3. Add a way to consume the proc buffers. Not sure there's a clean approach to doing this inline (and I don't think this adds anything over using DEVNULL anyway) but it might be possible to allow the user to consume them.

Happy to look at fixing this myself given some discussion over the approaches.

URL to code causing the issue

No response

MCVE

import time
import subprocess
from litestar.testing.client.subprocess_client import _get_available_port, StartupError
from contextlib import contextmanager, asynccontextmanager
import pathlib
import secrets
from collections.abc import AsyncIterator, Iterator

import httpx
import pytest

from litestar import Litestar, Request, get
from litestar.testing import subprocess_async_client


@get("/health")
async def health(request: Request) -> dict[str, str]:
    # Adjust this and the failure point will change
    print(secrets.token_hex(4096))
    return {"status": "ok"}

def get_app() -> Litestar:
    return Litestar(route_handlers=[health])


@pytest.fixture(scope="session", autouse=True)
def anyio_backend() -> str:
    return "asyncio"


@contextmanager
def run_devnull_app(workdir: pathlib.Path, app: str, retry_count: int = 100, retry_timeout: int = 1) -> Iterator[str]:
    """Launch a litestar application in a subprocess with a random available port.

    Args:
        workdir: Path to working directory where run command will be executed
        app: Path to Litestar application, e.g.: "my_app:application"
        retry_count: Number of retries to wait for the application to start
        retry_timeout: Timeout in seconds to wait between retries

    Raises:
        StartupError: If the application fails to start with given retry count and timeout
    """
    port = _get_available_port()
    with subprocess.Popen(
        args=["litestar", "--app", app, "run", "--port", str(port)],
        stderr=subprocess.DEVNULL,
        stdout=subprocess.DEVNULL,
        cwd=workdir,
    ) as proc:
        url = f"http://127.0.0.1:{port}"
        application_started = False

        for _ in range(retry_count):
            try:
                httpx.get(url, timeout=0.1)
                application_started = True
                break
            except httpx.TransportError:
                time.sleep(retry_timeout)

        if not application_started:
            proc.kill()
            raise StartupError("Application failed to start")

        yield url
        proc.kill()


@asynccontextmanager
async def subprocess_devnull_async_client(workdir: pathlib.Path, app: str) -> AsyncIterator[httpx.AsyncClient]:
    """Provides an async httpx client for a litestar app launched in a subprocess.

    Args:
        workdir: Path to the directory in which the app module resides.
        app: Uvicorn app string that can be resolved in the provided working directory, e.g.: "app:app"
    """
    with run_devnull_app(workdir=workdir, app=app) as url:
        async with httpx.AsyncClient(base_url=url) as client:
            yield client


class TestDevnull:
    @pytest.fixture(scope='session')
    async def devnull_client(self) -> AsyncIterator[httpx.AsyncClient]:
        async with subprocess_devnull_async_client(workdir=pathlib.Path(__file__).parent, app="test_deadlock:get_app") as c:
            yield c

    @pytest.mark.parametrize("i", range(10))
    async def test_devnull_health(self, devnull_client: httpx.AsyncClient, i: int) -> None:
        resp = await devnull_client.get("/health")
        assert resp.status_code == 200


class TestPipe:
    @pytest.fixture(scope='session')
    async def client(self) -> AsyncIterator[httpx.AsyncClient]:
        async with subprocess_async_client(workdir=pathlib.Path(__file__).parent, app="test_deadlock:get_app") as c:
            yield c


    @pytest.mark.parametrize("i", range(10))
    async def test_health(self, client: httpx.AsyncClient, i: int) -> None:
        resp = await client.get("/health")
        assert resp.status_code == 200

Steps to reproduce

  1. Set up a subprocess client
  2. Set up a test suite with print output (or with dependencies that output to stdout)
  3. Run the suite, it will at some stage lock up if you're filling the pipe enough.

Screenshots

No response

Logs


Litestar Version

2.19

Platform

  • Linux
  • Mac
  • Windows
  • Other (Please specify in the description above)

Metadata

Metadata

Assignees

No one assigned

    Labels

    Bug 🐛This is something that is not working as expected

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions