Something wicked is going on with identity or sqlobject

[Alberto]

Hi,

I'm almost ready to go on production (sort of) with two sites i'm
building built with turbogears.
After deploying with mod_python/Apacje2 on a debian box I decided to
stress the server with ab2 but, unfortunately, if I go over 10
concurrent requests, the server log (cherrypy's) gets crowded with
tracebacks like these:

15/Jan/2006:22:05:00 HTTP INFO Traceback (most recent call last):
File
"/usr/lib/python2.4/site-packages/CherryPy-2.2.0beta-py2.4.egg/cherrypy/_cphttptools.py",
line 96, in _run
applyFilters('before_main')
File
"/usr/lib/python2.4/site-packages/CherryPy-2.2.0beta-py2.4.egg/cherrypy/filters/__init__.py",
line 131, in applyFilters
method()
File "/home/alberto/turbogears/turbogears/visit.py", line 99, in
beforeMain
visit=self.get_visit()
File "/home/alberto/turbogears/turbogears/visit.py", line 139, in
get_visit
return self.new_visit()
File "/home/alberto/turbogears/turbogears/visit.py", line 122, in
new_visit
visit= TG_Visit( visit_key=visit_key, expiry=now+self.timeout )
File
"/usr/lib/python2.4/site-packages/SQLObject-0.7.1dev_r1500-py2.4.egg/sqlobject/main.py",
line 1197, in __init__
self._create(id, **kw)
File
"/usr/lib/python2.4/site-packages/SQLObject-0.7.1dev_r1500-py2.4.egg/sqlobject/main.py",
line 1221, in _create
self.set(**kw)
File
"/usr/lib/python2.4/site-packages/SQLObject-0.7.1dev_r1500-py2.4.egg/sqlobject/main.py",
line 1142, in set
self._connection._SO_update(self, args)
File
"/usr/lib/python2.4/site-packages/SQLObject-0.7.1dev_r1500-py2.4.egg/sqlobject/dbconnection.py",
line 561, in _SO_update
self.query("UPDATE %s SET %s WHERE %s = %s" %
AttributeError: 'TG_Visit' object has no attribute 'id'

15/Jan/2006:22:05:00 HTTP INFO Traceback (most recent call last):
File
"/usr/lib/python2.4/site-packages/CherryPy-2.2.0beta-py2.4.egg/cherrypy/_cphttptools.py",
line 96, in _run
applyFilters('before_main')
File
"/usr/lib/python2.4/site-packages/CherryPy-2.2.0beta-py2.4.egg/cherrypy/filters/__init__.py",
line 131, in applyFilters
method()
File "/home/alberto/turbogears/turbogears/visit.py", line 99, in
beforeMain
visit=self.get_visit()
File "/home/alberto/turbogears/turbogears/visit.py", line 139, in
get_visit
return self.new_visit()
File "/home/alberto/turbogears/turbogears/visit.py", line 122, in
new_visit
visit= TG_Visit( visit_key=visit_key, expiry=now+self.timeout )
File
"/usr/lib/python2.4/site-packages/SQLObject-0.7.1dev_r1500-py2.4.egg/sqlobject/main.py",
line 1197, in __init__
self._create(id, **kw)
File
"/usr/lib/python2.4/site-packages/SQLObject-0.7.1dev_r1500-py2.4.egg/sqlobject/main.py",
line 1224, in _create
self._SO_finishCreate(id)
File
"/usr/lib/python2.4/site-packages/SQLObject-0.7.1dev_r1500-py2.4.egg/sqlobject/main.py",
line 1242, in _SO_finishCreate
del self.sqlmeta._creating
AttributeError: _creating

ab2 says 411 requests failed (out of 500), which is intolerable for
me/my client.

I can reproduce the problem with cherrypy's built in server so I don't
think it's mod_python related. Seems to me sqlobject, multithread
related... Anyone experienced similar problems under high load?

Cheers, Alberto

[Alberto]

Thanks to
http://pythonpaste.org/archives/message/20051202.225107.c9697187.en.html
I've finally found the problem:

It seems sqlobject is not thread-safe when initializing sqlobjects
(though it claims to be). The following patch to visit.py works around
it (and also makes the visit key more secure as someone pointed out in
the group). Sorry for posting it here but trac seems to be down again.

Index: turbogears/visit.py
===================================================================
--- turbogears/visit.py (revisión: 516)
+++ turbogears/visit.py (copia de trabajo)
@@ -7,6 +7,7 @@
from sqlobject import *
from sqlobject.sqlbuilder import *
from datetime import *
+from random import random

hub = PackageHub("turbogears.visit")
__connection__ = hub
@@ -109,10 +110,15 @@
# instead change cherrypy.request.objectPath to the url
desired.
cherrypy.request.objectPath= e.path

+ def _make_key(self, seed=None):
+ ''' Returns a (pseudo)random hash based on seed '''
+ rand_str = str(seed) + str(random()) +
str(cherrypy.request.remoteHost) + str(cherrypy.request.remotePort)
+ return sha.new(rand_str).hexdigest()
+
def new_visit( self ):
log.info( "Creating new visit" )
- now= datetime.now()
- visit_key= sha.new(str(now)).hexdigest()
+ now = datetime.now()
+ visit_key = self._make_key(now)

visit= TG_Visit( visit_key=visit_key, expiry=now+self.timeout
)

self.send_cookie( visit_key )

@@ -224,9 +230,15 @@
self.lock.release()

+lock = threading.RLock()
class TG_Visit(SQLObject):
class sqlmeta:
table="tg_visit"
+ def __init__(self, *args, **kwargs):
+ lock.acquire()
+ return_value = super(TG_Visit, self).__init__(*args, **kwargs)
+ lock.release()
+ return return_value

visit_key= StringCol( length=40, alternateID=True,
alternateMethodName="by_visit_key" )

[Kevin Dangoor]

On 1/16/06, Alberto <alb...@toscat.net> wrote:
>
> Thanks to
> http://pythonpaste.org/archives/message/20051202.225107.c9697187.en.html
> I've finally found the problem:
>
> It seems sqlobject is not thread-safe when initializing sqlobjects
> (though it claims to be). The following patch to visit.py works around
> it (and also makes the visit key more secure as someone pointed out in
> the group). Sorry for posting it here but trac seems to be down again.

Oh yeah. That's a good catch.

Now that Trac is up, can you submit the patch there? I've been having
bad luck with emailed patches.

Kevin

[Alberto]

There it is
http://trac.turbogears.org/turbogears/attachment/ticket/397/threading.patch.
Alberto

[Jeff Watkins]

Patches should only address one issue. The visit cookie should not be
modified in the same patch as a hack to get around a flaw in SQLObject.

Have you checked whether this threading problem is present without the
reloader thread?

Jeff

--
Jeff Watkins
http://nerd.newburyportion.com/

[Alberto]

> Patches should only address one issue. The visit cookie should not be
> modified in the same patch as a hack to get around a flaw in SQLObject.

Yep, sorry, I just diffed in a hurry and had the visit key already
hacked so the patch included both hacks. I've uploaded to the Trac two
separate patches, one for the key and one for sqlobject (In the same
ticket, though.. If the Trac is up I'll create a separate ticket for
the key thingie when I finish writing this)

I've posted the sqlobject patch at sqlobject's sourceforge tracker too.

> Have you checked whether this threading problem is present without the
> reloader thread?
>

Reloader thread?? Do you mean:

a) the template reloader? (I'm too lazy/busy to check right now in the
code if it's threaded or something.
b) the visit-expiration-time-updater-thread?
c) cherrypy's module reloader?
d) none of the above.

