TypeError: 'ProcessorFormatter' object is not callable && stream formatter is missing Colorama/Pretty Printing

RoscoeTheDog commented 1 year ago

I have been using a logging configuration with the standard structlog package and not been using the django-structlog for awhile. I probably should have setup the django server logging configuration awhile back initially but now is better than never I suppose. I'm having some problems getting there though.

My current structlog configuration (not django-structlog) writes formatted JSON to a log file. A stream handler typically targets a ConsoleRenderer() to pretty print things to the console window as per many standard code examples shown. However, in my case, I wanted a little more customizability in how the ordering was displayed with it's key/pair values and other arguments when a log msg is received. My solution is probably not the most elegant, but it worked. I copied the source code of the ConsoleRenderer.py to a new module in my project directory and called it CustomConsoleRenderer.py instead. Then when configuring the log handles, I would simply reference the CustomConsoleRenderer instead with it's modifications.

Following the basic django-structlog example, I got JSON successfully writing to the intended log file and can see it displaying in the console window in a solid red color. However, all pretty formatting and colors are gone from the console stream and I can't figure out how to get it back.

You can see the settings.py logging configuration below. Please note that in order to get logging working in my django project, I had to comment out the callable "()" setting from each of the formatters. I have a leading suspicion this is part of the stream formatting issues. When having the callable enabled "()": structlog.stdlib.ProcessorFormatter,, I get the following error:

--- Logging error ---
Traceback (most recent call last):
  File "C:\python39\lib\logging\__init__.py", line 1083, in emit
    msg = self.format(record)
  File "C:\python39\lib\logging\__init__.py", line 927, in format
    return fmt.format(record)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\structlog\stdlib.py", line 964, in format
    ed = p(logger, meth_name, ed)
TypeError: 'ProcessorFormatter' object is not callable
Call stack:
  File "C:\Users\admin\AppData\Local\JetBrains\Toolbox\apps\PyCharm-P\ch-0\221.5591.52\plugins\python\helpers\pydev\_pydev_bundle\pydev_monkey.py", line 795, in __call__
    ret = self.original_func(*self.args, **self.kwargs)
  File "C:\python39\lib\threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "C:\python39\lib\threading.py", line 954, in _bootstrap_inner
    self.run()
  File "C:\python39\lib\threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "C:\python39\lib\socketserver.py", line 683, in process_request_thread
    self.finish_request(request, client_address)
  File "C:\python39\lib\socketserver.py", line 360, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "C:\python39\lib\socketserver.py", line 747, in __init__
    self.handle()
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\servers\basehttp.py", line 202, in handle
    self.handle_one_request()
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\servers\basehttp.py", line 227, in handle_one_request
    handler.run(self.server.get_app())
  File "C:\python39\lib\wsgiref\handlers.py", line 137, in run
    self.result = application(self.environ, self.start_response)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\contrib\staticfiles\handlers.py", line 80, in __call__
    return self.application(environ, start_response)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\wsgi.py", line 131, in __call__
    response = self.get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\base.py", line 140, in get_response
    response = self._middleware_chain(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\utils\deprecation.py", line 136, in __call__
    response = response or self.get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\utils\deprecation.py", line 136, in __call__
    response = response or self.get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\utils\deprecation.py", line 136, in __call__
    response = response or self.get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\utils\deprecation.py", line 136, in __call__
    response = response or self.get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\utils\deprecation.py", line 136, in __call__
    response = response or self.get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\utils\deprecation.py", line 136, in __call__
    response = response or self.get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\utils\deprecation.py", line 136, in __call__
    response = response or self.get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\exception.py", line 55, in inner
    response = get_response(request)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\django\core\handlers\base.py", line 197, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\Accounts\views.py", line 17, in login_view
    logger.info('testing 123', test='some value')
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\structlog\_log_levels.py", line 130, in meth
    return self._proxy_to_logger(name, event, **kw)
  File "C:\Users\admin\PycharmProjects\MyDjangoServer4_0_4\venv\lib\site-packages\structlog\_base.py", line 206, in _proxy_to_logger
    return getattr(self._logger, method_name)(*args, **kw)
Message: {'timestamp': '2022-12-24T14:33:35.307564Z', 'level': 'info', 'event': 'testing 123', 'test': 'some value'}
Arguments: ()

Below is the logging configuration in settings.py

stream_formatter = structlog.stdlib.ProcessorFormatter(processor=custom_console_renderer.ConsoleRenderer(),)
file_formatter = structlog.stdlib.ProcessorFormatter(
    processor=structlog.processors.JSONRenderer(sort_keys=False),
    foreign_pre_chain=
    [
        structlog.processors.TimeStamper(fmt='iso'),
        structlog.stdlib.add_log_level,
        custom_processors.OrderKeys()],

)

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json_formatter": {
            # "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.JSONRenderer(sort_keys=False),
        },
        "stream_formatter": {
            # "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.stdlib.ProcessorFormatter(processor=custom_console_renderer.ConsoleRenderer(),),
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "stream_formatter",
        },
        "json_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "django_server.log",
            "formatter": "json_formatter",
        },
    },
    "loggers": {
        "root_logger": {
            "handlers": ["console", "json_file"],
            "level": "INFO",
        },
    }
}

