duplicate sockets ? mod-perl 2.0.2, apache 2.2

[André Warnier <aw...@ice-sa.com>]

Hi List.

I have a puzzling problem in a custom PerlAuthenHandler module.
I have checked the documentation, and the mod-perl mailing lists as far 
as a year back without finding anything relevant.
I cannot believe something this simple and this big would not have been 
found out yet by someone else, so I suppose there is a very stupid 
mistake on my part, but for the life of me..

In summary, the problem is that in the authen module I open a tcp 
connection to an external server *once*, but the server sees *two* 
connections being opened.
I know the above because I trace what happens on both sides and that is 
what the logfiles show.

If this rings a bell for anyone right now, you might not need to peruse 
the rest, just give me a clue.

More in detail :

Environment :
Apache/2.2.3 (Debian) DAV/2 mod_jk/1.2.18 PHP/4.4.4-8+etch4
mod_ssl/2.2.3 OpenSSL/0.9.8c mod_perl/2.0.2 Perl/v5.8.8 Server at
xxx.com Port 80
Host uname -a :
Linux arthur 2.6.18-4-686 #1 SMP Wed May 9 23:03:12 UTC 2007 i686 GNU/Linux

My custom authen module is supposed to do user authentication versus a 
proprietary database system. For that it open a TCP connection with the
database server, sends it some XML-formatted request, and reads the 
answer to determine if the authentication worked or not.
I use the same database connection and verification code in a perl 
cgi-bin script to the same effect, and it works fine there.

When using this same code in this new Apache2 module however, it looks 
(from the external database server connection trace) as if the Apache2 
module is opening the connection not once, but twice !
Then what seems to happen is that the message to the database is sent on 
one of these sockets, but my module tries to read the answer on the 
"other" (?) socket and gets stuck waiting for an answer that never comes 
(because on the second connection, the database server never received 
any request).

The code used to open the socket is the following; it is located in a 
sub() used by the authentication module, and there is only one
place where this code is present, and is called.

   my $XMLAddr = inet_aton($XMLHost); # XMLHost is "localhost"
   my $Paddr = sockaddr_in($XMLPort, $XMLAddr); # XMLPort is "11100"
   unless (socket(XMLSRV, PF_INET, SOCK_STREAM, getprotobyname('tcp'))
&& connect(XMLSRV, $Paddr)) {
     $r->warn("$$:  ** Cannot connect to Star XML server **");
     return 0;
   }
   XMLSRV->autoflush(1);
   binmode(XMLSRV);
   $r->warn("$$:  Connected to StarXML.");

According to the Apache server log, the above code is executed once, not 
twice.
But according to the target database system log, 2 separate tcp 
connections are being opened !

Next, I send the XML message on the same handle via

$xmlout = "<tag>some message</tag>";
   unless (defined($xmlsize = send(XMLSRV,$xmlout,0))) {
     $r->warn("  ** Star XML request not sent : $! **");
     close XMLSRV;
     return 0;
   }

The Apache logfile shows the message sent once, correctly.
The database server log shows the message being received on one of the
now open connections (unfortunately, it doesn't say which).

Then I try to read the response, via

[...]
     $xmlread = recv(XMLSRV,$xmlbuf,4096,0); # read header

And that is where I get stuck, waiting forever on the recv(), although
the database server log shows the response being sent (but unfortunately 
not on which connection it is being sent).

I have tried various methods to open the socket and write/read to/from
it (IO::Socket::INET, syswrite, sysread, read, etc..) but nothing seems
to make a difference.  There are always 2 connections on the database
server side, for a single new() or open() or connect() on the Apache 
side, and it always gets stuck on the read() or recv().  I have also 
inserted a tunnel-like tracing module (similar to socat) between the 
authentication module and the database system, which confirms that my 
apache module is effectively opening 2 connections instead of one.  I'm 
puzzled.

The Apache configuration for the authentication is as follows :

<Location "/priv">
   #SetHandler perl-script
   PerlAuthenHandler AM::Authtest
   AuthType Basic
   AuthName "Protected Area"
   Require valid-user
   PerlSetVar DebugLevel 1
   PerlSetVar ClientCode "SKA"
   PerlSetVar CookieName 'JoeSkasCookie'
   PerlSetVar LogMethod "STARLOGXML"
   PerlSetVar LogStarXMLHost "arthur:11300"
   PerlSetVar LogStarHost "arthur:11002"
   PerlSetVar LogStarDB "STARLOG"
</Location>


Before I send more info or source code, does this ring a bell for anyone
?  Am I overlooking something evident or some Apache/mod_perl
particularity regarding sockets ?

Thank you in advance,
aw

Re: duplicate sockets ? mod-perl 2.0.2, apache 2.2

[André Warnier <aw...@ice-sa.com>]

Philippe M. Chiasson wrote:
> Perrin Harkins wrote:
>> On 9/13/07, André Warnier <aw...@ice-sa.com> wrote:
>>> In summary, the problem is that in the authen module I open a tcp
>>> connection to an external server *once*, but the server sees *two*
>>> connections being opened.
>> Any chance you are running that code during startup, before the fork happens?
> 
I don't think so, but then what do I know ?

The module is mentioned only in the <location> section mentioned 
earlier, and only as a PerlAuthenHandler.  It is not pre-loaded or 
anything.  There is some unconditional logging in the module, and it 
does not show up when starting/restarting Apache.
The log shows that the module is called when it should, iow when a user 
tries to access the protected area.

This link :
http://ska.dev.wissensbank.com/mod_perl_list/
gives temporary access to pretty much everything relevant : module 
source, apache logfiles, database module log, and a link to trigger the 
authentication and consequent module's execution (which you can follow 
later in the logfiles).