If the answer is (a), the yes as I'm running with kid.precompiled=True
as to work around the "None not callable" bug on a semi-production
site.
If you mean (b) then no, as I don't know how to "turn it off".
If you mean (c) then yes as it's on "production" environment (I think
cherrypy's autoreloader thread is off in "production", am I wrong?).
If the answer is d, the I don't know what you mean :)

Anyway, I'm pretty sure it's an sqlobject's bug as Randall Smith
described the exact same problem before at
http://pythonpaste.org/archives/message/20051202.225107.c9697187.en.html
(it's where I "stole" the hack from)

I'm pretty sure it's not an identity bug anyway, just what made the bug
arise so this probably shouldn't have spilled to your side. It's the
first thing I saw on the traceback though, and I posted way before
investigating... my apologies.

Cheers,
Alberto

[Jeff Watkins]

Alberto wrote:
> Reloader thread?? Do you mean:
>
> a) the template reloader? (I'm too lazy/busy to check right now in the
> code if it's threaded or something.
> b) the visit-expiration-time-updater-thread?
> c) cherrypy's module reloader?
> d) none of the above.

I meant a & c. You can't turn off the visit updater thread. (If someone
doesn't want it, he can turn off Visit Tracking all together.)

> If the answer is (a), the yes as I'm running with kid.precompiled=True
> as to work around the "None not callable" bug on a semi-production
> site.

