Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Change logging to structlog #46

Merged
merged 7 commits into from
May 9, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 5 additions & 4 deletions docs/controllers.md
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,9 @@ be the first two parameters.
from asgikit.requests import Request, read_json
from asgikit.responses import respond_text, respond_redirect
from selva.web import controller, get, post
from loguru import logger
import structlog

logger = structlog.get_logger()


@controller
Expand All @@ -28,7 +30,7 @@ class IndexController:
class AdminController:
@post("send")
async def handle_data(self, request: Request):
logger.info(await read_json(request))
logger.info("request body", content=str(await read_json(request)))
await respond_redirect(request.response, "/")
```

Expand All @@ -41,8 +43,7 @@ handler with the annotation `FromPath`:

```python
from typing import Annotated
from selva.web.converter import FromPath
from selva.web.routing.decorator import get
from selva.web import get, FromPath


@get("/:path_param")
Expand Down
76 changes: 45 additions & 31 deletions docs/logging.md
Original file line number Diff line number Diff line change
@@ -1,54 +1,57 @@
# Logging

Selva uses [loguru](https://pypi.org/project/loguru/) for logging, but provides
Selva uses [Structlog](https://www.structlog.org) for logging and provides
some facilities on top of it to make its usage a bit closer to other frameworks
like Spring Boot.

First, an interceptor to the standard `logging` module is configured by default,
as suggested in <https://github.com/Delgan/loguru#entirely-compatible-with-standard-logging>.
It is integrated with the standard library logging, so libraries that use it are logged
through Structlog. It also enables filtering by logger name using the standard library.

Second, a custom logging filter is provided in order to set the logging level for
each package independently.
## Why?

## Configuring logging
Nowadays, it is very likely that your application is deployed to a cloud and its
logs are sent to an aggregator like Graylog, so a structured logging format seems
to be the logical choice.

For more information on why use structured logging, refer to the
[Structlog documentation](https://www.structlog.org/en/stable/why.html).

## Configure logging

Logging is configured in the Selva configuration:

```yaml
logging:
root: WARNING
level:
root: WARNING # (1)
level: # (2)
application: INFO
application.service: TRACE
sqlalchemy: DEBUG
enable:
- packages_to_activate_logging
disabled:
- packages_to_deactivate_logging
selva: DEBUG
format: json # (3)
setup: selva.logging.setup # (4)
```

The `root` property is the *root* level. It is used if no other level is set for the
package where the log comes from.
1. Log level of the root logger.
2. Mapping of logger names to log level.
3. Log format. Possible values are `"json"`, `"logfmt"`, `"keyvalue""` and `"console"`.
4. Setup function to configure logging.

The `level` property defines the logging level for each package independently.
The `format` config defines which renderer will be used. The possible values map to:

The `enable` and `disable` properties lists the packages to enable or disable logging.
This comes from loguru, as can be seen in <https://github.com/Delgan/loguru#suitable-for-scripts-and-libraries>.
| value | renderer |
|----------|----------------------------------------------------------|
| `json` | `structlog.processors.JSONRenderer()` |
| `logfmt` | `structlog.processors.LogfmtRenderer(bool_as_flag=True)` |
| `keyvalue` | `structlog.processors.KeyValueRenderer()` |
| `console` | `structlog.dev.ConsoleRenderer()` |

## Manual logger setup
If not defined, `format` defaults to `"json"` if `sys.stderr.isatty() == False`,
or `"console"` otherwise. This is done to use the `ConsoleRenderer` during development
and the `JSONRenderer` when deploying to production.

If you want full control of how loguru is configured, you can provide a logger setup
function and reference it in the configuration file:
## Manual logger setup

=== "application/logging.py"

```python
from loguru import logger


def setup(settings):
logger.configure(...)
```
If you need full control of how Structlog is configured, you can provide a logger setup
function. You just need to reference it in the configuration file:

=== "configuration/settings.yaml"

Expand All @@ -57,5 +60,16 @@ function and reference it in the configuration file:
setup: application.logging.setup
```

=== "application/logging.py"

```python
import structlog
from selva.configuration import Settings


def setup(settings: Settings):
structlog.configure(...)
```

The setup function receives a parameter of type `selva.configuration.Settings`,
so you can have access to the whole settings.
6 changes: 4 additions & 2 deletions docs/middleware.md
Original file line number Diff line number Diff line change
Expand Up @@ -30,9 +30,11 @@ in the processing of the request:
from datetime import datetime

from asgikit.requests import Request
import structlog
from selva.di import service
from selva.web.middleware import Middleware, CallNext
from loguru import logger

logger = structlog.get_logger()


@service
Expand All @@ -43,7 +45,7 @@ in the processing of the request:
request_end = datetime.now()

delta = request_end - request_start
logger.info("Request time: {}", delta)
logger.info("request duration", duration=str(delta))
```

1. Invoke the middleware chain to process the request
Expand Down
4 changes: 3 additions & 1 deletion examples/background_tasks/application.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,10 +2,12 @@

from asgikit.requests import Request
from asgikit.responses import respond_json
from loguru import logger
import structlog

from selva.web import controller, get

logger = structlog.get_logger()


@controller
class Controller:
Expand Down
9 changes: 0 additions & 9 deletions examples/database/application/__init__.py
Original file line number Diff line number Diff line change
@@ -1,9 +0,0 @@
import sys

from loguru import logger

logger.remove()
logger.enable("selva")
logger.disable("databases")
logger.disable("aiosqlite")
logger.add(sys.stderr, level="DEBUG")
14 changes: 8 additions & 6 deletions examples/database/application/service.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,21 +2,23 @@
from typing import Annotated

from databases import Database
from loguru import logger
import structlog

from selva.configuration import Settings
from selva.di import Inject, service

logger = structlog.get_logger()


@service
def database_factory(settings: Settings) -> Database:
database = Database(settings.database.url)
logger.info("Sqlite database created")
logger.info("sqlite database created")

yield database

os.unlink(database.url.database)
logger.info("Sqlite database destroyed")
logger.info("sqlite database destroyed")


@service
Expand All @@ -25,7 +27,7 @@ class Repository:

async def initialize(self):
await self.database.connect()
logger.info("Sqlite database connection opened")
logger.info("sqlite database connection opened")

await self.database.execute(
"create table if not exists counter(value int not null)"
Expand All @@ -34,13 +36,13 @@ async def initialize(self):

async def finalize(self):
await self.database.disconnect()
logger.info("Sqlite database connection closed")
logger.info("sqlite database connection closed")

async def test(self):
await self.database.execute("select 1")

async def count(self) -> int:
await self.database.execute("update counter set value = value + 1")
result = await self.database.fetch_val("select value from counter")
logger.info("Current count: {}", result)
logger.info("count updated", count=result)
return result
7 changes: 5 additions & 2 deletions examples/hello_world/application.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,12 +2,15 @@

from asgikit.requests import Request, read_json
from asgikit.responses import respond_json
from loguru import logger
from pydantic import BaseModel

import structlog

from selva.di import Inject, service
from selva.web import FromPath, FromQuery, controller, get, post

logger = structlog.get_logger()


class MyModel(BaseModel):
name: str
Expand All @@ -32,7 +35,7 @@ async def greet_query(
number: Annotated[int, FromQuery] = 1,
):
greeting = self.greeter.greet(name)
logger.info(greeting)
logger.info(greeting, name=name, number=number)
await respond_json(request.response, {"greeting": greeting, "number": number})

@get("/:name")
Expand Down
11 changes: 7 additions & 4 deletions examples/middleware/application/middleware.py
Original file line number Diff line number Diff line change
Expand Up @@ -4,10 +4,13 @@

from asgikit.requests import Request
from asgikit.responses import respond_status
from loguru import logger

import structlog

from selva.web.middleware import Middleware

logger = structlog.get_logger()


class TimingMiddleware(Middleware):
async def __call__(self, chain, request: Request):
Expand All @@ -20,7 +23,7 @@ async def __call__(self, chain, request: Request):
request_end = datetime.now()

delta = request_end - request_start
logger.info("Request time: {}", delta)
logger.info("request duration", duration=str(delta))


class LoggingMiddleware(Middleware):
Expand All @@ -35,7 +38,7 @@ async def __call__(self, chain, request: Request):
request_line = f"{request.method} {request.path} HTTP/{request.http_version}"
status = request.response.status

logger.info('{} "{}" {} {}', client, request_line, status.value, status.phrase)
logger.info("request", client=client, request_line=request_line, status=status.value, status_phrase=status.phrase)


class AuthMiddleware(Middleware):
Expand All @@ -52,7 +55,7 @@ async def __call__(self, chain, request: Request):

authn = authn.removeprefix("Basic")
user, password = base64.urlsafe_b64decode(authn).decode().split(":")
logger.info("User '{}' with password '{}'", user, password)
logger.info("user logged in", user=user, password=password)
request["user"] = user

await chain(request)
10 changes: 5 additions & 5 deletions examples/middleware/application/service.py
Original file line number Diff line number Diff line change
Expand Up @@ -6,23 +6,23 @@
DEFAULT_NAME = "World"


class Settings(NamedTuple):
class Config(NamedTuple):
default_name: str


@service
def settings_factory() -> Settings:
def settings_factory() -> Config:
default_name = os.getenv("DEFAULT_NAME", DEFAULT_NAME)
return Settings(default_name)
return Config(default_name)


@service
class Greeter:
settings: Annotated[Settings, Inject]
config: Annotated[Config, Inject]

@property
def default_name(self):
return self.settings.default_name
return self.config.default_name

def greet(self, name: str = None):
greeted_name = name or self.default_name
Expand Down
7 changes: 6 additions & 1 deletion examples/settings/configuration/settings.yaml
Original file line number Diff line number Diff line change
@@ -1 +1,6 @@
message: ${MESSAGE:Hello, World!}
message: ${MESSAGE:Hello, World!}

logging:
root: info
level:
selva.web: debug
4 changes: 2 additions & 2 deletions examples/sqlalchemy/application/model.py
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ class Base(DeclarativeBase):

class MyModel(Base):
__tablename__ = 'my_model'
id: Mapped[int] = mapped_column(primary_key=True, autoincrement=True)
id: Mapped[int] = mapped_column(Integer, primary_key=True, autoincrement=True)
name: Mapped[str] = mapped_column(String(length=100))

def __repr__(self):
Expand All @@ -21,7 +21,7 @@ class OtherBase(DeclarativeBase):

class OtherModel(OtherBase):
__tablename__ = 'my_model'
id: Mapped[int] = Column(primary_key=True, autoincrement=True)
id: Mapped[int] = Column(Integer, primary_key=True, autoincrement=True)
name: Mapped[str] = Column(String(length=100))

def __repr__(self):
Expand Down
Loading