Logging in daemon when IP based VirtualHost being used may not be working.

[GoogleCodeExporter]

Need to investigate further.

https://groups.google.com/forum/?fromgroups=#!topic/modwsgi/jV4XzGofyMw

Original issue reported on code.google.com by [email protected] on 14 Nov 2012 at 10:29

[GoogleCodeExporter]

I have a production server hosting many domains affected by this. It was 
triggered after upgrade from Ubuntu 10.04 LTS (Lucid) to 12.04 LTS (Precise).

I'm still trying to solve this since the Python application (Trac) on the 
apache web-server fails to work - just showing web-site users:

500 Internal Sever Error

Even the basic simple "Hello World" WSGI application fails the same way.

There are no entries in the apache server or virtual-host log files except:

[Fri Jan 18 21:02:53 2013] [info] mod_wsgi (pid=22700): Attach interpreter ''.
[Fri Jan 18 21:04:53 2013] [info] mod_wsgi (pid=22700): Create interpreter 
'tjworld.net|/trac'.


Can I assist in any way?

Original comment by [email protected] on 19 Jan 2013 at 8:46

[GoogleCodeExporter]

What specific Apache and mod_wsgi versions are you using? Are using an OS 
binary package for mod_wsgi or compiling from source code yourself?

If you are using a binary package for mod_wsgi and cant install a version from 
source code, with any modifications to try, does make it a little bit harder to 
work out.

Original comment by [email protected] on 19 Jan 2013 at 11:13

[GoogleCodeExporter]

The upgraded server has the binary packages from Ubuntu 12.04 Precise:

$ apt-cache policy apache2
apache2:
  Installed: 2.2.22-1ubuntu1.2
  Candidate: 2.2.22-1ubuntu1.2
  Version table:
 *** 2.2.22-1ubuntu1.2 0
        500 http://gb.archive.ubuntu.com/ubuntu/ precise-updates/main i386 Packages
        500 http://security.ubuntu.com/ubuntu/ precise-security/main i386 Packages
        100 /var/lib/dpkg/status
     2.2.22-1ubuntu1 0
        500 http://archive.ubuntu.com/ubuntu/ precise/main i386 Packages

$ apt-cache policy libapache2-mod-wsgi
libapache2-mod-wsgi:
  Installed: 3.3-4build1ubuntu0~tj
  Candidate: 3.3-4build1ubuntu0~tj
  Version table:
 *** 3.3-4build1ubuntu0~tj 0
        100 /var/lib/dpkg/status
     3.3-4build1 0
        500 http://archive.ubuntu.com/ubuntu/ precise/main i386 Packages

I tried a no-change rebuild of the mod_wsgi package myself (as you can see from 
the ~tj in the package version). This was simply to fix an issue where the 
build servers use Python 2.7.2 but Ubuntu 12.04 uses Python 2.7.3 and therefore 
mod_wsgi would warn about incompatible compile and run-time Python versions.

I have the apache httpd source from their github repo and the mod_wsgi source 
from the Ubuntu package, and the hg repo.

I'm currently working at applying the Debian packaging to the hg repo trunk so 
that it can be installed as a regular Debian/Ubuntu package.

I'm also parsing the source-code of both packages trying to figure out the code 
flow.

Original comment by [email protected] on 19 Jan 2013 at 11:56

[GoogleCodeExporter]

To try and narrow down the cause I've been inserting debug logging at function 
entry/return and at control-flow decision points of the form:

