From ff1507a30d44df02c6c7c53d2bd800eaa9dfeed4 Mon Sep 17 00:00:00 2001 From: Joachim Jablon Date: Sat, 2 Mar 2024 11:36:51 +0100 Subject: [PATCH] Add logs, evolve Django demo to use blueprints --- docs/howto/django.md | 6 +++- docs/howto/logging.md | 13 +++++-- procrastinate/blueprints.py | 9 +++++ procrastinate/worker.py | 4 +-- procrastinate_demos/demo_django/demo/tasks.py | 12 ++++++- .../demo_django/project/settings.py | 35 ++++++++++++++++++- 6 files changed, 72 insertions(+), 7 deletions(-) diff --git a/docs/howto/django.md b/docs/howto/django.md index 9649d1022..27966df2a 100644 --- a/docs/howto/django.md +++ b/docs/howto/django.md @@ -174,7 +174,10 @@ PROCRASTINATE_ON_APP_READY: str ## Logs Procrastinate logs to the `procrastinate` logger. You can configure it -in your `LOGGING` settings. +in your `LOGGING` settings. The exact setup depends on whether you use +a structured logging library such as [`structlog`]. + +See {doc}`logging` for more information. ## Startup actions @@ -227,3 +230,4 @@ postgres' LISTEN/NOTIFY that integrate with Django. For instance, [open an issue]: https://github.com/procrastinate-org/procrastinate/issues [this talk at djangocon 2019]: https://www.youtube.com/watch?v=_DIlE-yc9ZQ [`AppConfig.ready()`]: https://docs.djangoproject.com/en/5.0/ref/applications/#django.apps.AppConfig.ready +[`structlog`]: (https://www.structlog.org/en/stable/) diff --git a/docs/howto/logging.md b/docs/howto/logging.md index 1a3b2e450..086da5523 100644 --- a/docs/howto/logging.md +++ b/docs/howto/logging.md @@ -18,8 +18,17 @@ class ProcrastinateLogFilter(logging.Filter): logging.getLogger("procrastinate").addFilter(ProcrastinateLogFilter) ``` -We'll try to document what attribute is available on each log, but one common thing is -the "action" attribute, that describes the event that triggered the logging. You can +One extra attribute that should be common to all procrastinate logs is +`action` attribute, that describes the event that triggered the logging. You can match on this. +By default, extra attributes are not shown in the log output. The easiest way +to see them is to use a structured logging library such as [`structlog`]. + +If you want a minimal example of a logging setup that displays the extra +attributes without using third party logging libraries, look at the +[Django demo] + [extra]: https://timber.io/blog/the-pythonic-guide-to-logging/#adding-context +[`structlog`]: https://www.structlog.org/en/stable/ +[Django demo]: https://github.com/procrastinate-org/procrastinate/blob/main/procrastinate_demos/demo_django/project/settings.py#L151 diff --git a/procrastinate/blueprints.py b/procrastinate/blueprints.py index 17d5fcc08..b3a123580 100644 --- a/procrastinate/blueprints.py +++ b/procrastinate/blueprints.py @@ -168,6 +168,15 @@ def add_tasks_from(self, blueprint: Blueprint, *, namespace: str) -> None: task.blueprint = self blueprint.tasks = new_tasks + logger.info( + "Adding tasks from blueprint", + extra={ + "action": "loading_blueprint", + "namespace": namespace, + "tasks": [t.name for t in new_tasks.values()], + }, + ) + # Add the namespaced tasks to this namespace self.tasks.update(new_tasks) diff --git a/procrastinate/worker.py b/procrastinate/worker.py index 18693573e..574df84e3 100644 --- a/procrastinate/worker.py +++ b/procrastinate/worker.py @@ -234,8 +234,8 @@ async def process_job(self, job: jobs.Job, worker_id: int = 0) -> None: def find_task(self, task_name: str) -> tasks.Task: try: return self.app.tasks[task_name] - except KeyError: - raise exceptions.TaskNotFound + except KeyError as exc: + raise exceptions.TaskNotFound from exc async def run_job(self, job: jobs.Job, worker_id: int) -> None: task_name = job.task_name diff --git a/procrastinate_demos/demo_django/demo/tasks.py b/procrastinate_demos/demo_django/demo/tasks.py index fcc6d7344..48418776b 100644 --- a/procrastinate_demos/demo_django/demo/tasks.py +++ b/procrastinate_demos/demo_django/demo/tasks.py @@ -4,6 +4,7 @@ from django.db import transaction +from procrastinate import App, Blueprint from procrastinate.contrib.django import app from .models import Book @@ -18,7 +19,16 @@ def index_book(book_id: int): set_indexed.defer(book_id=book_id) -@app.task(queue="index") +# Showcasing a task using blueprints. This is not mandatory at all. +# The blueprint is loaded in PROCRASTINATE_ON_APP_READY +blueprint = Blueprint() + + +@blueprint.task(queue="index") async def set_indexed(book_id: int): # Async ORM call await Book.objects.filter(id=book_id).aupdate(indexed=True) + + +def on_app_ready(app: App): + app.add_tasks_from(blueprint, namespace="bp") diff --git a/procrastinate_demos/demo_django/project/settings.py b/procrastinate_demos/demo_django/project/settings.py index 47b0bff40..6c04cb8e8 100644 --- a/procrastinate_demos/demo_django/project/settings.py +++ b/procrastinate_demos/demo_django/project/settings.py @@ -12,6 +12,7 @@ from __future__ import annotations +import logging from pathlib import Path # Build paths inside the project like this: BASE_DIR / 'subdir'. @@ -126,16 +127,46 @@ DEFAULT_AUTO_FIELD = "django.db.models.BigAutoField" + +# This emulates what a normal structured logging setup (e.g. structlog) +# would get you out of the box, but we didn't want the demo to depend on +# a specific logging library. +class ProcrastinateFilter(logging.Filter): + _reserved_log_keys = frozenset( + """args asctime created exc_info exc_text filename + funcName levelname levelno lineno module msecs message msg name pathname + process processName relativeCreated stack_info thread threadName""".split() + ) + + def filter(self, record: logging.LogRecord): + record.procrastinate = {} + for key, value in vars(record).items(): + if not key.startswith("_") and key not in self._reserved_log_keys | { + "procrastinate" + }: + record.procrastinate[key] = value # type: ignore + return True + + LOGGING = { "version": 1, "formatters": { - "procrastinate": {"format": "%(asctime)s %(levelname)-7s %(name)s %(message)s"}, + "procrastinate": { + "format": "%(asctime)s %(levelname)-7s %(name)s %(message)s %(procrastinate)s" + }, }, "handlers": { "procrastinate": { "level": "DEBUG", "class": "logging.StreamHandler", "formatter": "procrastinate", + "filters": ["procrastinate"], + }, + }, + "filters": { + "procrastinate": { + "()": "procrastinate_demos.demo_django.project.settings.ProcrastinateFilter", + "name": "procrastinate", }, }, "loggers": { @@ -146,3 +177,5 @@ }, }, } + +PROCRASTINATE_ON_APP_READY = "procrastinate_demos.demo_django.demo.tasks.on_app_ready"