mosquito / logging-journald

Pure python logging handler for writing logs to the journald using native protocol
MIT License
6 stars 1 forks source link

Got "Unable to write message" with Celery, Celery Beat and Django #12

Open BonaFideIT opened 1 day ago

BonaFideIT commented 1 day ago

I am using Django, Celery, Celery Beat and logging-journald.

python: 3.11.2
django: 4.2.16
celery: 5.4.0
django-celery-beat: 2.7.0
logging-journald: 0.6.9

In Django I have defined the journald logging handler like that:

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "simple": {
            "format": "%(levelname)s %(asctime)s %(message)s",
        },
    },
    "handlers": {
        "journald": {
            "level": "INFO",
            "class": "app.log_handler.CustomJournaldHandler",
            "formatter": "simple",
        },
     },
    "loggers": {
        "celery": {
            "handlers": ["journald"],
            "level": "DEBUG",
            "propagate": False,
        },
    },
}

Other Django settings:

INSTALLED_APPS = [
    "django.contrib.admin",
    "django.contrib.auth",
    "django.contrib.sites",
    "django.contrib.contenttypes",
    "django.contrib.sessions",
    "django.contrib.messages",
    "django.contrib.staticfiles",
    "django.contrib.humanize",
    "app",
    "django_celery_beat",
] 

# celery
CELERY_WORKER_CONCURRENCY = multiprocessing.cpu_count() - 1
CELERY_TIMEOUT = 60 * 10  # 10 min
CELERY_BEAT_SCHEDULER = "django_celery_beat.schedulers:DatabaseScheduler"

Celery.py:

import os
from logging.config import dictConfig 

from celery import Celery
from celery.signals import setup_logging 

os.environ.setdefault("DJANGO_SETTINGS_MODULE", "settings.local")

from django.conf import settings

app = Celery("app")
app.config_from_object("django.conf:settings", namespace="CELERY")

@setup_logging.connect
def config_loggers(*args, **kwargs):
    """Hook to pass django logging config to celery"""
    dictConfig(settings.LOGGING)

app.conf.result_expires = 60 * 60
app.conf.update(result_extended=True) 
app.autodiscover_tasks(lambda: settings.INSTALLED_APPS)

The handler is implemented like that:

# logging
import logging
from logging_journald import JournaldLogHandler, check_journal_stream

# exceptions
from django.core.exceptions import ImproperlyConfigured

class CustomJournaldHandler(JournaldLogHandler):
    """Logging handler for journald."""

    def __init__(self, *args, use_message_id: bool = False, **kwargs):
        if not (
            # Check if program running as systemd service
            check_journal_stream()
            or
            # Check if journald socket is available
            JournaldLogHandler.SOCKET_PATH.exists()
        ):
            raise ImproperlyConfigured(
                "Neither running as systemd service nor journald socket available."
            )
        super().__init__(*args, use_message_id=use_message_id, **kwargs)

When starting Celery and Celery Beat with:

celery -A settings worker --beat --scheduler django -O fair -l DEBUG -E

I get the following log:

 -------------- celery@***** v5.4.0 (opalescent)
--- ***** ----- 
-- ******* ---- Linux-5.15.0-126-generic-x86_64-with-glibc2.35 2024-11-30 11:18:56
- *** --- * --- 
- ** ---------- [config]
- ** ---------- .> app:         ****:0x7f99451701d0
- ** ---------- .> transport:   redis://localhost:6379/0
- ** ---------- .> results:     redis://localhost:6379/1
- *** --- * --- .> concurrency: 7 (prefork)
-- ******* ---- .> task events: ON
--- ***** ----- 
 -------------- [queues]
                .> celery           exchange=celery(direct) key=celery

[tasks]
  . celery.accumulate
  [...]

DEBUG 2024-11-30 12:38:50,325 | Worker: Starting Beat
DEBUG 2024-11-30 12:38:50,328 ^-- substep ok
DEBUG 2024-11-30 12:38:50,328 | Worker: Starting Hub
DEBUG 2024-11-30 12:38:50,328 ^-- substep ok
DEBUG 2024-11-30 12:38:50,328 | Worker: Starting Pool
DEBUG 2024-11-30 12:38:50,988 ^-- substep ok
DEBUG 2024-11-30 12:38:50,988 | Worker: Starting Consumer
DEBUG 2024-11-30 12:38:50,989 | Consumer: Starting Connection
INFO 2024-11-30 12:38:50,993 Connected to redis://localhost:6379/0
DEBUG 2024-11-30 12:38:50,993 ^-- substep ok
DEBUG 2024-11-30 12:38:50,993 | Consumer: Starting Events
DEBUG 2024-11-30 12:38:50,994 ^-- substep ok
DEBUG 2024-11-30 12:38:50,994 | Consumer: Starting Mingle
INFO 2024-11-30 12:38:50,994 mingle: searching for neighbors
Unable to write message 'INFO 2024-11-30 12:38:51,523 beat: Starting...' to journald
INFO 2024-11-30 12:38:51,523 beat: Starting...
[...]

The message Unable to write message 'INFO 2024-11-30 12:38:51,523 beat: Starting...' to journald results from this error:

Traceback (most recent call last):
  File "/home/***/.venv/lib/python3.11/site-packages/logging_journald.py", line 126, in send
    self.socket.sendall(value)
OSError: [Errno 9] Bad file descriptor

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/***/.venv/lib/python3.11/site-packages/logging_journald.py", line 265, in emit
    self.transport.send(self._format_record(record))
  File "/home/***/.venv/lib/python3.11/site-packages/logging_journald.py", line 134, in send
    self.socket.sendmsg(
OSError: [Errno 9] Bad file descriptor
BonaFideIT commented 1 day ago

Also it seams to be that celery beat is the problem here, because starting celery without beat: celery -A settings worker --scheduler django -O fair -l DEBUG -E does nor result in the Unable to write message.