On Wed 23 Apr 2008, David E. Wheeler wrote:
> I'm busy finalizing the port of Bricolage to mod_perl2. In the  
> process, I've discovered a bit of weirdness with our TransHandler. For  
> certain requests, it seems to execute twice. Under mod_perl1, here's  
> an example:
>
> 75947 Apache=SCALAR(0x295ed70) TransHandler start for /workflow/
> profile/desk/101/101/
> 75947 Apache=SCALAR(0x295ed70) TransHandler finish for /workflow/
> profile/desk/101/101/
> 75947 Apache=SCALAR(0x295ed70) AccessHandler start for /workflow/
> profile/desk/101/101/
> 75947 Apache=SCALAR(0x295ed70) AccessHandler finish for /workflow/
> profile/desk/101/101/
> 75947 Apache=SCALAR(0x29d6f60) TransHandler start for /101/
> 75947 Apache=SCALAR(0x29d6f60) TransHandler finish for /101/
> 75947 Apache=SCALAR(0x29d6f60) AccessHandler start for /101/
> 75947 Apache=SCALAR(0x29d6f60) AccessHandler finish for /101/
> 75947 Apache=SCALAR(0x8b5970) ResponseHandler start for /workflow/
> profile/desk/101/101/
> 75947 Apache=SCALAR(0x8b5970) ResponseHandler finish for /workflow/
> profile/desk/101/101/
> 75947 Apache=SCALAR(0x299e870) CleanupHandler start for /workflow/
> profile/desk/101/101/
> 75947 Apache=SCALAR(0x299e870) CleanupHandler finish for /workflow/
> profile/desk/101/101/
>
> The first number is the process number. I've just added print  
> statements to each of our handlers, one at the start and one at the  
> end. Note how there is this strange interim request for /101/ that the  
> TransHandler and the AccessHandler handle. I've no idea where that  
> comes from or what it's for. But the request finishes fine under  
> mod_perl1: the ResponseHandler creates the response, and the  
> CleanupHandler disconnects the session.
>
> Under mod_perl2, however, the same request looks like this:
>
> 75749 Apache2::RequestRec=SCALAR(0x29f3300) TransHandler start for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=SCALAR(0x29f3300) TransHandler finish for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=SCALAR(0x29f3300) AccessHandler start for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=SCALAR(0x29f3300) AccessHandler finish for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=SCALAR(0x2a10eb0) TransHandler start for /101/
> 75749 Apache2::RequestRec=SCALAR(0x2a10eb0) TransHandler finish for /
> 101/
> 75749 Apache2::RequestRec=SCALAR(0x2a10eb0) CleanupHandler start for /
> 101/
> 75749 Apache2::RequestRec=SCALAR(0x2a10eb0) CleanupHandler finish for /
> 101/
> 75749 Apache2::RequestRec=SCALAR(0x734df0) ResponseHandler start for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=SCALAR(0x734df0) ResponseHandler finish for /
> workflow/profile/desk/101/101/
>
> Note how the CleanupHandler runs on the /101/ request *before* the  
> response handler handles the original request URI. This leads to  
> errors, since the CleanupHandler syncs the cache and disconnects it --  
> so that here it's not available to the response handler! Without the  
> session, Bricolage gets pretty severe heartburn. So I'm again  
> wondering WTF that /101/ request is about, and why it's screwing with  
> our session. Note that this is a single request, all handled by a  
> single Apache process (using prefork).
>
> When I disable the TransHandler, I get this instead:
>
> 75793 Apache2::RequestRec=SCALAR(0x8dcf00) AccessHandler start for /
> workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=SCALAR(0x8dcf00) AccessHandler finish for /
> workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=SCALAR(0x292cd00) ResponseHandler start for /
> workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=SCALAR(0x292cd00) ResponseHandler finish  
> for /workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=SCALAR(0x28757c0) CleanupHandler start for /
> workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=SCALAR(0x28757c0) CleanupHandler finish for /
> workflow/profile/desk/101/101/
>
> The weird /101 request goes away, and all works as it should!
>
> My config, FWIW, looks like this:
>
> NameVirtualHost *:80
> <VirtualHost *:80>
>    DocumentRoot           /usr/local/bricolage/comp
>    ServerName             localhost
>    DefaultType            "text/html; charset=utf-8"
>    AddDefaultCharset      utf-8
>    SetHandler             perl-script
>    PerlResponseHandler    Bric::App::Handler
>    PerlAccessHandler      Bric::App::AccessHandler
>    PerlCleanupHandler     Bric::App::CleanupHandler
> </VirtualHost>
>
> Has anyone seen something like this before? For this request, all the  
> TransHandler does is return DECLINED. I get the same issues even if I  
> modify it do make sure it does nothing more than return DECLINED. Is  
> there some side-effect of using a TransHandler that I've just missed,  
> that it forces this weird appearence of a subrequest that then pushes  
> the CleanupHandler execution ahead of the ResponseHandler?

I think the /101 request is a subrequest. Do you use path_info? This together
with the perl-script handler can cause a subrequest when apache wants to
translate PATH_INFO to PATH_INFO_TRANSLATED. You can distinguish between a
subrequest and the main request by examining $r->main.

Better register your cleanup handler with the request pool of the request you
want.

Torsten

--
Need professional mod_perl support?
Just hire me: torsten.foertsch@(protected)