Logging config tries too hard

[Ivan Sagalaev]

Hello everyone,

It's been a while since I last posted here, please forgive if I break any new rules inadvertently.

I'd like to revisit a decision made in [18993][]. My use case is very simple and obvious: I want all logging going into stdout.

As currently implemented, I can't do it easily with a custom `LOGGING` setting, because:

- If I leave existing Django loggers enabled it ties me to the behavior chosen by Django, which doesn't necessarily match what I want. For example, Django won't log debug and info messages if `DEBUG = False`. And with `DEBUG = True` I will be having two log messages for every log into the 'django' logger: one from the Django's own handler, and another after it propagates to my root logger.

- If I disable existing Django loggers, I effectively disable all logging from Django (and from 'py.warnings' for good measure).

In fact, the idea of providing a default logging configuration which a user can then *build upon* isn't really workable with Python logging: you can either fully reuse or fully discard what's been provided, but you can't meaningfully define a consistent configuration. Also, I have my doubts that this "build upon" use case is based on any real demand. In my experience there are only two approaches to configuring logging: "logging? huh, didn't think about it" and "get your hands off my logging, I know what I'm doing!"

The latter, incidentally, is what the old way was doing: define a sensible default value for `LOGGING` and let users to overwrite it completely. Currently, the default logging configuration is hard-coded in `django.utils.log`.

Also, I couldn't find the actual reasoning for the current behavior in the original ticket. It starts talking about having a more useful default, not about changing the way how this default configuration is applied.

[18993]: https://code.djangoproject.com/ticket/18993

[Aymeric Augustin]

It’s unclear to me as well how the current system is intended to be used.

All my projects do this:

# Configure logging manually to avoid merging with Django's defaults.

LOGGING = {

    # custom logging configuration goes here

}

logging.config.dictConfig(LOGGING)

LOGGING_CONFIG = None

Essentially they enforce my logging config and prevent Django from interfering.

I’ve never managed to get results I understand with any other technique.

Likely I could figure it out, given enough time, but until now I haven’t.

-- 

Aymeric.

--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.
To post to this group, send email to django-d...@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/57ca68fd-214a-4fe4-b759-7fc8cb597b35%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Tim Graham]

Just to be sure, which version of Django are you using? There were some simplifications in Django 1.9 that attempted to make writing custom logging configurations easier and further changes in Django 1.10.

https://github.com/django/django/commit/8efea1b8d5b5fb0cfef1a3244c339cebf8af36c5
https://github.com/django/django/commit/5b94b17feff15a9f0345f92fc0568bfe7038e3a3

[Ivan Sagalaev]

It’s unclear to me as well how the current system is intended to be used.

I can speculate, that the idea was that you *can* disable the existing loggers and define your own, but the effect of it actually disabling all logging from Django instead of it falling through to the custom root logger was overlooked.

All my projects do this:

# Configure logging manually to avoid merging with Django's defaults.

LOGGING = {

    # custom logging configuration goes here

}

logging.config.dictConfig(LOGGING)

LOGGING_CONFIG = None

Yes, that's the workaround I'm using right now, too. It works, but it's not very clean with having to import logging and do this non-obvious dance for what feels like it should just be the default behavior.

[Ivan Sagalaev]

Just to be sure, which version of Django are you using? There were some simplifications in Django 1.9 that attempted to make writing custom logging configurations easier and further changes in Django 1.10.

I'm using 1.9, but I'm referring to the code in master.
 

https://github.com/django/django/commit/8efea1b8d5b5fb0cfef1a3244c339cebf8af36c5
https://github.com/django/django/commit/5b94b17feff15a9f0345f92fc0568bfe7038e3a3

I don't see how these have anything to do with what I'm describing. I'm talking about this function: https://github.com/django/django/blob/master/django/utils/log.py#L66

When `LOGGING_CONFIG` isn't explicitly disabled it first unconditionally initializes logging with the hard-coded configuration and then applies a user one, if present. And the latter can't really neutralize the effect of the former.

[Carl Meyer]

On 09/06/2016 04:57 PM, Ivan Sagalaev wrote:
> I'm
> talking about this function:
> https://github.com/django/django/blob/master/django/utils/log.py#L66
>
> When `LOGGING_CONFIG` isn't explicitly disabled it first unconditionally
> initializes logging with the hard-coded configuration and then applies a
> user one, if present. And the latter can't really neutralize the effect
> of the former.

FWIW I agree that the current behavior here is broken and should be
fixed. The design seems to be based in an assumption that
`disable_existing_loggers=True` can "undo" the effects of the previous
config, when it can't, and in fact it does something much nastier -- it
silences all previously-created loggers.

I clearly recall outlining this issue in a Trac ticket at some point
quite a while ago, but I can't seem to find that ticket now.

Fixing this in a way that doesn't change logging behavior for projects
upgrading from a previous Django version may be tricky, unless we gate
the effect of the change on (yet another) setting.

Carl

[Tim Graham]

Carl, I think this is the thread with your past comments: https://groups.google.com/d/topic/django-developers/no2IhnRty68/discussion

