#12012 Logging: Final call for comments

[Russell Keith-Magee]

Hi all,

A final call for comment before I commit #12012 to trunk. Barring
objection, my intention is to commit this early next week.

I've integrated the suggestions that have arisen since the first draft:

* This patch has docs :-) There aren't any tests though, and I think
it's going to have to stay that way; this is one of those areas where
it's almost impossible to test because it's very difficult to mock out
early stages of app configuration. The good news is that the complex
logic is all contained inside Python's logging library itself, and the
logging calls that have been introduced are all exercised as part of a
normal test run.

* I've modified the interpretation of LOGGING_CONFIG such that a
value of None means "don't configure logging"

* I've modified the global-settings and project template logging
settings. They are now at parity.

* I've modified the logging information that is provided in the 4XX
loggers so that a status code is provided as logging context. 4XX
messages are all still logged as warnings, but if you want to change
this, you now have enough detail in the log record to use a log filter
for that purpose.

If you have any objections, now is the time to raise them.

Yours,
Russ Magee %-)

[Jacob Kaplan-Moss]

On Thu, Sep 30, 2010 at 8:56 AM, Russell Keith-Magee
<rus...@keith-magee.com> wrote:
> If you have any objections, now is the time to raise them.

This isn't an objection, per se -- don't let it stop you committing --
but I'm somewhat concerned with the verbosity of the LOGGING setting.
We're adding 40 lines of configuration to a file only about 100 lines
long, which to my mind means we've increased the cognitive load of
groking settings.py by about 40%. When I look at the new LOGGING
setting, I don't have a firm idea what it's doing.

Now, I know the format's coming straight from the new logging work in
Python 2.7, and I clearly don't want to come up with our own format.
I'm just hoping someone'll have a bright idea how to cut down on "oh
god WTF do those lines mean!?" nature of the new crud at the bottom of
settings.py

Jacob

[Russell Keith-Magee]

For posterity -- Jacob and I talked about this on IRC; we came to two
conclusions:

* I'll have a fiddle to see if I can make the default configuration
more concise. Given that the only logger we actually need to do
something is the AdminEmailHandler, there's probably some room to
leave out a couple of handlers and loggers, or at the very least give
some brief inline documentation of what is there.

* I'll include a comment in the project template that provides a
direct link to Django's logging documentation. If we're going to
introduce a big block of configuration, the least we can do is point
people at the instructions for how to use it.

One other thing that I forgot to mention in my original email: This
patch drops the startup.py proposal. It looks like Arthur Koziel's app
refactor will cover this use case, and we don't want to introduce an
interface that we deprecate in the next release.

Russ %-)

[Andy McCurdy]

Russ,

This will be a welcomed addition to debugging Django apps. I have a question about startup.py. I notice that startup runs after settings are loaded, but before models. Does this mean that code within startup.py cannot safely access the ORM? If the ORM is fully accessible in startup.py, it's safe to ignore the rest of the mail.

If I cannot access models from startup.py, I have two concerns:

1. It seems fairly limiting. We currently have a hacked together startup system for several ORM-related tasks. I'd love to replace this with yours, assuming I don't lose functionality. Most notable, we have configuration stored in the DB that is used to determine application behavior. Another use case is using the startup system to add some of our template tags libraries to builtins. Some of these template tag libs import models. Would this end up causing circular reference issues?

We used to have these kinds of tasks load on the first request Django processed using the request_started signal. However, this was limiting because management commands and celery tasks never received the signal. We need a system where no matter how our Django is loaded, startup happens.

2. What kind of error message am I going to receive if I do access models? Debugging circular references is quite painful. At the very least, we should consider a user trying to import models (or something else that imports models) a common error and attempt to present a concise error message.

-andy

--
You received this message because you are subscribed to the Google Groups "Django developers" group.
To post to this group, send email to django-d...@googlegroups.com.
To unsubscribe from this group, send email to django-develop...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/django-developers?hl=en.

[Russell Keith-Magee]

On Fri, Oct 1, 2010 at 1:53 AM, Andy McCurdy <sed...@gmail.com> wrote:
> Russ,
> This will be a welcomed addition to debugging Django apps. I have a question
> about startup.py. I notice that startup runs after settings are loaded, but
> before models. Does this mean that code within startup.py cannot safely
> access the ORM? If the ORM is fully accessible in startup.py, it's safe to
> ignore the rest of the mail.

The startup.py proposal has been dropped from the RC version of this patch.

I still believe that there is a strong need for a 'startup logic'
entry point, but it isn't required for the purposes of logging, and
there is a significant overlap with the concerns of the AppCache
refactor that was the subject of a SoC project this year. Rather than
introduce an interface that wasn't strictly needed and was potentially
going to be deprecated in the next release, we have opted to leave out
this piece of functionality.

Yours,
Russ Magee %-)

[Kevin Howerton]

re: verbose logging configuration.

This bothered me as well initially, though after starting to use
logging extensively I realized that there isn't really a more concise
way to provide all of the features that the logging config brings to
the table.

We can however, create a very concise default setup that mimics the
current admin-email behavior and provide additional documentation on
having more complex setups on djangoproject.com

ie:
LOGGING = {
'handlers': {
'mail_admins': { 'level': 'ERROR', 'class':
'django.utils.log.AdminEmailHandler' }
}
'loggers': {
'django': { 'handlers': ['mail_admins'], 'level':
'ERROR', 'propagate': True }
}
}

Regarding the 'version' setting.. .is that in the python 2.7
implementation? I ended up removing it from the included
logging-config in lumberjack as it wasn't really doing much.

I'm really pretty excited about this making it into 1.3... Thanks
guys! I haven't looked at the code extensively, but it looks really
good (a lot of improvements over what I had). I will take it for a
test drive this weekend though.

