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

dockerflow.logging.JsonLogFormatter is weird about %s style logging #29

Open
peterbe opened this issue Nov 9, 2018 · 4 comments
Open

Comments

@peterbe
Copy link
Contributor

peterbe commented Nov 9, 2018

I have this config:

    # Logging
    LOGGING_USE_JSON = values.BooleanValue(True)
    LOGGING_DEFAULT_LEVEL = values.Value("INFO")

    @property
    def LOGGING(self):
        return {
            "version": 1,
            "disable_existing_loggers": False,
            "formatters": {
                "json": {
                    "()": "dockerflow.logging.JsonLogFormatter",
                    "logger_name": "buildhub",
                },
                "verbose": {"format": "%(levelname)s %(asctime)s %(name)s %(message)s"},
            },
            "handlers": {
                "console": {
                    "level": self.LOGGING_DEFAULT_LEVEL,
                    "class": "logging.StreamHandler",
                    "formatter": ("json" if self.LOGGING_USE_JSON else "verbose"),
                },
                "sentry": {
                    "level": "ERROR",
                    "class": (
                        "raven.contrib.django.raven_compat.handlers" ".SentryHandler"
                    ),
                },
                "null": {"class": "logging.NullHandler"},
            },
            "root": {"level": "INFO", "handlers": ["sentry", "console"]},

...

When I do:

In [1]: import logging

In [2]: logger = logging.getLogger("myproject")

In [3]: logger.info("Hi!")
{"Timestamp": 1541787363833421056, "Type": "myproject", "Logger": "buildhub", "Hostname": "MacBook-Pro-131.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 68488, "Fields": {"msg": "Hi!"}}

In [4]: logger.info("Hi %s", "peter")
{"Timestamp": 1541787379742094080, "Type": "myproject", "Logger": "buildhub", "Hostname": "MacBook-Pro-131.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 68488, "Fields": {"msg": "Hi peter"}}

In [5]: logger.info("Hi %s", {'name': 'Peter'})
{"Timestamp": 1541787416647823104, "Type": "myproject", "Logger": "buildhub", "Hostname": "MacBook-Pro-131.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 68488, "Fields": {}}

Notice that when the param to logger.debug(template, THIS) isn't a string the final "msg" becomes empty ("Fields": {}).

@peterbe
Copy link
Contributor Author

peterbe commented Nov 9, 2018

Contrast that with regular "verbose" logging:

▶ DJANGO_LOGGING_USE_JSON=False DJANGO_LOGGING_DEFAULT_LEVEL=DEBUG ./manage.py shell
Python 3.6.5 (default, Mar 30 2018, 06:41:53)
Type 'copyright', 'credits' or 'license' for more information
IPython 6.4.0 -- An enhanced Interactive Python. Type '?' for help.

In [1]: import logging

In [2]: logger = logging.getLogger("myproject")

In [3]: logger.info("Hi!")
INFO 2018-11-09 18:19:07,726 myproject Hi!

In [4]: logger.info("Hi %s", "peter")
INFO 2018-11-09 18:19:13,941 myproject Hi peter

In [5]: logger.info("Hi %s", {'name': 'Peter'})
INFO 2018-11-09 18:19:20,103 myproject Hi {'name': 'Peter'}

@peterbe
Copy link
Contributor Author

peterbe commented Nov 9, 2018

The "cause" of this is that the record.getMessage() here becomes this string: "Hi {'name': 'Peter'}"
and because of the line:

if message and not message.startswith('{') and not message.endswith('}'):

...it decides to not include the message.

I'm trying to parse that code comment two lines above but struggling to understand what it means ... is not already a JSON blob.

@peterbe
Copy link
Contributor Author

peterbe commented Nov 9, 2018

Because I'm timely desperate for a solution, here's how I solved it:

In [3]: stuff = {'name': 'Peter'}

In [4]: logger.info(f"Hi {stuff}")
{"Timestamp": 1541788091760187904, "Type": "myproject", "Logger": "buildhub", "Hostname": "MacBook-Pro-131.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 69542, "Fields": {}}

In [5]: logger.info(f"Hi {stuff} ")
{"Timestamp": 1541788125543843072, "Type": "myproject", "Logger": "buildhub", "Hostname": "MacBook-Pro-131.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 69542, "Fields": {"msg": "Hi {'name': 'Peter'} "}}

By making sure the logging message string has an extra character that is not }, it works.

@diox
Copy link
Contributor

diox commented Sep 26, 2019

So if you still care @peterbe #37 will make it easier for you to override this behavior, there is a is_value_jsonlike method you can override on the JsonLogFormatter class.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants