path: root/docs/user-guides/debugging-techniques.rst

====================
Debugging Techniques
====================

Be it when initially setting up mod_wsgi for the first time, or later
during development or use of your WSGI application, you are bound to get
some sort of unexpected Python error. By default all you are usually going
to see as evidence of this is a HTTP 500 "Internal Server Error" being
displayed in the browser window and little else.

The purpose of this document is to explain where to go look for more
details on what caused the error, describe techniques one can use to have
your WSGI application generate more useful debug information, as well as
mechanisms that can be employed to interactively debug your application.

Note that although this document is intended to deal with techniques which
can be used when using mod_wsgi, many of the techniques are also directly
transferable or adaptable to other web hosting mechanisms for WSGI
applications.

Apache Error Log Files
----------------------

When using mod_wsgi, unless you or the web framework you are using takes
specific action to catch exceptions and present the details in an alternate
manner, the only place that details of uncaught exceptions will be recorded
is in the Apache error log files. The Apache error log files are therefore
your prime source of information when things go wrong.

Do note though that log messages generated by mod_wsgi are logged with
various severity levels and which ones will be output to the Apache error
log files will depend on how Apache has been configured. The standard
configuration for Apache has the !LogLevel directive being set to 'warn'.
With this setting any important error messages will be output, but
informational messages generated by mod_wsgi which can assist in working
out what it is doing are not. Thus, if new to mod_wsgi or trying to debug a
problem, it is worthwhile setting the Apache configuration to use 'info'
log level instead::

    LogLevel info

If your Apache web server is only providing services for one host, it is
likely that you will only have one error log file. If however the Apache
web server is configured for multiple virtual hosts, then it is possible
that there will be multiple error log files, one corresponding to the main
server host and an additional error log file for each virtual host. Such a
virtual host specific error log if one is being used, would have been
configured through the placing of the Apache CustomLog directive within
the context of the VirtualHost container.

Although your WSGI application may be hosted within a particular virtual
host and that virtual host has its own error log file, some error and
informational messages will still go to the main server host error log
file. Thus you may still need to consult both error log files when using
virtual hosts.

Messages of note that will end up in the main server host error log file
include notifications in regard to initialisation of Python and the
creation and destruction of Python sub interpreters, plus any errors which
occur when doing this.

Messages of note that would end up in the virtual host error log file, if
it exists, include details of uncaught Python exceptions which occur when
the WSGI application script is being loaded, or when the WSGI application
callable object is being executed.

Messages that are logged by a WSGI application via the 'wsgi.errors' object
passed through to the application in the WSGI environment are also logged.
These will go to the virtual host error log file if it exists, or the main
error log file if the virtual host is not setup with its own error log file.
Thus, if you want to add debugging messages to your WSGI application code,
you can use 'wsgi.errors' in conjunction with the 'print' statement as shown
below::

    def application(environ, start_response):
        status = '200 OK'
        output = b'Hello World!'

        print >> environ['wsgi.errors'], "application debug #1"

        response_headers = [('Content-type', 'text/plain'),
                            ('Content-Length', str(len(output)))]
        start_response(status, response_headers)

        print >> environ['wsgi.errors'], "application debug #2"

        return [output]

If 'wsgi.errors' is not available to the code which needs to output log
messages, then it should explicitly direct output from the 'print'
statement to 'sys.stderr'::

    import sys

    def function():
        print >> sys.stderr, "application debug #3"
            ...

If ``sys.stderr`` or ``sys.stdout`` is used directly then
these messages will end up in the main server host error log file and not
that for the virtual host unless the WSGI application is running in a
daemon process specifically associated with a virtual host.

Do be aware though that writing to ``sys.stdout`` is by default
restricted in versions of mod_wsgi prior to 3.0 and will result in an
exception occurring of the form::

    IOError: sys.stdout access restricted by mod_wsgi

This is because portable WSGI applications should not write to
``sys.stdout`` or use the 'print' statement without specifying an
alternate file object besides ``sys.stdout`` as the target. This
restriction can be disabled for the whole server using the
WSGIRestrictStdout directive, or by mapping ``sys.stdout`` to
``sys.stderr`` at global scope within in the WSGI application script
file::

    import sys
    sys.stdout = sys.stderr

In general, a WSGI application should always endeavour to only log messages
via the 'wsgi.errors' object that is passed through to a WSGI application
in the WSGI environment. This is because this is the only way of logging
messages for which there is some guarantee that they will end up in a log
file that you might have access to if using a shared server.

An application shouldn't however cache 'wsgi.errors' and try to use it
outside of the context of a request. If this is done an exception will be
raised indicating that the request has expired and the error log object
is now invalid.

That messages output via ``sys.stderr`` and ``sys.stdout`` end up in
the Apache error logs at all is provided as a convenience but there is no
requirement in the WSGI specification that they are valid means of a WSGI
application logging messages.

Displaying Request Environment
------------------------------

When a WSGI application is invoked, the request headers are passed as CGI
variables in the WSGI request environment. The dictionary used for this
also holds information about the WSGI execution environment and mod_wsgi.
This includes mod_wsgi specific variables indicating the name of the
process and application groups within which the WSGI application is
executing.

Knowing the values of the process and application group variables can be
important when needing to validate that your Apache configuration is doing
what you intended as far as ensuring your WSGI application is running in
daemon mode or otherwise.

A simple way of validating such details or getting access to any of the
other WSGI request environment variables is to substitute your existing
WSGI application with one which echos back the details to your browser.
Such a task can be achieved with the following test application. The
application could be extended as necessary to display other information as
well, with process ID, user ID and group ID being shown as examples::

    import cStringIO
    import os

    def application(environ, start_response):
        headers = []
        headers.append(('Content-Type', 'text/plain'))
        write = start_response('200 OK', headers)

        input = environ['wsgi.input']
        output = cStringIO.StringIO()

        print >> output, "PID: %s" % os.getpid()
        print >> output, "UID: %s" % os.getuid()
        print >> output, "GID: %s" % os.getgid()
        print >> output

        keys = environ.keys()
        keys.sort()
        for key in keys:
            print >> output, '%s: %s' % (key, repr(environ[key]))
        print >> output

        output.write(input.read(int(environ.get('CONTENT_LENGTH', '0'))))

        return [output.getvalue()]

For the case of the process group as recorded by the
'mod_wsgi.process_group' variable in the WSGI request environment, if the
value is an empty string then the WSGI application is running in embedded
mode. For any other value it will be running in daemon mode with the process
group named by the variables value.

Note that by default WSGI applications run in embedded mode, which means
within the Apache server child processes which accept the original requests.
Daemon mode processes would only be used through appropriate use of the
WSGIDaemonProcess and WSGIProcessGroup directives to delegate the WSGI
application to a named daemon process group.

For the case of the application group as recorded by the
'mod_wsgi.application_group' variable in the WSGI request environment, if the
value is an empty string then the WSGI application is running in the main
Python interpreter. That is, the very first interpreter created when Python
was initialised. For any other value it indicates it is running in the named
Python sub interpreter.

Note that by default WSGI applications would always run in a sub
interpreter rather than the main interpreter. The name of this sub
interpreter would be automatically constructed from the name of the server
or virtual host, the URL mount point of the WSGI application and the number
of the listener port when it is other than ports 80 or 443.

To delegate a WSGI application to run in main Python interpreter, the
WSGIApplicationGroup directive would need to have been used with the value
'%{GLOBAL}'. Although the value is '%{GLOBAL}', this translates to the
empty string seen for the value of 'mod_wsgi.application_group' within the
WSGI request environment.

The WSGIApplicationGroup directive could also be used to designate a
specific named sub interpreter rather than that selected automatically.

For newcomers this can all be a bit confusing, which is where the test
application comes in as you can use it to validate where your WSGI
application is running is where you intended it to run.

The set of WSGI request environment variables will also show the WSGI
variables indicating whether process is multithreaded and whether the
process group is multiprocess or not. For a more complete explanation
of what that means see documentation of
:doc:`../user-guides/processes-and-threading`.

Tracking Request and Response
-----------------------------

Although one can use above test application to display the request
environment, it is replacing your original WSGI application. Rather than
replace your existing application you can use a WSGI middleware wrapper
application which logs the details to the Apache error log instead::

    # Original WSGI application.

    def application(environ, start_response):
        ...

    # Logging WSGI middleware.

    import pprint

    class LoggingMiddleware:

        def __init__(self, application):
            self.__application = application

        def __call__(self, environ, start_response):
            errors = environ['wsgi.errors']
            pprint.pprint(('REQUEST', environ), stream=errors)

            def _start_response(status, headers, *args):
                pprint.pprint(('RESPONSE', status, headers), stream=errors)
                return start_response(status, headers, *args)

            return self.__application(environ, _start_response)

    application = LoggingMiddleware(application)

The output from the middleware would end up in the Apache error log for the
virtual host, or if no virtual host specific error log file, in the main
Apache error log file.

For more complicated problems it may also be necessary to track both the
request and response content as well. A more complicated middleware which
can log these as well as header information to the file system is as
follows::

    # Original WSGI application.

    def application(environ, start_response):
        ...

    # Logging WSGI middleware.

    import threading
    import pprint
    import time
    import os

    class LoggingInstance:
        def __init__(self, start_response, oheaders, ocontent):
            self.__start_response = start_response
            self.__oheaders = oheaders
            self.__ocontent = ocontent

        def __call__(self, status, headers, *args):
            pprint.pprint((status, headers)+args), stream=self.__oheaders)
            self.__oheaders.close()

            self.__write = self.__start_response(status, headers, *args)
            return self.write

        def __iter__(self):
            return self

        def write(self, data):
            self.__ocontent.write(data)
            self.__ocontent.flush()
            return self.__write(data)

        def next(self):
            data = self.__iterable.next()
            self.__ocontent.write(data)
            self.__ocontent.flush()
            return data

        def close(self):
            if hasattr(self.__iterable, 'close'):
                self.__iterable.close()
            self.__ocontent.close()

        def link(self, iterable):
            self.__iterable = iter(iterable)

    class LoggingMiddleware:

        def __init__(self, application, savedir):
            self.__application = application
            self.__savedir = savedir
            self.__lock = threading.Lock()
            self.__pid = os.getpid()
            self.__count = 0

        def __call__(self, environ, start_response):
            self.__lock.acquire()
            self.__count += 1
            count = self.__count
            self.__lock.release()

            key = "%s-%s-%s" % (time.time(), self.__pid, count)

            iheaders = os.path.join(self.__savedir, key + ".iheaders")
            iheaders_fp = file(iheaders, 'w')

            icontent = os.path.join(self.__savedir, key + ".icontent")
            icontent_fp = file(icontent, 'w+b')

            oheaders = os.path.join(self.__savedir, key + ".oheaders")
            oheaders_fp = file(oheaders, 'w')

            ocontent = os.path.join(self.__savedir, key + ".ocontent")
            ocontent_fp = file(ocontent, 'w+b')

            errors = environ['wsgi.errors']
            pprint.pprint(environ, stream=iheaders_fp)
            iheaders_fp.close()

            length = int(environ.get('CONTENT_LENGTH', '0'))
            input = environ['wsgi.input']
            while length != 0:
                data = input.read(min(4096, length))
                if data:
                    icontent_fp.write(data)
                    length -= len(data)
                else:
                    length = 0
            icontent_fp.flush()
            icontent_fp.seek(0, os.SEEK_SET)
            environ['wsgi.input'] = icontent_fp

            iterable = LoggingInstance(start_response, oheaders_fp, ocontent_fp)
            iterable.link(self.__application(environ, iterable))
            return iterable

    application = LoggingMiddleware(application, '/tmp/wsgi')

For this middleware, the second argument to the constructor should be a
preexisting directory. For each request four files will be saved. These
correspond to input headers, input content, response status and headers,
and request content.

Poorly Performing Code
----------------------

The WSGI specification allows any iterable object to be returned as the
response, so long as the iterable yields string values. That this is the
case means that one can too easily return an object which satisfies this
requirement but has some sort of performance related issue.

The worst case of this is where instead of returning a list containing
strings, a single string is returned. The problem with a string is that
when it is iterated over, a single character of the string is yielded each
time. In other words, a single character is written back to the client on
each loop, with a flush occurring in between to ensure that the character
has actually been written and isn't just being buffered.

Although for small strings a performance impact may not be noticed, if
returning large strings the affect on request throughput could be quite
significant.

Another case which can cause problems is to return a file like object. For
iteration over a file like object, typically what can occur is that a
single line within the file is returned each time. If the file is a line
oriented text file where each line is a of a reasonable length, this may be
okay, but if the file is a binary file there may not actually be line
breaks within the file.

For the case where file contains many short lines, throughput would be
affected much like in the case where a string is returned. For the case
where the file is just binary data, the result can be that the complete
file may be read in on the first loop. If the file is large, this could
cause a large transient spike in memory usage. Once that memory is
allocated, it will then be retained by the process, albeit that it may be
reused by the process at a later point.

Because of the performance impacts in terms of throughput and memory usage,
both these cases should be avoided. For the case of returning a string, it
should be returned with a single element list. For the case of a file like
object, the 'wsgi.file_wrapper' extension should be used, or a wrapper
which suitably breaks the response into chunks.

In order to identify where code may be inadvertently returning such iterable
types, the following code can be used::

    import types

    import cStringIO
    import socket
    import StringIO

    BAD_ITERABLES = [
      cStringIO.InputType,
      socket.SocketType,
      StringIO.StringIO,
      types.FileType,
      types.StringType,
    ]

    class ValidatingMiddleware:

        def __init__(self, application):
            self.__application = application

        def __call__(self, environ, start_response):
            errors = environ['wsgi.errors']

            result = self.__application(environ, start_response)

            value = type(result)
            if value == types.InstanceType:
                value = result.__class__
            if value in BAD_ITERABLES:
                print >> errors, 'BAD ITERABLE RETURNED: ',
                print >> errors, 'URL=%s ' % environ['REQUEST_URI'],
                print >> errors, 'TYPE=%s' % value

            return result

    def application(environ, start_response):
        ...

    application = ValidatingMiddleware(application)

Error Catching Middleware
-------------------------

Because mod_wsgi only logs details of uncaught exceptions to the Apache
error log and returns a generic HTTP 500 "Internal Server Error" response,
if you want the details of any exception to be displayed in the error
page and be visible from the browser, you will need to use a WSGI error
catching middleware component.

One example of WSGI error catching middleware is the ErrorMiddleware class
from Paste.

  * http://www.pythonpaste.org
    
This class can be configured not only to catch exceptions and present the
details to the browser in an error page, it can also be configured to send
the details of any errors in email to a designated recipient, or log the
details to an alternate log file.

Being able to have error details sent by email would be useful in a
production environment or where your application is running on a web
hosting environment and the Apache error logs would not necessarily be
closely monitored on a day to day basis. Enabling of that particular
feature though should possibly only be done when you have some confidence
in the application else you might end up getting inundated with emails.

To use the error catching middleware from Paste you simply need to wrap
your existing application with it such that it then becomes the top level
application entry point::

    def application(environ, start_response):
        status = '200 OK'
        output = b'Hello World!\n'

        response_headers = [('Content-type', 'text/plain'),
                            ('Content-Length', str(len(output)))]
        start_response(status, response_headers)

        return [output]

    from paste.exceptions.errormiddleware import ErrorMiddleware
    application = ErrorMiddleware(application, debug=True)

In addition to displaying information about the Python exception that has
occurred and the stack traceback, this middleware component will also
output information about the WSGI environment such that you can see what
was being passed to the WSGI application. This can be useful if the cause
of any problem was unexpected values passed in the headers of the HTTP
request.

Note that error catching middleware is of absolutely no use for trying
to capture and display in the browser any errors that occur at global scope
within the WSGI application script when it is being imported. Details of
any such errors occurring at this point will only be captured in the Apache
error log files. As much as possible you should avoid performing
complicated tasks when the WSGI application script file is being imported,
instead you should only trigger such actions the first time a request is
received. By doing this you will be able to capture errors in such
initialisation code with the error catching middleware.

Also note that the debug mode whereby details are displayed in the browser
should only be used during development and not in a production system. This
is because details which are displayed may be of use to anyone who may wish
to compromise your site.

Python Interactive Debugger
---------------------------

Python debuggers such as implemented by the 'pdb' module can sometimes be
useful in debugging Python applications, especially where there is a need
to single step through code and analyse application state at each point.
Use of such debuggers in web applications can be a bit more tricky than
normal applications though and especially so with mod_wsgi.

The problem with mod_wsgi is that the Apache web server can create multiple
child processes to respond to requests. Partly because of this, but also
just to prevent problems in general, Apache closes off standard input at
startup. Thus there is no actual way to interact with the Python debugger
module if it were used.

To get around this requires having complete control of the Apache web
server that you are using to host your WSGI application. In particular, it
will be necessary to shutdown the web server and then startup the 'httpd'
process explicitly in single process debug mode, avoiding the 'apachectl'
management application altogether::

    $ apachectl stop
    $ httpd -X

If Apache is normally started as the 'root' user, this also will need to be
run as the 'root' user otherwise the Apache web server will not have the
required permissions to write to its log directories etc.

The result of starting the 'httpd' process in this way will be that the
Apache web server will run everything in one process rather than using
multiple processes. Further, it will not close off standard input thus
allowing the Python debugger to be used.

Do note though that one cannot be using the ability of mod_wsgi to run
your application in a daemon process when doing this. The WSGI application
must be running within the main Apache process.

To trigger the Python debugger for any call within your code, the following
customised wrapper for the 'Pdb' class should be used::

    class Debugger:

        def __init__(self, object):
            self.__object = object

        def __call__(self, *args, **kwargs):
            import pdb, sys
            debugger = pdb.Pdb()
            debugger.use_rawinput = 0
            debugger.reset()
            sys.settrace(debugger.trace_dispatch)

            try:
                return self.__object(*args, **kwargs)
            finally:
                debugger.quitting = 1
                sys.settrace(None)

This might for example be used to wrap the actual WSGI application callable
object::

    def application(environ, start_response):
        status = '200 OK'
        output = b'Hello World!\n'

        response_headers = [('Content-type', 'text/plain'),
                            ('Content-Length', str(len(output)))]
        start_response(status, response_headers)

        return [output]

    application = Debugger(application)

When a request is now received, the Python debugger will be triggered and
you can interactively debug your application from the window you ran the
'httpd' process. For example::

    > /usr/local/wsgi/scripts/hello.py(21)application()
    -> status = '200 OK'

    (Pdb) list
     16             finally:
     17                 debugger.quitting = 1
     18                 sys.settrace(None)
     19
     20     def application(environ, start_response):
     21  ->     status = '200 OK'
     22         output = b'Hello World!\n'
     23
     24         response_headers = [('Content-type', 'text/plain'),
     25                             ('Content-Length', str(len(output)))]
     26         start_response(status, response_headers)

    (Pdb) print start_response
    <built-in method start_response of mod_wsgi.Adapter object at 0x1160180>

    cont

When wishing to allow the request to complete, issue the 'cont' command. If
wishing to cause the request to abort, issue the 'quit' command. This will
result in a 'BdbQuit' exception being raised and would result in a HTTP
500 "Internal Server Error" response being returned to the client. To kill
off the whole 'httpd' process, after having issued 'cont' or 'quit' to exit
the debugger, interrupt the process using 'CTRL-C'.

To see what commands the Python debugger accepts, issue the 'help' command
and also consult the documentation for the 'pdb' module on the Python web
site.

Note that the Python debugger expects to be able to write to
``sys.stdout`` to display information to the terminal. Thus if using
using a Python web framework which replaces ``sys.stdout`` such as
web.py, you will not be able to use the Python debugger.

Browser Based Debugger
----------------------

In order to use the Python debugger modules you need to have direct access
to the host and the Apache web server that is running your WSGI application.
If your only access to the system is via your web browser this makes the use
of the full Python debugger impractical.

An alternative to the Python debugger modules which is available is an
extension of the WSGI error catching middleware previously described. This
is the EvalException class from Paste. It embodies the error catching
attributes of the ErrorMiddleware class, but also allows some measure of
interactive debugging and introspection through the web browser.

As with any WSGI middleware component, to use the class entails creating
a wrapper around the application you wish to debug::

    def application(environ, start_response):
        status = '200 OK'
        output = b'Hello World!\n'

        response_headers = [('Content-type', 'text/plain'),
                            ('Content-Length', str(len(output)))]
        start_response(status, response_headers)

        return [output]

    from paste.evalexception.middleware import EvalException
    application = EvalException(application)

Like ErrorMiddleware when an unexpected exception occurs a web page is
presented which shows the location of the error along with the contents of
the WSGI application environment. Where EvalException is different however
is that it is possible to inspect the local variables residing within each
stack frame down to where the error occurred. Further, it is possible to
enter Python code which can be evaluated within the context of the selected
stack frame in order to access data or call functions or methods of
objects.

In order for this to all work requires that subsequent requests back to
the WSGI application always end up with the same process where the error
originally occurred. With mod_wsgi this does however present a bit of a
problem as Apache can create and use multiple child processes to handle
requests.

Because of this requirement, if you want to be able to use this browser
based interactive debugger, if running your application in embedded mode of
mod_wsgi, you will need to configure Apache such that it only starts up one
child process to handle requests and that it never creates any additional
processes. The Apache configuration directives required to achieve this are
as follows::

    StartServers 1
    ServerLimit 1

The directives must be placed at global scope within the main Apache
configuration files and will affect the whole Apache web server.

If you are using the worker MPM on a UNIX system, restricting Apache to
just a single process may not be an issue, at least during development. If
however you are using the prefork MPM on a UNIX system, you may see issues
if you are using an AJAX intensive page that relies on being able to
execute parallel requests, as only one request at a time will be able to be
handled by the Apache web server.

If using Apache 2.X on a UNIX system, a better approach is to use daemon
mode of mod_wsgi and delegate your application to run in a single daemon
process. This process may be single or multithreaded as per any threading
requirements of your application.

Which ever configuration is used, if the browser based interactive debugger
is used it should only be used on a development system and should never be
deployed on a production system or in a web hosting environment. This is
because the debugger will allow one to execute arbitrary Python code within
the context of your application from a remote client.

Debugging Crashes With GDB
--------------------------

In cases where Apache itself crashes for no apparent reason, the above
techniques are not always particularly useful. This is especially the case
where the crash occurs in non Python code outside of your WSGI application.

The most common cause of Apache crashing, besides any still latent bugs
that may exist in mod_wsgi, of which hopefully there aren't any, are shared
library version mismatches. Another major cause of crashes is third party C
extension modules for Python which are not compatible with being used in a
Python sub interpreter which isn't the first interpreter created when
Python is initialised, or modules which are not compatible with Python sub
interpreters being destroyed and the module then being used in a new Python
sub interpreter.

Examples of where shared library version mismatches are known to occur are
between the version of the 'expat' library used by Apache and that embedded
within the Python 'pyexpat' module. Another is between the version of the
MySQL client libraries used by PHP and the Python MySQL module.

Both these can be a cause of crashes where the different components are
compiled and linked against different versions of the shared library for
the packages in question. It is vitally important that all packages making
use of a shared library were compiled against and use the same version of
a shared library.

Another problematic package is Subversion. In this case there can be
conflicts between the version of Subversion libraries used by mod_dav_svn
and the Python Subversion bindings. Certain versions of the Python
Subversion modules also cause problems because they appear to be
incompatible with use in a Python sub interpreter which isn't the first
interpreter created when Python is initialised.

In this latter issue, the sub interpreter problems can often be solved by
forcing the WSGI application using the Python Subversion modules to run in
the '%{GLOBAL}' application group. This solution often also resolves issues
with SWIG generated bindings, especially where the ``-thread`` option was
supplied to 'swig' when the bindings were generated.

Whatever the reason, in some cases the only way to determine why Apache or
Python is crashing is to use a C code debugger such as 'gdb'. Now although
it is possible to attach 'gdb' to a running process, the preferred method
for using 'gdb' in conjunction with Apache is to run Apache in single
process debug mode from within 'gdb'.

