[SERF-177] svn 1.8.15 + serf on Solaris 9/10 + httpd 2.2.27 + kerberos

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: serf-1.3.8
• Fix Version/s: serf-1.3.8
• Labels: kerberos
• Environment: Solaris 9/SPARC, 10/SPARC
• Assignee: Unassigned
• Reporter: The Written Word, Inc.
• Created: 31/Dec/15 19:33
• Updated: 03/Apr/16 12:24
• Resolved: 14/Feb/16 01:07

Description

I have Apache httpd 2.2.27 + mod_auth_kerb-5.4 on a RHEL 6 host and
subversion 1.8.15 + serf-1.3.8 built on a Solaris 9/10 host. I would
like to use subversion on the Solaris hosts to authenticate against
the Kerberos server on the RHEL 6 host. I built serf to link against
GSSAPI on Solaris (so -DSERF_HAVE_GSSAPI was defined when building
serf and serf is linked against -ssl). Subversion appears to be
hanging:
$ svn info http://shu.il.thewrittenword.com
[hang]

On the server, access_log shows the following ad infinitum:
10.191.57.54 - - [31/Dec/2015:08:50:11 +0000] "OPTIONS / HTTP/1.1" 401 -
10.191.57.54 - - [31/Dec/2015:08:50:11 +0000] "OPTIONS / HTTP/1.1" 401 -
10.191.57.54 - - [31/Dec/2015:08:50:11 +0000] "OPTIONS / HTTP/1.1" 401 -
10.191.57.54 - - [31/Dec/2015:08:50:11 +0000] "OPTIONS / HTTP/1.1" 401 -
...

I also built subversion 1.8.15 on a Solaris 11 host and it behaves
correctly. serf was built the same way on this platform. So, maybe
some hiccup with serf+GSSAPI on Solaris 9/10?

With verbose logging enabled in serf-1.3.8 (CONN_VERBOSE=1
AUTH_VERBOSE=1 in serf_private.h), I see the following:
(Solaris 11/SPARC, working)
[2015-12-31T09:54:58.607054+00] outgoing.c: created connection 0xd9f38
[2015-12-31T09:54:58.615186+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:54:58.615282+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:54:58.615330+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:54:58.615384+00] [l:10.191.57.128:36956 r:10.191.57.117:80] outgoing.c: Limit max. nr. of outstanding requests for this connection to 1.
[2015-12-31T09:54:58.615430+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Initialized Kerberos context for this connection.
[2015-12-31T09:54:58.615486+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:54:58.645588+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Set Negotiate authn header on retried request.
[2015-12-31T09:54:58.663860+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Validate Negotiate response header.
[2015-12-31T09:54:58.663907+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: SPNEGO handshake completed.
[2015-12-31T09:54:58.664483+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Assume for now that the server supports persistent SPNEGO authentication.
[2015-12-31T09:54:58.665046+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:54:58.665101+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:54:58.665148+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:54:58.665195+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Server requires per-request SPNEGO authn, switching to stateless mode.
[2015-12-31T09:54:58.665239+00] [l:10.191.57.128:36956 r:10.191.57.117:80] outgoing.c: Limit max. nr. of outstanding requests for this connection to 1.
[2015-12-31T09:54:58.665305+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:54:58.666779+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Set Negotiate authn header on retried request.
[2015-12-31T09:54:58.685354+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Validate Negotiate response header.
[2015-12-31T09:54:58.685401+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: SPNEGO handshake completed.
[2015-12-31T09:54:58.685521+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Add initial Negotiate header to request.
[2015-12-31T09:54:58.685569+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:54:58.705019+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Validate Negotiate response header.
[2015-12-31T09:54:58.705067+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: SPNEGO handshake completed.
[2015-12-31T09:54:58.705354+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Add initial Negotiate header to request.
[2015-12-31T09:54:58.705403+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:54:58.724719+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Validate Negotiate response header.
[2015-12-31T09:54:58.724767+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: SPNEGO handshake completed.
[2015-12-31T09:54:58.725049+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Add initial Negotiate header to request.
[2015-12-31T09:54:58.725099+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:54:58.744328+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: Validate Negotiate response header.
[2015-12-31T09:54:58.744377+00] [l:10.191.57.128:36956 r:10.191.57.117:80] auth/auth_spnego.c: SPNEGO handshake completed.

(Solaris 10/SPARC, not working)
[2015-12-31T09:40:43.940512+00] outgoing.c: created connection 0x84398
[2015-12-31T09:40:43.942857+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.942985+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.943060+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.943140+00] [l:10.191.57.54:44663 r:10.191.57.117:80] outgoing.c: Limit max. nr. of outstanding requests for this connection to 1.
[2015-12-31T09:40:43.943211+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego.c: Initialized Kerberos context for this connection.
[2015-12-31T09:40:43.943294+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.981619+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.981723+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.981799+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.981884+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.982837+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.982920+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.982995+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.983071+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.984166+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.984248+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.984322+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.984398+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.985637+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.985719+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.985793+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.985870+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.986967+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.987049+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.987123+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.987199+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.988302+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.988384+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.988458+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.988535+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.989632+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.989714+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.989788+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.989864+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.990836+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate
[2015-12-31T09:40:43.990918+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Client supports: Negotiate
[2015-12-31T09:40:43.990992+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: ... matched: Negotiate
[2015-12-31T09:40:43.991069+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth_spnego_gss.c: Get principal for [e-mail]
[2015-12-31T09:40:43.992167+00] [l:10.191.57.54:44663 r:10.191.57.117:80] auth/auth.c: Server authz required. Response header(s): Negotiate,Negotiate

Older versions of subversion built against neon with GSSAPI support on
Solaris 9/10 worked fine. I am only seeing a problem now where serf
has replaced neon in the build.

gss_init_sec_context() on Solaris 11 and RHEL 6 returns 1 whereas on
Solaris 9/10 it returns 0. However, gss_init_sec_context() in
subversion+neon on Solaris 10 returns 1. No idea why the behavior is
different but I think this is the cause.