|
Jamie Kirkpatrick
jkp at kirkconsulting.co.uk
Tue Mar 15 15:25:27 EST 2005
On 14 Mar 2005, at 11:13, Graham Dumpleton wrote:
>
> On Monday, March 14, 2005, at 08:07 PM, Jamie Kirkpatrick wrote:
>> That said, have you setup use of Apache in the main configuration
>> file
>>
>> or in a .htaccess file? Can you post what configuration you are using
>>
>> so we can see if it is pretty normal or something strange? Post it if
>>
>> you can.
>>
>> I can post but its rather long - I am pretty darn confident that
>> there is nothing wrong with the config tho. I havent changed barely
>> anything from the stock install, in-fact, I can reproduce the error
>> by leaving everything as is from when the install is performed and
>> only adding a python handler to the default htdocs directory. The
>> only thing I have consistently changed is the port the server is
>> listening on to port 8080. I have tested with the minimum of
>> changes: added a handler and dropped in a small test script.
>
> The whole Apache config file isn't required, but just the small
> section where
> your define SetHandler/AddHandler and PythonHandler. Ie., the
> appropriate
> <Directory> construct covering your htdocs directory. This is just to
> get the
> whole picture and clarify that it is being done within a Directory
> directive
> as opposed to being at global scope in the config.
DocumentRoot "/opt/local/apache2/htdocs"
<Directory />
Options FollowSymLinks
AllowOverride None
</Directory>
<Directory "/opt/local/apache2/htdocs">
AddHandler mod_python .py
PythonHandler mod_python.publisher
PythonDebug On
Options Indexes FollowSymLinks
AllowOverride None
Order allow,deny
Allow from all
</Directory>
<snip>
> Sending a copy of the hello.py wouldn't hurt as well.
cat hello.py
def hello(name=None):
if name:
return 'Hello, %s!' % name.capitalize()
else:
return 'Hello there!'
>
> Based on your other answers, is very strange and nothing obvious
> stands out.
> The next thing I would try is to localise where the 500 error
> actually gets
> raised. There are four possible places it could be occurring. These
> are:
>
> 1. In Python code executed within the handler itself.
>
> 2. In the Python code part of mod_python. Ie., somewhere within the
> file
> lib/python/mod_python/apache.py.
>
> 3. In the C code part of mod_python. Ie., somewhere within the file
> src/mod_python.c.
>
> 4. In Apache itself somewhere prior to, but possibly after mod_python
> is
> invoked. Lets hope not. :-)
>
> Elimination of 1 is pretty straight forward by using a test handler
> which
> contains:
>
> from mod_python import apache
> apache.log_error("start import")
>
> def handler(req):
> apache.log_error("start handler")
> req.content_type = "text/plain"
> req.send_http_header()
> req.write("Hello World!")
> apache.log_error("end handler")
> return apache.OK
>
> apache.log_error("end import")
Using the above code after a stop / start i get this in the error_log:
[Tue Mar 15 19:31:49 2005] [notice] mod_python: Creating 32 session
mutexes based on 150 max processes and 0 max threads.
[Tue Mar 15 19:31:49 2005] [notice] Digest: generating secret for
digest authentication ...
[Tue Mar 15 19:31:49 2005] [notice] Digest: done
[Tue Mar 15 19:31:50 2005] [notice] Apache/2.0.53 (Unix) DAV/2
mod_python/3.1.3 Python/2.4 configured -- resuming normal operations
[Tue Mar 15 19:31:54 2005] [notice] mod_python: (Re)importing module
'test'
[Tue Mar 15 19:31:54 2005] [error] start import
[Tue Mar 15 19:31:54 2005] [error] end import
[Tue Mar 15 19:31:54 2005] [error] start handler
[Tue Mar 15 19:31:54 2005] [error] end handler
All normal. BUT, when I use a restart, it doesnt even get that far:
[Tue Mar 15 19:33:11 2005] [notice] mod_python: Creating 32 session
mutexes based on 150 max processes and 0 max threads.
[Tue Mar 15 19:33:11 2005] [notice] Digest: generating secret for
digest authentication ...
[Tue Mar 15 19:33:11 2005] [notice] Digest: done
[Tue Mar 15 19:33:12 2005] [notice] Apache/2.0.53 (Unix) DAV/2
mod_python/3.1.3 Python/2.4 configured -- resuming normal operations
Nothing shows in the log as you can see. Then a stop / start again and
everything is normal.
>
> If the 500 error is not generated from within the import of the
> handler
> module or the handler itself when called, you should see in the Apache
> error log all of the messages above.
>
> BTW, as an extra precaution, if Apache is able to write to your
> document
> directories, you may want to manually remove any ".pyc" files that may
> have been generated as the result of a prior test, before running the
> test.
It isn't, but thanks anyway. I take it it caches stuff?
>
> To test out 2, one would need to modify
> lib/python/mod_python/apache.py
> and reinstall it. You should add calls to apache.log_error() into
> apache.py
> to track where it may get to within its execution.
>
> I think the appropriate place to place log statements in that file is
> at
> the start of the class method:
>
> def HandlerDispatch(self, req):
>
> log_error("start dispatch")
>
> Prior to the final return of the method, add:
>
> log_error("end dispatch %s"%str(result))
>
> There is a return part way through the method which returns a 500
> error,
> but it is preceded by logging of a message anyway.
Right - so i alterterd the file, recompiled and installed (I mean
forced a recompilation of the python object files). On a normal run
(stop/start) using the above handler i get this in the error_log:
[Tue Mar 15 20:06:28 2005] [notice] Apache/2.0.53 (Unix) DAV/2
mod_python/3.1.3 Python/2.4 configured -- resuming normal operations
[Tue Mar 15 20:06:31 2005] [error] start dispatch
[Tue Mar 15 20:06:31 2005] [notice] mod_python: (Re)importing module
'test'
[Tue Mar 15 20:06:31 2005] [error] start import
[Tue Mar 15 20:06:31 2005] [error] end import
[Tue Mar 15 20:06:31 2005] [error] start handler
[Tue Mar 15 20:06:31 2005] [error] end handler
[Tue Mar 15 20:06:31 2005] [error] end dispatch 0
And everything works fine. However, when I restart I see nothing in
the error_log:
[Tue Mar 15 20:09:17 2005] [notice] SIGHUP received. Attempting to
restart
[Tue Mar 15 20:09:17 2005] [notice] mod_python: Creating 32 session
mutexes based on 150 max processes and 0 max threads.
[Tue Mar 15 20:09:17 2005] [notice] Digest: generating secret for
digest authentication ...
[Tue Mar 15 20:09:17 2005] [notice] Digest: done
[Tue Mar 15 20:09:18 2005] [notice] Apache/2.0.53 (Unix) DAV/2
mod_python/3.1.3 Python/2.4 configured -- resuming normal operations
That shows the restart and there is nothing following it even after I
pull up the 500 error several times. Access_log shows 500 errors:
192.168.2.2 - - [15/Mar/2005:20:09:20 +0000] "GET /test.py HTTP/1.1"
500 641
192.168.2.2 - - [15/Mar/2005:20:09:35 +0000] "GET /test.py HTTP/1.1"
500 641
>
> If it is found that 500 is being returned from the method, this would
> localise the cause of the problem to this method. At this point we
> would
> have to start analysing further the method and the potential sources
> of
> the 500 error by adding more logging and checking where result is
> being
> set to 500.
>
> If this method always returns a 200 status response, yet the browser
> still sees 500, we would have to consider number 3 above.
As it doesn't even seem to be getting as far as calling the method
since the first message isnt logged then I guess this points to the C
code?
>
> At this point things get a bit trickier as one is dealing with the C
> code.
> It is worth noting though that most instances of where a 500 response
> are
> generated in the mod_python.c file are preceded by message logging.
> The
> only ones that aren't are all of the form:
>
> /* get/create interpreter */
> idata = get_interpreter(interp_name, req->server);
>
> if (!idata)
> return HTTP_INTERNAL_SERVER_ERROR;
>
> Not being able to get/create the interpreter is pretty severe and if
> that
> was happening then no Python code at all would be getting executed. I
> am
> not sure why this situation couldn't be logged as well. Thus instead
> of
> that above, have:
>
> if (!idata) {
> ap_log_rerror(APLOG_MARK, APLOG_NOERRNO|APLOG_ERR, 0, req,
> "python_handler: Can't get/create
> interpreter.");
>
> return HTTP_INTERNAL_SERVER_ERROR;
> }
OK - so this does indeed seem to be the case. On a restart I get the
message logged:
[Tue Mar 15 20:20:55 2005] [notice] Apache/2.0.53 (Unix) DAV/2
mod_python/3.1.3 Python/2.4 configured -- resuming normal operations
[Tue Mar 15 20:20:59 2005] [error] [client 192.168.2.2] python_handler:
Can't get/create interpreter.
So, at least we have a better idea where things are going wrong
(unfortunately its in the C code). One thing of note. I noticed that
after restarting httpd and doing `ps ax | grep httpd` I saw some
strange results. If I havent yet called a page (just restarted) I can
see only one instance. However, as soon as I call a script (and get
the 500 error) I see multiple instances of httpd -
7717 ?? Ss 0:01.23 /opt/local/apache2/bin/httpd -k start
7792 ?? S 0:00.02 /opt/local/apache2/bin/httpd -k start
7793 ?? S 0:00.01 /opt/local/apache2/bin/httpd -k start
7794 ?? S 0:00.01 /opt/local/apache2/bin/httpd -k start
7795 ?? S 0:00.00 /opt/local/apache2/bin/httpd -k start
7796 ?? S 0:00.01 /opt/local/apache2/bin/httpd -k start
They dont die either. This is obvioulsy wrong, but whats causing it I
dont know. Hope that gives you a better idea on whats going on. Let
me know what to try next and I'll do it when I get a moment.
Cheers
Jamie
|