To do this it is necessary to first shutdown Apache. The 'gdb' debugger can
then be started against the 'httpd' executable and then the process started
up from inside of 'gdb'::

    $ /usr/local/apache/bin/apachectl stop
    $ sudo gdb /usr/local/apache/bin/httpd
    GNU gdb 6.1-20040303 (Apple version gdb-384) (Mon Mar 21 00:05:26 GMT 2005)
    Copyright 2004 Free Software Foundation, Inc.
    GDB is free software, covered by the GNU General Public License, and you are
    welcome to change it and/or distribute copies of it under certain conditions.
    Type "show copying" to see the conditions.
    There is absolutely no warranty for GDB.  Type "show warranty" for details.
    This GDB was configured as "powerpc-apple-darwin"...Reading symbols for shared
    libraries ........ done

    (gdb) run -X
    Starting program: /usr/local/apache/bin/httpd -X
    Reading symbols for shared libraries .+++ done
    Reading symbols for shared libraries ..................... done

If Apache is normally started as the 'root' user, this also will need to be
run as the 'root' user otherwise the Apache web server will not have the
required permissions to write to its log directories etc.

If Apache was crashing on startup, you should immediately encounter the
error, otherwise use your web browser to access the URL which is causing
the crash to occur. You can then commence trying to debug why the crash is
occurring.

Note that you should ensure that you have not assigned your WSGI
application to run in a mod_wsgi daemon process using the WSGIDaemonProcess
and WSGIProcessGroup directives. This is because the above procedure will
only catch crashes which occur when the application is running in embedded
mode. If it turns out that the application only crashes when run in mod_wsgi
daemon mode, an alternate method of using 'gdb' will be required.

In this circumstance you should run Apache as normal, but ensure that you
only create one mod_wsgi daemon process and have it use only a single
thread::

    WSGIDaemonProcess debug threads=1
    WSGIProcessGroup debug

If not running the daemon process as a distinct user where you can tell
which process it is, then you will also need to ensure that Apache
!LogLevel directive has been set to 'info'. This is to ensure that
information about daemon processes created by mod_wsgi are logged to the
Apache error log. This is necessary, as you will need to consult the Apache
error logs to determine the process ID of the daemon process that has been
created for that daemon process group::

    mod_wsgi (pid=666): Starting process 'debug' with threads=1.

Knowing the process ID, you should then run 'gdb', telling it to attach
directly to the daemon process::

    $ sudo gdb /usr/local/apache/bin/httpd 666
    GNU gdb 6.1-20040303 (Apple version gdb-384) (Mon Mar 21 00:05:26 GMT 2005)
    Copyright 2004 Free Software Foundation, Inc.
    GDB is free software, covered by the GNU General Public License, and you are
    welcome to change it and/or distribute copies of it under certain conditions.
    Type "show copying" to see the conditions.
    There is absolutely no warranty for GDB.  Type "show warranty" for details.
    This GDB was configured as "powerpc-apple-darwin"...Reading symbols for shared
    libraries ........ done

    /Users/grahamd/666: No such file or directory.
    Attaching to program: `/usr/local/apache/bin/httpd', process 666.
    Reading symbols for shared libraries .+++..................... done
    0x900c7060 in sigwait ()
    (gdb) cont
    Continuing.

Once 'gdb' has been started and attached to the process, then initiate the
request with the URL that causes the application to crash.

Attaching to the running daemon process can also be useful where a single
request or the whole process is appearing to hang. In this case one can
force a stack trace to be output for all running threads to try and
determine what code is getting stuck. The appropriate gdb command in this
instance is 'thread apply all bt'::

    sudo gdb /usr/local/apache-2.2/bin/httpd 666
    GNU gdb 6.3.50-20050815 (Apple version gdb-477) (Sun Apr 30 20:06:22 GMT 2006)
    Copyright 2004 Free Software Foundation, Inc.
    GDB is free software, covered by the GNU General Public License, and you are
    welcome to change it and/or distribute copies of it under certain conditions.
    Type "show copying" to see the conditions.
    There is absolutely no warranty for GDB.  Type "show warranty" for details.
    This GDB was configured as "powerpc-apple-darwin"...Reading symbols
    for shared libraries ....... done

    /Users/grahamd/666: No such file or directory.
    Attaching to program: `/usr/local/apache/bin/httpd', process 666.
    Reading symbols for shared libraries .+++..................... done
    0x900c7060 in sigwait ()
    (gdb) thread apply all bt

    Thread 4 (process 666 thread 0xd03):
    #0  0x9001f7ac in select ()
    #1  0x004189b4 in apr_pollset_poll (pollset=0x1894650,
        timeout=-1146117585187099488, num=0xf0182d98, descriptors=0xf0182d9c)
        at poll/unix/select.c:363
    #2  0x002a57f0 in wsgi_daemon_thread (thd=0x1889660, data=0x18895e8)
        at mod_wsgi.c:6980
    #3  0x9002bc28 in _pthread_body ()

    Thread 3 (process 666 thread 0xc03):
    #0  0x9001f7ac in select ()
    #1  0x0041d224 in apr_sleep (t=1000000) at time/unix/time.c:246
    #2  0x002a2b10 in wsgi_deadlock_thread (thd=0x0, data=0x2aee68) at
        mod_wsgi.c:7119
    #3  0x9002bc28 in _pthread_body ()

    Thread 2 (process 666 thread 0xb03):
    #0  0x9001f7ac in select ()
    #1  0x0041d224 in apr_sleep (t=299970002) at time/unix/time.c:246
    #2  0x002a2dec in wsgi_monitor_thread (thd=0x0, data=0x18890e8) at
        mod_wsgi.c:7197
    #3  0x9002bc28 in _pthread_body ()

    Thread 1 (process 666 thread 0x203):
    #0  0x900c7060 in sigwait ()
    #1  0x0041ba9c in apr_signal_thread (signal_handler=0x2a29a0
        <wsgi_check_signal>) at threadproc/unix/signals.c:383
    #2  0x002a3728 in wsgi_start_process (p=0x1806418, daemon=0x18890e8)
        at mod_wsgi.c:7311
    #3  0x002a6a4c in wsgi_hook_init (pconf=0x1806418, ptemp=0x0,
        plog=0xc8, s=0x18be8d4) at mod_wsgi.c:7716
    #4  0x0000a5b0 in ap_run_post_config (pconf=0x1806418, plog=0x1844418,
        ptemp=0x180e418, s=0x180da78) at config.c:91
    #5  0x000033d4 in main (argc=3, argv=0xbffffa8c) at main.c:706