-k

[Russell Keith-Magee]

Hi all,

Following feedback from Jacob and others in IRC, I've just uploaded an
RC2 patch.

This patch:

* Dramatically simplifies the logging configuration, removing
everything that isn't absolutely required.

* Adds a note in the project template settings.py telling the user
what the default configuration does, and where to go for more
information.

* Adds a note in the docs that LOGGING_CONFIG=None just disables the
configuration process, it doesn't disable logging altogether.

* Corrects a typo in the example configuration regarding the
disable_existing_loggers setting.

These are fairly minor modifications, so I'm still intending to commit
early next week, barring major objections.

Yours,
Russ Magee %-)

[Vinay Sajip]

On Oct 1, 3:45 am, Kevin Howerton <kevin.hower...@gmail.com> wrote:
> Regarding the 'version' setting.. .is that in the python 2.7
> implementation?  I ended up removing it from the included
> logging-config in lumberjack as it wasn't really doing much.

Yes, it's required so that we can introduce schema changes in future
Python versions without breaking backwards compatibility. It's best to
leave it in, it's just an extra line after all.

Regards,

Vinay Sajip

[Kevin Howerton]

Hey...

Discussed with Russell on IRC ... line 21 of log.py...

# Ensure the creation of the Django logger
logger = logging.getLogger('django')

I guess it's trying to check if the logger exists? The getLogger
method will actually never fail (as far as I'm aware), as nothing
actually happens until you try to push a message to the handler(s) of
that logger... and at that point you will get a warning if the logger
doesn't have handlers associated with it.

I came up with this to check if a logger exists and has been setup,
you can test for the existence of handlers... ie:

logger = logging.getLogger('adsf')
if not logger.handlers:
dictConfig(settings.LOGGING)

I feel like that check is unnecessary anyhow... but I guess that's how
you'd do it if it is necessary.

-k

[Vinay Sajip]

On Oct 1, 10:28 pm, Kevin Howerton <kevin.hower...@gmail.com> wrote:

> # Ensure the creation of the Django logger
> logger = logging.getLogger('django')
>

I think the comment is misleading. I agree, there'd be no need to
create the logger there as it doesn't seem to be used there. Two
points:

1. Library code should add a NullHandler instance to the top-level
logger so that in the absence of any other configuration, you don't
get spurious "No handlers found ..." message. This should be just
after the logger = logging.getLogger('django') line:

logger.addHandler(NullHandler())

This line should always be there, and the NullHandler should be
omitted from the example configurations. Essentially, it's implicitly
there in addition to the handlers configured in settings.py. If this
is not done and the user turns off configuration via LOGGING_CONFIG =
None but omits to add any other configuration, you would get that "No
handlers found ..." message.

2. Library code should generally never add handlers (other than
NullHandler) unless it's under the application (site) developer's
control. That's happening in this case because of the convention with
LOGGING_CONFIG: the site developer is effectively telling Django to
add those handlers, albeit in a declarative way.

Hope that's clear!

Regards,

Vinay Sajip

[Vinay Sajip]

On Oct 1, 7:06 am, Russell Keith-Magee <russ...@keith-magee.com>
wrote:

>
> These are fairly minor modifications, so I'm still intending to commit
> early next week, barring major objections.
>

As per my answer to Kevin - I think a NullHandler addition to the
'django' logger needs to happen internally (not under a site
developer's control) and the 'null' handler should be removed from the
examples (as it won't be needed any more). That should make the
configuration dictionary even simpler :-)

Regards,

Vinay Sajip

[Kevin Howerton]

Definitely agree. Caught the missing nullhandler behavior when
logging is off too... though didn't make the connection that this was
likely intended to handle that case.

It might make more sense to put this logic in conf/__init__.py
following the calls to configure the logger. Though that doesn't
really matter as the handler could only be added once anyhow.

ie:

logger = logging.getLogger('django')

if not logger.handlers:
logger.addHandler(NullHandler())

Also didn't realize that adding a nullhandler to just the root logger
would remove those warnings (pretty cool)... ended up writing a bit
that adds a nullhandler to any logger without handlers for my
implementation in lumberjack... woops.

-k

[Vinay Sajip]

On Oct 2, 1:59 am, Kevin Howerton <kevin.hower...@gmail.com> wrote:

> Also didn't realize that adding a nullhandler to just the root logger
> would remove those warnings (pretty cool)... ended up writing a bit
> that adds a nullhandler to any logger without handlers for my
> implementation in lumberjack... woops.
>

Yes, that's because a search is done for handlers in all ancestors of
a logger (except when propagate is sent to False - ancestor scanning
stops there).

A very common case is for an application developer to just add
handlers to the root logger, to capture events from all components/
libraries used. That's usually what you need for development, though
sometimes you also have files fed by just one component (e.g. SQL
queries) . For production, of course, you have e.g. email handlers for
critical stuff as well, plus files just to catch errors, and so on.

Regards,

Vinay Sajip

[Russell Keith-Magee]

On Sat, Oct 2, 2010 at 8:59 AM, Kevin Howerton <kevin.h...@gmail.com> wrote:
> Definitely agree.  Caught the missing nullhandler behavior when
> logging is off too... though didn't make the connection that this was
> likely intended to handle that case.
>
> It might make more sense to put this logic in conf/__init__.py
> following the calls to configure the logger.  Though that doesn't
> really matter as the handler could only be added once anyhow.
>
> ie:
>
> logger = logging.getLogger('django')
> if not logger.handlers:
>   logger.addHandler(NullHandler())

Ok - I've added this code to my RC patch.

Thanks for the clarification, Vinay and Kevin.

Yours,
Russ Magee %-)