Psycopg2/mod_wsgi problem: Two different Decimal classes
Ben Hoyt
Our web app is showing a critical error: We're seeing multiple copies
of the Decimal class -- the id's of the classes themselves are
different.
Printing stuff in decimal.py's __new__:
decimal.Decimal == <class 'decimal.Decimal'>
id(decimal.Decimal) == 147710692
value.__class__ == <class 'decimal.Decimal'>
id(value.__class__) == 144723308
We can get it to happen in requests about once every 10 minutes,
intermittently. And it's happening when value comes from psycopg2
(from a Postgres NUMERIC).
When it occurrs it means that psycopg2 can't convert to Decimal,
because Decimal.__new__ uses isinstance(value, Decimal) -- which says,
"No, it's not Decimal" because the id's of the classes are different,
even though it clearly is a decimal.Decimal instance.
Ideas, anyone?
Notes:
* We're running web.py 0.21 with Python 2.4.4, Apache 2.2.3, mod_wsgi,
psycopg 2.0.5.1, and PostgreSQL 8.1.4.
* We've reduced Apache's number of processes and threads to 1 (one),
and it still occurs.
* To "print" that stuff out, we're actually setting local vars so we
see those things in the Django error traceback.
Thanks,
Ben.
--
Ben Hoyt, +64 21 331 841
http://www.benhoyt.com/
Graham Dumpleton
> Hi guys,
>
> Our web app is showing a critical error: We're seeing multiple copies
> of the Decimal class -- the id's of the classes themselves are
> different.
>
> Printing stuff in decimal.py's __new__:
>
> decimal.Decimal == <class 'decimal.Decimal'>
> id(decimal.Decimal) == 147710692
>
> value.__class__ == <class 'decimal.Decimal'>
> id(value.__class__) == 144723308
Pardon my ignorance, but what package is decimal.py from?
> We can get it to happen in requests about once every 10 minutes,
> intermittently. And it's happening when value comes from psycopg2
> (from a Postgres NUMERIC).
>
> When it occurrs it means that psycopg2 can't convert to Decimal,
> because Decimal.__new__ uses isinstance(value, Decimal) -- which says,
> "No, it's not Decimal" because the id's of the classes are different,
> even though it clearly is a decimal.Decimal instance.
>
> Ideas, anyone?
>
> Notes:
> * We're running web.py 0.21 with Python 2.4.4, Apache 2.2.3, mod_wsgi,
> psycopg 2.0.5.1, and PostgreSQL 8.1.4.
> * We've reduced Apache's number of processes and threads to 1 (one),
> and it still occurs.
> * To "print" that stuff out, we're actually setting local vars so we
> see those things in the Django error traceback.
Would need more information about what code is in what files and
whether you are relying on mod_wsgi ability to reload the WSGI
application script file, but similar issues to this are often seen
when module reloaders are used. The issue in relation to pickling is
described for mod_wsgi in:
http://code.google.com/p/modwsgi/wiki/IssuesWithPickleModule
Do you see your problem if you do a full restart of Apache and then
use your application without changing any code, or have you only been
seeing it after you have been trying to change code and rely on some
automatic module reloader?
Graham
Aaron Swartz
Ben Hoyt
Pardon my ignorance, but what package is decimal.py from?
It's a standard library module (on its own -- not in a package), but it's new in Python 2.4:
http://docs.python.org/lib/module-decimal.html
Would need more information about what code is in what files and
whether you are relying on mod_wsgi ability to reload the WSGI
application script file, but similar issues to this are often seen
when module reloaders are used.
Okay, we've dug a bit deeper: Decimal was pretty much a red herring. It seemed awfully like a Decimal or __new__ problem, so we didn't look at mod_wsgi and reloading till late today.
It definitely has to do with module reloading (but, Aaron, we have web.reloader off, so it's not a web.py issue). We actually didn't realise mod_wsgi was doing any reloading at all, but then looking at the docs more closely it says reloading's on by default (WSGIScriptReloading On).
We're not 100% sure, but our main problem seems to be this:
"For many WSGI applications [the mod_wsgi reloading] mechanism will generally work fine, however there are a few limitations on what is reloaded, plus some Python C extension modules can be incompatible with this feature." (from the bottom of http://code.google.com/p/modwsgi/wiki/ApplicationIssues)
We're using psycopg2, which is a Python module written mostly in C, and the C module is doing an import decimal. We see further down in that mod_wsgi wiki page that we should have been "cautious if using any Python database client".
Graham, we realise it's not exactly a mod_wsgi problem, but because of the weird nature of the bugs that crop up, and because using Python database clients is a fairly common thing in web apps, we think it'd be *much* safer to have WSGIScriptReloading Off by default. What do you think?
Do you see your problem if you do a full restart of Apache and then
use your application without changing any code ...
Yeah, that's the one thing we still don't understand -- why the problem happened in the first place. It was happening after a full restart of Apache and without editing or changing any code. Why was reloading kicking in at all? Or are we still missing something?
Now we've turned WSGIScriptReloading Off and haven't seen it since ... though it's a bit hard to be certain, as the error didn't reliably occur before. But we *think* it's good now.
The issue in relation to pickling is described for mod_wsgi in:
http://code.google.com/p/modwsgi/wiki/IssuesWithPickleModule
Ah, that's interesting. We're using pickle too -- I think I'll have a good read of that right now. :-)
Cheers,
Ben.
Graham Dumpleton
> (Forwarding this to the mod_wsgi group as well, just for reference.)
Hmm, hasn't showed up there yet.
> Pardon my ignorance, but what package is decimal.py from?
>
> It's a standard library module (on its own -- not in a package), but it's
> new in Python 2.4:http://docs.python.org/lib/module-decimal.html
Ahh, my box only has Python 2.3, so no wonder I couldn't find it. :-)
> Would need more information about what code is in what files and
>
> > whether you are relying on mod_wsgi ability to reload the WSGI
> > application script file, but similar issues to this are often seen
> > when module reloaders are used.
>
> Okay, we've dug a bit deeper: Decimal was pretty much a red herring. It
> seemed awfully like a Decimal or __new__ problem, so we didn't look at
> mod_wsgi and reloading till late today.
>
> It definitely has to do with module reloading (but, Aaron, we have
> web.reloader off, so it's not a web.py issue). We actually didn't realise
> mod_wsgi was doing any reloading at all, but then looking at the docs more
> closely it says reloading's on by default (WSGIScriptReloading On).
>
> We're not 100% sure, but our main problem seems to be this:
>
> "For many WSGI applications [the mod_wsgi reloading] mechanism will
> generally work fine, however there are a few limitations on what is
> reloaded, plus some Python C extension modules can be incompatible with this
> feature." (from the bottom ofhttp://code.google.com/p/modwsgi/wiki/ApplicationIssues)
>
> We're using psycopg2, which is a Python module written mostly in C, and the
> C module is doing an import decimal. We see further down in that mod_wsgi
> wiki page that we should have been "cautious if using any Python database
> client".
>
> Graham, we realise it's not exactly a mod_wsgi problem, but because of the
> weird nature of the bugs that crop up, and because using Python database
> clients is a fairly common thing in web apps, we think it'd be *much* safer
> to have WSGIScriptReloading Off by default. What do you think?
I need to cover in documentation better the purpose of the WSGI
application script file. That is, that in the main it should be
regarded as stepping stone only to trigger into the actual application
which would be stored in a normal set of Python modules or packages
outside of your Apache document tree. This is how one would use it
with Django, TurboGears, Trac, MoinMoin etc. The web.py package is a
bit different as applications are small enough that they can be fit in
the WSGI application script file.
Being a stepping stone, it is reloaded on changes to make it easier
for people, especially in web hosting environment, to get second
chance to get their configuration correct if they stuff it up the
first time. If reloading wasn't enabled, they would have to get the
whole of Apache restarted instead, thus potentially having to annoy
site admins.
How much actual caching of global data and application logic do you
have in the script file.
> Do you see your problem if you do a full restart of Apache and then
>
> > use your application without changing any code ...
>
> Yeah, that's the one thing we still don't understand -- why the problem
> happened in the first place. It was happening after a full restart of Apache
> and without editing or changing any code. Why was reloading kicking in at
> all? Or are we still missing something?
Maybe.
What I would suggest is setting:
LogLevel info
in your main Apache configuration file. This will turn on additional
logging from mod_wsgi, including messages when it is loading and/or
reloading WSGI script files and when it is creating interpreters for
the first time.
That may help to understand the issue better.
Graham
Graham Dumpleton
> We're not 100% sure, but our main problem seems to be this:
>
> "For many WSGI applications [the mod_wsgi reloading] mechanism will
> generally work fine, however there are a few limitations on what is
> reloaded, plus some Python C extension modules can be incompatible with this
>
> We're using psycopg2, which is a Python module written mostly in C, and the
> C module is doing an import decimal. We see further down in that mod_wsgi
> wiki page that we should have been "cautious if using any Python database
> client".
Do not that that section in the documentation only refers to when you
have explicitly set:
WSGIReloadMechanism Interpreter
The default is to only reload the WSGI script file, not destroy and
recreate the whole interpreter. Thus, unless you had gone and set that
directive, the specific problems mentioned in there would not be an
issue.
As I previously suggested, try increasing the log level so that
exactly when the script file is being reloaded is displayed and try
and cross reference any behaviour to that.
Graham
Ben Hoyt
Okay, the plot thickens ... we turned "WSGIScriptReloading Off", and we thought that fixed it, but it hadn't. Same old bug -- two Decimal classes.
What I would suggest is setting "LogLevel info"
Good call. We did this, and the error.log snippet looks like this (from starting Apache through till the error occurs -- this probably won't line-wrap nicely, but oh well):
[Fri Jul 13 21:35:14 2007] [info] Server: Apache/2.2.3, Interface: mod_ssl/2.2.3, Library: OpenSSL/0.9.8e
[Fri Jul 13 21:35:14 2007] [info] mod_wsgi (pid=26971): Attach interpreter ''.
[Fri Jul 13 21:35:14 2007] [info] mod_wsgi (pid=26976): Attach interpreter ''.
[Fri Jul 13 21:35:14 2007] [notice] Apache/2.2.3 (Debian) configured -- resuming normal operations
[Fri Jul 13 21:35:14 2007] [info] Server built: Apr 15 2007 14:32:15
[Fri Jul 13 21:36:01 2007] [info] mod_wsgi (pid=26971): Create interpreter ' demo.micropledge.com|'.
[Fri Jul 13 21:36:02 2007] [info] mod_wsgi (pid=26976): Create interpreter 'micropledge.com|'.
[Fri Jul 13 21:38:01 2007] [info] mod_wsgi (pid=26971): Create interpreter 'micropledge.com| '.
[Fri Jul 13 21:38:01 2007] [info] mod_wsgi (pid=26976): Create interpreter 'demo.micropledge.com|'.
[Fri Jul 13 21:40:16 2007] [error] [client 202.78.158.138] Traceback ... (funny decimal/class bug)
So you can see we have two virtual hosts running mod_wsgi apps -- is this a problem?
It's doing "Create interpreter" TWICE for each host, two minutes apart -- why would this be? And the second time, micropledge.com| uses the same pid as demo.micropledge.com| did the first time. Doing some more testing, things work fine when it just loads the interpreters once (i.e., we only get the first two "Create interpreter" lines above) ... but when it loads an interpreter for the same host over an old host's pid (like it did above), that's when the bad stuff happens.
We've put a "print >> debug_file, timestamp, pid, etc" line into decimal.py, so that we can see whenever it gets loaded, and it's definitely getting loaded four times here -- once for each "Create interpreter".
And the problem -- occurring only on demo.micropledge.com -- is because decimal.py is loaded into pid=26976 for micropledge.com| the first time, and it's loaded again into pid=26976 for demo.micropledge.com| the second time when the error occurs. The two Decimal classes created are different (isinstance and their id's say so) and so they sometimes conflict when demo.micropledge.com requests are handled.
To cut a long story short: We're only testing on and getting the errors on demo.micropledge.com, but our other host micropledge.com seems to be interfering with demo's process and/or interpreter (and therefore its Decimal type).
Any further ideas?
Do you think it's a mod_wsgi issue, or something with our setup? We're running a pretty standard mod_wsgi config -- the only config directive we have is WSGIScriptAlias and "WSGIScriptReloading Off".
How much actual caching of global data and application logic do you
have in the script file.
import sys, os
sys.path += [os.path.dirname(__file__)]
import web # web.py
import config, errors, urls, util # our stuff
web.wsgifunc(web.webpyfunc(urls, globals()))
The only other thing to note is that we also have another virtual host running Trac under mod_python, but this hasn't been a problem to date, and I'm almost certain it's not the issue.
Cheers,
Ben.
Ben Hoyt
Do you think it's a mod_wsgi issue, or something with our setup? We're running a pretty standard mod_wsgi config -- the only config directive we have is WSGIScriptAlias and "WSGIScriptReloading Off".
Hmmm, I've done some more tests, and things aren't getting any clearer. It's not related to mod_wsgi at all. It happens when we have just one site running mod_wsgi, and it happens when mod_wsgi isn't even loaded (both sites running on mod_python).
But it is something to do with two different interpreter instances interfering with each other. Or at least two different versions of decimal.py being loaded (and hence two types of Decimal class).
mod_python doesn't have quite as good info logging as mod_wsgi, so I can't quite tell what's happening there, but if I have the sites running on mod_wsgi, I see the problem I described bofore: an interpreter for micropledge.com is being loaded into the same process on top of (?) the interpreter for demo.micropledge.com.
And one id of the Decimal class is from the first interpreter in that process, the other from the other interpreter, but both are being seen at the same time when isinstance() bombs out.
-Ben
Graham Dumpleton
If you are also using psycopg2 and the problems relates to use of
decimal module in conjunction with that somehow, then I would
speculate that it could be psycopg2 that is the problem.
The particular problem I am thinking of derives from the fact that C
extension modules are only loaded once per process. Thus, where there
are multiple Python sub interpreters they all use the same version of
the internal C extension module within psycopg2. This is a problem for
two reasons.
The first problem is that different sub interpreters cannot use
different versions of a C extension module. If they do use different
versions then the version loaded first will take precedence. When a
second version is then loaded from another sub interpreter, the C
extension module already loaded is used instead, and the Python
wrappers for the alternate version may not work with that first C
extension module.
The second problem is if the C extension module hasn't been written so
that it will work if used from multiple sub interpreters at the same
time. The sort of issues that can arise here is if the C extension
module caches Python objects injected into the C extension module from
one sub interpreter, and the C extension module tries to reuse that
cached Python object in executing code for a different sub
interpreter.
In this problem of caching, imagine that the Decimal class type is
being cached from one sub interpreter, but is then being used in
checks across multiple sub interpreters. As you might be able to see
that would then cause isinstance checks to fail if the cached Decimal
class type is used in calls from sub interpreters other than which the
Decimal class type originated.
If you can post your two VirtualHost definitions I could give a more
accurate example, but what I suggest you do is use the daemon mode of
mod_wsgi to delegate the running of your demo site WSGI application to
a dedicated daemon sub process, thus ensuring it isn't running in the
same process as your main site. That should ensure there is no
possibility for conflict. Thus:
<VirtualHost *:80>
ServerName demo.micropledge.com
CustomLog logs/demo.micropledge.com-errors_log common
WSGIDaemonProcess demo.micropledge.com threads=15
WSGIProcessGroup demo.micropledge.com
WSGIScriptAlias / /some/path/demo.wsgi
...
</VirtualHost>
<VirtualHost *:80>
ServerName micropledge.com
ServerAlias www.micropledge.com
WSGIScriptAlias / /some/path/production.wsgi
...
</VirtualHost>
The CustomLog directive will ensure that all mod_wsgi messages related
to the demo site WSGI application go into its own log file.
I would still really like to see your VirtualHost configurations
though and particularly whether you are using a wildcard in your
ServerAlias directive. I saw a recent problem with mod_python which I
could not explain, and the only strange thing about it that made it
different was that a wildcard was being used with ServerAlias
directive, with the wildcard pattern overlapping the ServerName for an
alternate VirtualHost container.
Graham
Graham Dumpleton
> decimal module in conjunction with that somehow, then I would
> speculate that it could be psycopg2 that is the problem.
This is definitely a problem in psycopg2 and I probably should log an
issue against that package telling them that their package is unusable
from multiple applications in different interpreters under mod_python
or mod_wsgi. The problem code in psycopg2 is:
PyObject *decimalType = NULL;
/* psyco_decimal_init
Initialize the module's pointer to the decimal type. */
void
psyco_decimal_init(void)
{
#ifdef HAVE_DECIMAL
PyObject *decimal = PyImport_ImportModule("decimal");
if (decimal) {
decimalType = PyObject_GetAttrString(decimal, "Decimal");
}
else {
PyErr_Clear();
decimalType = (PyObject *)&PyFloat_Type;
Py_INCREF(decimalType);
}
#endif
}
/** DECIMAL - cast any kind of number into a Python Decimal object **/
#ifdef HAVE_DECIMAL
static PyObject *
typecast_DECIMAL_cast(char *s, Py_ssize_t len, PyObject *curs)
{
PyObject *res = NULL;
char *buffer;
if (s == NULL) {Py_INCREF(Py_None); return Py_None;}
if ((buffer = PyMem_Malloc(len+1)) == NULL)
PyErr_NoMemory();
strncpy(buffer, s, (size_t) len); buffer[len] = '\0';
res = PyObject_CallFunction(decimalType, "s", buffer);
PyMem_Free(buffer);
return res;
}
#else
#define typecast_DECIMAL_cast typecast_FLOAT_cast
#endif
In other words, they do exactly like I suspected, which is to cache a
reference to the Decimal type object and then use that from multiple
sub interpreters.
The only solution as I already described is to use daemon mode of
mod_wsgi to force applications to run in different processes.
Will be fun to see what the psycopg2 people have to say. :-)
Graham
Graham Dumpleton
http://www.initd.org/tracker/psycopg/ticket/192
Graham
On Jul 14, 3:44 pm, Graham Dumpleton <Graham.Dumple...@gmail.com>
wrote:
Ben Hoyt
This is definitely a problem in psycopg2 and I probably should log an
issue against that package telling them that their package is unusable
Aha! Thank you, thank you very much!
We haven't tried daemon mode yet (will soon), but if C modules are only loaded once per process instead of once per interpreter, then yeah, that's definitely the problem. What a nightmare!
PyObject *decimal = PyImport_ImportModule("decimal");
if (decimal) {
decimalType = PyObject_GetAttrString(decimal, "Decimal");
}
Incidentally, we looked at that code snippet just the other day, and it *looked* fine then ... but of course we hadn't realised the thing about C modules only being loaded once per process.
Does this mean there'd be no easy way to fix this problem using mod_python (unless psycopg2 was fixed)? Not that we care to go back now.
Will be fun to see what the psycopg2 people have to say. :-)
Yes, will indeed. Thanks for submitting the psycopg bug ticket.
Once again, cheers. Our love for mod_wsgi is doubled. Perhaps trebled. :-)
-Ben
Graham Dumpleton
> > This is definitely a problem in psycopg2 and I probably should log an
> > issue against that package telling them that their package is unusable
>
> Aha! Thank you, thank you very much!
>
> We haven't tried daemon mode yet (will soon), but if C modules are only
> loaded once per process instead of once per interpreter, then yeah, that's
> definitely the problem. What a nightmare!
>
> PyObject *decimal = PyImport_ImportModule("decimal");
>
> > if (decimal) {
> > decimalType = PyObject_GetAttrString(decimal, "Decimal");
> > }
>
> Incidentally, we looked at that code snippet just the other day, and it
> *looked* fine then ... but of course we hadn't realised the thing about C
> modules only being loaded once per process.
>
> Does this mean there'd be no easy way to fix this problem using mod_python
> (unless psycopg2 was fixed)?
Correct, if using just mod_python there wouldn't be a way around it
except for fixing psycopg2. At least in mod_wsgi one can use daemon
mode to delegate applications to separate processes thereby avoiding
the issue.
I am actually quite surprised that this issue hasn't come up
previously with mod_python as the code in psycopg2 has been there for
many years.
FWIW, I have extended my documentation on application issues when
using mod_wsgi to add a section on problems with multiple
interpreters.
http://code.google.com/p/modwsgi/wiki/ApplicationIssues
Described there are general problems with extension modules when using
multiple sub interpreters, plus this specific issue.
Look forward to seeing how you go with daemon mode of mod_wsgi as a
way of getting around this.
Graham
Brent Pedersen
so i've hit this problem as well though i think it might have been
with a datetime object, not a decimal.... i've switched to pgdb for
now, but prefer psycopg2. is it confirmed that psycopg2 works in
daemon mode? i am ignorant of how that works, would it be restricted
to processes=1 threads=1 in order to avoid similar problems?
thanks,
-brent
Graham Dumpleton
The issue is not number of processes and/or threads, but which sub
interpreter the application runs in and whether there are other
applications in same process running in other sub interpreters.
In short, delegate each application to a separate daemon process using
mod_wsgi daemon mode. Then force the application to run in the main
interpreter of their respective processes, by setting:
WSGIApplicationGroup %{GLOBAL}
So, one application per process group and all running in the main
Python interpreter and not a secondary sub interpreter.
Graham
Brent Pedersen
i also see this ticket: http://www.initd.org/tracker/psycopg/ticket/192
is fixed, so maybe i'll try the svn version.
thanks
-brent
Evren Esat Özkan
I'm using Django with mod_python/psycog2 and faced with same decimal
errors some time ago.
Till that time, I'm using psycopg1. Now I tried latest svn version of
psycopg2 but I still getting same errors.
It says "If running in the main interpreter, use a cached version of
the Decimal object. Else repeat the object lookup." in bugfix
message.
I have "PythonInterpreter projectname" lines in all apache config
files. May be I'm doing something wrong with these interpereter
stuff??
Is this svn release solved your decimal errors?
Thanks,
Evren
On Nov 5, 6:28 pm, "Brent Pedersen" <bpede...@gmail.com> wrote:
> ah, ok. i got that set up no problem.
> i also see this ticket:http://www.initd.org/tracker/psycopg/ticket/192
> is fixed, so maybe i'll try the svn version.
> thanks
> -brent
>
Graham Dumpleton
> Hello,
>
> I'm using Django with mod_python/psycog2 and faced with same decimal
> errors some time ago.
> Till that time, I'm using psycopg1.
were using psycopg1 then it cant be the same error as I don't believe
it supports the Decimal type.
Graham
Evren Esat Özkan
give me these decimal errors. Then I realized it's reason and switched
to p1. Yesterday I installed p2 from latest svn trunk but same errors
occured again. Then I complety removed p2 and switched my all 4
django sites to p1 but I still got *same* decimal errors. I don't know
how this can be possible but I checked; tried to "import psycopg2" and
it gaves me import error, and django debug screen says it using
"postgresql" as db adapter.
So I gived up and switched to mod_wsgi. I hope I'll never see this
decimal errors again.
Thank you for your interest.
Evren
On Nov 20, 11:57 pm, Graham Dumpleton <Graham.Dumple...@gmail.com>