Possible leaking of Win32 event handles when Apache restarted.

• Key: MODPYTHON-195
• Type: Bug
• Status: Reopened
• Priority: Major
• Assignee: Graham Dumpleton
• Reporter: Graham Dumpleton
• Component/s: core
• Affects Version/s: 3.2.10, 3.3.1

Description

Jeff Robins in:

  http://mail-archives.apache.org/mod_mbox/httpd-python-dev/200610.mbox/[e-mail]%3e

indicates a belief that when an Apache restart is performed on Windows that there are a number of Win32 event handles leaked. His belief is that this seems to be linked to mod_python.

Comments

[Graham Dumpleton]

Jeff provides the following further information. The question is whether there is a more accepted way of doing this now as that email was from two years ago and that it is dependent on something that change from release to release is a problem. Maybe a simple static variable can be used to determine if call has already been made since on the restart, the mod_python module should by rights be unloaded from memory which means the static should get reset to 0, thus first call could always be setting it to 1 and second call not doing anything it already 1.


Anyway, Jeffs email follows:

I added some logging to python_init in mod_python.c to try to understand what is going on. Apparently when you run apache as a service on win32 the python_init function gets called TWICE on restart (I have no idea why) and the first time is somehow spurious (perhaps it is running in the context of the parent process that spawns the child process that really services requests?)
yet python_init allocates stuff anyway which never gets freed, for example the "interpreters_lock" allocated via
apr_thread_mutex_create(&interpreters_lock, APR_THREAD_MUTEX_UNNESTED, p);


I found this posting on the web
http://mail-archives.apache.org/mod_mbox/httpd-dev/200311.mbox/[e-mail]%3E
which seems to agree that the ap_hook_post_config callback gets called twice on win32 running as a service and suggested this hack:

#ifdef WIN32
    /* Do not run post_config in the Windows parent process
     * The envar AP_PARENT_PID is set in the env list (by mpm_winnt)
     * for the child process.
     * **WARNING**:
     * This check is not as robust as I would like because the name of
this
     * envar is subject to change from release to release.
     */
    if (!getenv("AP_PARENT_PID")) {
        return OK;
    }
#endif

I put this into python_init() just to see what would happen and sure enough, the leaking 4 handles went away. I don't know what to do at this point since I am uncomfortable with the hack. Yet clearly python_init() is not expecting to be called twice on restart. Is this an apache bug or a well-know (heh) feature that modules must protect themselves against?

But python_init() uses:

    apr_pool_userdata_get(&data, userdata_key, s->process->pool);
    if (!data) {
        apr_pool_userdata_set((const void *)1, userdata_key,
                              apr_pool_cleanup_null, s->process->pool);
        return OK;
    }

This is apparently a standard trick used to get around fact that post_config_hook functions are called twice. For example, from mod_auth_digest.c in Apache source code:

    /* initialize_module() will be called twice, and if it's a DSO
     * then all static data from the first call will be lost. Only
     * set up our static data on the second call. */
    apr_pool_userdata_get(&data, userdata_key, s->process->pool);
    if (!data) {
        apr_pool_userdata_set((const void *)1, userdata_key,
                               apr_pool_cleanup_null, s->process->pool);
        return OK;
    }

Thus, although it does get called twice, wouldn't expect it to get down to the mutex creation as above should stop it.

Jeff, can you do further debugging to track what happens with access to userdata above on each call and whether it does in fact stop subsequent code from executing the first time through and post any results against this issue in JIRA.

[Jeff Robbins]

   [[ Old comment, sent from unregistered email on Tue, 24 Oct 2006 06:56:50 -0400 ]]

I think the problem with a static is that the code gets called in the
context of the parent process and the child process. We need some way of
knowing only to run in the context of the child process. mpm_winnt.c uses
AP_PARENT_PID as an environmental only visible to the child process so while
it is risky in the sense of a dependency, it is how the code that apparently
produces this problem by creating the windows-specific process architecture
communicates with itself.

[Jeff Robbins]

   [[ Old comment, sent from unregistered email on Tue, 24 Oct 2006 06:56:50 -0400 ]]

I think the problem with a static is that the code gets called in the
context of the parent process and the child process. We need some way of
knowing only to run in the context of the child process. mpm_winnt.c uses
AP_PARENT_PID as an environmental only visible to the child process so while
it is risky in the sense of a dependency, it is how the code that apparently
produces this problem by creating the windows-specific process architecture
communicates with itself.

