Porting Bricolage to mp2: TransHandler Interference

Howdy,

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

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


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?

Many TIA for any insight you can provide.

Best,

David

Re: Porting Bricolage to mp2: TransHandler Interference

>
> 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/

>
> NameVirtualHost *: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
>

cleanup handlers are just callbacks run when a memory pool goes out of
scope. your test suggests that the memory pool allocated for the
request is going out of scope before the response handler runs, which is
odd indeed :)

I'd try these things:

o use a PerlLogHandler instead of a PerlCleanupHandler

o push your cleanup from an earlier phase instead of httpd.conf

o call $r->cleanup_register from an earlier phase instead of pushing
a handler

HTH

--Geoff

Re: Porting Bricolage to mp2: TransHandler Interference

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

Re: Porting Bricolage to mp2: TransHandler Interference

On Apr 23, 2008, at 11:09, Geoffrey Young wrote:

> cleanup handlers are just callbacks run when a memory pool goes out
> of scope.

Oh. And here I thought that they ran when the request completed.

> your test suggests that the memory pool allocated for the request is
> going out of scope before the response handler runs, which is odd
> indeed :)

Any idea how that can happen? Or what that weird /101/ "subrequest" is
about?

> I'd try these things:
>
> o use a PerlLogHandler instead of a PerlCleanupHandler

But that runs before the request is returned to the user, right?

> o push your cleanup from an earlier phase instead of httpd.conf
>
> o call $r->cleanup_register from an earlier phase instead of
> pushing a handler

Thanks, I'll give those a try, just as soon as I finish building a
debugging perl + mod_perl + Apache system to debug another issue on
the developers list. :-)

Thanks,

David

Re: Porting Bricolage to mp2: TransHandler Interference

On Apr 23, 2008, at 11:16, Torsten Foertsch wrote:

> 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.

I was fiddling with that yesterday, and $r->main seemed to return true
every time. But I'll try again.

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

Will do, thanks.

David

Re: Porting Bricolage to mp2: TransHandler Interference

On Apr 23, 2008, at 11:19, David E. Wheeler wrote:

> On Apr 23, 2008, at 11:16, Torsten Foertsch wrote:
>
>> 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.
>
> I was fiddling with that yesterday, and $r->main seemed to return
> true every time. But I'll try again.

The /101/ request *is* a subrequest? WTF is that coming from? It seems
to happen after the AccessHandler finishes, but before the
ResponseHandler runs. Maybe AccessHandler somehow triggers it? I don't
see anything in there that looks like it calls path_info(), but I'll
keep looking.

Best,

David

Re: Porting Bricolage to mp2: TransHandler Interference

On Apr 23, 2008, at 11:53, David E. Wheeler wrote:

>> I was fiddling with that yesterday, and $r->main seemed to return
>> true every time. But I'll try again.
>
> The /101/ request *is* a subrequest? WTF is that coming from? It
> seems to happen after the AccessHandler finishes, but before the
> ResponseHandler runs. Maybe AccessHandler somehow triggers it? I
> don't see anything in there that looks like it calls path_info(),
> but I'll keep looking

The creation of the subrequest is weird. There code in Bricolage that
uses path_info() (it runs on Mason after all), but I can't see why the
subrequest gets created *only* if there is a TransHandler, even if
that TransHandler does nothing but return DECLINED.

To whit, I changed the TransHandler to just use
Apache2::Const::DECLINED for its handler. Nothing else. The request
looks like this:

77532 AccessHandler start for (main) /workflow/profile/desk/101/101/
77532 AccessHandler finish for (main) /workflow/profile/desk/101/101/
77532 CleanupHandler start for (sub) /101/
77532 ResponseHandler start for (main) /workflow/profile/desk/101/101/
77532 ResponseHandler finish for (main) /workflow/profile/desk/101/101/
77532 CleanupHandler start for (main) /workflow/profile/desk/101/101/
77532 CleanupHandler finish for (main) /workflow/profile/desk/101/101/

If I remove the TransHandler altogether, it looks like this:

77709 AccessHandler start for (main) /workflow/profile/desk/101/101/
77709 AccessHandler finish for (main) /workflow/profile/desk/101/101/
77709 ResponseHandler start for (main) /workflow/profile/desk/101/101/
77709 ResponseHandler finish for (main) /workflow/profile/desk/101/101/
77709 CleanupHandler start for (main) /workflow/profile/desk/101/101/
77709 CleanupHandler finish for (main) /workflow/profile/desk/101/101/

No subrequest appears at all! So this leads me to conclude one of two
things. Either

1. Internally, mod_perl's TransHandler code triggers the subrequest.
Why it would, I have no idea, but if there is no TransHandler, that
code doesn't execute and there is no subrequest. Or:

2. There is some code executing somewhere in Bricolage between the
AccessHander and the ResponseHandler, but only if there is a
TransHandler. If this is the case, I have no idea where that code
would be. Remember, this is my httpd.conf:

NameVirtualHost *: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
PerlTransHandler Apache2::Const::DECLINE


So, with this information, I can at least work around the problem by
declining to do anything in the AccessHandler or the CleanupHandler
when $r->main returns something, but I'm still mystfied as to where
this subrequest is coming from.

Thanks,

David

Re: Porting Bricolage to mp2: TransHandler Interference

