События Struclog неправильно отображаются в консоли при выполнении задач Celery

Я использую structlog и celery в своем Django приложении и у меня возникают трудности при логировании задач с помощью structlog в консоли. Действительно, события не выравниваются должным образом при выводе в консоль во время выполнения задачи Celery. Когда выполняется больше задач, логи становятся едва читаемыми. clear_contextvars и reset_contextvars в верхней части задач не меняют проблему.

Какова может быть причина этого перекоса?

Консоль

celery_worker-1  | 2022-10-09T12:25:57.251196Z [info     ] Fetch orders complete                       [account.tasks] account=Anna
celery_worker-1  | 2022-10-09T12:25:57.934244Z [info     ] Fetch trades                                [account.tasks] account=Anna length=0 symbol=BBB
celery_worker-1  | 2022-10-09T12:25:58.896769Z [info     ] Fetch trades                                [account.tasks] account=Anna length=1 symbol=BBB
celery_worker-1  | 2022-10-09T12:25:58.911502Z [info     ] Fetch trades complete                       [account.tasks] account=Anna
celery_worker-1  | 2022-10-09T12:25:58.974451Z [info     ] Update assets inventory                     [2022-10-09T12:25:58.976925Zpnl.tasks] account=Anna
celery_worker-1  |  [info     ] Fetch orders                                [account.tasks] account=Nico
celery_worker-1  | 2022-10-09T12:25:58.989326Z2022-10-09T12:25:58.990257Z [info     ] Update contracts inventory                  [pnl.tasks] account=Anna
celery_worker-1  |  [info     ] Update assets inventory no required         [pnl.tasks] account=Anna
celery_worker-1  | 2022-10-09T12:25:59.011112Z [info     ] Update contracts inventory no required      [pnl.tasks] account=Anna
celery_worker-1  | 2022-10-09T12:26:00.380746Z [info     ] Fetch orders complete                       [account.tasks] account=Nico
celery_worker-1  | 2022-10-09T12:26:01.222383Z [info     ] Fetch trades                                [account.tasks] account=Nico length=0 symbol=ABC
celery_worker-1  | 2022-10-09T12:26:01.570339Z [info     ] Fetch trades                                [account.tasks] account=Nico length=1 symbol=ABC
celery_worker-1  | 2022-10-09T12:26:01.588788Z [info     ] Fetch trades complete                       [account.tasks] account=Nico

Версия пакетов

celery==5.2.7  # latest
django-structlog==3.0.1  # latest
structlog==22.1.0  # latest

tasks.py

import structlog

logger = structlog.get_logger(__name__)


@app.task(bind=True, name='Update_inventory')
def update_inventory(self, pk):

    account = Account.objects.get(pk=pk)
    log_asset = logger.bind(account=account.name)
    log_asset.info('Log event')
    ...

celery.py

import structlog
from django_structlog.celery.steps import DjangoStructLogInitStep

app.steps['worker'].add(DjangoStructLogInitStep)


@setup_logging.connect
def receiver_setup_logging(loglevel, logfile, format, colorize, **kwargs):
    from logging.config import dictConfig
    from django.conf import settings
    dictConfig(settings.LOGGING)

settings.py

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'json_formatter': {
            '()': structlog.stdlib.ProcessorFormatter,
            'processor': structlog.processors.JSONRenderer(sort_keys=False),
        },
        'plain_console': {
            '()': structlog.stdlib.ProcessorFormatter,
            'processor': structlog.dev.ConsoleRenderer(pad_event=43, colors=True, force_colors=True),
        },
        'key_value': {
            '()': structlog.stdlib.ProcessorFormatter,
            'processor': structlog.processors.KeyValueRenderer(key_order=['level',
                                                                          'logger',
                                                                          'event',
                                                                          'timestamp'],
                                                               sort_keys=False
                                                               ),
        },
    },
    'handlers': {
        'console': {
            'class': 'logging.StreamHandler',
            'formatter': 'plain_console',
        },
        'json_file': {
            'class': 'logging.handlers.WatchedFileHandler',
            'filename': 'logs/json.log',
            'formatter': 'json_formatter',
        },
        'flat_line_file': {
            'class': 'logging.handlers.WatchedFileHandler',
            'filename': 'logs/flat_line.log',
            'formatter': 'key_value',
        },
    },
    'loggers': {
        '': {
            'handlers': ['console', 'flat_line_file', 'json_file'],
            'level': 'WARNING',
            'propagate': False,
        },
        'account': {
            'handlers': ['console', 'flat_line_file', 'json_file'],
            'level': 'INFO',
            'propagate': False,
        },
        'authentication': {
            'handlers': ['console', 'flat_line_file', 'json_file'],
            'level': 'INFO',
            'propagate': False,
        },
        'myapp': {
            'handlers': ['console', 'flat_line_file', 'json_file'],
            'level': 'INFO',
            'propagate': False,
        }
    }
}

structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        structlog.stdlib.filter_by_level,
        structlog.processors.TimeStamper(fmt="iso"),
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.processors.StackInfoRenderer(),
        structlog.processors.format_exc_info,
        structlog.processors.UnicodeDecoder(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=True,
)

Вернуться на верх