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].

[kennylajara]

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 handler again, with prefix INFO [uvicorn.error].

@laggardkernel I agree we should not use the root logger but, IMO, Uvicorn shouldn't repeat the log anyway just because we use the python logging function. Example: I am not using the root logger bu I still see Uvicorn's logs twice, one with my format and another one formated by Uvicorn.

[Kludex]

The original issue here is the logger's name, not the duplication. The latter is not a uvicorn issue.

[Kolumbs]

can someone explain again why you would want to have in uvicorn/config.py following line:

logger = logging.getLogger("uvicorn.error") # at the time of writing this comment line 113

So naming here uvicorn.error causes logging to propagate this name. This creates a bit visually not appealing messages if I format logger using %(name)s, as some messages logged by this logger are not explicitly error messages.

For example starting uvicorn with INFO loglevel:

INFO:uvicorn.error:Started server process [13314]
INFO:uvicorn.error:Waiting for application startup.
INFO:uvicorn.error:Application startup complete.
INFO:uvicorn.error:Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)

So why not just name it uvicorn or uvicorn.server instead

[Kludex]

The thumbs down above are just mean. If you think you've found an issue, and you want to be sure, create a discussion. We're going to do our best to help.

Anyway... After @euri10's comment on https://github.com/encode/uvicorn/pull/1489#issuecomment-1161955896 (I also agree with it), I'll be closing this issue.

I'll not lock the issue, if someone has good arguments, or a good strategy that can refute the mentioned comment, feel free to say it. Always open to hear what others have to say. ✌️

[Kludex]

Reopening this, as I want to think if we can have a solution that works for everybody.

[gruckion]

This is nuts.. it's been open since 2020 and we can't even get the name of the logger changed? What on earth...

[Kludex]

This is nuts.. it's been open since 2020 and we can't even get the name of the logger changed? What on earth...

Such a bad comment on a volunteer driven project. :man_facepalming:

I'm willing to review a PR for this. A start point can be what was already implemented on https://github.com/encode/uvicorn/pull/1489. The last comment on that PR specifies what is missing to get that done.

[lukehinds]

Hello,

I was curious if there was any solution to this yet?

I have the same issue:

2023-09-27 20:00:11,207 - uvicorn.error - INFO - Started server process [15858]
2023-09-27 20:00:11,207 - uvicorn.error - INFO - Waiting for application startup.
2023-09-27 20:00:11,207 - uvicorn.error - INFO - Application startup complete.

Would you be up for renaming this logger to just uvicorn:app or something of that ilk?

[epigramx]

The only problem I can imagine they have, is that old uses of this may have build operating-system tools around that naming, but it's up to the devs to decide.

[sabaimran]

I'm also experiencing this issue with my websocket connections. It's rather difficult to suppress those loglines too.