[mod_python] multiple processing of the same python script by the handler

Sun Mar 29 05:45:01 EDT 2009

2009/3/29 David Sfiligoi <webmaster at world-vr.com>:
> Hi List,
>
> I have been working around, trying to resolve you name it this problem for at
> least a year now.  I don't know what to do anymore...everytime I implement
> some new functionality to my system I find myself writing bastard code to
> work around this issue.
>
> The simplest way to 'reproduce' this issue is by using the logging module.
>
> To explain this in its simplest form I can use the logging module. A simple
> script that takes all the parameters passed to the script via the url and log
> them to a file via the logger.
>
> from mod_python import Cookie, apache
> from mod_python import util
>
> import logging, logging.handlers
>
> logger = logging.getLogger('mymodpythong app.py')
> logging_handler = logging.FileHandler('/mylogfile.log')
> formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
> logging_handler.setFormatter(formatter)
> logger.addHandler(logging_handler)
> logger.setLevel(logging.INFO)
>
> def handler(req):
>        request_data = util.FieldStorage(req)
>        clientip = req.get_remote_host(apache.REMOTE_NOLOOKUP)
>        str_req_data = str(clientip) + "| "
>        for key in request_data:
>                str_req_data += str(key) + ": " + str(request_data[key]) + "| "
>
>
>        logger.info(str_req_data[:-2])
>        return apache.OK
>
>
>
> Now the behavior on my apache 2.2(on prefork mpm) is the following.  I can get
> 1 line logged or 2 or 5 with the exact same data.  It almost looks like
> modpython process is processing the same data a few time sand who ever finish
> first get promoted to return the data to apache.  Now this doesn't only apply
> to logging, if I open a socket and send data to another server, on that
> server side they would get the same multiple same data.
>
> This is a log snapshot from my production system.  This is an log from a
> visitor who loads the page.  (the html page sends the onUnload event to the
> python script). As you can see mod python logged 3 times the same data
>
> 2009-03-28 21:57:49,854 INFO 76.177.106.67| CC: US| tdid: XXXXXXX| product:
> removed| version: db2.9| unloadTime: 0.003| unloadLoc: urlremoved| event:
> unload| Referer: urlremoved| cookietid: None
> 2009-03-28 21:57:49,854 INFO 76.177.106.67| CC: US| tdid: XXXXXXX| product:
> removed| version: db2.9| unloadTime: 0.003| unloadLoc: urlremoved| event:
> unload| Referer: urlremovedl| cookietid: None
> 2009-03-28 21:57:49,854 INFO 76.177.106.67| CC: US| tdid: XXXXXXX| product:
> removed| version: db2.9| unloadTime: 0.003| unloadLoc: urlremoved| event:
> unload| Referer: urlremoved| cookietid: None
> 2009-03-28 21:57:52,785 INFO 76.177.106.67| CC: US| tdid: XXXXXXX| product:
> removed| version: db2.9| unloadTime: 3.249| unloadLoc: urlremoved| event:
> onload| Referer: urlremoved| cookietid: None
> 2009-03-28 21:57:52,785 INFO 76.177.106.67| CC: US| tdid: XXXXXXX| product:
> removed| version: db2.9| unloadTime: 3.249| unloadLoc: urlremoved| event:
> onload| Referer: urlremoved| cookietid: None
> 2009-03-28 21:57:52,785 INFO 76.177.106.67| CC: US| tdid: XXXXXXX| product:
> removed| version: db2.9| unloadTime: 3.249| unloadLoc: urlremoved| event:
> onload| Referer: urlremoved| cookietid: None

If you change a mod_python handler script, it will be automatically
reloaded. This would be a problem in your code as you installed a log
handler each time it is loaded into the same process. Having multiple
instances of the log handler installed would result in the same
information possibly being logged multiple times.

I would suggest you add inside your handler script:

  req.log_error("I have been called")

If that appears twice in the Apache error log file then I would be
concerned, otherwise I would say the problem is with your use of the
logging module.