On Wed 23 Apr 2008, David E. Wheeler wrote:
> I'm busy finalizing the port of Bricolage to mod_perl2. In the =A0
> process, I've discovered a bit of weirdness with our TransHandler. For =A0
> certain requests, it seems to execute twice. Under mod_perl1, here's =A0
> an example:
>
> 75947 Apache=3DSCALAR(0x295ed70) TransHandler start for /workflow/
> profile/desk/101/101/
> 75947 Apache=3DSCALAR(0x295ed70) TransHandler finish for /workflow/
> profile/desk/101/101/
> 75947 Apache=3DSCALAR(0x295ed70) AccessHandler start for /workflow/
> profile/desk/101/101/
> 75947 Apache=3DSCALAR(0x295ed70) AccessHandler finish for /workflow/
> profile/desk/101/101/
> 75947 Apache=3DSCALAR(0x29d6f60) TransHandler start for /101/
> 75947 Apache=3DSCALAR(0x29d6f60) TransHandler finish for /101/
> 75947 Apache=3DSCALAR(0x29d6f60) AccessHandler start for /101/
> 75947 Apache=3DSCALAR(0x29d6f60) AccessHandler finish for /101/
> 75947 Apache=3DSCALAR(0x8b5970) ResponseHandler start for /workflow/
> profile/desk/101/101/
> 75947 Apache=3DSCALAR(0x8b5970) ResponseHandler finish for /workflow/
> profile/desk/101/101/
> 75947 Apache=3DSCALAR(0x299e870) CleanupHandler start for /workflow/
> profile/desk/101/101/
> 75947 Apache=3DSCALAR(0x299e870) CleanupHandler finish for /workflow/
> profile/desk/101/101/
>
> The first number is the process number. I've just added print =A0
> statements to each of our handlers, one at the start and one at the =A0
> end. Note how there is this strange interim request for /101/ that the =A0
> TransHandler and the AccessHandler handle. I've no idea where that =A0
> comes from or what it's for. But the request finishes fine under =A0
> mod_perl1: the ResponseHandler creates the response, and the =A0
> CleanupHandler disconnects the session.
>
> Under mod_perl2, however, the same request looks like this:
>
> 75749 Apache2::RequestRec=3DSCALAR(0x29f3300) TransHandler start for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=3DSCALAR(0x29f3300) TransHandler finish for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=3DSCALAR(0x29f3300) AccessHandler start for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=3DSCALAR(0x29f3300) AccessHandler finish for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=3DSCALAR(0x2a10eb0) TransHandler start for /101/
> 75749 Apache2::RequestRec=3DSCALAR(0x2a10eb0) TransHandler finish for /
> 101/
> 75749 Apache2::RequestRec=3DSCALAR(0x2a10eb0) CleanupHandler start for /
> 101/
> 75749 Apache2::RequestRec=3DSCALAR(0x2a10eb0) CleanupHandler finish for /
> 101/
> 75749 Apache2::RequestRec=3DSCALAR(0x734df0) ResponseHandler start for /
> workflow/profile/desk/101/101/
> 75749 Apache2::RequestRec=3DSCALAR(0x734df0) ResponseHandler finish for /
> workflow/profile/desk/101/101/
>
> Note how the CleanupHandler runs on the /101/ request *before* the =A0
> response handler handles the original request URI. This leads to =A0
> errors, since the CleanupHandler syncs the cache and disconnects it -- =A0
> so that here it's not available to the response handler! Without the =A0
> session, Bricolage gets pretty severe heartburn. So I'm again =A0
> wondering WTF that /101/ request is about, and why it's screwing with =A0
> our session. Note that this is a single request, all handled by a =A0
> single Apache process (using prefork).
>
> When I disable the TransHandler, I get this instead:
>
> 75793 Apache2::RequestRec=3DSCALAR(0x8dcf00) AccessHandler start for /
> workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=3DSCALAR(0x8dcf00) AccessHandler finish for /
> workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=3DSCALAR(0x292cd00) ResponseHandler start for /
> workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=3DSCALAR(0x292cd00) ResponseHandler finish =A0
> for /workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=3DSCALAR(0x28757c0) CleanupHandler start for /
> workflow/profile/desk/101/101/
> 75793 Apache2::RequestRec=3DSCALAR(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
>
> =A0 =A0DocumentRoot =A0 =A0 =A0 =A0 =A0 /usr/local/bricolage/comp
> =A0 =A0ServerName =A0 =A0 =A0 =A0 =A0 =A0 localhost
> =A0 =A0DefaultType =A0 =A0 =A0 =A0 =A0 =A0"text/html; charset=3Dutf-8"
> =A0 =A0AddDefaultCharset =A0 =A0 =A0utf-8
> =A0 =A0SetHandler =A0 =A0 =A0 =A0 =A0 =A0 perl-script
> =A0 =A0PerlResponseHandler =A0 =A0Bric::App::Handler
> =A0 =A0PerlAccessHandler =A0 =A0 =A0Bric::App::AccessHandler
> =A0 =A0PerlCleanupHandler =A0 =A0 Bric::App::CleanupHandler
>

>
> Has anyone seen something like this before? For this request, all the =A0
> TransHandler does is return DECLINED. I get the same issues even if I =A0
> modify it do make sure it does nothing more than return DECLINED. Is =A0
> there some side-effect of using a TransHandler that I've just missed, =A0
> that it forces this weird appearence of a subrequest that then pushes =A0
> the CleanupHandler execution ahead of the ResponseHandler?


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

Better register your cleanup handler with the request pool of the request y=
ou=20
want.

Torsten

=2D-
Need professional mod_perl support?
Just hire me: torsten.foertsch@gmx.net