It is suggested when trying to debug such issues that the daemon process be
made to run with only a single thread. This will reduce how many stack
traces one needs to analyse.

If you are running with multiple processes within the daemon process group
and all requests are hanging, you will need to get a snapshot of what is
happening in all processes in the daemon process group. Because doing this
by hand will be tedious, it is better to automate it.

To automate capturing the stack traces, first create a file called 'gdb.cmds'
which contains the following::

    set pagination 0
    thread apply all bt
    detach
    quit

This can then be used in conjunction with 'gdb' to avoid needing to enter
the commands manually. For example::

    sudo gdb /usr/local/apache-2.2/bin/httpd -x gdb.cmds -p 666

To be able to automate this further and apply it to all processes in a
daemon process group, then first off ensure that daemon processes are named
in 'ps' output by using the 'display-name' option to WSGIDaemonProcess
directive.

For example, to apply default naming strategy as implemented by mod_wsgi, use::

    WSGIDaemonProcess xxx display-name=%{GLOBAL}

In the output of a BSD derived 'ps' command, this will now show the process
as being named '(wsgi:xxx)'::

    $ ps -cxo command,pid | grep wsgi
    (wsgi:xxx)        666

Note that the name may be truncated as the resultant name can be no longer
than what was the length of the original executable path for Apache. You
may therefore like to name it explicitly::

    WSGIDaemonProcess xxx display-name=(wsgi:xxx)

Having named the processes in the daemon process group, we can now parse the
output of 'ps' to identify the process and apply the 'gdb' command script to
each::

    for pid in `ps -cxo command,pid | awk '{ if ($0 ~ /wsgi:xxx/ && $1 !~ /grep/) print $NF }'`; do sudo gdb -x gdb.cmds -p $pid; done

The actual name given to the daemon process group using the 'display-name'
option should be replaced in this command line. That is, change 'wsgi:xxx'
appropriately.

If you are having problems with process in daemon process groups hanging,
you might consider implementing a monitoring system which automatically
detects somehow when the processes are no longer responding to requests and
automatically trigger this dump of the stack traces before restarting the
daemon process group or Apache.

Extracting Python Stack Traces
------------------------------

Using gdb to get stack traces as described above only gives you information
about what is happening at the C code level. This will not tell where in the
actual Python code execution was at. Your only clue is going to be where a
call out was being made to some distinct C function in a C extension module
for Python.

One can get stack traces for Python code by using::

    def _stacktraces():
       code = []
       for threadId, stack in sys._current_frames().items():
           code.append("\n# ThreadID: %s" % threadId)
           for filename, lineno, name, line in traceback.extract_stack(stack):
               code.append('File: "%s", line %d, in %s' % (filename,
                       lineno, name))
               if line:
                   code.append("  %s" % (line.strip()))

       for line in code:
           print >> sys.stderr, line

The caveat here obviously is that the process has to still be running. There
is also the issue of how you trigger that function to dump stack traces for
executing Python threads.

If the problem you have is that some request handler threads are stuck,
either blocked, or stuck in an infinite loop, and you want to know what they
are doing, then so long as there are still some handler threads left and
the application is still responding to requests, then you could trigger it
from a request handler triggered by making a request against a specific URL.

This though depends on you only running your application within a single
process because as soon as you have multiple processes you have no guarantee
that a request will go to the process you want to debug.

A better method therefore is to have a perpetually running background thread
which monitors for a specific file in the file system. When that file is
created or the modification time changes, then the background thread would
dump the stack traces for the process.