[Jeff Robbins]

   [[ Old comment, sent from unregistered email on Tue, 24 Oct 2006 09:13:26 -0400 ]]

Graham,

I added a printout after the call to apr_pool_user_data_get. What I think
is happening is that the hook python_init() is called "again" in the parent
process (so data is already 1) and then called the expected 2 times in the
child process (wherein the usual protection works and the bulk of
python_init() only runs through on the second time in. The problem is that
the parent process on windows is long-lived and is just there to spin up and
down the child process that does the real web serving. It is the parent
process run through python_init() that needs to be defeated, and the usual
protection does no good there.

code in mod_python.c:
rc = apr_pool_userdata_get(&data, userdata_key, s->process->pool);
// JSR
ap_log_error(APLOG_MARK, APLOG_NOERRNO|APLOG_ERR, 0, s, "python_init:
apr_pool_userdata_get() rc=%d data=%x", rc, data);

error log fragment: (with my comments added):
[Tue Oct 24 09:04:41 2006] [notice] Parent: Received restart signal --
Restarting the server.
[Tue Oct 24 09:04:41 2006] [notice] Child 1952: Exit event signaled. Child
process is ending.
[Tue Oct 24 09:04:41 2006] [error] python_init: apr_pool_userdata_get() rc=0
data=1 // this is the call in the parent process that we need to skip
[Tue Oct 24 09:04:41 2006] [notice] Parent: Created child process 9688
[Tue Oct 24 09:04:41 2006] [error] python_init: apr_pool_userdata_get() rc=0
data=0 // these are the two calls in the new child process
[Tue Oct 24 09:04:41 2006] [error] python_init: apr_pool_userdata_get() rc=0
data=1
[Tue Oct 24 09:04:41 2006] [notice] mod_python: Creating 8 session mutexes
based on 0 max processes and 50 max threads.
[Tue Oct 24 09:04:41 2006] [notice] Child 9688: Child process is running
[Tue Oct 24 09:04:42 2006] [notice] Child 1952: Released the start mutex
[Tue Oct 24 09:04:42 2006] [notice] Child 9688: Acquired the start mutex.
[Tue Oct 24 09:04:42 2006] [notice] Child 9688: Starting 50 worker threads.

Given the long-lived nature of the parent process, I'm beginning to think
that your idea of a static might be better than checking for the
environmental.

- Jeff

[Graham Dumpleton]

Can you see if you can come up with some check based on values of 'initialized' and 'child_init_pool'. First step would be to print out their values amongst your above debug.

The 'initialized' flag is in there to work around issues with older Mac OS X versions. That used in combination with whether child_init_pool is still zero or not, indicating parent or child process, may give you enough to work out when to return and not execute the function again.

[Graham Dumpleton]

Haven't been able to validate this first hand, but have accepted the following change in python_init() to stop Win32 parent process performing global mutex and Python initialisation.

#ifdef WIN32
    /* No need to run python_init() in Win32 parent processes as
     * the lack of fork on Win32 means we get no benefit as far as
     * inheriting a preinitialized Python interpreter. Further,
     * upon a restart on Win32 platform the python_init() function
     * will be called again in the parent process but without some
     * resources allocated by the previous call having being
     * released properly, resulting in memory and Win32 resource
     * leaks.
     */
    if (!getenv("AP_PARENT_PID"))
        return OK;
#endif /* WIN32 */


See MODPYTHON-195 thread at:

  http://mail-archives.apache.org/mod_mbox/httpd-python-dev/200611.mbox/thread

starting with:

  http://mail-archives.apache.org/mod_mbox/httpd-python-dev/200611.mbox/[e-mail]%3e

[Graham Dumpleton]

The change for this appears to be having the side affect of the mod_python/Python version information not showing up in the Apache startup string. This is based on logging shown in email:

  http://www.modpython.org/pipermail/mod_python/2007-May/023582.html

Where would would expect to see something like:

  Apache/2.2.4 (Win32) mod_python/3.3.1 Python/2.5 PHP/5.2.1 configured -- resuming normal operations

on Windows one is only seeing:

  Apache/2.2.4 (Win32) PHP/5.2.1

This is because the version information is output in the first Windows process created, but the change is stopping the code which composes the version information from being run.

The code should be reorganised so that calls to ap_add_version_component() for mod_python and Python are always done. When done second time it is redundant but doesn't matter.

[Graham Dumpleton]

This changes also possibly prevents Apache being run in single process mode on Windows when mod_python is loaded. This is because Python will not be initialised in the single process and when a request arrives for mod_python it will fail.