> If you mean (c) then yes as it's on "production" environment (I think
> cherrypy's autoreloader thread is off in "production", am I wrong?).

Grrr... I was afraid of that. I'll look at the code to see whether
there's anything else I can do to make certain this doesn't come up.
Part of the problem is that the Visit code *may* be executing outside
the standard TG transaction. I try to wrap the operations in a
transaction to get around SQLObject's broken caching, but I guess it
didn't work.

> I'm pretty sure it's not an identity bug anyway, just what made the bug
> arise so this probably shouldn't have spilled to your side. It's the
> first thing I saw on the traceback though, and I posted way before
> investigating... my apologies.

Hah. I wasn't really worried it was a visit/identity bug (it just didn't
feel like it), but I don't want anything to stand in the way of TG
developers *using* visit/identity.

--
Jeff Watkins
http://newburyportion.com/

[Alberto]

Well, the patch I've posted at ticket 397 for sqlobject DOES solve the
problem. I'm pretty sure it is an SQLObject's bug as: it's also
reported by Randall Smith, it's solved by this patch and, as I
understand it, python doesn't guarantee thread-safeness for the
__init__ method.

SQLObject's comments are outdated as they say something about the new()
method of MetaSQLObject being threadsafe (at sqlobject/main.py), which
therefore makes SQLObject instances initialization threadsafe. I've
grepped around and could not find MetaSQLObject anywhere. On the other
hand, SQLObject's metaclass is DeclariveMeta, which delegates the
class's initialization to the class's __classinit__ method, so my guess
is that the old behaviour has been replaced by this. Someone more
familiar with sqlobject's internals, please correct me if I'm wrong.

Anyway, what I wanted to say is that I'm pretty sure SQLObject is the
cause of this bug, and the patch fixes it so I think it's better not to
work around it but fixing the root cause as this is something that will
affect ALL SQLObject instances, it just happens a TG_Visit instance is
initizalized on each request, so the stressing with ab2 with many
concurrent requests made the bug arise.

I know this is not the (only) place I should post it, but this list
seems more alive than sqlobject's AND TG has a Trac.

> Hah. I wasn't really worried it was a visit/identity bug (it just didn't
> feel like it), but I don't want anything to stand in the way of TG
> developers *using* visit/identity.

Don't worry, I'm using it ;)

Cheers, Alberto

[Kevin Dangoor]

On 1/17/06, Alberto <alb...@toscat.net> wrote:
> Anyway, what I wanted to say is that I'm pretty sure SQLObject is the
> cause of this bug, and the patch fixes it so I think it's better not to
> work around it but fixing the root cause as this is something that will
> affect ALL SQLObject instances, it just happens a TG_Visit instance is
> initizalized on each request, so the stressing with ab2 with many
> concurrent requests made the bug arise.

Yes, this is an SQLObject bug. I mentioned your patch over on the
sqlobject list to make sure they're aware of it. Using locks is a way
to fix this for now.

Kevin