Having body causes duplicate log entries

[vrslev]

Take the example and run it with uvicorn:

from pydantic import BaseModel
from starlite import Starlite, post


class RouteData(BaseModel):
    id: str


@post()
def route(value: RouteData) -> None:
    pass


app = Starlite(route_handlers=[route])

You will notice that all log entries are duplicated:

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

If you change value type to string i. e. it would change to be query parameter:

@post()
def route(value: str) -> None:
    pass

then duplicate entires disappear:

INFO:     Started server process [75353]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)

[Goldziher]

That's not body, that's a query param of a type that can't be handled. If you change the key from value to data what happens?

The issue here is that the errors are swollen, no?

[peterschutt]

I've been looking too @Goldziher

I've repro'd with fresh environment and just starlite and uvicorn installed. Repro with:

import logging
from pydantic import BaseModel
from starlite import Starlite, post, Provide


class RouteData(BaseModel):
    id: str


@post(path="/")
def route(data: RouteData) -> RouteData:
    return data


app = Starlite(route_handlers=[route], openapi_config=None)

It happens even with the correct data kwarg. Seems to be comming from openapi generation. If you set openapi_config=None to app like I have in the script above it stops.

[peterschutt]

Seems to occur irrespective of handler method, e.g.,

from pydantic import BaseModel
from starlite import Starlite, get


class RouteData(BaseModel):
    id: str


@get()
def route(value: RouteData) -> RouteData:
    return value


app = Starlite(route_handlers=[route])

[vrslev]

@peterschutt

Seems to be comming from openapi generation

When I commented out all logging statements in openapi-schema-pydantic package it started working fine.

https://github.com/kuimono/openapi-schema-pydantic/search?q=logging

[peterschutt]

Ah OK, good spot @vrslev.

I've just had a look and they use the module level logging handlers like logging.info() rather than setting up a library scoped logger.

From logging docs:

This function (as well as info(), warning(), error() and critical()) will call basicConfig() if the root logger doesn’t have any handler attached.

By letting it call basicConfig() another handler gets added to root logger and hence the duplicated messages.

So if you configure a handler to the root logger before calling Starlite() then this would be avoidable I think, but you shouldn't have to. They should be instantiating named loggers for their lib and have a null handler attached to the root logger of their namespace so it doesn't affect downstream.

[peterschutt]

I opened kuimono/openapi-schema-pydantic#19

We may as well leave this open as a reminder to track that.

[peterschutt]

I've PR'd upstream for this so it is out of our hands now.