Description of problem:
Upon writing a QE test for cli sessions, I have a problem that pops up in one particullar test where a keyring is populated with a valid session, but authorization will fail for a unknown reason.
I run the same cli test 5 times, an on the fifth try, it works. I'll be attaching the output of my test to this ticket.
After review, Rob even determined:
"There is definitely something strange going on here just from reviewing
1. I'm not sure I completely follow it, but it appears it starts with a
session, makes a request, the request fails as unauthenticated, so it
makes another request using full negotiation and presumably writes an
updated session cookie."
Version-Release number of selected component (if applicable):
I've only been able to reproduce this in the test.
Steps to Reproduce:
1. run the "ipa-cert-cli" test. See me if you would like help doing this.
session support fails
Test code relevant to this bug:
rlPhaseStartTest "Create a valid keyring, then try issuing a command that will fallback to kerberos auth. Verify that the fallback happens"
keyctl purge user # Purging keys to be certain that the user-find populates the keyring properly.
rlRun "keyctl clear @s" 0 "Clear local session keyring"
rlRun "keyctl clear @u" 0 "Clear local user keyring"
KinitAsUser $u1 $u1pass
ipa -vv user-find $u1 &> $outf # running ipa user-find to populate the keyring.
ipa user-find admin &> /dev/null
rlRun "keyctl list @s | grep ipa_session_cookie | grep $u1" 0 "verify u1's ipa session cookie was created"
rlRun "grep Authorization:\ negotiate $outf" 0 "This first user-find should complete a full kerberos auth."
ipa -vv user-find $u1 &>/dev/shm/1
ipa -vv user-find $u1 &>/dev/shm/2
ipa -vv user-find $u1 &>/dev/shm/3
ipa -vv user-find $u1 &>/dev/shm/4
ipa -vv user-find $u1 &>/dev/shm/5
ipa -vv user-find $u1 &> $outf # This command should work off of the current session.
rlRun "grep Authorization:\ negotiate $outf" 1 "Re-verify that a normal user-find does not do a full kerberos auth"
ipa -vv --delegate user-find &> $outf # this command should force a full kerberos auth
rlRun "grep Authorization:\ negotiate $outf" 0 "ipa delegate should force a full kerberos auth. Verify that it happened."
result of first pass at cli command
result of second pass at cli command
result of fifth pass at cli command. This one succeeds.
The test code itself. Wiki formatting made it mostly unreadable.
I'll take a look at this, just getting back from a few days of PTO, assigned to myself.
I looked at Michael's test, his output and our implementation, here's some comments:
1) I cannot not reproduce the problem using master
2) The test has some funky elements, see below
3) We are not sending a valid cookie to the server. The set-cookie header has values intended only for the client (e.g. httponly, secure, etc.) But we're sending back exactly what we received, instead we should parse the cookie, extract the cookie data, and only send the cookie data in the cookie. I did a test and the server seems to handle the extraneous fields OK, but we should obey the protocol.
4) There is not enough information in Michaels' debug output to fully diagnose what was going wrong, but from looking at the code it appears as if it's catching a ProtocolError exception because you can see the key being deleted, that only happens inside the ProtocolError exception block as far as I can tell, or if you get a 403 status, but I'm not seeing a 403. Unfortunately the is no logging of the ProtocolError so I can't be sure that is what is happening or if it is what the nature of the error is. FWIW I'm not sure we should be purging the key on a ProtocolError, I think a 403 status is the only time we should purge.
5) I wonder if the ProtocolError could be due to the improperly formatted cookie header. That does not seem likely however because it seems to work otherwise.
There is something funky in Michaels debug logs for sure but I can't reproduce it and the logging information in our code is not sufficient for full diagnosis. If Michael is still seeing this I suggest we hop onto his system, edit our code to add some more diagnostic logging, and run the tests again. Other than that I'm at a loss.
1) The first user-find is sufficient to populate the keyring, what is the purpose is the 2nd user-find?
2) Why are the validation checks interspersed with the extra user-find (above) and delayed by 5 seconds?
3) You have a number of sleeps scattered through the test, some as long as 30 seconds. Why? What purpose do they serve?
4) You run 5 user-find commands without checking anything. Finally on the 6th you verify there is no krb auth. Some of the user-find's have sleeps interspersed. Are you trying to verify after a number of commands things still work? I think 2 checks are sufficient, 1st to verify you're using a session, and the next to verify that wasn't a one-time deal, sleeps should not be necessary.
Marked ticket #3076 as a duplicate of this.
Linked to Bugzilla bug: https://bugzilla.redhat.com/show_bug.cgi?id=786199 (Red Hat Enterprise Linux 6)
I have tested this again. Again everything seems to work fine. Resolution is "works for me".
However, as noted above in issue 3 we are not sending a correct cookie back to the server, we're including extraneous cookie information from the browser only Set-Cookie header, we should only be sending the cookie value (e.g. ipa_session=xxxxxxxxxxxxxxxx). The server seems to gracefully ignore the extra junk we're sending in the Cookie header (note Set-Cookie and Cookie do not share the same values). We should parse the Set-Cookie and extract just the session_id from it and store that in the keyring. I have a patch that does that and should be applied, but this is just a technical correctness issue, it is in no way causing a problem at the moment.
If this a cosmetic change I would prefer to hold it off till next release.
Putting back to NEEDS triage.
This is not a cosmetic fix. We should treat the cookie on the client side the same way a browser does, including proper enforcement of whom we will send the cookie to. This should remain in 3.0.1.
Metadata Update from @mgregg:
- Issue assigned to jdennis
- Issue set to the milestone: FreeIPA 3.0.2
to comment on this ticket.