ap_log_error(APLOG_MARK, WSGI_LOG_DEBUG(0)...

This has narrowed down the issue somewhat. This appears to indicate that there 
is no module found:

[Sun Jan 20 03:16:10 2013] [debug] mod_wsgi.c(6494): (pid=29424): 
wsgi_execute_script() entry.
[Sun Jan 20 03:16:10 2013] [debug] mod_wsgi.c(1429): (pid=29424): 
newLogObject().
[Sun Jan 20 03:16:10 2013] [debug] mod_wsgi.c(1602): (pid=29424): Log_call().
[Sun Jan 20 03:16:10 2013] [debug] mod_wsgi.c(1602): (pid=29424): Log_call().
[Sun Jan 20 03:16:10 2013] [debug] mod_wsgi.c(1602): (pid=29424): Log_call().
[Sun Jan 20 03:16:10 2013] [debug] mod_wsgi.c(1602): (pid=29424): Log_call().
[Sun Jan 20 03:16:10 2013] [debug] mod_wsgi.c(6696): (pid=29424): 
wsgi_execute_script() status = HTTP_INTERNAL_SERVER_ERROR
[Sun Jan 20 03:16:10 2013] [debug] mod_wsgi.c(6792): (pid=29424): 
wsgi_execute_script() return 500.

This comes from wsgi_execute_script(), which indicates that the module pointer 
remains NULL and therefore the function returns with HTTP 500:

    /* Assume an internal server error unless everything okay. */

    status = HTTP_INTERNAL_SERVER_ERROR;

        ap_log_error(APLOG_MARK, WSGI_LOG_DEBUG(0), wsgi_server,
                     "(pid=%d): %s() status = HTTP_INTERNAL_SERVER_ERROR",
                     getpid(), __FUNCTION__);

    /* Determine if script exists and execute it. */

    if (module) {
        ap_log_error(APLOG_MARK, WSGI_LOG_DEBUG(0), wsgi_server,
                     "(pid=%d): %s() if(module)...",
                     getpid(), __FUNCTION__);

...

    wsgi_release_interpreter(interp);

    ap_log_error(APLOG_MARK, WSGI_LOG_DEBUG(0), wsgi_server,
                 "(pid=%d): %s() return %d.",
                 getpid(), __FUNCTION__, status);


    return status;
}

Original comment by [email protected] on 20 Jan 2013 at 3:19

[GoogleCodeExporter]

Further narrowing seems to indicate that PyImport_ExecCodeModuleEx() is failing 
in wsgi_load_source():

[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(6541): (pid=13749): 
wsgi_execute_script() name=_mod_wsgi_46bca81cd16f0ff04aadf7f43f503dc3.
[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(6210): (pid=13749): 
wsgi_load_source() entry. filename=/home/tjworld.net/trac/apache/trac.wsgi.
[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(6322): (pid=13749): 
wsgi_load_source() name=_mod_wsgi_46bca81cd16f0ff04aadf7f43f503dc3 co=b6395bf0, 
filename=/home/tjworld.net/trac/apache/trac.wsgi.
[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(6330): (pid=13749): 
wsgi_load_source() m=0.
[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(2001): (pid=13749): 
wsgi_log_python_error().
[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(1429): (pid=13749): 
newLogObject().
[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(6382): (pid=13749): 
wsgi_load_source() return.
[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(6713): (pid=13749): 
wsgi_execute_script() status = HTTP_INTERNAL_SERVER_ERROR
[Sun Jan 20 04:28:24 2013] [debug] mod_wsgi.c(6809): (pid=13749): 
wsgi_execute_script() return 500.

Original comment by [email protected] on 20 Jan 2013 at 4:32

[GoogleCodeExporter]

With this additional debug logging the cause has finally been identified. The 
system upgrade shouldn't have broken WSGI/Python/Trac but it appears it did. 
I'll do further investigations tomorrow to determine if this is simply Trac's 
installation location not being updated, or if there is some change in the way 
Python searches for it.

This doesn't fix or excuse the lack of error reporting from mod_wsgi, however!

    ap_log_error(APLOG_MARK, WSGI_LOG_DEBUG(0), wsgi_server,
                 "(pid=%d): %s() name=%s co=%pp, filename=%s.",
                 getpid(), __FUNCTION__, name, (void *)co, filename);
    if (co)
        m = PyImport_ExecCodeModuleEx((char *)name, co, (char *)filename);

    Py_XDECREF(co);

    ap_log_error(APLOG_MARK, WSGI_LOG_DEBUG(0), wsgi_server,
                 "(pid=%d): %s() m=%pp.",
                 getpid(), __FUNCTION__, (void *)m);
    if (!m) {
        PyErr_Print();
    }


[Sun Jan 20 04:45:39 2013] [debug] mod_wsgi.c(6545): (pid=16825): 
wsgi_execute_script() name=_mod_wsgi_46bca81cd16f0ff04aadf7f43f503dc3.
[Sun Jan 20 04:45:39 2013] [debug] mod_wsgi.c(6210): (pid=16825): 
wsgi_load_source() entry. filename=/home/tjworld.net/trac/apache/trac.wsgi.
[Sun Jan 20 04:45:39 2013] [debug] mod_wsgi.c(6322): (pid=16825): 
wsgi_load_source() name=_mod_wsgi_46bca81cd16f0ff04aadf7f43f503dc3 co=b646cbf0, 
filename=/home/tjworld.net/trac/apache/trac.wsgi.
[Sun Jan 20 04:45:39 2013] [debug] mod_wsgi.c(6330): (pid=16825): 
wsgi_load_source() m=0.
[Sun Jan 20 04:45:39 2013] [error] Traceback (most recent call last):
[Sun Jan 20 04:45:39 2013] [error]   File 
"/home/tjworld.net/trac/apache/trac.wsgi", line 12, in <module>
[Sun Jan 20 04:45:39 2013] [error]     import trac.web.main
[Sun Jan 20 04:45:39 2013] [error] ImportError: No module named trac.web.main
[Sun Jan 20 04:45:39 2013] [debug] mod_wsgi.c(2001): (pid=16825): 
wsgi_log_python_error().
[Sun Jan 20 04:45:39 2013] [debug] mod_wsgi.c(6386): (pid=16825): 
wsgi_load_source() return.
[Sun Jan 20 04:45:39 2013] [debug] mod_wsgi.c(6717): (pid=16825): 
wsgi_execute_script() status = HTTP_INTERNAL_SERVER_ERROR
[Sun Jan 20 04:45:39 2013] [debug] mod_wsgi.c(6813): (pid=16825): 
wsgi_execute_script() return 500.

Original comment by [email protected] on 20 Jan 2013 at 4:49

[GoogleCodeExporter]

I've been investigating why wsgi_load_source() doesn't log. I've narrowed it 
down to the request object.

Although request_rec* r is non-NULL, which triggers the use of 
ap_log_rerror(...), it seems as if many of the (const char*) fields of the 
request are NULL. I've been trying to print (the_request, uri, unparsed_uri) 
and they all show as NULL. E.g:

[Sun Jan 20 17:57:54 2013] [error] ImportError: No module named trac.web.main
[Sun Jan 20 17:57:54 2013] [debug] mod_wsgi.c(6372): (pid=13617): 
wsgi_load_source() request (null).
[Sun Jan 20 17:57:54 2013] [debug] mod_wsgi.c(2001): (pid=13617): 
wsgi_log_python_error().


        if (r) {

        ap_log_error(APLOG_MARK, WSGI_LOG_DEBUG(0), wsgi_server, "(pid=%d): %s() request %s.", getpid(), __FUNCTION__, r->unparsed_uri);

            ap_log_rerror(APLOG_MARK, WSGI_LOG_ERR(0), r,
                          "mod_wsgi (pid=%d): Target WSGI script '%s' cannot "
                          "be loaded as Python module.", getpid(), filename);
        }

Original comment by [email protected] on 20 Jan 2013 at 5:59

[GoogleCodeExporter]

It appears the lack of a complete request structure is responsible. 

[Sun Jan 20 18:05:40 2013] [debug] mod_wsgi.c(6373): (pid=16501): 
wsgi_load_source() the_request=(null), unparsed_uri=(null), uri=(null), 
protocol=(null), hostname=tjworld.net, status_line=(null), method=(null), 
range=(null), path_info=(null).

At this point its a bit beyond me to understand the intricacies of httpd and 
modules.

Original comment by [email protected] on 20 Jan 2013 at 6:07