To avoid a new setting, we could add some custom key/value to LOGGING for the new behavior and pop it before the dict is passed to dictConfig.

[Ivan Sagalaev]

Actually… I'm failing to imagine a scenario where such a change would lead to any bad things:

- If `disable_existing_loggers` is True, the incompatibility would manifest itself in Django loggers not being silenced, provided the user has defined a root logger. Which is probably the intended behavior, and I'm having a hard time imagining someone actually relying on it. Most probably users currently work around it either by doing their own config from scratch, or by redefining Django loggers, both of which will continue working after the change.

- If `disable_existing_loggers` is explicitly set to False, then we could initialize them as we do now.

How does that sound?

[Carl Meyer]

Hi Ivan,

On Sep 8, 2016, at 9:00 PM, Ivan Sagalaev <man...@softwaremaniacs.org> wrote:

Actually… I'm failing to imagine a scenario where such a change would lead to any bad things:

You may be right, but it's hard to evaluate that without knowing precisely what change you are envisioning. Can you be more specific about exactly what change you propose?

It sounds like you are maybe proposing to decide whether to pre-initialize logging with the built-in default config or not based on whether the user's LOGGING setting has disable_existing_loggers set to True or False? I think that would have the backwards-compatibility properties you outline below, but it doesn't seem to me that it arrives at a very satisfying end result; the system becomes if anything more complex and harder to explain than it is now. 

I think the best end result would be one where LOGGING simply defines the full config and it is always applied (by Django) exactly once, and the defaults we want are set as the global default for LOGGING, and just documented so that people who want to set LOGGING themselves can easily copy them as a starting point. But we'll need some kind of deprecation path to get there, at least for people who currently have disable_existing_loggers=False, in order to prevent them from suddenly losing the default config. 

Carl

--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.
To post to this group, send email to django-d...@googlegroups.com.
Visit this group at https://groups.google.com/group/django-developers.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/78325f82-badf-4e75-9206-be244a8e9cfc%40googlegroups.com.

[Ivan Sagalaev]

It sounds like you are maybe proposing to decide whether to pre-initialize logging with the built-in default config or not based on whether the user's LOGGING setting has disable_existing_loggers set to True or False?

Yes, I was thinking on my feet and this was one idea I came up with that would allow a sane migration story. But I don't like it either on the same grounds as you, it complicates things just a tad too much.
 

I think the best end result would be one where LOGGING simply defines the full config and it is always applied (by Django) exactly once, and the defaults we want are set as the global default for LOGGING, and just documented so that people who want to set LOGGING themselves can easily copy them as a starting point.

I'm actually for that, too. And the defaults should live in global_settings.py, not hard-coded in utils/log.py

Funny, it was exactly like that before it's been changed to the current way in 1.5 :-)
 

But we'll need some kind of deprecation path to get there, at least for people who currently have disable_existing_loggers=False, in order to prevent them from suddenly losing the default config.

I'm not familiar with the current deprecation policy in Django. If you can point me to it, I could probably carve some time in the nearby future and prepare a pull request.

[Claude Paroz]

Le vendredi 9 septembre 2016 07:31:42 UTC+2, Ivan Sagalaev a écrit :

I think the best end result would be one where LOGGING simply defines the full config and it is always applied (by Django) exactly once, and the defaults we want are set as the global default for LOGGING, and just documented so that people who want to set LOGGING themselves can easily copy them as a starting point.

I'm actually for that, too. And the defaults should live in global_settings.py, not hard-coded in utils/log.py

Funny, it was exactly like that before it's been changed to the current way in 1.5 :-)

As the committer of the current implementation, I must admit I was probably not aware of the weird behavior of disable_existing_loggers at the time.
The main drawback of the proposed solution is that each time we change the default LOGGING config, people with custom LOGGING will have to look at a diff of the change and manually merge the interesting parts in their custom config (hoping that they are reading the full release notes!). But I'm not sure there's a better solution.

Claude

[Carl Meyer]

On 09/08/2016 11:31 PM, Ivan Sagalaev wrote:
> I'm not familiar with the current deprecation policy in Django. If you
> can point me to it, I could probably carve some time in the nearby
> future and prepare a pull request.

Here is the deprecation policy:
https://docs.djangoproject.com/en/dev/internals/release-process/#deprecation-policy

As it applies to this case, basically we need to ensure that people's
existing logging config continues to function as it does now in the next
release of Django. If they need to make updates to their settings in
order to preserve the same logging behavior, we need a deprecation
warning raised that will alert them to to the need for this change (and
they should be able to silence the deprecation warning by making the
needed change).

I think there's probably some wiggle room in the definition of
"continues to function as it does now." As you pointed out, it's
probably OK if a logger that someone has currently silenced with
disable_existing_loggers=True starts giving output in the next version -
at least that's a change that they are likely to notice and can deal
with as desired. (It should still be noted in the release notes). But
it's a big problem if someone were to silently stop getting logging
output that they currently get.

Carl

[Cristiano Coelho]

I had troubles understanding the logging setup the first time, but after that, its quite simple on every project. I usually end up copy/pasting some console and db logger class and just add it to the config, I don't really think it is that difficult