Best place for code that processes stuff from settings.py once (for logging implementation)
Simon Willison
add support for logging related settings in settings.py.
The current idea (suggested by Ivan Sagalaev) is to allow for a
standard Django-style setting that look something like this:
LOGGING = {
'django.db.sql': {
'handler': 'django.utils.log.StdErrHandler',
'level': 'DEBUG',
},
'django.errors': {
'handler': 'logging.handlers.SMTPHandler',
...
}
}
So each key is the name of a logger, and the value is a dictionary
that configures various aspects about how log events sent to that
logger be processed (what levels to pay attention to, what handler to
use etc). If a handler isn't mentioned in the LOGGING dictionary (it
will be empty by default) then all log messages sent to that handler
will be silently discarded.
To implement this, I need to write some code that executes only once,
iterates over the django.conf.settings.LOGGING dictionary and uses it
to make the relevant calls to the Python logging framework to set
everything up - the above should map to code something like this
executing:
logger = logging.getLogger('django.db.sql')
logger.setLevel(logging.DEBUG)
logger.addHandler(django.utils.log.StdErrHandler())
logger = logging.getLogger('django.errors')
logger.addHandler(logging.handlers.SMTPHandler(...))
Here's the problem: I need the above to happen once, on startup, some
time AFTER the user's settings have been loaded. I can't figure out
where the appropriate place to do this is.
The best example I've found of code that executes once in Django core
is the code in the Settings class constructor:
http://code.djangoproject.com/browser/django/trunk/django/conf/__init__.py#L62
This is where the time.tzset() call based on the TIME_ZONE setting
happens, for example.
Unfortunately, that code executes the first time anything attempts to
access a property on the django.conf.settings module (which is a
LazySettings module until the first time it is accessed). I could put
the logging stuff in there, but it feels like a bit of a cludge.
The other interesting happens-once execution point I found is the
AppCache class here, which is instantiated once the first time the
django.db.models.loading class is imported:
http://code.djangoproject.com/browser/django/trunk/django/db/models/loading.py#L15
It appears to use the terrifying Borg pattern to avoid being
instantiated more than once.
Neither of these seem like particularly suitable places to put code
that configures logger objects based on the LOGGING setting.
This relates to a wider problem I've had when working with Django
(which I've seen crop up all over the place, but I'm not sure there's
a best practice for handling) - what to do with Django application/
project code that should only be executed once. We had this problem
with class registration for the admin, and ended up hacking around it
with a call to admin.autoload() in the urls.py file - which seems to
have resulted in urls.py becoming a defacto standard place for putting
code that's meant to run once on startup.
For logging, I want advanced users to be able to write their own
Python logging configuration code (see example above) rather than
using the LOGGING setting. Should I tell them to put that in urls.py
as well?
I'm ashamed to admit it, but I tend to shy away from using signals in
my own code purely because I don't know where I should put the code
that registers them.
Is there a straight forward solution to this that I've been missing,
or is it an ongoing problem? If it's a problem, can we fix it? What
makes it so difficult to fix (I'm going to guess there's no easy
solution, or we would have sorted it out ages ago)? Are there any
previous discussions I should be reading to catch up on this?
Alternatively, should I just stick my log configuring code in the
Setting class constructor and leave well alone?
Thanks,
Simon
Simon Willison
> Alternatively, should I just stick my log configuring code in the
> Setting class constructor and leave well alone?
http://github.com/simonw/django/commit/eb9737129501a6d17014afdb55c8bb4d5222b693
Full patch against trunk here:
http://dpaste.com/hold/105598/
Same disclaimer applies: not meant as production code yet, feedback on
the implementation enthusiastically welcomed.
Simon Willison
> or is it an ongoing problem? If it's a problem, can we fix it? What
> makes it so difficult to fix (I'm going to guess there's no easy
> solution, or we would have sorted it out ages ago)? Are there any
> previous discussions I should be reading to catch up on this?
Benjamin Slavin
<si...@simonwillison.net> wrote:
>
> On Twitter Malcolm pointed me here: http://code.djangoproject.com/ticket/5685
That's my ticket, and I had mostly forgotten about it.
As you've found out, there is no way to hook into the bootstrap
process. For signals, we just stuff them somewhere (typically
__init__.py or models.py) where we expect them to be imported. I've
always felt that this is a bit of a kludge, but there's been no better
way to handle it.
Right now the primary solution is to patch Django itself, and there
are at least a few place where that could be done. Your approaches
(modifying the settings or models modules) rely on incidental behavior
-- these modules happen to be loaded in almost every case, so whatever
we throw in there will also get run.
The path I took was a more traditional approach to bootstrapping --
attaching the functionality to the code entry points: the various
request handlers and the management command module.
I'm still not happy with the implementation in the patch on that
ticket, but I think it's in the right direction.
Because of Django's initialization procedure, addressing the
bootstrapping process is actually a bit complex:
* Some things need to be run before any models are loaded.
Specifically... anything that wants to listen to the class_prepared
signal. This is quite hard because an accidental import of a model
creates all sorts of mess.
* Some things just need to be run before the Django environment is
used (to run a management command or handle a request)... registering
signal listeners, for example.
* Logging may need to come even earlier. If you truly want to log
everything, you'll want to run that code first.
The reason I opened #5685 was primarily because there is no way to
solve this problem without either:
1. Patching trunk
or
2. Writing a bunch of custom wrappers around the Django code to do the
setup... and these wrappers are tedious, easy to screw up and don't
play well with each other.
That means: I'm strongly in favor of any hook to allow code to be run
before the Django environment is setup, and I'm not tied to any
particular path of solving the problem.
Best,
- Ben
Simon Willison
> That means: I'm strongly in favor of any hook to allow code to be run
> before the Django environment is setup, and I'm not tied to any
> particular path of solving the problem.
than logging, signing and a smatter of CSRF stuff - but it would be
great to see some progress on this front. If anyone's looking for a
project, it strikes me that a very useful step one would be to go
through and document exactly how Django initialises itself at the
moment - what loads in what order, when are settings evaluated, what
bits of Django actually look at INSTALLED_APPS etc.
Jeremy Dunck
On Oct 12, 2009, at 11:04 AM, Simon Willison <si...@simonwillison.net>
wrote:
>
> On Oct 12, 9:03 am, Benjamin Slavin <benjamin.sla...@gmail.com> wrote:
>> That means: I'm strongly in favor of any hook to allow code to be run
>> before the Django environment is setup, and I'm not tied to any
>> particular path of solving the problem.
>
> a very useful step one would be to go
> through and document exactly how Django initialises itself at the
> moment - what loads in what order, when are settings evaluated, what
> bits of Django actually look at INSTALLED_APPS etc.
It's a bit dated now, but this might be a useful place to start.
http://code.djangoproject.com/wiki/DevModelCreation
>
Also, I bet Marty knows this area well from his book work.
Marty Alchin
> Also, I bet Marty knows this area well from his book work.
Actually, I didn't research much on the initialization process as a
whole, if there indeed is such a beast. I started with what happens
when Python actually encounters a model definition, which occurs after
settings and INSTALLED_APPS have been taken into account, which is
pretty much where the DevModelCreation article starts as well. Like
most people, I've generally deferred to James on the startup issue
here.
http://www.b-list.org/weblog/2007/nov/05/server-startup/
-Gul
Vinay Sajip
am ;-) - but how about the following: add a setting called e.g.
SETUP_CALLBACKS (or whatever name you prefer) which will be an
iterable (say, tuple) of callables which are called from
Settings.__init__ in the same way that Simon's code on ticket #12012
works. In fact you could have two sets of callables, one before
INSTALLED_APPS loading and one after, if you wanted to.
Obviously the callables would be restricted in what they could do, but
it need be no worse than the restrictions on e.g. what you can import
in settings.py.
Obviously this approach could be tweaked - e.g. instead of a tuple of
callables, you could have a tuple of (callable, args, kwargs) - but
that's detail. Is the basic idea workable?
Regards,
Vinay Sajip
Benjamin Slavin
> am ;-) - but how about the following: add a setting called e.g.
> SETUP_CALLBACKS (or whatever name you prefer) which will be an
> iterable (say, tuple) of callables which are called from
> Settings.__init__ in the same way that Simon's code on ticket #12012
> works. In fact you could have two sets of callables, one before
> INSTALLED_APPS loading and one after, if you wanted to.
There really is no such thing as "INSTALLED_APPS loading". I think
you mean "model loading"... if so, it's not quite so simple. Maybe
there's a way to make this approach work, but it's at least not as
easy as "let's just add these two settings".
> Obviously the callables would be restricted in what they could do, but
> it need be no worse than the restrictions on e.g. what you can import
> in settings.py.
The big offender here is that __import__ (and thus "import ..." and
"from ... import ...") has consequences. Models are initialized the
first time the Python interpreter sees them. I'll illustrate why this
is a problem through an example:
Lets say you have myapp/bootstrap.py and bootstrap.py does an import
(from myapp.views import some_signal_i_care_about) and myapp.views
imports myapp.models. Right there... with two seemingly innocuous
imports, we've broken the contract that the environment is pristine.
Now, if we register a listener for class_prepared, it will never* get
called for anything in myapp.models, or anything imported there. (*
From memory... this is true unless there's a deferred processing of a
model relationship, in which case it's even harder to predict the
outcome)
So, given the current state of affairs it goes beyond just "what they
could do" to "what could be imported". Even a stray import in an
__init__.py could create a series of problems.
> Obviously this approach could be tweaked - e.g. instead of a tuple of
> callables, you could have a tuple of (callable, args, kwargs) - but
> that's detail. Is the basic idea workable?
If we're building a bootstrapping system, it's likely possible to
introduce some additional logic into the metaclass approach that
models use, and work around this case.... but it's non-trivial.
I'd love to take a stab at this again, but am not sure when I'm going
to have time... so I'd be quite happy for someone else to beat me to
it.
Best,
- Ben
Vinay Sajip
> There really is no such thing as "INSTALLED_APPS loading". I think
> you mean "model loading"... if so, it's not quite so simple. Maybe
> there's a way to make this approach work, but it's at least not as
> easy as "let's just add these two settings".
# Expand entries in INSTALLED_APPS like "django.contrib.*" to a
list
# of all those apps.
new_installed_apps = []
for app in self.INSTALLED_APPS:
if app.endswith('.*'):
app_mod = importlib.import_module(app[:-2])
appdir = os.path.dirname(app_mod.__file__)
app_subdirs = os.listdir(appdir)
app_subdirs.sort()
name_pattern = re.compile(r'[a-zA-Z]\w*')
for d in app_subdirs:
if name_pattern.match(d) and os.path.isdir(os.path.join
(appdir, d)):
new_installed_apps.append('%s.%s' % (app[:-2],
d))
else:
new_installed_apps.append(app)
self.INSTALLED_APPS = new_installed_apps
I know it was sloppy of me to call it "INSTALLED_APPS loading" as that
happens in db/models/loading.py - I thought it would be clear from my
saying I was talking about calling from Settings.__init__().
> The big offender here is that __import__ (and thus "import ..." and
> "from ... import ...") has consequences. Models are initialized the
> first time the Python interpreter sees them. I'll illustrate why this
> is a problem through an example:
>
> Lets say you have myapp/bootstrap.py and bootstrap.py does an import
> (from myapp.views import some_signal_i_care_about) and myapp.views
> imports myapp.models. Right there... with two seemingly innocuous
> imports, we've broken the contract that the environment is pristine.
other django modules in settings.py. I thought I covered this by
saying "Obviously the callables would be restricted in what they could
can import in settings.py".
loading is done? Certainly for the logging configuration and other
configuration which isn't model-dependent, where is the problem? I
agree this limitation would need to be well documented and perhaps
have better error reporting.
> Now, if we register a listener for class_prepared, it will never* get
> called for anything in myapp.models, or anything imported there. (*
> From memory... this is true unless there's a deferred processing of a
> model relationship, in which case it's even harder to predict the
> outcome)
>
> So, given the current state of affairs it goes beyond just "what they
> could do" to "what could be imported". Even a stray import in an
> __init__.py could create a series of problems.
restrictions on e.g. what you can import in settings.py" to "what they
could do". Perhaps I should have specifically referred to "imports
made from code imported and called from settings.py", but I thought
that would be evident.
> If we're building a bootstrapping system, it's likely possible to
> introduce some additional logic into the metaclass approach that
> models use, and work around this case.... but it's non-trivial.
Importing problems in settings.py? Before I knew better, I once did
from django.db.backends.utils import CursorDebugWrapper
in settings.py, which seems innocuous and appears not to be model-
dependent in any way, and yet it gave an error:
"Error: Can't find the file 'settings.py' in the directory containing
'./manage.py'. It appears you've customized things.
You'll have to run django-admin.py, passing it your settings module.
(If the file settings.py does indeed exist, it's causing an
ImportError somehow.)"
We could certainly do with better error messages in such cases.
I'm not saying the approach I suggested was a complete fix for all the
problems people might have. But it seems to cover at least the use
case Simon started this thread with (logging configuration) in a way
that gives the user control over if and when and how logging gets
configured, early-ish in the game. It might apply to other types of
site-wide configuration, too.
Regards,
Vinay Sajip
Benjamin Slavin
> I know it was sloppy of me to call it "INSTALLED_APPS loading" as that
> happens in db/models/loading.py - I thought it would be clear from my
> saying I was talking about calling from Settings.__init__().
Ok... I see what you're saying. I've always viewed that block as
simple expanding the wildcard entries in INSTALLED_APPS and didn't get
that you were referring to it. My apologies for the misunderstanding
there.
>> The big offender here is that __import__ (and thus "import ..." and
>> "from ... import ...") has consequences. Models are initialized the
>> first time the Python interpreter sees them. I'll illustrate why this
>> is a problem through an example:
>
> Yes, but that's also true if you just try to import models or some
> other django modules in settings.py. I thought I covered this by
> saying "Obviously the callables would be restricted in what they could
> do, but it need be no worse than the restrictions on e.g. what you
> can import in settings.py".
I agree it's the same problem as in settings.py. That said, because
it's just one module and most people (from my experience) don't do
imports (aside from standard library stuff) in settings.py, it's a
much less complex interaction.
My concern -- borne from my own work to solve this problem -- is that
it gets very tricky to simply apply a set of coding practices to solve
the problem. I know that saying "you can't import anything that might
import a model" was difficult for my team. We got it to work, but it
did take a good bit of effort to get things working.
> Aren't we talking about the same thing - having to work with how model
> loading is done? Certainly for the logging configuration and other
> configuration which isn't model-dependent, where is the problem?
> I agree this limitation would need to be well documented and perhaps
> have better error reporting.
>
> That is why I specifically appended "but it need be no worse than the
> restrictions on e.g. what you can import in settings.py" to "what they
> could do". Perhaps I should have specifically referred to "imports
> made from code imported and called from settings.py", but I thought
> that would be evident.
We are mostly aligned. The problem, again, comes from the risk of
spurious imports. Maybe we were doing something wrong when we tried to
solve this previously... but I can tell you that the import problem
was a real pain for us.. even when we were trying to be careful.
So, I do understand the direction you're headed. My concern (from
experience) is that it's not as simple as the restrictions on
settings.py. In settings.py you have a single file to worry about and,
as I said before, we don't tend to see many imports there because it's
configuration not logic.
> Before I knew better, I once did
>
> from django.db.backends.utils import CursorDebugWrapper
>
> in settings.py, which seems innocuous and appears not to be model-
> dependent in any way, and yet it gave an error:
>
> "Error: Can't find the file 'settings.py' in the directory containing
> './manage.py'. It appears you've customized things.
> You'll have to run django-admin.py, passing it your settings module.
> (If the file settings.py does indeed exist, it's causing an
> ImportError somehow.)"
This is actually a different problem. It's a circular import:
django/db/__init__.py does an import of settings... which imports your
settings.py... which imports CursorDebugWrapper (which passes through
django/db/__init__.py)... and so on... so you're going to get an
ImportError.
The problem with doing the model importing is that in many cases it
won't generate an exception... it will just fail silently. For
example, signal listeners will be registered after the signal has
already fired.
However, I'm actually really glad you used this example. It's helped
me realized that the circular import problem actually means that we
can't explicitly or accidentally import our settings either... which
means even Simon's code would stop working.
settings.py
============
CALLBACKS = ['django.utils.log.setup']
django/utils/log.py
============
def setup(): # I've extrapolated this from Simon's current patch to
Settings.__init__()
from django.conf import settings # THIS WILL FAIL
log.configure_from_dict(settings.LOGGING)
Even passing the settings as an argument (to the callback) won't work
for many cases. For example, you can't register a listener for
class_prepared because django.db imports settings (as you saw).
I think that we need to keep settings as a discrete piece of
functionality -- establishing configuration.
It looks like I may actually be able to put a bit of time toward a new
implementation for this, so I'll keep the list posted.
- Ben
Vinay Sajip
> > I know it was sloppy of me to call it "INSTALLED_APPS loading" as that
> > happens in db/models/loading.py - I thought it would be clear from my
> > saying I was talking about calling from Settings.__init__().
>
> Ok... I see what you're saying. I've always viewed that block as
> simple expanding the wildcard entries in INSTALLED_APPS and didn't get
> that you were referring to it. My apologies for the misunderstanding
> there.
> My concern -- borne from my own work to solve this problem -- is that
> it gets very tricky to simply apply a set of coding practices to solve
> the problem. I know that saying "you can't import anything that might
> import a model" was difficult for my team. We got it to work, but it
> did take a good bit of effort to get things working.
>
> spurious imports. Maybe we were doing something wrong when we tried to
> solve this previously... but I can tell you that the import problem
> was a real pain for us.. even when we were trying to be careful.
> So, I do understand the direction you're headed. My concern (from
> experience) is that it's not as simple as the restrictions on
> settings.py. In settings.py you have a single file to worry about and,
> as I said before, we don't tend to see many imports there because it's
> configuration not logic.
> django/db/__init__.py does an import of settings... which imports your
> settings.py... which imports CursorDebugWrapper (which passes through
> django/db/__init__.py)... and so on... so you're going to get an
> ImportError.
in settings.py leads to headaches, not just premature imports of
models.
> However, I'm actually really glad you used this example. It's helped
> me realized that the circular import problem actually means that we
> can't explicitly or accidentally import our settings either... which
> means even Simon's code would stop working.
> functionality -- establishing configuration.
obvious place.
> It looks like I may actually be able to put a bit of time toward a new
> implementation for this, so I'll keep the list posted.
Regards,
Vinay Sajip
Vinay Sajip
> implementation for this, so I'll keep the list posted.
did: changed Django in two places, conf/__init__.py and db/models/
loading.py. Here's a link to the diff (relative to r11620):
http://gist.github.com/209519
The two changes are to look for settings called BOOTSTRAP_CALLBACKS
and PRE_MODEL_CALLBACKS, each of which supposed to be a tuple of
callables, and all the callbacks are called at the appropriate times.
Next, I ran django-admin.py startproject logtest to create a brand-new
project. I changed settings.py, here's a link to it. The interesting
changes are at the end, after "import logging".
http://gist.github.com/209522
So, I've actually added (in BOOTSTRAP_CALLBACKS) a callable to
initialise logging (and another callable to test it, commented out for
now). In PRE_MODEL_CALLBACKS, I've added a callable which registers a
listener for class_prepared.
I then ran "python manage.py validate" in the project directory, which
gave me 0 errors. The logtest.log file shows that the listener was
registered and called back as expected. Here's the link to the log
file:
http://gist.github.com/209526
So, we can initialise logging, register a class_prepared listener, and
log some information when it's called.
Ben, what do you think about this?
Regards,
Vinay Sajip
Ivan Sagalaev
> * Logging may need to come even earlier. If you truly want to log
> everything, you'll want to run that code first.
Is it really the case that we want to log everything? I believe that
logging after initialization is enough. And for my example of a logging
handler that uses ORM it's the only way it can work. Initialization by
definition shouldn't do anything interesting for an application
programmer to look for, it should either succeed or fail with an
exception saying that it "can't run your program, sorry".
As it stands now loading and processing of all the settings is the point
that marks success of initialization. So I'm with Simon in putting
logging somewhere where all the other settings get processed.
Vinay Sajip
> Is it really the case that we want to log everything? I believe that
> logging after initialization is enough. And for my example of a logging
working on Django internals, logging can be a good way of diagnosing
problems which could occur anywhere in the system. So the more
coverage, the better.
> handler that uses ORM it's the only way it can work. Initialization by
> definition shouldn't do anything interesting for an application
> programmer to look for, it should either succeed or fail with an
> exception saying that it "can't run your program, sorry".
scenarios, but if there's a problem with the ORM system itself you'd
probably want to diagnose it using file-based handlers.
> As it stands now loading and processing of all the settings is the point
> that marks success of initialization. So I'm with Simon in putting
> logging somewhere where all the other settings get processed.
three places where you can hook into Django initialization -
Settings.__init__, pre app/model loading and post app/model loading.
My test will demonstrate initialization of logging at the first hook
point, then capture of the class_prepared signal in pre app/model
loading so that model loading can be watched, then post app/model
loading to show that you can use models in the hooked code.
Regards,
Vinay Sajip