Mailing List CGatePro@mail.stalker.com Message #100603
From: Gib Henry <gib@realpeople.com>
Subject: LDAP Mystery: Evaporating connection
Date: Thu, 02 Sep 2010 15:07:42 -0500
To: CommuniGate Pro Mailing List <CGatePro@mail.stalker.com>
I can connect to CGP’s LDAP from my office machine.  Both machines have fixed public addresses.  When I use identical software with identical configurations at home, I get “Cannot connect” errors.

The server machine's console log shows that the incoming connection is accepted.  The CGP log concurs, says the connection is accepted, then, in the same .001 second, closes the connection without furnishing the search info requested:

14:07:51.117 5 LDAP [0.0.0.0]:636 <- [71.8.91.99]:53018 connection request. socket=44
14:07:51.117 5 LDAP new VStream created, n=1
14:07:51.117 5 LDAP stream thread started
14:07:51.117 4 LDAP-000411([71.8.91.99]) got connection on [24.73.176.117]:636(realpeople.com) from [71.8.91.99]:53018
14:07:51.117 4 LDAP-000411([71.8.91.99]) SSLv2 client hello as TLSv1: method=RC4_MD5, session=3855 < ...>
14:07:51.117 4 LDAP-000411([71.8.91.99]) TLS handshake: sending 'server_hello'
14:07:51.117 5 LDAP-000411([71.8.91.99]) TLS out 22: (74) ...
14:07:51.117 4 LDAP-000411([71.8.91.99]) TLS handshake: sending the certificate
14:07:51.117 5 LDAP-000411([71.8.91.99]) TLS out 22: (607) ...
14:07:51.117 4 LDAP-000411([71.8.91.99]) TLS handshake: sending 'hello_done'
14:07:51.117 5 LDAP-000411([71.8.91.99]) TLS out 22: (4) ...
14:07:51.307 4 LDAP-000411([71.8.91.99]) TLS client key exchange processed
14:07:51.307 4 LDAP-000411([71.8.91.99]) security initiated
14:07:51.397 5 LDAP-000411([71.8.91.99]) TLS inp 20: (1) 01
14:07:51.397 4 LDAP-000411([71.8.91.99]) TLS 'change cipher' processed
14:07:51.397 4 LDAP-000411([71.8.91.99]) TLS 'change cipher' sending
14:07:51.397 5 LDAP-000411([71.8.91.99]) TLS out 20: (1) 01
14:07:51.397 5 LDAP-000411([71.8.91.99]) TLS inp 22: (32) ...
14:07:51.397 4 LDAP-000411([71.8.91.99]) TLS 'finish handshake' processed
14:07:51.398 4 LDAP-000411([71.8.91.99]) TLS handshake: sending 'finished'
14:07:51.398 5 LDAP-000411([71.8.91.99]) TLS out 22: (32) ...
14:07:51.398 4 LDAP-000411([71.8.91.99]) TLS(RC4_MD5) connection accepted for 'realpeople.com', session 3855
14:07:51.398 4 LDAP-000411([71.8.91.99]) TLS connection is closing
14:07:51.398 5 LDAP-000411([71.8.91.99]) TLS out 21: (18) ...
14:07:51.398 4 LDAP-000411([71.8.91.99]) closing connection
14:07:51.398 4 LDAP-000411([71.8.91.99]) releasing stream
14:08:06.000 5 LDAP stream thread finished

Any insight into what happened (or rather, did NOT happen) here at 14:07:51.398???  There is NO error message; the connection just evaporates.  The comparable area of the log for a successful connection from the office looks like this (differences underlined in red):

14:10:27.990 5 LDAP [0.0.0.0]:636 <- [24.73.176.115]:58909 connection request. socket=35
14:10:27.990 5 LDAP new VStream created, n=1
14:10:27.991 5 LDAP stream thread started
14:10:27.991 4 LDAP-000412([24.73.176.115]) got connection on [24.73.176.117]:636(realpeople.com) from [24.73.176.115]:58909
14:10:28.548 4 LDAP-000412([24.73.176.115]) SSLv2 client hello as TLSv1: method=RC4_MD5, session=3857 < ...
14:10:28.548 4 LDAP-000412([24.73.176.115]) TLS handshake: sending 'server_hello'
14:10:28.548 5 LDAP-000412([24.73.176.115]) TLS out 22: (74) ...
14:10:28.548 4 LDAP-000412([24.73.176.115]) TLS handshake: sending the certificate
14:10:28.548 5 LDAP-000412([24.73.176.115]) TLS out 22: (607)...
14:10:28.548 4 LDAP-000412([24.73.176.115]) TLS handshake: sending 'hello_done'
14:10:28.548 5 LDAP-000412([24.73.176.115]) TLS out 22: (4) 0E 00 00 00
14:10:28.660 5 LDAP-000412([24.73.176.115]) TLS inp 22: (70) ...
14:10:28.661 4 LDAP-000412([24.73.176.115]) TLS client key exchange processed
14:10:28.661 4 LDAP-000412([24.73.176.115]) security initiated
14:10:28.729 5 LDAP-000412([24.73.176.115]) TLS inp 20: (1) 01
14:10:28.729 4 LDAP-000412([24.73.176.115]) TLS 'change cipher' processed
14:10:28.729 4 LDAP-000412([24.73.176.115]) TLS 'change cipher' sending
14:10:28.729 5 LDAP-000412([24.73.176.115]) TLS out 20: (1) 01
14:10:29.077 5 LDAP-000412([24.73.176.115]) TLS inp 22: (32) ...
14:10:29.077 4 LDAP-000412([24.73.176.115]) TLS 'finish handshake' processed
14:10:29.078 4 LDAP-000412([24.73.176.115]) TLS handshake: sending 'finished'
14:10:29.078 5 LDAP-000412([24.73.176.115]) TLS out 22: (32) ...
14:10:29.078 4 LDAP-000412([24.73.176.115]) TLS(RC4_MD5) connection accepted for 'realpeople.com', session 3857
14:10:29.079 5 LDAP-000412([24.73.176.115]) TLS inp 23: (41) ...
14:10:29.079 5 LDAP-000412([24.73.176.115]) inp: SEQ(23) ...
14:10:29.079 4 LDAP-000412([24.73.176.115]) BINDing as 'gib'
14:10:29.079 2 LDAP-000412([24.73.176.115]) 'gib@realpeople.com' connected from [24.73.176.115]:58909
14:10:29.079 4 LDAP-000412([24.73.176.115]) Logged in as <master>. authType=0
14:10:29.079 5 LDAP-000412([24.73.176.115]) s-out: 30 0C 02 01 01 61 07 0A 01 00 04 00 04 00
14:10:29.079 5 LDAP-000412([24.73.176.115]) TLS out 23: (30) ...
14:10:29.163 5 LDAP-000412([24.73.176.115]) TLS inp 23: (96) ...
14:10:29.163 5 LDAP-000412([24.73.176.115]) inp: SEQ(78) ...
14:10:29.163 4 LDAP-000412([24.73.176.115]) searching(one) 'ou=Clients,cn=realpeople.com'
14:10:29.163 4 LDAP-000412([24.73.176.115]) searching where (objectclass=*)
14:10:29.163 4 LDAP-000412([24.73.176.115]) searching for objectclass


Thanks in advance for any clues as to why the top connection fails while the bottom one succeeds.  Cheers,
--
Gib Henry
Subscribe (FEED) Subscribe (DIGEST) Subscribe (INDEX) Unsubscribe Mail to Listmaster