#4246: VDT 1.10.1k VOMS: voms-proxy-init failure shuts down server

VDT 1.10.1k
VOMS 1.8.3p1
VOMS Admin 2.0.14-1

When attempting to get a voms proxy for a user that does not exist in
the VO, the VOMS server shuts down and no longer processes any new requests.

The only solution I have found is to re-cycle the server.

The results shown later are the output from the following steps:
1. execute voms-proxy-init as myself (weigand)
- this works

2. execute voms-proxy-init as root user
- should fail as root host cert is not in the VO

3. execute voms-proxy-init as mysql (weigand)
- should work, but fails with "globus_gss_assist token :3: failure:
Connection closed
"

4. re-cycle the server doing..
- vdt-control --off voms
- vdt-control --on voms

5. execute voms-proxy-init as myself (weigand)
- this now works again

The other bizarre (to me) behavior I don't understand is the number of
retries it is doing on each attempt. The messages indicate that it is
trying another server but the vomses file has only one entry for the
oiv_test1 VO.


John Weigand

1. execute voms-proxy-init as myself (weigand)

[weigand@cms-xen3 bin]$ voms-proxy-init -voms oiv_test1:/oiv_test1
Enter GRID pass phrase:
Your identity: /DC=org/DC=doegrids/OU=People/CN=John Weigand 458491
Creating temporary proxy ............................................. Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov] "oiv_test1" Done
Creating proxy .................................. Done
Your proxy is valid until Wed Oct 22 01:32:46 2008


2. execute voms-proxy-init as root user

[root@cms-xen3 osg-voms]# voms-proxy-init --voms oiv_test1:/oiv_test1
Your identity: /DC=org/DC=doegrids/OU=Services/CN=cms-xen3.fnal.gov
Creating temporary proxy
.................................................... Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov] "oiv_test1"
Failed

Error: oiv_test1: Unable to satisfy Request!

Trying next server for oiv_test1.
Creating temporary proxy ...............................................
Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov]
"oiv_test1"gss_assist_get_unwrap failure:
globus_gss_assist token :3: failure: Connection closed
Failed

Error: GSS authentication failure
globus_gss_assist token :3: failure: Connection closed


Trying next server for oiv_test1.
Creating temporary proxy ....................................... Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov]
"oiv_test1"gss_assist_get_unwrap failure:
globus_gss_assist token :3: failure: Connection closed
Failed

Error: GSS authentication failure
globus_gss_assist token :3: failure: Connection closed


Trying next server for oiv_test1.
Creating temporary proxy ............................ Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov]
"oiv_test1"gss_assist_get_unwrap failure:
globus_gss_assist token :3: failure: Connection closed
Failed

Error: GSS authentication failure
globus_gss_assist token :3: failure: Connection closed


None of the contacted servers for oiv_test1 were capable
of returning a valid AC for the user.


3. execute voms-proxy-init as mysql (weigand)

[weigand@cms-xen3 bin]$ voms-proxy-init -voms oiv_test1:/oiv_test1
Enter GRID pass phrase:
Your identity: /DC=org/DC=doegrids/OU=People/CN=John Weigand 458491
Creating temporary proxy ................................. Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov]
"oiv_test1"gss_assist_get_unwrap failure:
globus_gss_assist token :3: failure: Connection closed
Failed

Error: GSS authentication failure
globus_gss_assist token :3: failure: Connection closed


Trying next server for oiv_test1.
Creating temporary proxy .................................. Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov]
"oiv_test1"gss_assist_get_unwrap failure:
globus_gss_assist token :3: failure: Connection closed
Failed

Error: GSS authentication failure
globus_gss_assist token :3: failure: Connection closed


Trying next server for oiv_test1.
Creating temporary proxy .......................................... Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov]
"oiv_test1"gss_assist_get_unwrap failure:
globus_gss_assist token :3: failure: Connection closed
Failed

Error: GSS authentication failure
globus_gss_assist token :3: failure: Connection closed