Sample code which takes this approach is included below. This code could be
placed temporarily at the end of your WSGI script file if you know you are
going to need it because of a recurring problem::

    import os
    import sys
    import time
    import signal
    import threading
    import atexit
    import Queue
    import traceback 

    FILE = '/tmp/dump-stack-traces.txt'

    _interval = 1.0

    _running = False
    _queue = Queue.Queue()
    _lock = threading.Lock()

    def _stacktraces(): 
        code = [] 
        for threadId, stack in sys._current_frames().items(): 
            code.append("\n# ProcessId: %s" % os.getpid()) 
            code.append("# ThreadID: %s" % threadId) 
            for filename, lineno, name, line in traceback.extract_stack(stack): 
                code.append('File: "%s", line %d, in %s' % (filename, 
                        lineno, name)) 
                if line: 
                    code.append("  %s" % (line.strip())) 

        for line in code:
            print >> sys.stderr, line

    try:
        mtime = os.path.getmtime(FILE)
    except:
        mtime = None

    def _monitor():
        while 1:
            global mtime

            try:
                current = os.path.getmtime(FILE)
            except:
                current = None

            if current != mtime:
                mtime = current
                _stacktraces()

            # Go to sleep for specified interval.

            try:
                return _queue.get(timeout=_interval)
            except:
                pass

    _thread = threading.Thread(target=_monitor)
    _thread.setDaemon(True)

    def _exiting():
        try:
            _queue.put(True)
        except:
            pass
        _thread.join()

    atexit.register(_exiting)

    def _start(interval=1.0):
        global _interval
        if interval < _interval:
            _interval = interval

        global _running
        _lock.acquire()
        if not _running:
            prefix = 'monitor (pid=%d):' % os.getpid()
            print >> sys.stderr, '%s Starting stack trace monitor.' % prefix
            _running = True
            _thread.start()
        _lock.release()

    _start()

Once your WSGI script file has been loaded, then touching the file
'/tmp/dump-stack-traces.txt' will cause stack traces for active Python
threads to be output to the Apache error log.

Note that the sample code doesn't deal with possibility that with multiple
processes for same application, that all processes may attempt to dump
information at the same time. As such, you may get interleaving of output
from multiple processes in Apache error logs at the same time.

What you may want to do is modify this code to dump out to some special
directory, distinct files containing the trace where the names of the file
include the process ID and a date/time. That way each will be separate.

An example of what one might expect to see from the above code is as
follows::

    # ProcessId: 666
    # ThreadID: 4352905216
    File: "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/threading.py", line 497, in __bootstrap
      self.__bootstrap_inner()
    File: "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/threading.py", line 522, in __bootstrap_inner
      self.run()
    File: "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/threading.py", line 477, in run
      self.__target(*self.__args, **self.__kwargs)
    File: "/Library/WebServer/Sites/django-1/htdocs/project.wsgi", line 72, in _monitor
      _stacktraces()
    File: "/Library/WebServer/Sites/django-1/htdocs/project.wsgi", line 47, in _stacktraces
      for filename, lineno, name, line in traceback.extract_stack(stack):

    # ThreadID: 4322832384
    File: "/Library/WebServer/Sites/django-1/htdocs/project.wsgi", line 21, in application
      return _application(environ, start_response)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/core/handlers/wsgi.py", line 245, in __call__
      response = middleware_method(request, response)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/contrib/sessions/middleware.py", line 36, in process_response
      request.session.save()
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/contrib/sessions/backends/db.py", line 63, in save
      obj.save(force_insert=must_create, using=using)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/db/models/base.py", line 434, in save
      self.save_base(using=using, force_insert=force_insert, force_update=force_update)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/db/models/base.py", line 527, in save_base
      result = manager._insert(values, return_id=update_pk, using=using)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/db/models/manager.py", line 195, in _insert
      return insert_query(self.model, values, **kwargs)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/db/models/query.py", line 1479, in insert_query
      return query.get_compiler(using=using).execute_sql(return_id)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/db/models/sql/compiler.py", line 783, in execute_sql
      cursor = super(SQLInsertCompiler, self).execute_sql(None)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/django/db/models/sql/compiler.py", line 727, in execute_sql
      cursor.execute(sql, params)
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/debug_toolbar/panels/sql.py", line 95, in execute
      stacktrace = tidy_stacktrace(traceback.extract_stack())
    File: "/Library/WebServer/Sites/django-1/lib/python2.6/site-packages/debug_toolbar/panels/sql.py", line 40, in tidy_stacktrace
      s_path = os.path.realpath(s[0])
    File: "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/posixpath.py", line 355, in realpath
      if islink(component):
    File: "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/posixpath.py", line 132, in islink
      st = os.lstat(path)

Note that one of the displayed threads will be that for the thread which is
dumping the stack traces. That stack trace can obviously be ignored.

One could extend the above recipe in more elaborate ways by using a WSGI
middleware that capture details of each request from the WSGI environment
and also dumping out from that the URL for the request being handled by
any threads. This may assist in working out whether problems are related
to a specific URL.