structlog.configure(
    processors=[
        structlog.processors.TimeStamper(fmt='iso'),
        structlog.processors.format_exc_info,
        structlog.processors.StackInfoRenderer(),
        custom_processors.add_structlog_level,
        custom_processors.OrderKeys(),  # custom processor. orders keys so it is easier to visualize
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=True,
)

Below is the modifications to this console renderer class. There are not many changes here. Not even sure it's relevant to post it related to my issue but here it is anyway:

# This file is dual licensed under the terms of the Apache License, Version
# 2.0, and the MIT License.  See the LICENSE file in the root of this
# repository for complete details.

"""
Helpers that make development with ``structlog`` more pleasant.
"""

# Custom iteration of ConsoleRenderer factored from the Structlog Library.

from __future__ import absolute_import, division, print_function

from six import StringIO

try:
    import colorama
except ImportError:
    colorama = None

__all__ = ["ConsoleRenderer"]

_MISSING = "{who} requires the {package} package installed.  "
_EVENT_WIDTH = 30  # pad the event name to so many characters

def _pad(s, l):
    """
    Pads *s* to length *l*.
    """
    missing = l - len(s)
    return s + " " * (missing if missing > 0 else 0)

if colorama is not None:
    _has_colorama = True

    RESET_ALL = colorama.Style.RESET_ALL
    BRIGHT = colorama.Style.BRIGHT
    DIM = colorama.Style.DIM
    RED = colorama.Fore.RED
    BLUE = colorama.Fore.BLUE
    CYAN = colorama.Fore.CYAN
    MAGENTA = colorama.Fore.MAGENTA
    YELLOW = colorama.Fore.YELLOW
    GREEN = colorama.Fore.GREEN
    RED_BACK = colorama.Back.RED
else:
    _has_colorama = False

    RESET_ALL = (
        BRIGHT
    ) = DIM = RED = BLUE = CYAN = MAGENTA = YELLOW = GREEN = RED_BACK = ""

class _ColorfulStyles(object):
    reset = RESET_ALL
    bright = BRIGHT

    level_critical = RED
    level_exception = RED
    level_error = RED
    level_warn = YELLOW
    level_info = GREEN
    level_debug = GREEN
    level_notset = RED_BACK

    timestamp = DIM
    logger_name = BLUE
    kv_key = CYAN
    kv_value = MAGENTA

class _PlainStyles(object):
    reset = ""
    bright = ""

    level_critical = ""
    level_exception = ""
    level_error = ""
    level_warn = ""
    level_info = ""
    level_debug = ""
    level_notset = ""

    timestamp = ""
    logger_name = ""
    kv_key = ""
    kv_value = ""

class ConsoleRenderer(object):
    """
    Render `event_dict` nicely aligned, possibly in colors, and ordered.
    :param int pad_event: Pad the event to this many characters.
    :param bool colors: Use colors for a nicer output.
    :param bool force_colors: Force colors even for non-tty destinations.
        Use this option if your logs are stored in a file that is meant
        to be streamed to the console.
    :param bool repr_native_str: When ``True``, :func:`repr()` is also applied
        to native strings (i.e. unicode on Python 3 and bytes on Python 2).
        Setting this to ``False`` is useful if you want to have human-readable
        non-ASCII output on Python 2.  The `event` key is *never*
        :func:`repr()` -ed.
    :param dict level_styles: When present, use these styles for colors. This
        must be a dict from level names (strings) to colorama styles. The
        default can be obtained by calling
        :meth:`ConsoleRenderer.get_default_level_styles`
    Requires the colorama_ package if *colors* is ``True``.
    .. _colorama: https://pypi.org/project/colorama/
    .. versionadded:: 16.0
    .. versionadded:: 16.1 *colors*
    .. versionadded:: 17.1 *repr_native_str*
    .. versionadded:: 18.1 *force_colors*
    .. versionadded:: 18.1 *level_styles*
    """

    def __init__(
        self,
        pad_event=_EVENT_WIDTH,
        colors=True,
        force_colors=False,
        repr_native_str=False,
        level_styles=None,
    ):
        if colors is True:
            if colorama is None:
                raise SystemError(
                    _MISSING.format(
                        who=self.__class__.__name__ + " with `colors=True`",
                        package="colorama",
                    )
                )

            if force_colors:
                colorama.deinit()
                colorama.init(strip=False)
            else:
                colorama.init()

            styles = _ColorfulStyles
        else:
            styles = _PlainStyles

        self._styles = styles
        self._pad_event = pad_event

        if level_styles is None:
            self._level_to_color = self.get_default_level_styles(colors)
        else:
            self._level_to_color = level_styles

        for key in self._level_to_color.keys():
            self._level_to_color[key] += styles.bright
        self._longest_level = len(
            max(self._level_to_color.keys(), key=lambda e: len(e))
        )

        if repr_native_str is True:
            self._repr = repr
        else:

            def _repr(inst):
                if isinstance(inst, str):
                    return inst
                else:
                    return repr(inst)

            self._repr = _repr

    def __call__(self, _, __, event_dict):
        sio = StringIO()

        ts = event_dict.pop("timestamp", None)
        if ts is not None:
            sio.write(
                # can be a number if timestamp is UNIXy
                self._styles.timestamp
                + str(ts)
                + self._styles.reset
                + " "
            )
        level = event_dict.pop("level", None)
        if level is not None:
            sio.write(
                "["
                + self._level_to_color[level]
                + _pad(level, self._longest_level)
                + self._styles.reset
                + "] "
            )

        event = event_dict.pop("event")
        if event_dict:
            event = _pad(event, self._pad_event) + self._styles.reset + " "
        else:
            event += self._styles.reset
        sio.write(self._styles.bright + event)

        logger_name = event_dict.pop("logger", None)
        if logger_name is not None:
            sio.write(
                "["
                + self._styles.logger_name
                + self._styles.bright
                + logger_name
                + self._styles.reset
                + "] "
            )

        stack = event_dict.pop("stack", None)
        exc = event_dict.pop("exception", None)
        sio.write(
            " ".join(
                self._styles.kv_key
                + key
                + self._styles.reset
                + "="
                + self._styles.kv_value
                + self._repr(event_dict[key])
                + self._styles.reset
                for key in event_dict.keys()    # changed from sorted() to standard formatting
            )
        )

        if stack is not None:
            sio.write("\n" + stack)
            if exc is not None:
                sio.write("\n\n" + "=" * 79 + "\n")
        if exc is not None:
            sio.write("\n" + exc)

        return sio.getvalue()

    @staticmethod
    def get_default_level_styles(colors=True):
        """
        Get the default styles for log levels
        This is intended to be used with :class:`ConsoleRenderer`'s
        ``level_styles`` parameter.  For example, if you are adding
        custom levels in your home-grown
        :func:`~structlog.stdlib.add_log_level` you could do::
            my_styles = ConsoleRenderer.get_default_level_styles()
            my_styles["EVERYTHING_IS_ON_FIRE"] = my_styles["critical"]
            renderer = ConsoleRenderer(level_styles=my_styles)
        :param bool colors: Whether to use colorful styles. This must match the
            `colors` parameter to :class:`ConsoleRenderer`. Default: True.
        """
        if colors:
            styles = _ColorfulStyles
        else:
            styles = _PlainStyles
        return {
            "critical": styles.level_critical,
            "exception": styles.level_exception,
            "error": styles.level_error,
            "warn": styles.level_warn,
            "warning": styles.level_warn,
            "info": styles.level_info,
            "debug": styles.level_debug,
            "notset": styles.level_notset,
        }

And finally here is the custom processors class. I believe it only has a single modification in it called OrderKeys. Its been years since setting this up from another project initially, so I'm not sure if there are other minor changes to the source file for rendering differently. I know this works with basic structlog module, so in theory, it should also work with the django-structlog module as well if properly configured.



import datetime
import json
import operator
import sys
import time

import six

from structlog._frames import (
    _find_first_app_frame_and_name,
    _format_exception,
    _format_stack,
)

def add_structlog_level(logger, name, event_dict):

    event_dict['level'] = name.lower()

    return event_dict

def order_keys(logger, name, event_dict):
    keys = ['timestamp', 'level', 'event', 'msg', 'path', 'exception', 'exc_info', 'path']

    # if keys is None:
    #     return event_dict
    # else:
    _ordered_keys = keys
    _event_dict = event_dict.copy()

    event_dict = {}

    for key in _ordered_keys:

        if _event_dict:
            for k, v in list(_event_dict.items()):
                if key == k:
                    event_dict[key] = _event_dict.pop(k)
                else:
                    continue

    return event_dict

class OrderKeys(object):

    def __new__(cls, keys=None):
        default = ['timestamp', 'level', 'event']

        if keys is None:
            keys = default

        def organize(self, logger, name, event_dict):
            _ordered_keys = keys
            _event_dict = event_dict.copy()

            event_dict = {}
            _do_last = []
            for key in _ordered_keys:
                for k, v in list(_event_dict.items()):
                    if key == k:
                        event_dict[key] = _event_dict.pop(k)
            for k, v in list(_event_dict.items()):
                event_dict[k] = v

            return event_dict

        return type("OrderKeys", (object,), {"__call__": organize})()```

jrobichaud commented 1 year ago

@RoscoeTheDog I believe it is more a structlog issue than a django-structlog issue.

do you have colorama python dependency installed?

RoscoeTheDog commented 1 year ago

do you have colorama python dependency installed?

Yes. Colorama is installed and formatting seems to work fine in the context of the normal structlog module. My little django project acts a trading hub and after a 'deal' / strategy is started, it initializes the standard structlog logging configuration from it's class constructor and all the formatting displays correctly. Ignore the fact that it's running in a shell here in the screenshot.. it works the same within a console window within the pycharm IDE editor too.

Its only when trying to log through django-structlog that I cannot get the color formatting working.

screenshots:

RoscoeTheDog commented 1 year ago

And for more reference and info, here is the logging config that is invoked before a deal starts. This is my standard structlog config which currently does seem to display stuff correctly.

Side note: there are some minor notes for my reference only. You can ignore these minor footnotes.

    def logging_config(self):
        """
        Structured logging configuration setup. With the correct configuration, we can also use this to
        pipe messages to user via GUI.
        https://www.structlog.org/en/stable/getting-started.html for more info.
        """

        # configure our *structlog* configuration with a processor chain
        structlog.configure(
            context_class=dict,
            wrapper_class=structlog.stdlib.BoundLogger,
            processors=[
                structlog.processors.TimeStamper(fmt='iso'),
                structlog.processors.format_exc_info,
                structlog.processors.StackInfoRenderer(),
                custom_processors.add_structlog_level,
                # order_keys,
                custom_processors.OrderKeys(),  # custom processor. orders keys so it is easier to visualize
                structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
            ],
            logger_factory=structlog.stdlib.LoggerFactory(),
        )

        # custom format renderer for the console output stream. Can change colors and styles if desired.
        stream_formatter = structlog.stdlib.ProcessorFormatter(
            processor=custom_console_renderer.ConsoleRenderer(),

            # Below is the default console renderer, as defined by the structlog devs.
            #
            #   Note: Had issues displaying and logging exception info.
            #       Took source and revised a custom version of it.
            #       Old configuration commented out for reference.

            # structlog.dev.ConsoleRenderer(
            # #     level_styles=
            # # {
            # #     'info:': '\033[31m',
            # #     # colorama ANSI sequences
            # #     # print(structlog.dev.ConsoleRenderer.get_default_level_styles()) for further example
            # # }
            # ),
            # foreign_pre_chain=
            # [
            #     # structlog.processors.TimeStamper(fmt='iso'),
            #     # custom_processors.OrderKeys(keys=['timestamp', 'level', 'event', 'msg', 'path', 'exc_info']),
            #     # format_exc_info,
            #     # custom_processors.add_structlog_level,
            #     # structlog.stdlib.add_log_level,
            #     # order_keys,
            #     # OrderKeys(keys=['timestamp', 'level', 'event', 'msg', 'exc_info']),
            #     structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
            #
            # ],
            # keep_exc_info=True,
            # keep_stack_info=True,
        )

        # custom formatter for the log file
        file_formatter = structlog.stdlib.ProcessorFormatter(
            processor=structlog.processors.JSONRenderer(sort_keys=False),
            foreign_pre_chain=
            [
                structlog.processors.TimeStamper(fmt='iso'),
                structlog.stdlib.add_log_level,
                custom_processors.OrderKeys()
                # custom_processors.OrderKeys(keys=['timestamp', 'level', 'event', 'msg', 'path', 'exc_info'])
            ],
        )

        # file handler. responsible for writing stuff to log
        self.file_handler = logging.FileHandler(self.log_name)

        # set formatter for file handler. responsible for formatting the log file (example: json output)
        self.file_handler.setFormatter(file_formatter)

        # stream handler. responsible for piping stuff to console.
        self.stream_handler = logging.StreamHandler()

        # set formatter for the stream handler. responsible for formatting the output stream (example: colors)
        self.stream_handler.setFormatter(stream_formatter)

        # create a standard self.logger from python module
        self.root_logger = logging.getLogger(self.log_name)

        # apply handlers to the standard self.logger
        self.root_logger.addHandler(self.stream_handler)
        self.root_logger.addHandler(self.file_handler)

        # set a global log level
        self.root_logger.setLevel(logging.DEBUG)

        # set log level for stdout/stderr stream
        self.stream_handler.setLevel(logging.DEBUG)

        # wrap the standard self.logger from python lib for structlog lib use.
        structlog.wrap_logger(
            self.root_logger,
            processors=[
                structlog.processors.TimeStamper(fmt='iso'),
                # custom_processors.add_structlog_level,
                structlog.stdlib.add_log_level,
            ]
        )
        self.logger = structlog.get_logger(self.log_name)

RoscoeTheDog commented 1 year ago

I suspect that your investigating this still. But if not, let me know if I should post this in the standard structlog github instead of the django-structlog github for troubleshooting support, and I'll make sure to do that too. Thanks jrobichaud!

jrobichaud commented 1 year ago

Can you reproduce the problem in django-structlog's demo project?

You could fork the project and make a branch to expose the problem.

https://django-structlog.readthedocs.io/en/latest/development.html#start-demo-app

Modify config/settings/local.py instead of your settings.py.

Open your browser 0.0.0.0:8000 and press the buttons. Check the logs.

After your reproduce the problem in the project, it will be easier to investigate this.

RoscoeTheDog commented 1 year ago

Apologies for my delaying getting on this. I do have an interest in resolving this issue but I have some health challenges I'm struggling with and also have just been busy with the holidays.

I first went to the hyperlink you provided, installed docker, WSL2, and got the demo project working in a standard CMD window. Everything seemed to be working as expected. When I enqued a log it would show up in the logging tab, so I proceeded with the forking of the project. The requirements were installed globally, so all resources should be available for a second test of the fork.

I forked the project as "django-structlog-colorama-testing-master" and updated the local.py with my configuration as you instructed. I also copied my two custom renderer scripts custom_console_render.py and custom_processors.py into this settings project directory so they could be referenced from the settings module, but I also had to specifically change the import path relative to config.settings , or more specifically, from config.settings import custom_processors, custom_console_renderer for them to build the project successfully.

My editor is Pycharm Professional. While in an embedded terminal window within this IDE, it begins at the root project directory C:\Users\admin\Documents\Github\django-structlog-colorama-testing-master>, I enter docker-compose up --build at this point. The project builds and starts successfully, but there are some issues from what I can see here when playing in the testing environment.

One important note is that going to 0.0.0.0:8000 doesn't connect to anything. It seems to start the server on http://127.0.0.1:8000 and http://172.19.0.5:8000 instead. Going to the first of those two http://127.0.0.1:8000 leads me to the expected testing webpage that I saw earlier from the docker demo project. Enqueing a task shows in the terminal window as django-structlog-colorama-testing-master-django-1 | 172.19.0.1 - - [03/Jan/2023 00:41:50] "POST /success_task HTTP/1.1" 201 -, but the logging tab does not show any resulting message. Additionally, when performing a raise exception action, I get redirected to a new page where the debugger catches a new exception unlike the original demo project. In the console output I get a traceback with a bunch of function calls I can't really follow too well. I'll include those as well for your review.

This kind of seems like the building of the project may not be configured correctly despite the dependencies being there. The project builds and starts but not being able to access 0.0.0.0:8000 is suspicious. I'm kind of lost as to what is the problem. I'm not all too familiar with docker, and I only know really basic knowledge on the celery middleware. This doesn't touch upon the issue/bug I raised yet, which was the color formatting issues when installing and using a config which works from the original structlog module in a basic django project (without celery, docker, or other dependencies), and not in a django-structlog context with all these extra dependencies/features. Once we get these environmental issues resolved, I am hoping we can continue diagnosing that bug further.

build log

C:\Users\admin\Documents\Github\django-structlog-colorama-testing-master>docker-compose up --build
[+] Building 1.7s (33/33) FINISHED
 => [django_structlog_demo_project_local_django internal] load build definition from Dockerfile                                                                                                                                                                      0.0s 
 => => transferring dockerfile: 32B                                                                                                                                                                                                                                  0.0s 
 => [django_structlog_demo_project_local_postgres internal] load build definition from Dockerfile                                                                                                                                                                    0.0s 
 => => transferring dockerfile: 32B                                                                                                                                                                                                                                  0.0s 
 => [django_structlog_demo_project_local_django internal] load .dockerignore                                                                                                                                                                                         0.0s 
 => => transferring context: 34B                                                                                                                                                                                                                                     0.0s 
 => [django_structlog_demo_project_local_postgres internal] load .dockerignore                                                                                                                                                                                       0.0s 
 => => transferring context: 34B                                                                                                                                                                                                                                     0.0s 
 => [django_structlog_demo_project_local_django internal] load metadata for docker.io/library/python:3.10-alpine                                                                                                                                                     1.3s 
 => [django_structlog_demo_project_local_postgres internal] load metadata for docker.io/library/postgres:14                                                                                                                                                          1.3s 
 => [django_structlog_demo_project_local_django internal] load build context                                                                                                                                                                                         0.0s 
 => => transferring context: 6.34kB                                                                                                                                                                                                                                  0.0s 
 => [django_structlog_demo_project_local_django  1/20] FROM docker.io/library/python:3.10-alpine@sha256:63d0c387f30f82da7e9404b7157b6f077656b5263c8d64c7b7b889f4d8c1c60a                                                                                             0.0s 
 => CACHED [django_structlog_demo_project_local_django  2/20] RUN apk update   && apk add --virtual build-deps gcc python3-dev musl-dev   && apk add postgresql-dev   && apk add libffi-dev py-cffi   && apk add gettext   && apk add postgresql-client              0.0s 
 => CACHED [django_structlog_demo_project_local_django  3/20] COPY ./requirements /requirements                                                                                                                                                                      0.0s 
 => CACHED [django_structlog_demo_project_local_django  4/20] RUN pip install -r /requirements/local.txt                                                                                                                                                             0.0s 
 => CACHED [django_structlog_demo_project_local_django  5/20] COPY ./compose/local/django/entrypoint /entrypoint                                                                                                                                                     0.0s 
 => CACHED [django_structlog_demo_project_local_django  6/20] RUN sed -i 's/\r//' /entrypoint                                                                                                                                                                        0.0s 
 => CACHED [django_structlog_demo_project_local_django  7/20] RUN chmod +x /entrypoint                                                                                                                                                                               0.0s 
 => CACHED [django_structlog_demo_project_local_django  8/20] COPY ./compose/local/django/start /start                                                                                                                                                               0.0s 
 => CACHED [django_structlog_demo_project_local_django  9/20] RUN sed -i 's/\r//' /start                                                                                                                                                                             0.0s 
 => CACHED [django_structlog_demo_project_local_django 10/20] RUN chmod +x /start                                                                                                                                                                                    0.0s 
 => CACHED [django_structlog_demo_project_local_django 11/20] COPY ./compose/local/django/celery/worker/start /start-celeryworker                                                                                                                                    0.0s 
 => CACHED [django_structlog_demo_project_local_django 12/20] RUN sed -i 's/\r//' /start-celeryworker                                                                                                                                                                0.0s 
 => CACHED [django_structlog_demo_project_local_django 13/20] RUN chmod +x /start-celeryworker                                                                                                                                                                       0.0s 
 => CACHED [django_structlog_demo_project_local_django 14/20] COPY ./compose/local/django/celery/beat/start /start-celerybeat                                                                                                                                        0.0s 
 => CACHED [django_structlog_demo_project_local_django 15/20] RUN sed -i 's/\r//' /start-celerybeat                                                                                                                                                                  0.0s 
 => CACHED [django_structlog_demo_project_local_django 16/20] RUN chmod +x /start-celerybeat                                                                                                                                                                         0.0s 
 => CACHED [django_structlog_demo_project_local_django 17/20] COPY ./compose/local/django/celery/flower/start /start-flower                                                                                                                                          0.0s 
 => CACHED [django_structlog_demo_project_local_django 18/20] RUN sed -i 's/\r//' /start-flower                                                                                                                                                                      0.0s 
 => CACHED [django_structlog_demo_project_local_django 19/20] RUN chmod +x /start-flower                                                                                                                                                                             0.0s 
 => CACHED [django_structlog_demo_project_local_django 20/20] WORKDIR /app                                                                                                                                                                                           0.0s 
 => [django_structlog_demo_project_local_postgres] exporting to image                                                                                                                                                                                                0.1s 
 => => exporting layers                                                                                                                                                                                                                                              0.0s 
 => => writing image sha256:c96bb5e82d57d698a82e3bd6f638539284bb6b5ba7795afe20c0e4b144bbc5c1                                                                                                                                                                         0.1s 
 => => naming to docker.io/library/django_structlog_demo_project_local_django                                                                                                                                                                                        0.0s 
 => => writing image sha256:ddf0f28d77eb6e843d7e1ef028bb6a43432fdcf1352eefcd5ba5a88ff2c94345                                                                                                                                                                         0.0s 
 => => naming to docker.io/library/django_structlog_demo_project_local_postgres                                                                                                                                                                                      0.0s 
 => [django_structlog_demo_project_local_postgres internal] load build context                                                                                                                                                                                       0.0s 
 => => transferring context: 4.97kB                                                                                                                                                                                                                                  0.0s 
 => [django_structlog_demo_project_local_postgres 1/4] FROM docker.io/library/postgres:14@sha256:cc80ac7c45f1518d74f6dbb4a982d9e88a457f8e2fbad90f81b09053c8058eb2                                                                                                    0.0s 
 => CACHED [django_structlog_demo_project_local_postgres 2/4] COPY ./compose/local/postgres/maintenance /usr/local/bin/maintenance                                                                                                                                   0.0s 
 => CACHED [django_structlog_demo_project_local_postgres 3/4] RUN chmod +x /usr/local/bin/maintenance/*                                                                                                                                                              0.0s 
 => CACHED [django_structlog_demo_project_local_postgres 4/4] RUN mv /usr/local/bin/maintenance/* /usr/local/bin     && rmdir /usr/local/bin/maintenance                                                                                                             0.0s 

Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them
[+] Running 6/0
 - Container django-structlog-colorama-testing-master-redis-1         Created                                                                                                                                                                                        0.0s 
 - Container django-structlog-colorama-testing-master-postgres-1      Created                                                                                                                                                                                        0.0s 
 - Container django-structlog-colorama-testing-master-flower-1        Created                                                                                                                                                                                        0.0s 
 - Container django-structlog-colorama-testing-master-celerybeat-1    Created                                                                                                                                                                                        0.0s 
 - Container django-structlog-colorama-testing-master-django-1        Created                                                                                                                                                                                        0.0s 
 - Container django-structlog-colorama-testing-master-celeryworker-1  Created                                                                                                                                                                                        0.0s 
Attaching to django-structlog-colorama-testing-master-celerybeat-1, django-structlog-colorama-testing-master-celeryworker-1, django-structlog-colorama-testing-master-django-1, django-structlog-colorama-testing-master-flower-1, django-structlog-colorama-testing-maste
r-postgres-1, django-structlog-colorama-testing-master-redis-1
django-structlog-colorama-testing-master-postgres-1      | 
django-structlog-colorama-testing-master-postgres-1      | PostgreSQL Database directory appears to contain a database; Skipping initialization
django-structlog-colorama-testing-master-postgres-1      | 
django-structlog-colorama-testing-master-postgres-1      | 2023-01-03 00:37:16.148 UTC [1] LOG:  starting PostgreSQL 14.6 (Debian 14.6-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
django-structlog-colorama-testing-master-postgres-1      | 2023-01-03 00:37:16.150 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
django-structlog-colorama-testing-master-postgres-1      | 2023-01-03 00:37:16.152 UTC [1] LOG:  listening on IPv6 address "::", port 5432
django-structlog-colorama-testing-master-postgres-1      | 2023-01-03 00:37:16.170 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
django-structlog-colorama-testing-master-postgres-1      | 2023-01-03 00:37:16.182 UTC [27] LOG:  database system was shut down at 2023-01-03 00:37:01 UTC
django-structlog-colorama-testing-master-postgres-1      | 2023-01-03 00:37:16.223 UTC [1] LOG:  database system is ready to accept connections
django-structlog-colorama-testing-master-redis-1         | 1:C 03 Jan 00:37:16.725 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
django-structlog-colorama-testing-master-redis-1         |                 _._                                                  
django-structlog-colorama-testing-master-redis-1         |            _.-``__ ''-._
django-structlog-colorama-testing-master-redis-1         |       _.-``    `.  `_.  ''-._           Redis 3.2.12 (00000000/0) 64 bit
django-structlog-colorama-testing-master-redis-1         |   .-`` .-```.  ```\/    _.,_ ''-._
django-structlog-colorama-testing-master-redis-1         |  (    '      ,       .-`  | `,    )     Running in standalone mode
django-structlog-colorama-testing-master-redis-1         |  |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6379
django-structlog-colorama-testing-master-redis-1         |  |    `-._   `._    /     _.-'    |     PID: 1
django-structlog-colorama-testing-master-redis-1         |   `-._    `-._  `-./  _.-'    _.-'
django-structlog-colorama-testing-master-redis-1         |  |`-._`-._    `-.__.-'    _.-'_.-'|
django-structlog-colorama-testing-master-redis-1         |  |    `-._`-._        _.-'_.-'    |           http://redis.io
django-structlog-colorama-testing-master-redis-1         |   `-._    `-._`-.__.-'_.-'    _.-'
django-structlog-colorama-testing-master-redis-1         |  |`-._`-._    `-.__.-'    _.-'_.-'|
django-structlog-colorama-testing-master-redis-1         |  |    `-._`-._        _.-'_.-'    |
django-structlog-colorama-testing-master-redis-1         |   `-._    `-._`-.__.-'_.-'    _.-'
django-structlog-colorama-testing-master-redis-1         |       `-._    `-.__.-'    _.-'
django-structlog-colorama-testing-master-redis-1         |           `-._        _.-'
django-structlog-colorama-testing-master-redis-1         |               `-.__.-'
django-structlog-colorama-testing-master-redis-1         | 
django-structlog-colorama-testing-master-redis-1         | 1:M 03 Jan 00:37:16.727 # Server started, Redis version 3.2.12
django-structlog-colorama-testing-master-redis-1         | 1:M 03 Jan 00:37:16.728 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or r
un the command 'sysctl vm.overcommit_memory=1' for this to take effect.
django-structlog-colorama-testing-master-redis-1         | 1:M 03 Jan 00:37:16.728 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo ne
ver > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled.
django-structlog-colorama-testing-master-redis-1         | 1:M 03 Jan 00:37:16.729 * DB loaded from disk: 0.000 seconds
django-structlog-colorama-testing-master-redis-1         | 1:M 03 Jan 00:37:16.730 * The server is now ready to accept connections on port 6379
django-structlog-colorama-testing-master-flower-1        | PostgreSQL is available
django-structlog-colorama-testing-master-django-1        | PostgreSQL is available
django-structlog-colorama-testing-master-flower-1        | You have incorrectly specified the following celery arguments after flower command: ['--app', '--broker']. Please specify them after celery command instead following this template: celery [celery args] flowe
r [flower args].
django-structlog-colorama-testing-master-flower-1        | [I 230103 00:37:19 command:162] Visit me at http://localhost:5555
django-structlog-colorama-testing-master-flower-1        | [I 230103 00:37:19 command:170] Broker: redis://redis:6379/0
django-structlog-colorama-testing-master-flower-1        | [I 230103 00:37:19 command:171] Registered tasks: 
django-structlog-colorama-testing-master-flower-1        |     ['celery.accumulate',
django-structlog-colorama-testing-master-flower-1        |      'celery.backend_cleanup',
django-structlog-colorama-testing-master-flower-1        |      'celery.chain',
django-structlog-colorama-testing-master-flower-1        |      'celery.chord',
django-structlog-colorama-testing-master-flower-1        |      'celery.chord_unlock',
django-structlog-colorama-testing-master-flower-1        |      'celery.chunks',
django-structlog-colorama-testing-master-flower-1        |      'celery.group',
django-structlog-colorama-testing-master-flower-1        |      'celery.map',
django-structlog-colorama-testing-master-flower-1        |      'celery.starmap']
django-structlog-colorama-testing-master-flower-1        | [I 230103 00:37:19 mixins:225] Connected to redis://redis:6379/0
django-structlog-colorama-testing-master-celerybeat-1    | PostgreSQL is available
django-structlog-colorama-testing-master-celeryworker-1  | PostgreSQL is available
django-structlog-colorama-testing-master-flower-1        | [W 230103 00:37:20 inspector:42] Inspect method active failed
django-structlog-colorama-testing-master-flower-1        | [W 230103 00:37:20 inspector:42] Inspect method registered failed
django-structlog-colorama-testing-master-flower-1        | [W 230103 00:37:20 inspector:42] Inspect method reserved failed
django-structlog-colorama-testing-master-flower-1        | [W 230103 00:37:20 inspector:42] Inspect method stats failed
django-structlog-colorama-testing-master-flower-1        | [W 230103 00:37:20 inspector:42] Inspect method conf failed
django-structlog-colorama-testing-master-flower-1        | [W 230103 00:37:20 inspector:42] Inspect method revoked failed
django-structlog-colorama-testing-master-flower-1        | [W 230103 00:37:20 inspector:42] Inspect method scheduled failed
django-structlog-colorama-testing-master-flower-1        | [W 230103 00:37:20 inspector:42] Inspect method active_queues failed
django-structlog-colorama-testing-master-django-1        | Operations to perform:
django-structlog-colorama-testing-master-django-1        |   Apply all migrations: account, admin, auth, contenttypes, sessions, sites, socialaccount, users
django-structlog-colorama-testing-master-django-1        | Running migrations:
django-structlog-colorama-testing-master-django-1        |   No migrations to apply.
django-structlog-colorama-testing-master-celerybeat-1    | celery beat v5.2.7 (dawn-chorus) is starting.
django-structlog-colorama-testing-master-celeryworker-1  | /usr/local/lib/python3.10/site-packages/celery/platforms.py:840: SecurityWarning: You're running the worker with superuser privileges: this is
django-structlog-colorama-testing-master-celeryworker-1  | absolutely not recommended!
django-structlog-colorama-testing-master-celeryworker-1  | 
django-structlog-colorama-testing-master-celeryworker-1  | Please specify a different user using the --uid option.
django-structlog-colorama-testing-master-celeryworker-1  | 
django-structlog-colorama-testing-master-celeryworker-1  | User information: uid=0 euid=0 gid=0 egid=0
django-structlog-colorama-testing-master-celeryworker-1  | 
django-structlog-colorama-testing-master-celeryworker-1  |   warnings.warn(SecurityWarning(ROOT_DISCOURAGED.format(
django-structlog-colorama-testing-master-celerybeat-1    | __    -    ... __   -        _
django-structlog-colorama-testing-master-celerybeat-1    | LocalTime -> 2023-01-03 00:37:22
django-structlog-colorama-testing-master-celerybeat-1    | Configuration ->
django-structlog-colorama-testing-master-celerybeat-1    |     . broker -> redis://redis:6379/0
django-structlog-colorama-testing-master-celerybeat-1    |     . loader -> celery.loaders.app.AppLoader
django-structlog-colorama-testing-master-celerybeat-1    |     . scheduler -> celery.beat.PersistentScheduler
django-structlog-colorama-testing-master-celerybeat-1    |     . db -> celerybeat-schedule
django-structlog-colorama-testing-master-celerybeat-1    |     . logfile -> [stderr]@%INFO
django-structlog-colorama-testing-master-celerybeat-1    |     . maxinterval -> 5.00 minutes (300s)
django-structlog-colorama-testing-master-celeryworker-1  |  
django-structlog-colorama-testing-master-celeryworker-1  |  -------------- celery@2ba9d3baf284 v5.2.7 (dawn-chorus)
django-structlog-colorama-testing-master-celeryworker-1  | --- ***** -----
django-structlog-colorama-testing-master-celeryworker-1  | -- ******* ---- Linux-5.10.16.3-microsoft-standard-WSL2-x86_64-with 2023-01-03 00:37:22
django-structlog-colorama-testing-master-celeryworker-1  | - *** --- * ---
django-structlog-colorama-testing-master-celeryworker-1  | - ** ---------- [config]
django-structlog-colorama-testing-master-celeryworker-1  | - ** ---------- .> app:         django_structlog_demo_project:0x7f9ae12c58a0
django-structlog-colorama-testing-master-celeryworker-1  | - ** ---------- .> transport:   redis://redis:6379/0
django-structlog-colorama-testing-master-celeryworker-1  | - ** ---------- .> results:     redis://redis:6379/0
django-structlog-colorama-testing-master-celeryworker-1  | - *** --- * --- .> concurrency: 8 (prefork)
django-structlog-colorama-testing-master-celeryworker-1  | -- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
django-structlog-colorama-testing-master-celeryworker-1  | --- ***** -----
django-structlog-colorama-testing-master-celeryworker-1  |  -------------- [queues]
django-structlog-colorama-testing-master-celeryworker-1  |                 .> celery           exchange=celery(direct) key=celery
django-structlog-colorama-testing-master-celeryworker-1  | 
django-structlog-colorama-testing-master-celeryworker-1  | 
django-structlog-colorama-testing-master-celeryworker-1  | [tasks]
django-structlog-colorama-testing-master-celeryworker-1  |   . django_structlog_demo_project.taskapp.celery.debug_task
django-structlog-colorama-testing-master-celeryworker-1  |   . django_structlog_demo_project.taskapp.celery.failing_task
django-structlog-colorama-testing-master-celeryworker-1  |   . django_structlog_demo_project.taskapp.celery.nested_task
django-structlog-colorama-testing-master-celeryworker-1  |   . django_structlog_demo_project.taskapp.celery.nesting_task
django-structlog-colorama-testing-master-celeryworker-1  |   . django_structlog_demo_project.taskapp.celery.successful_task
django-structlog-colorama-testing-master-celeryworker-1  | 
django-structlog-colorama-testing-master-celeryworker-1  | /usr/local/lib/python3.10/site-packages/celery/fixups/django.py:203: UserWarning: Using settings.DEBUG leads to a memory
django-structlog-colorama-testing-master-celeryworker-1  |             leak, never use this setting in production environments!
django-structlog-colorama-testing-master-celeryworker-1  |   warnings.warn('''Using settings.DEBUG leads to a memory
django-structlog-colorama-testing-master-celeryworker-1  | 
django-structlog-colorama-testing-master-django-1        | WARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead.
django-structlog-colorama-testing-master-django-1        |  * Running on all addresses (0.0.0.0)
django-structlog-colorama-testing-master-django-1        |  * Running on http://127.0.0.1:8000
django-structlog-colorama-testing-master-django-1        |  * Running on http://172.19.0.5:8000
django-structlog-colorama-testing-master-django-1        | Press CTRL+C to quit
django-structlog-colorama-testing-master-django-1        |  * Restarting with stat
django-structlog-colorama-testing-master-django-1        | Performing system checks...
django-structlog-colorama-testing-master-django-1        | 
django-structlog-colorama-testing-master-django-1        | System check identified no issues (0 silenced).
django-structlog-colorama-testing-master-django-1        | 
django-structlog-colorama-testing-master-django-1        | Django version 4.1.5, using settings 'config.settings.local'
django-structlog-colorama-testing-master-django-1        | Development server is running at http://0.0.0.0:8000/
django-structlog-colorama-testing-master-django-1        | Using the Werkzeug debugger (http://werkzeug.pocoo.org/)
django-structlog-colorama-testing-master-django-1        | Quit the server with CONTROL-C.
django-structlog-colorama-testing-master-django-1        |  * Debugger is active!
django-structlog-colorama-testing-master-django-1        |  * Debugger PIN: 123-245-591

raise exception

django-structlog-colorama-testing-master-django-1        | {'timestamp': '2023-01-03T00:43:23.712115Z', 'level': 'error', 'event': 'request_failed', 'code': 500, 'request': 'POST /raise_exception', 'exception': 'Traceback (most recent call last):\n  File "/usr/local
/lib/python3.10/site-packages/django/core/handlers/base.py", line 197, in _get_response\n    response = wrapped_callback(request, *callback_args, **callback_kwargs)\n  File "/usr/local/lib/python3.10/contextlib.py", line 79, in inner\n    return func(*args, **kwds)\
n  File "/app/django_structlog_demo_project/home/views.py", line 38, in raise_exception\n    raise Exception("This is a view raising an exception.")\nException: This is a view raising an exception.'}
django-structlog-colorama-testing-master-django-1        | 172.19.0.1 - - [03/Jan/2023 00:43:23] "POST /raise_exception HTTP/1.1" 500 -
django-structlog-colorama-testing-master-django-1        | Traceback (most recent call last):
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django/contrib/staticfiles/handlers.py", line 80, in __call__
django-structlog-colorama-testing-master-django-1        |     return self.application(environ, start_response)
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django/core/handlers/wsgi.py", line 131, in __call__
django-structlog-colorama-testing-master-django-1        |     response = self.get_response(request)
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django/core/handlers/base.py", line 140, in get_response
django-structlog-colorama-testing-master-django-1        |     response = self._middleware_chain(request)
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django/core/handlers/exception.py", line 57, in inner
django-structlog-colorama-testing-master-django-1        |     response = response_for_exception(request, exc)
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django/core/handlers/exception.py", line 140, in response_for_exception
django-structlog-colorama-testing-master-django-1        |     response = handle_uncaught_exception(
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django/core/handlers/exception.py", line 181, in handle_uncaught_exception
django-structlog-colorama-testing-master-django-1        |     return debug.technical_500_response(request, *exc_info)
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django_extensions/management/technical_response.py", line 40, in null_technical_500_response
django-structlog-colorama-testing-master-django-1        |     raise exc_value.with_traceback(tb)
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django/core/handlers/exception.py", line 55, in inner
django-structlog-colorama-testing-master-django-1        |     response = get_response(request)
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/site-packages/django/core/handlers/base.py", line 197, in _get_response
django-structlog-colorama-testing-master-django-1        |     response = wrapped_callback(request, *callback_args, **callback_kwargs)
django-structlog-colorama-testing-master-django-1        |   File "/usr/local/lib/python3.10/contextlib.py", line 79, in inner
django-structlog-colorama-testing-master-django-1        |     return func(*args, **kwds)
django-structlog-colorama-testing-master-django-1        |   File "/app/django_structlog_demo_project/home/views.py", line 38, in raise_exception
django-structlog-colorama-testing-master-django-1        |     raise Exception("This is a view raising an exception.")
django-structlog-colorama-testing-master-django-1        | Exception: This is a view raising an exception.
django-structlog-colorama-testing-master-django-1        | 172.19.0.1 - - [03/Jan/2023 00:43:23] "GET /raise_exception?__debugger__=yes&cmd=resource&f=style.css HTTP/1.1" 304 -
django-structlog-colorama-testing-master-django-1        | 172.19.0.1 - - [03/Jan/2023 00:43:23] "GET /raise_exception?__debugger__=yes&cmd=resource&f=debugger.js HTTP/1.1" 304 -
django-structlog-colorama-testing-master-django-1        | 172.19.0.1 - - [03/Jan/2023 00:43:25] "GET /raise_exception?__debugger__=yes&cmd=resource&f=console.png HTTP/1.1" 304 -

local.py

import structlog

from .base import *  # noqa: F403
from .base import env

# GENERAL
# ------------------------------------------------------------------------------
# https://docs.djangoproject.com/en/dev/ref/settings/#debug
DEBUG = True
# https://docs.djangoproject.com/en/dev/ref/settings/#secret-key
SECRET_KEY = env(
    "DJANGO_SECRET_KEY",
    default="DXatocQyyroxzcpo0tDxK3v5Rm4fatD9U7UeuLWwnZMOIaCQdPWovuqp4rxOct1T",
)
# https://docs.djangoproject.com/en/dev/ref/settings/#allowed-hosts
ALLOWED_HOSTS = ["localhost", "0.0.0.0", "127.0.0.1"]

# CACHES
# ------------------------------------------------------------------------------
# https://docs.djangoproject.com/en/dev/ref/settings/#caches
CACHES = {
    "default": {
        "BACKEND": "django.core.cache.backends.locmem.LocMemCache",
        "LOCATION": "",
    }
}

# TEMPLATES
# ------------------------------------------------------------------------------
# https://docs.djangoproject.com/en/dev/ref/settings/#templates
TEMPLATES[0]["OPTIONS"]["debug"] = DEBUG  # noqa F405

# EMAIL
# ------------------------------------------------------------------------------
# https://docs.djangoproject.com/en/dev/ref/settings/#email-backend
EMAIL_BACKEND = env(
    "DJANGO_EMAIL_BACKEND", default="django.core.mail.backends.console.EmailBackend"
)
# https://docs.djangoproject.com/en/dev/ref/settings/#email-host
EMAIL_HOST = "localhost"
# https://docs.djangoproject.com/en/dev/ref/settings/#email-port
EMAIL_PORT = 1025

# django-debug-toolbar
# ------------------------------------------------------------------------------
# https://django-debug-toolbar.readthedocs.io/en/latest/installation.html#prerequisites
INSTALLED_APPS += ["debug_toolbar"]  # noqa F405
# https://django-debug-toolbar.readthedocs.io/en/latest/installation.html#middleware
MIDDLEWARE += ["debug_toolbar.middleware.DebugToolbarMiddleware"]  # noqa F405
# https://django-debug-toolbar.readthedocs.io/en/latest/configuration.html#debug-toolbar-config
DEBUG_TOOLBAR_CONFIG = {
    "DISABLE_PANELS": ["debug_toolbar.panels.redirects.RedirectsPanel"],
    "SHOW_TEMPLATE_CONTEXT": True,
}
# https://django-debug-toolbar.readthedocs.io/en/latest/installation.html#internal-ips
INTERNAL_IPS = ["127.0.0.1", "10.0.2.2"]
if env("USE_DOCKER") == "yes":
    import socket

    hostname, _, ips = socket.gethostbyname_ex(socket.gethostname())
    INTERNAL_IPS += [ip[:-1] + "1" for ip in ips]

# django-extensions
# ------------------------------------------------------------------------------
# https://django-extensions.readthedocs.io/en/latest/installation_instructions.html#configuration
INSTALLED_APPS += ["django_extensions"]  # noqa F405
# Celery
# ------------------------------------------------------------------------------

# http://docs.celeryproject.org/en/latest/userguide/configuration.html#task-eager-propagates
CELERY_TASK_EAGER_PROPAGATES = True

# DATABASES
# ------------------------------------------------------------------------------
# https://docs.djangoproject.com/en/dev/ref/settings/#databases
DATABASES = {"default": env.db("DATABASE_URL")}
DATABASES["default"]["ATOMIC_REQUESTS"] = True

# Your stuff...
# ------------------------------------------------------------------------------

from config.settings import custom_processors, custom_console_renderer
stream_formatter = structlog.stdlib.ProcessorFormatter(processor=custom_console_renderer.ConsoleRenderer(), )
file_formatter = structlog.stdlib.ProcessorFormatter(
    processor=structlog.processors.JSONRenderer(sort_keys=False),
    foreign_pre_chain=
    [
        structlog.processors.TimeStamper(fmt='iso'),
        structlog.stdlib.add_log_level,
        custom_processors.OrderKeys()],

)

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "json_formatter": {
            # "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.processors.JSONRenderer(sort_keys=False),
        },
        "stream_formatter": {
            # "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.stdlib.ProcessorFormatter(processor=custom_console_renderer.ConsoleRenderer(), ),
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "stream_formatter",
        },
        "json_file": {
            "class": "logging.handlers.WatchedFileHandler",
            "filename": "django_server.log",
            "formatter": "json_formatter",
        },
    },
    "loggers": {
        "root_logger": {
            "handlers": ["console", "json_file"],
            "level": "INFO",
        },
    }
}

structlog.configure(
    processors=[
        structlog.processors.TimeStamper(fmt='iso'),
        structlog.processors.format_exc_info,
        structlog.processors.StackInfoRenderer(),
        custom_processors.add_structlog_level,
        custom_processors.OrderKeys(),  # custom processor. orders keys so it is easier to visualize
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    cache_logger_on_first_use=True,
)

MIDDLEWARE += [
    "django_structlog.middlewares.RequestMiddleware",
    "django_structlog.middlewares.CeleryMiddleware",
]

jrobichaud commented 1 year ago

Accessing by 127.0.0.1 is better, I will update the documentation. This is dumb I used 0.0.0.0.

Note: About the exception in the log, I intentionally made some views raising exceptions. The error message is “This is a view raising an exception.”

You are currently getting both django’s logger and django-structlog’s loggers since your did not disable the other loggers:

"disable_existing_loggers": False,

jrobichaud commented 1 year ago

@RoscoeTheDog did you manage to reproduce the bug with the demo project?

RoscoeTheDog commented 1 year ago

Unfortunately not. While I did get the demo project up and running, I was unable to get basic logging functionality working using my described approach. I was hoping that I could get you to investigate this issue further since I can't get the demo project environment to write to the logs using the custom_processor and custom_console_render modules. I assume this is an import/referencing issue within the demo project. The default demo project runs and writes to logs OK out of the box, but after integrating those custom formatter modules as described it fails to write anything to the logs. So I'm not really sure what to do from there.

And just in practical terms; having color formatting is a nice feature but a necessity for my ongoing django project. I'm building a personal trading platform and API for myself and that has been consuming a lot of time while I still have it. I just accepted a new job, and still have issues managing physical health challenges, so these two things themselves will consume even more time. I would have love to contribute to this issue further but to be quite frank, I don't think I'll get around to it. I did provide all source/resources related to the issue and it would be awesome if you managed to troubleshoot it, but I know we all have our own priorities and time commitments so I don't blame you if you don't want to touch it. You can close the issue if you think that is the best choice.

jrobichaud commented 1 year ago

Commit your code in a branch on your fork and I could take a look at it.

RoscoeTheDog commented 1 year ago

Commit your code in a branch on your fork and I could take a look at it.

I appreciate it. I just commited those now on my fork which is public, so I believe you should be able to see those changes now. I'm still rather new-ish to github (haven't worked w/ teams yet), but I can still navigate and use the platform just fine. I hope you have better luck sourcing the issue than I did.

jrobichaud commented 1 year ago

Fixed the demo project in this commit: https://github.com/jrobichaud/django-structlog/commit/63bdb4d5abcb176b932e52a2da12a2d8ae749318

You need to update your docker-compose.yml to add tty: true on the services that need colouring.

See: https://github.com/docker/compose/issues/2231#issuecomment-165137408

RoscoeTheDog commented 1 year ago

Maybe don't close it too soon. This solution sounds as though it might fix the problems within a docker/Django test project, but my original bug report was actually from when trying to use the django-structlog middleware within a Django project without docker. If this fix is a docker related configuration yaml setting, then it will not the underlying issue I'm encountering in Djangos structlog middleware and the coloring issue.

This a different project configuration and runtime. Can we not just create a new Django project, paste in my settings in the Django settings.py module, and reproduce the bug?

jrobichaud commented 1 year ago

About the crash TypeError: 'ProcessorFormatter' object is not callable it is because you did this:

        "stream_formatter": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.stdlib.ProcessorFormatter(processor=custom_console_renderer.ConsoleRenderer(), ),
        },

Instead of this:

        "stream_formatter": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": custom_console_renderer.ConsoleRenderer(),
        },

jrobichaud / django-structlog

TypeError: 'ProcessorFormatter' object is not callable && stream formatter is missing Colorama/Pretty Printing #162