Trying next server for oiv_test1.
Creating temporary proxy ................................ Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov]
"oiv_test1"gss_assist_get_unwrap failure:
globus_gss_assist token :3: failure: Connection closed
Failed

Error: GSS authentication failure
globus_gss_assist token :3: failure: Connection closed


None of the contacted servers for oiv_test1 were capable
of returning a valid AC for the user.


4. re-cycle the server

[root@cms-xen3 osg-voms]# vdt-control --off voms
disabling init service voms... ok
[root@cms-xen3 osg-voms]# vdt-control --on voms
enabling init service voms... ok
[root@cms-xen3 osg-voms]#




5. execute voms-proxy-init as myself (weigand)

[weigand@cms-xen3 bin]$ voms-proxy-init -voms oiv_test1:/oiv_test1
Enter GRID pass phrase:
Your identity: /DC=org/DC=doegrids/OU=People/CN=John Weigand 458491
Creating temporary proxy ................................... Done
Contacting cms-xen3.fnal.gov:15000
[/DC=org/DC=doegrids/OU=Services/CN=http/cms-xen3.fnal.gov] "oiv_test1" Done
Creating proxy
.............................................................. Done
Your proxy is valid until Wed Oct 22 01:34:35 2008

Hi John,


This sounds really serious.

Right now the VDT is short-handed. Tim is out for the week, and I'm out
on Wednesday. So it will be a few days before we can dig into this.

I know that we moved to VOMS 1.8.3 because we had to, but bugs were
found in it by EGEE and they are currently certifying VOMS 1.8.8. So
there is a chance that this is a known problem. We'll ask the VOMS folks.

-alain

-----------------------------------------------------------------
Alain Roy vdt-support@opensciencegrid.org
VDT Support http://vdt.cs.wisc.edu/support.html

(Copying Vincenzo Ciaschini)

Vincenzo--

The VDT team received this bug report today. We're a bit short-handed at
the moment, so we haven't looked into it beyond reading the email.

However, I know that you have made bug fixes since VOMS 1.8.3, so I
thought I would just check with you: does this sound like something you
might have fixed?

Thanks,
-alain

p.s. VOMS "1.8.3p1" is VOMS 1.8.3 plus some patches, but they are
patches we submitted to you and you accepted, so there is nothing
surprising there, I hope. In particular, they are the OpenSSL patches,
the patch to build on Mac OS X, the patch to make voms-proxy-init have a
better return code, and to add the --dont-verify-ac option to
voms-proxy-info. Oh, and the log permission patch.

-----------------------------------------------------------------
Alain Roy vdt-support@opensciencegrid.org
VDT Support http://vdt.cs.wisc.edu/support.html


On Tue Oct 21 13:42:53 2008, weigand@fnal.gov wrote:
requests.
Done
"oiv_test1" Done
"oiv_test1" Done

Commit comment:
New branch for building and testing VOMS 1.8.8.


Changed files:
A vdt/branches/vdt-1.10.1-voms-1.8.8/

To generate a diff:
svn diff -c 8257 file:///p/condor/workspaces/vdt/svn

John:


Hm, I think we are saying that we actually get different behavior.
Here's what I did:

[as cat:] voms-proxy-init -voms VDT # success
[as vdt:] voms-proxy-init -voms VDT # failure
[as cat:] voms-proxy-init -voms VDT # success (I think)
[as root:] voms-proxy-init -voms VDT # failure
[as cat:] voms-proxy-init -voms VDT # failure

I would have to go through the whole sequence again to be 100% sure.

-- Tim

Vincenzo--

That makes sense to me, assuming everything is on the same computer.

John--

Did you run your tests all on one computer?

-alain

On Oct 31, 2008, at 10:30 AM, Vincenzo Ciaschini via RT wrote:

Vincenzo:

On 31 Oct 2008, you wrote:


I think I understand your hypothesis, but I have evidence that
suggests that it is not correct for the cases we're seeing.

I started investigating the suggested workaround by reproducing the
failure itself (all on the VOMS server machine):

