Hi All,
Sorry for the long post, but I think I have a nice contribution to the
session handling mechanism, but I've got a bug I just can't track down.
Make yourself a cup of coffee, sit down and have a read.
In an effort to make session handling more transparent and less error
prone, I've added a new method called get_session to the request object.
(As an aside, I've also created a new apache config directive
PythonSessionOptions, a req.get_session_options() to read the directive,
and a small internal change to req.internal_redirect() to pass a session
to a redirected request).
req.get_session() returns the session instance if it exists or creates a
new one. Internally it calls some python code,
mod_python.Session.create_session(), which does the actual work. The
user will only use get_session() to access their session, and so all our
deadlocking issues are gone forever.
It mostly works, but I've found that approx 1 in 10000 requests will
segfault. Calling mod_python.Session.create_session directly does not
segfault (tested for 2000000 requests) so that is not the issue.
I really hope someone can spot where the problem is. I've reduced
everything to the simplest possible case. The unlock method in
TestSession very rarely segfault or raise an exception and then
segfault, but very rarely. It only fails 0.004% of the time based on
500000 requests. I suspect some kind of garbage collection issue, maybe
a circular reference caused by req->session->_req, but I don't
understand why it works 99.996 % of the time.
I've included the full error.log for 5000000 requests at the end of this
message, but the ones that caught my eye as unusual are:
[Tue Jun 07 17:52:02 2005] [notice] child pid 15066 exit signal
Segmentation fault (11)
Fatal Python error: deletion of interned string failed
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: Traceback (most recent call last):
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File "/usr/lib/python2.3/site-packages/mod_python/apache.py",
line 299, in HandlerDispatch\n result = object(req)
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File "/var/www/mp/mptest.py", line 19, in handler\n sess =
req.get_session()
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File
"/usr/lib/python2.3/site-packages/mod_python/TestSession.py", line 46,
in create_session\n return TestSession(req,sid)
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File
"/usr/lib/python2.3/site-packages/mod_python/TestSession.py", line 40,
in unlock\n if self._lock and self._locked:
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: AttributeError: 'TestSession' object has no attribute '_lock'
[Tue Jun 07 18:04:03 2005] [notice] child pid 16170 exit signal
Segmentation fault (11)
Fatal Python error: GC object already tracked
I hope someone can give me some insight to the problem. Note that I'm
using mpm-worker.
Regards,
Jim
------------------------------------------------------------------------
mptest.py
# the test handler
from mod_python import apache
from mod_python import TestSession
def handler(req):
req.content_type = 'text/plain'
req.write('mptest.py')
if req.path_info:
test_case = req.path_info[1:]
else:
test_case = '1'
if test_case == '1':
# the good case - always works
sess = TestSession.create_session(req,None)
elif test_case == '2':
# the bad case - sometimes segfaults
sess = req.get_session()
else:
req.write('no test specified')
return apache.OK
---------------------------------------------------------------------------------------------------
mod_python/TestSession.py
# emulate a simple test session
import _apache
from Session import _new_sid
class TestSession(object):
def __init__(self, req, sid=0, secret=None, timeout=0, lock=1):
req.log_error("TestSession.__init__")
self._req = req
self._lock = 1
self._locked = 0
self._sid = _new_sid(req)
self.lock()
self.unlock()
def lock(self):
if self._lock:
_apache._global_lock(self._req.server, self._sid)
self._locked = 1
def unlock(self):
# unlock will ocassionally segfault
if self._lock and self._locked:
_apache._global_unlock(self._req.server, self._sid)
self._locked = 0
def create_session(req,sid):
return TestSession(req,sid)
-------------------------------------------------------------------------------------------------
src/requestobject.c
In the following code session is a PyObject* defined in the the
requestobject struct.
static PyObject *req_get_session(requestobject *self, PyObject *args)
{
PyObject *m;
PyObject *sid;
if (!self->session) {
m = PyImport_ImportModule("mod_python.TestSession");
/* is this redirected request with an existing session? */
sid = PyObject_CallMethod(self->subprocess_env, "get",
"(ss)","REDIRECT_PYSID", "");
self->session = PyObject_CallMethod(m, "create_session",
"(OO)", self, sid);
Py_DECREF(m);
Py_DECREF(sid);
if (self->session == NULL)
return NULL;
}
return self->session;
}
--------------------------------------------------------------------------------------------------------
/var/log/apache2/error.log
The full error log for approx 500000 requests (generated using grep -v
"TestSession.__init" error.log).
[Tue Jun 07 16:35:32 2005] [notice] mod_python: Creating 32 session
mutexes based on 6 max processes and 25 max threads.
[Tue Jun 07 16:35:32 2005] [notice] Apache/2.0.54 (Debian GNU/Linux)
mod_python/3.2.0-dev-20050519 Python/2.3.5 configured -- resuming normal
operations
[Tue Jun 07 16:35:49 2005] [notice] child pid 11540 exit signal
Segmentation fault (11)
[Tue Jun 07 16:35:49 2005] [notice] child pid 11545 exit signal
Segmentation fault (11)
[Tue Jun 07 16:36:05 2005] [notice] child pid 11601 exit signal
Segmentation fault (11)
[Tue Jun 07 16:46:21 2005] [notice] child pid 11629 exit signal
Segmentation fault (11)
[Tue Jun 07 16:46:35 2005] [notice] child pid 11949 exit signal
Segmentation fault (11)
[Tue Jun 07 17:04:07 2005] [notice] child pid 12454 exit signal
Segmentation fault (11)
[Tue Jun 07 17:11:47 2005] [notice] child pid 12351 exit signal
Segmentation fault (11)
[Tue Jun 07 17:18:08 2005] [notice] child pid 12342 exit signal
Segmentation fault (11)
[Tue Jun 07 17:18:20 2005] [notice] child pid 13057 exit signal
Segmentation fault (11)
[Tue Jun 07 17:34:48 2005] [notice] child pid 12859 exit signal
Segmentation fault (11)
[Tue Jun 07 17:36:35 2005] [notice] child pid 13599 exit signal
Segmentation fault (11)
[Tue Jun 07 17:38:10 2005] [notice] child pid 13698 exit signal
Segmentation fault (11)
[Tue Jun 07 17:39:02 2005] [notice] child pid 13764 exit signal
Segmentation fault (11)
[Tue Jun 07 17:39:13 2005] [notice] child pid 13819 exit signal
Segmentation fault (11)
[Tue Jun 07 17:39:15 2005] [notice] child pid 13810 exit signal
Segmentation fault (11)
[Tue Jun 07 17:40:02 2005] [notice] child pid 13917 exit signal
Segmentation fault (11)
[Tue Jun 07 17:41:03 2005] [notice] child pid 13048 exit signal
Segmentation fault (11)
Fatal Python error: GC object already tracked
[Tue Jun 07 17:42:41 2005] [notice] child pid 14016 exit signal Aborted (6)
Fatal Python error: GC object already tracked
[Tue Jun 07 17:45:10 2005] [notice] child pid 14321 exit signal Aborted (6)
[Tue Jun 07 17:48:01 2005] [notice] child pid 14439 exit signal
Segmentation fault (11)
[Tue Jun 07 17:48:49 2005] [notice] child pid 14508 exit signal
Segmentation fault (11)
[Tue Jun 07 17:50:03 2005] [notice] child pid 14615 exit signal
Segmentation fault (11)
[Tue Jun 07 17:50:03 2005] [notice] child pid 14672 exit signal
Segmentation fault (11)
Fatal Python error: GC object already tracked
[Tue Jun 07 17:50:53 2005] [notice] child pid 14665 exit signal
Segmentation fault (11)
[Tue Jun 07 17:50:53 2005] [notice] child pid 14758 exit signal Aborted (6)
[Tue Jun 07 17:51:18 2005] [notice] child pid 14800 exit signal
Segmentation fault (11)
[Tue Jun 07 17:51:18 2005] [notice] child pid 14832 exit signal
Segmentation fault (11)
[Tue Jun 07 17:51:18 2005] [notice] child pid 14864 exit signal
Segmentation fault (11)
[Tue Jun 07 17:51:20 2005] [notice] child pid 14893 exit signal
Segmentation fault (11)
[Tue Jun 07 17:51:21 2005] [notice] child pid 14921 exit signal
Segmentation fault (11)
[Tue Jun 07 17:51:21 2005] [notice] child pid 14928 exit signal
Segmentation fault (11)
[Tue Jun 07 17:51:23 2005] [notice] child pid 14977 exit signal
Segmentation fault (11)
[Tue Jun 07 17:51:24 2005] [notice] child pid 15006 exit signal
Segmentation fault (11)
[Tue Jun 07 17:52:02 2005] [notice] child pid 15066 exit signal
Segmentation fault (11)
Fatal Python error: deletion of interned string failed
[Tue Jun 07 17:53:06 2005] [notice] child pid 15109 exit signal Aborted (6)
Fatal Python error: deletion of interned string failed
[Tue Jun 07 17:53:55 2005] [notice] child pid 15210 exit signal Aborted (6)
[Tue Jun 07 17:54:03 2005] [notice] child pid 15104 exit signal
Segmentation fault (11)
[Tue Jun 07 17:54:05 2005] [notice] child pid 15312 exit signal
Segmentation fault (11)
[Tue Jun 07 17:54:17 2005] [notice] child pid 15405 exit signal
Segmentation fault (11)
[Tue Jun 07 17:55:04 2005] [notice] child pid 15437 exit signal
Segmentation fault (11)
[Tue Jun 07 17:55:04 2005] [notice] child pid 15483 exit signal
Segmentation fault (11)
[Tue Jun 07 17:55:17 2005] [notice] child pid 15563 exit signal
Segmentation fault (11)
[Tue Jun 07 17:55:54 2005] [error] [client 192.168.1.12] PythonHandler
mptest: Traceback (most recent call last):
[Tue Jun 07 17:55:54 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File "/usr/lib/python2.3/site-packages/mod_python/apache.py",
line 287, in HandlerDispatch\n log=debug)
[Tue Jun 07 17:55:54 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File "/usr/lib/python2.3/site-packages/mod_python/apache.py",
line 422, in import_module\n module = sys.modules[module_name]
[Tue Jun 07 17:55:54 2005] [error] [client 192.168.1.12] PythonHandler
mptest: KeyError: 'mptest'
[Tue Jun 07 17:55:58 2005] [notice] child pid 15474 exit signal
Segmentation fault (11)
[Tue Jun 07 17:56:08 2005] [notice] child pid 15600 exit signal
Segmentation fault (11)
[Tue Jun 07 17:56:08 2005] [notice] child pid 15644 exit signal
Segmentation fault (11)
[Tue Jun 07 17:57:08 2005] [notice] child pid 15730 exit signal
Segmentation fault (11)
[Tue Jun 07 17:57:10 2005] [notice] child pid 15778 exit signal
Segmentation fault (11)
[Tue Jun 07 17:57:44 2005] [notice] child pid 15772 exit signal
Segmentation fault (11)
[Tue Jun 07 17:58:11 2005] [notice] child pid 15902 exit signal
Segmentation fault (11)
[Tue Jun 07 17:58:21 2005] [notice] child pid 15945 exit signal
Segmentation fault (11)
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: Traceback (most recent call last):
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File "/usr/lib/python2.3/site-packages/mod_python/apache.py",
line 299, in HandlerDispatch\n result = object(req)
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File "/var/www/mp/mptest.py", line 19, in handler\n sess =
req.get_session()
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File
"/usr/lib/python2.3/site-packages/mod_python/TestSession.py", line 46,
in create_session\n return TestSession(req,sid)
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: File
"/usr/lib/python2.3/site-packages/mod_python/TestSession.py", line 40,
in unlock\n if self._lock and self._locked:
[Tue Jun 07 17:58:57 2005] [error] [client 192.168.1.12] PythonHandler
mptest: AttributeError: 'TestSession' object has no attribute '_lock'
[Tue Jun 07 17:59:38 2005] [notice] child pid 15939 exit signal
Segmentation fault (11)
[Tue Jun 07 18:02:59 2005] [notice] child pid 15865 exit signal
Segmentation fault (11)
[Tue Jun 07 18:02:59 2005] [notice] child pid 16051 exit signal
Segmentation fault (11)
[Tue Jun 07 18:03:02 2005] [notice] child pid 16142 exit signal
Segmentation fault (11)
[Tue Jun 07 18:04:03 2005] [notice] child pid 16170 exit signal
Segmentation fault (11)
Fatal Python error: GC object already tracked
[Tue Jun 07 18:04:16 2005] [notice] child pid 16248 exit signal Aborted (6)
[Tue Jun 07 18:04:40 2005] [notice] child pid 16285 exit signal
Segmentation fault (11)
[Tue Jun 07 18:05:15 2005] [notice] child pid 16318 exit signal
Segmentation fault (11)
[Tue Jun 07 18:16:49 2005] [notice] child pid 16573 exit signal
Segmentation fault (11)
[Tue Jun 07 18:17:50 2005] [notice] child pid 16924 exit signal
Segmentation fault (11)