Logging Error #1899

lucaszhang99 · 2023-03-13T22:23:04Z

lucaszhang99
Mar 13, 2023

Hi guys, my uvicorn just started to complain this new logging error with no changes to code at all but restarted docker, any suggestions will be appreciated. The docker image is running on an oracle linux machine

--- Logging error ---
Traceback (most recent call last):
File "/usr/local/lib/python3.11/logging/init.py", line 1114, in emit
self.flush()
File "/usr/local/lib/python3.11/logging/init.py", line 1094, in flush
self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
File "/usr/local/bin/uvicorn", line 8, in
sys.exit(main())
File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1130, in call
return self.main(*args, **kwargs)
File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1055, in main
rv = self.invoke(ctx)
File "/usr/local/lib/python3.11/site-packages/click/core.py", line 1404, in invoke
return ctx.invoke(self.callback, **ctx.params)
File "/usr/local/lib/python3.11/site-packages/click/core.py", line 760, in invoke
return __callback(*args, **kwargs)
File "/usr/local/lib/python3.11/site-packages/uvicorn/main.py", line 403, in main
run(
File "/usr/local/lib/python3.11/site-packages/uvicorn/main.py", line 568, in run
server.run()
File "/usr/local/lib/python3.11/site-packages/uvicorn/server.py", line 59, in run
return asyncio.run(self.serve(sockets=sockets))
File "/usr/local/lib/python3.11/asyncio/runners.py", line 190, in run
return runner.run(main)
File "/usr/local/lib/python3.11/asyncio/runners.py", line 118, in run
return self._loop.run_until_complete(task)
File "/usr/local/lib/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 436, in run_asgi
result = await app( # type: ignore[func-returns-value]
File "/usr/local/lib/python3.11/site-packages/uvicorn/middleware/proxy_headers.py", line 78, in call
return await self.app(scope, receive, send)
File "/usr/local/lib/python3.11/site-packages/fastapi/applications.py", line 273, in call
await super().call(scope, receive, send)
File "/usr/local/lib/python3.11/site-packages/starlette/applications.py", line 122, in call
await self.middleware_stack(scope, receive, send)
File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 162, in call
await self.app(scope, receive, _send)
File "/usr/local/lib/python3.11/site-packages/starlette/middleware/exceptions.py", line 68, in call
await self.app(scope, receive, sender)
File "/usr/local/lib/python3.11/site-packages/fastapi/middleware/asyncexitstack.py", line 18, in call
await self.app(scope, receive, send)
File "/usr/local/lib/python3.11/site-packages/starlette/routing.py", line 718, in call
await route.handle(scope, receive, send)
File "/usr/local/lib/python3.11/site-packages/starlette/routing.py", line 276, in handle
await self.app(scope, receive, send)
File "/usr/local/lib/python3.11/site-packages/starlette/routing.py", line 69, in app
await response(scope, receive, send)
File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 164, in call
await send(
File "/usr/local/lib/python3.11/site-packages/starlette/middleware/exceptions.py", line 65, in sender
await send(message)
File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 159, in _send
await send(message)
File "/usr/local/lib/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 506, in send
self.access_logger.info(
Message: '%s - "%s %s HTTP/%s" %d

Kludex · 2023-03-13T22:46:46Z

Kludex
Mar 13, 2023
Maintainer Sponsor

How can I reproduce it?

5 replies

lucaszhang99 Mar 13, 2023
Author

I cannot really provide exact code, but the I am running docker compose with following command lines starting this container. That is the only change involving uvicorn.
command: bash -c "uvicorn app.main:app --host=0.0.0.0 --port=80 | service cron start"

lucaszhang99 Mar 13, 2023
Author

The code is accepting a large json bulb from local network and storing in database, I am using uvicorn's logger by
logger = logging.getLogger("uvicorn")
and i did not change the logger format, this logger error is being triggered when receive a request.
if self.access_log: self.access_logger.info( '%s - "%s %s HTTP/%s" %d', get_client_addr(self.scope), self.scope["method"], get_path_with_query_string(self.scope), self.scope["http_version"], status_code, )

Kludex Mar 13, 2023
Maintainer Sponsor

If you can create an MRE, I can try to help.

lucaszhang99 Mar 13, 2023
Author

@Kludex Thanks for the offering, i was able to reproduce the issue is caused by " | service cron start" in my dockercompose file, and i have been able to find some suggestions from https://stackoverflow.com/questions/9172046/broken-pipe-when-running-python-with-cron

nilfr May 1, 2024

@Kludex I am having the same issue.

#!/usr/bin/env python3
from fastapi import FastAPI, HTTPException, Request
from fastapi.responses import JSONResponse
from os import getenv
from http import HTTPStatus
from dotenv import load_dotenv
from datetime import datetime
from logging import Formatter
from uvicorn.config import LOGGING_CONFIG
import uvicorn
import json

class JsonFormatter(Formatter):
    def __init__(self):
        super(JsonFormatter, self).__init__()

    def format(self, record):
        json_record = {}
        json_record["timestamp"] = datetime.fromtimestamp(record.created).isoformat()
        json_record["level"] = record.levelname.lower()
        json_record["message"] = record.getMessage()
        return json.dumps(json_record)

log_config = LOGGING_CONFIG
log_config["formatters"] = {
    "default": {
        "()": JsonFormatter,
    },
    "access": {
        "()": JsonFormatter,
    }
}
log_config["handlers"]["default"] = {
    "formatter": "default",
    "class": "logging.StreamHandler",
    "stream": "ext://sys.stdout",
}

# Allow customization of log level and version.
VERSION = "dev"

load_dotenv()

port: str = getenv('PORT', "8080")
app: FastAPI = FastAPI()

@app.exception_handler(HTTPException)
async def http_exception_handler(request, exc: HTTPException) -> JSONResponse:
    return JSONResponse({
        "title": HTTPStatus(exc.status_code).phrase,
        "code": exc.status_code,
        "message": exc.detail,
    }, status_code=exc.status_code)

@app.get('/health', status_code=200)
async def read_health() -> JSONResponse:
    return JSONResponse({
        "title": HTTPStatus(HTTPStatus.OK).phrase,
        "code": HTTPStatus.OK,
        "message": "ServiceHealthy",
    })

@app.api_route("/{path_name:path}")
async def catch_all(request: Request, path_name: str) -> JSONResponse:
    raise HTTPException(status_code=404, detail="UnknownEndpoint")

def main() -> None:
    try:
        # Use `uvicorn` in production.
        config = uvicorn.Config("main:app",
            host="0.0.0.0",
            port=int(port),
            log_config=log_config,
            server_header=False,
        )
        server = uvicorn.Server(config)
        server.run()
    except KeyboardInterrupt:
        # Avoid stack traces when exiting with Ctrl+C.
        pass

if __name__ == '__main__':
    main()

If I run my application by itself usign ./main.py, I am able to avoid any stack traces when I hit CTRL + C:

$ ./main.py 
{"timestamp": "2024-05-01T10:45:16.348475", "level": "info", "message": "Started server process [27984]"}
{"timestamp": "2024-05-01T10:45:16.348587", "level": "info", "message": "Waiting for application startup."}
{"timestamp": "2024-05-01T10:45:16.348687", "level": "info", "message": "Application startup complete."}
{"timestamp": "2024-05-01T10:45:16.350186", "level": "info", "message": "Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)"}
^C{"timestamp": "2024-05-01T10:45:17.854568", "level": "info", "message": "Shutting down"}
{"timestamp": "2024-05-01T10:45:17.955023", "level": "info", "message": "Waiting for application shutdown."}
{"timestamp": "2024-05-01T10:45:17.955163", "level": "info", "message": "Application shutdown complete."}
{"timestamp": "2024-05-01T10:45:17.955197", "level": "info", "message": "Finished server process [27984]"}

But if I run my application as part of a pipe, e.g. ./main.py | tee app.log and I hit CTRL + C, it will always get the BrokenPipeError, even if I try to catch it using except.

$ ./main.py | tee app.log
{"timestamp": "2024-05-01T10:45:49.363184", "level": "info", "message": "Started server process [28510]"}
{"timestamp": "2024-05-01T10:45:49.363335", "level": "info", "message": "Waiting for application startup."}
{"timestamp": "2024-05-01T10:45:49.363477", "level": "info", "message": "Application startup complete."}
{"timestamp": "2024-05-01T10:45:49.364677", "level": "info", "message": "Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)"}
^C--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/__init__.py", line 1104, in emit
    self.flush()
  File "/usr/lib/python3.10/logging/__init__.py", line 1084, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/nilfr/repos/templates/python-api-fastapi/./main.py", line 83, in <module>
    main()
  File "/home/nilfr/repos/templates/python-api-fastapi/./main.py", line 77, in main
    server.run()
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 69, in serve
    await self._serve(sockets)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 88, in _serve
    await self.shutdown(sockets=sockets)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 258, in shutdown
    logger.info("Shutting down")
Message: 'Shutting down'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/__init__.py", line 1104, in emit
    self.flush()
  File "/usr/lib/python3.10/logging/__init__.py", line 1084, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/nilfr/repos/templates/python-api-fastapi/./main.py", line 83, in <module>
    main()
  File "/home/nilfr/repos/templates/python-api-fastapi/./main.py", line 77, in main
    server.run()
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 69, in serve
    await self._serve(sockets)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 88, in _serve
    await self.shutdown(sockets=sockets)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 290, in shutdown
    await self.lifespan.shutdown()
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/lifespan/on.py", line 67, in shutdown
    self.logger.info("Waiting for application shutdown.")
Message: 'Waiting for application shutdown.'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/__init__.py", line 1104, in emit
    self.flush()
  File "/usr/lib/python3.10/logging/__init__.py", line 1084, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/nilfr/repos/templates/python-api-fastapi/./main.py", line 83, in <module>
    main()
  File "/home/nilfr/repos/templates/python-api-fastapi/./main.py", line 77, in main
    server.run()
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 69, in serve
    await self._serve(sockets)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 88, in _serve
    await self.shutdown(sockets=sockets)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 290, in shutdown
    await self.lifespan.shutdown()
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/lifespan/on.py", line 76, in shutdown
    self.logger.info("Application shutdown complete.")
Message: 'Application shutdown complete.'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/__init__.py", line 1104, in emit
    self.flush()
  File "/usr/lib/python3.10/logging/__init__.py", line 1084, in flush
    self.stream.flush()
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/nilfr/repos/templates/python-api-fastapi/./main.py", line 83, in <module>
    main()
  File "/home/nilfr/repos/templates/python-api-fastapi/./main.py", line 77, in main
    server.run()
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 69, in serve
    await self._serve(sockets)
  File "/home/nilfr/repos/templates/python-api-fastapi/.venv/lib/python3.10/site-packages/uvicorn/server.py", line 92, in _serve
    logger.info(message, process_id, extra={"color_message": color_message})
Message: 'Finished server process [%d]'
Arguments: (28510,)
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
BrokenPipeError: [Errno 32] Broken pipe

When I change the stream to be ext://sys.stderr (the default, which I don't want) and then run the app using ./main.py 2>&1 | tee app.log it will not throw the error, but it will omit those last shutdown messages:

$ ./main.py 2>&1 | tee app.log
{"timestamp": "2024-05-01T10:46:56.453665", "level": "info", "message": "Started server process [29511]"}
{"timestamp": "2024-05-01T10:46:56.453772", "level": "info", "message": "Waiting for application startup."}
{"timestamp": "2024-05-01T10:46:56.453874", "level": "info", "message": "Application startup complete."}
{"timestamp": "2024-05-01T10:46:56.455072", "level": "info", "message": "Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)"}
^C

Should this be tracked as a bug? Maybe there should be an option to disable shutdown messages.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logging Error #1899

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 1 comment 5 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Logging Error #1899

lucaszhang99 Mar 13, 2023

Replies: 1 comment · 5 replies

Kludex Mar 13, 2023 Maintainer Sponsor

lucaszhang99 Mar 13, 2023 Author

lucaszhang99 Mar 13, 2023 Author

Kludex Mar 13, 2023 Maintainer Sponsor

lucaszhang99 Mar 13, 2023 Author

nilfr May 1, 2024

lucaszhang99
Mar 13, 2023

Replies: 1 comment 5 replies

Kludex
Mar 13, 2023
Maintainer Sponsor

lucaszhang99 Mar 13, 2023
Author

lucaszhang99 Mar 13, 2023
Author

Kludex Mar 13, 2023
Maintainer Sponsor

lucaszhang99 Mar 13, 2023
Author