[as cat:] voms-proxy-init -voms VDT # success
[as root:] voms-proxy-init -voms VDT # failure
[as cat:] voms-proxy-init -voms VDT # failure

This pattern *is* the bug pattern we've been seeing.

So then I went to remove root's proxy. I expected to find it in /tmp/
x509up_u0, but that file didn't exist. Then Alain suggested running
grid-proxy-info to find out where the proxy file was located. Here's
its output:

ERROR: Couldn't find a valid proxy.

grid_proxy_info.c:
354
:globus_gsi_system_config
.c:globus_gsi_sysconfig_get_proxy_filename_unix:6015:
Could not find a valid proxy certificate file location
globus_gsi_system_config.c:globus_i_gsi_sysconfig_create_key_string:477:
Error with key filename
globus_gsi_system_config.c:globus_i_gsi_sysconfig_check_keyfile_unix:
4668:
File does not exist: /tmp/x509up_u0 is not a valid file

So then I wondered if I could observe the server trying to find the
root proxy. I started an strace on the running server (in its failure
state) -- I used the '-f' option to trace all forked processes and I
started the strace on both of the VOMS processes that I found using
ps. Once the strace was running, I tried running voms-proxy-init from
my user (cat) again.

In a nutshell, I can find no evidence of the server trying to read
something that looks like a proxy certificate. It does read the HTTP
service certificate and key, which is what we configure the VOMS
server to use to identify itself. And it reads a few CA certificates
and related files. And it creates and unlinks a bunch of temporary
files (but not any named /tmp/x509*). But that's about it. So if the
idea is that the server tries to read its own certificate, but Globus
forces it to find a proxy instead, I find no evidence to support that
claim.

Furthermore, I suggest that the pattern of errors and recovery we see
-- i.e., that we must restart the VOMS server to restore functionality
-- is more consistent with an inconsistent state in core, not on
disk. Why would restarting the VOMS server clear out the root proxy
on the machine?

And then there's John's email, which preceded this one, that suggests
that removing an existing root proxy does not cause the running server
to suddenly recover.

In sum, I think we have a real bug here, one that is worth
investigating soon. In the meantime, I suppose, we can send out a
warning to our users to avoid running voms-proxy-init as root. Longer
term, even if the bug itself is fixed, why not add code to voms-proxy-
init that detects when it is being run as root or is using a root-
owned certificate, and simply have it print a clear error message and
NOT contact the server at all? If that is a known unsupported use
case, then I think the client should be more robust about preventing it.

-- Tim

John also noticed that running voms-proxy-init on a separate computer
showed the same problem. This substantiate the theory that the problem
is not a root proxy.

-alain

-----------------------------------------------------------------
Alain Roy vdt-support@opensciencegrid.org
VDT Support http://vdt.cs.wisc.edu/support.html

Commit comment:
Two more file extension renamings.


Changed files:
D vdt/branches/vdt-1.10.1-voms-1.8.8/VOMS/nmi/mysql.in
A vdt/branches/vdt-1.10.1-voms-1.8.8/VOMS/nmi/mysql.nmi
A vdt/branches/vdt-1.10.1-voms-1.8.8/VOMS/nmi/voms-mysql.cvs
D vdt/branches/vdt-1.10.1-voms-1.8.8/VOMS/nmi/voms-mysql.in

To generate a diff:
svn diff -c 8308 file:///p/condor/workspaces/vdt/svn

Back on 21 October 2008, John Weigand wrote:


As you seem to already know (!), this bug has been fixed in our latest build of
VOMS 1.8.8-2 released in VDT 1.10.1n. Thanks again for finding the bug and
helping us figure out the scope of the problem.

In case you're interested, Vincenzo says that the bug is actually a problem with
the MySQL connection. Some MySQL function call hangs or fails or something, and
causes the behavior we were seeing. He updated the VOMS-MySQL connector to
avoid that particular call, and that is the fix.

I am closing this ticket now.

-- Tim