In the basic authentication dialog, you can enter whathever you want, 
the problem happens during the subsequent phase of checking that id.

In the Apache error.log, the first message that appears for a particular 
"click" on the protected link, is
Starting Authtest
That's a very good sign, but it's downhill from there..
(note : for the timestamp, the server in question in in Germany, I guess 
Western European time).

Sigh. I keep on expecting someone will find the absolute beginner 
bloober in my code and shame me, but I would like to understand what 
happens.

Thanks

Re: duplicate sockets ? mod-perl 2.0.2, apache 2.2

[André Warnier <aw...@ice-sa.com>]

Philippe M. Chiasson wrote:
> André Warnier wrote:
[...]
> Even better is to turn the problem code into a short mod_perl test skeleton
> (http://perl.apache.org/docs/2.0/user/help/help.html#Problem_Description)

I tried to do that at first, but the problem appears only when I open 
the connection to the database server, and did not find an easy way to 
really simplify that part.  That portion, by the way, is offset in a 
sub(), which is only called when get_basic_auth_pw() returns a user-id.

> 
>> I am not explicitly running this during startup, but maybe it happens 
>> without my knowledge.
>> Is a PerlAuthenHandler executed during a start/restart, even if I do not 
>> pre-load it ?
> 
> I should not be, no. Unless you explicitely load it somewhere else, like
> in a startp.pl or similar.

I added a link in my links the web page to the startup.pl script I use. 
But it makes no reference whatsoever to the authentication module.

> 
>> And if so, does it explain why I get two connections, and 
>> can I do anything about it and/or about these duplicate sockets ?
> 
> Missing from the link you give is the relevant httpd.conf file
> that configures your module.
I also addded a link to a copy of the configuration file for that 
virtual server.  The reference to the module is at the end.
There is no other reference to this module anywhere else (not in the 
main httpd.conf file, not in other virtual servers).

> 
[...]
> BTW, are you using a threaded MPM by any chance ?
I don't really know.  This is the vanilla version of Apache2 available 
for Linux Debian Etch.  The configuration and modules are spread out all 
over the place, and the main apache2.conf file shows several MPM 
settings, but conditional.
How do I see what MPM it is using ?
Is there some kind of httpd command-line option that would tell me which 
is the MPM used (à la perl -V) ?  (ok, I can look it up in the Apache 
doc, but maybe you know off-hand ?).

> 
> Also, you should _really_ avoid filehandles like XMLSRV and stick with
> lexicals, like connect(my $xmlsrv, [...]) as these are more global than
> you might think.
It was so in the first version of the module (which had the same 
problem). I changed it to a "vanilla" filehandle to see if it made any 
difference.  I can change it back and test again if you wish.
I also tried to use IO::Socket:.INET instead of low-level sockets and 
other variations, but all variations have the same symptoms.
All the socket connection code (open, write, read, close) is in a sub(). 
  If I change it to avoid a filehandle and use a variable, should I use 
a lexical (my $xmlsrv), or a global (our $xmlsrv) ? Should I check if 
the variable is defined beforehand, and force a "close()" if it is ?

> 
> Another thought. Did you realize that when a web browser visits a password
> protected area, it will have to make *2* requests ?
> First it will make a regular request, and the server will say 401, auth required.
> That's when the browser asks the user for a username/password and re-sends.
> Could that explain it ?

Yes, I understand this.  The module follows the general plan as per the 
examples in the documentation : it calls get_basic_auth_pw(), and if it 
subsequently has no user-id, returns 401 immediately.  In that case, no 
socket to the database module is ever opened (that I know of).
(I can follow this in the logfile)
If it gets a user-id/pw (at the second call), then it proceeds to check 
it against the database, and for that it needs to open the socket.
Because of the diag logging messages I put in the code, I don't see how 
it could possibly call the socket-opening code twice.
But that is of course the very reason why I am puzzled, because the 
database module logging shows it does, somehow.

Re: duplicate sockets ? mod-perl 2.0.2, apache 2.2

["Philippe M. Chiasson" <go...@ectoplasm.org>]

Perrin Harkins wrote:
> On 9/13/07, André Warnier <aw...@ice-sa.com> wrote:
>> In summary, the problem is that in the authen module I open a tcp
>> connection to an external server *once*, but the server sees *two*
>> connections being opened.
> 
> Any chance you are running that code during startup, before the fork happens?

And that would be caused by the famous/infamous

http://perl.apache.org/docs/2.0/user/handlers/server.html#Start_Immediately_Restarts

------------------------------------------------------------------------
Philippe M. Chiasson     GPG: F9BFE0C2480E7680 1AE53631CB32A107 88C3A5A5
http://gozer.ectoplasm.org/       m/gozer\@(apache|cpan|ectoplasm)\.org/

Re: duplicate sockets ? mod-perl 2.0.2, apache 2.2

[Perrin Harkins <pe...@elem.com>]

On 9/13/07, André Warnier <aw...@ice-sa.com> wrote:
> In summary, the problem is that in the authen module I open a tcp
> connection to an external server *once*, but the server sees *two*
> connections being opened.

Any chance you are running that code during startup, before the fork happens?

- Perrin