On Wed 23 Apr 2008, David E. Wheeler wrote:
> No subrequest appears at all! So this leads me to conclude one of two =A0
> things. Either
>
> 1. Internally, mod_perl's TransHandler code triggers the subrequest. =A0
> Why it would, I have no idea, but if there is no TransHandler, that =A0
> code doesn't execute and there is no subrequest. Or:
>
> 2. There is some code executing somewhere in Bricolage between the =A0
> AccessHander and the ResponseHandler, but only if there is a =A0
> TransHandler. If this is the case, I have no idea where that code =A0
> would be. Remember, this is my httpd.conf:
>
> NameVirtualHost *:80
>
> =A0 DocumentRoot =A0 =A0 =A0 =A0 =A0 /usr/local/bricolage/comp
> =A0 ServerName =A0 =A0 =A0 =A0 =A0 =A0 localhost
> =A0 DefaultType =A0 =A0 =A0 =A0 =A0 =A0"text/html; charset=3Dutf-8"
> =A0 AddDefaultCharset =A0 =A0 =A0utf-8
> =A0 SetHandler =A0 =A0 =A0 =A0 =A0 =A0 perl-script
> =A0 PerlResponseHandler =A0 =A0Bric::App::Handler
> =A0 PerlAccessHandler =A0 =A0 =A0Bric::App::AccessHandler
> =A0 PerlCleanupHandler =A0 =A0 Bric::App::CleanupHandler
> =A0 PerlTransHandler =A0 =A0 =A0 Apache2::Const::DECLINE
>
>
> So, with this information, I can at least work around the problem by =A0
> declining to do anything in the AccessHandler or the CleanupHandler =A0
> when $r->main returns something, but I'm still mystfied as to where =A0
> this subrequest is coming from.

Well, I think I can shed some light on that mystery. When you use=20
the "perl-script" handler instead of "modperl" then your C-level response=20
handler is modperl_response_handler_cgi (see src/modules/perl/mod_perl.c).=
=20
This function calls modperl_env_request_populate (see modperl_env.c) and th=
at=20
calls ap_add_cgi_vars (see httpd.../server/util_script.c). All that happens=
=20
in the response phase *before* the PerlResponseHandler is called.

ap_add_cgi_vars contains the following code:

if (r->path_info && r->path_info[0]) {
...
pa_req =3D ap_sub_req_lookup_uri(ap_escape_uri(r->pool, r->path_info)=
, r,
NULL);
if (pa_req->filename) {
...
apr_table_setn(e, "PATH_TRANSLATED", pt);

You see, if path_info is used the C-notion of $r->lookup_uri is used to map=
=20
this path_info to the file system. The result is then made available as=20
$r->subprocess_env->{PATH_TRANSLATED}. This environment variable is seldom=
=20
used but unfortunately part of the CGI/1.1 standard=20
(http://hoohoo.ncsa.uiuc.edu/cgi/env.html).

Why the subreq is not set up if your transhandler is not used I can only=20
guess. Maybe it sets $r->path_info explicitly maybe it sets $r->filename so=
=20
that the standard maptostorage handler sets path_info. But path_info is=20
probably empty if your transhandler is not used.

=46urther I recall a problem/bug that if the PerlCleanupHandler is the only=
=20
configured Perl handler for a request it is not called. But that does not=20
seem to hit you since you have a (Trans|Access)Handler at least. If you thi=
nk=20
that may be the case try the threading mod_perl branch. There the problem i=
s=20
solved (http://svn.apache.org/repos/asf/perl/modperl/branches/threa ding).=20
That branch still does not work with perl 5.10.

Torsten

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

Re: Porting Bricolage to mp2: TransHandler Interference

On Apr 24, 2008, at 02:20, Torsten Foertsch wrote:

> Well, I think I can shed some light on that mystery. When you use
> the "perl-script" handler instead of "modperl" then your C-level
> response
> handler is modperl_response_handler_cgi (see src/modules/perl/
> mod_perl.c).
> This function calls modperl_env_request_populate (see modperl_env.c)
> and that
> calls ap_add_cgi_vars (see httpd.../server/util_script.c). All that
> happens
> in the response phase *before* the PerlResponseHandler is called.

Well, I'm no C coder, but I get the idea. Sure enough, when I use the
"perl-script" handler (as we've been doing for mod_perl 1, of course),
I see:

Trans: /workflow/profile/desk/101/101/
Trans: /101/
Cleanup: /101/
Response: /workflow/profile/desk/101/101/
Cleanup: /workflow/profile/desk/101/101/

But when I switch to the "modperl" handler (which was a simple find-
and-replace, thank you very much), I see:

Trans: /workflow/profile/desk/101/101/
Response: /workflow/profile/desk/101/101/
Cleanup: /workflow/profile/desk/101/101/

*So* much better! So already Bricolage is better running on mod_perl 2
than on mod_perl 1. :-)

> Why the subreq is not set up if your transhandler is not used I can
> only
> guess. Maybe it sets $r->path_info explicitly maybe it sets $r-
> >filename so
> that the standard maptostorage handler sets path_info. But path_info
> is
> probably empty if your transhandler is not used.

It is odd, but it does seem like the perl-script handler is doing
something different if I've installed a TransHandler.

> Further I recall a problem/bug that if the PerlCleanupHandler is the
> only
> configured Perl handler for a request it is not called. But that
> does not
> seem to hit you since you have a (Trans|Access)Handler at least. If
> you think
> that may be the case try the threading mod_perl branch. There the
> problem is
> solved (http://svn.apache.org/repos/asf/perl/modperl/branches/threa ding
> ).
> That branch still does not work with perl 5.10.

I don't think that's related, but it's good to know that there is
ongoing work on this stuff.

Thanks a million for the detailed explanation!

Best,

David