unfavorable logger name "uvicorn.error"

[doncatnip]

https://github.com/encode/uvicorn/blob/master/uvicorn/protocols/websockets/websockets_impl.py

Every time a new websocket request comes in something like this appears in the logs:

INFO  [uvicorn.error] ('127.0.0.1', 47014) - "WebSocket /api" [accepted]

This is slightly confusing since it is in fact not an error. What's the purpose of naming it uvicorn.error ? We noticed this when ossec kept triggering on every incoming request spamming us with false alarms.

There are other questionable occurences like

INFO  [uvicorn.error] Application startup complete.

Important

• We're using Polar.sh so you can upvote and help fund this issue.
• We receive the funding once the issue is completed & confirmed by you.
• Thank you in advance for helping prioritize & fund our backlog.

[tomchristie]

The intent was to follow gunicorn's "access" vs. "error" logs, although I'd agree.

Perhaps we could go with something more like "uvicorn.server", "uvicorn.http", "uvicorn.websockets" for internal messaging, and "uvicorn.access" for the HTTP access logs.

[doncatnip]

Ok, I see. Yes, I think 'error' just as 'warn' and 'info' should exclusively refer to the log level, not the category.

[ahadjhassine]

Same problem here. Please change if possible.

[florimondmanca]

Sounds sensible to me too! 👍

Please change if possible.

Speaking for myself here, but I don’t find such remarks very helpful. This is a volunteer-driven and collaborative project, so we shouldn’t put work expectations on others.

With that said, as always I’m sure maintainers would be very happy to review any PRs to help resolve this. :)

[M-e-r-c-u-r-y]

I've had similar confusing logs from uvicorn when using tortoise orm with fastapi.

WARNING:  Detected file change in 'main.py'. Reloading...
INFO:     Shutting down
INFO:uvicorn.error:Shutting down
INFO:     Waiting for application shutdown.
INFO:uvicorn.error:Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:uvicorn.error:Application shutdown complete.
INFO:     Finished server process [141]
INFO:uvicorn.error:Finished server process [141]
INFO:     Started server process [145]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:uvicorn.error:Application startup complete.

An error shown as INFO doesn't seem logical, an error saying application startup complete is even more confusing.

[rudicba]

I was confused too

[moezubair]

ah I thought I was doing something wrong, good to know others faced the same issue

[uricholiveira]

I've had similar confusing logs from uvicorn when using tortoise orm with fastapi.

WARNING:  Detected file change in 'main.py'. Reloading...
INFO:     Shutting down
INFO:uvicorn.error:Shutting down
INFO:     Waiting for application shutdown.
INFO:uvicorn.error:Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:uvicorn.error:Application shutdown complete.
INFO:     Finished server process [141]
INFO:uvicorn.error:Finished server process [141]
INFO:     Started server process [145]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:uvicorn.error:Application startup complete.

An error shown as INFO doesn't seem logical, an error saying application startup complete is even more confusing.

Any fix of it?

[mizhgun]

@uricholiveira 'uvicorn.error' is just the logger's name. The problem is root logger usage in tortoise orm's FastAPI integration though.

[SAIVENKATARAJU]

Hi,
even I am facing the same issue and could not able to launch the server.

INFO:     Waiting for application startup.
08/10/2021 13:06:08 - INFO - uvicorn.error -   Waiting for application startup.
INFO:     Application startup complete.
08/10/2021 13:06:08 - INFO - uvicorn.error -   Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
08/10/2021 13:06:08 - INFO - uvicorn.error -   Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)

app = FastAPI()

@app.post("/extractanswer/")
async def create_item(data:dict):
    # logging.info(request.form())
    # item_dict = item.dict()
    # logging.info(data)
   //some code
       

if __name__ == '__main__':
    uvicorn.run(app,host="0.0.0.0", port=8000)

Please help me with the issue

[laggardkernel]

That's not uvicorn's fault. Some other package or the questioner yourself configured the root logger. And message from logger uvicorn.error are propagated to the root logger, printed by handler on root logger again, with prefix INFO [uvicorn.error].