#4100 'Ticket expired' message lost by the FreeIPA RPC client fallback code
Closed: Invalid None Opened 10 years ago by mkosek.

Ticket was cloned from Red Hat Bugzilla (product Red Hat Enterprise Linux 6): Bug 1043488

Description of problem:
ipa cert-show $id shows only the ERROR field of the output and at some cases,
this info is not clear enough.

Version-Release number of selected component (if applicable):
ipa-admintools-3.0.0-26.el6_4.2.x86_64

How reproducible:
always

Steps to Reproduce:
1. ipa environment with some cert issue (expireds)
2. ipa cert-show 1
3.

Actual results:
ipa: ERROR: cannot connect to Gettext('any of the configured servers',
domain='ipa', localedir=None): https://hostname/ipa/xml,
https://hostname/ipa/xml

Expected results:

ipa: INFO: Connection to https://hostname/ipa/xml failed with Insufficient
access: SASL(-1): generic failure: GSSAPI Error: Unspecified GSS failure.
Minor code may provide more information (Ticket not yet valid)
ipa: INFO: trying https://hostname/ipa/xml
ipa: INFO: Connection to https://hostname2/ipa/xml failed with [Errno -5985]
Could not connect to hostname2 using any address
ipa: ERROR: cannot connect to Gettext('any of the configured servers',
domain='ipa', localedir=None): https://hostname1/ipa/xml,
https://hostname2/ipa/xml

Additional info:
In this particular case the problem was a bad kerberos ticket at /tmp/krb5cc_xx
and the helpful info was the "Ticket not yet valid" message from the verbose
output.

Rob's analysis:

During the CA renewal the trust on the audit certificate wasn't set properly resulting in the CA shutting down right after starting. This caused the LDAP and Apache server certs to not renew and expire.

To reproduce this bug, have at least 2 masters. Expired certificates should not be necessary:

- kinit admin
- ipa cert-show 1
- set date back to when SSL certs still valid
- ipa cert-show 1 (or any IPA command, really)
- fail

There are two problems:

1) The 'Ticket expired' message got lost by the XML-RPC client fallback code.

2) The mod_auth_kerb code to manage the Apache cert for S4U2proxy apparently doesn't consider not-valid-yet to be a reason to get a new ticket.

Hopefully, this is easy to reproduce and would make better troubleshooting.

I have spend a couple of days trying to reproduce the bug with both the original reported IPA version (3.0.0-26.el6_4.2.x86_64) and FreeIPA built master branch.

My setup was 1 master, 1 replica, and 1 client.

I request a Kerberos ticket for the client. Then I set the time on both the master and the replica backwards so that the ticket is not yet valid but SSL certs still are.

Most of the time I get the following error message, which is close to desired behavior:

ipa: ERROR: Kerberos error: Kerberos error: ('Unspecified GSS failure.  Minor code may provide more information', 851968)/('Ticket not yet valid', -1765328351)/

{{{/var/log/httpd/error_log}}} contains the following (in debug mode):

Mon Mar 02 11:18:55.043065 2015] [wsgi:error] [pid 27771] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Mon Mar 02 11:18:55.043223 2015] [wsgi:error] [pid 27771] ipa: DEBUG: WSGI jsonserver_session.__call__:
[Mon Mar 02 11:18:55.043485 2015] [wsgi:error] [pid 27771] ipa: DEBUG: found session cookie_id = 9e573ec7b11c3ec52966b0f83d0cded0
[Mon Mar 02 11:18:55.043958 2015] [wsgi:error] [pid 27771] ipa: DEBUG: found session data in cache with id=9e573ec7b11c3ec52966b0f83d0cded0
[Mon Mar 02 11:18:55.044154 2015] [wsgi:error] [pid 27771] ipa: DEBUG: jsonserver_session.__call__: session_id=9e573ec7b11c3ec52966b0f83d0cded0 start_timestamp=2015-03-03T11:19:03 access_timestamp=2015-03-02T11:18:55 expiration_timestamp=2015-03-03T11:39:03
[Mon Mar 02 11:18:55.044264 2015] [wsgi:error] [pid 27771] ipa: DEBUG: storing ccache data into file "/var/run/ipa_memcached/krbcc_27771"
[Mon Mar 02 11:18:55.045008 2015] [wsgi:error] [pid 27771] ipa: DEBUG: get_credential_times: principal=HTTP/vm-107.idm.lab.bos.redhat.com@IDM.LAB.BOS.REDHAT.COM, authtime=03/03/15 11:18:54, starttime=03/03/15 11:19:01, endtime=03/04/15 11:18:52, renew_till=12/31/69 19:00:00
[Mon Mar 02 11:18:55.045191 2015] [wsgi:error] [pid 27771] ipa: DEBUG: ccache expired, deleting session, need login
[Mon Mar 02 11:18:55.045335 2015] [wsgi:error] [pid 27771] ipa: DEBUG: jsonserver_session: 401 Unauthorized need login

In about 1 in 10 cases I get the actual error message reported in the bug (this is for FreeIPA 4.1.3)

ipa: ERROR: cannot connect to 'any of the configured servers': https://vm-042.idm.lab.bos.redhat.com/ipa/xml, https://vm-109.idm.lab.bos.redhat.com/ipa/xml

with this output in {{{httpd/error_log}}}:

[Mon Mar 02 09:11:43.037600 2015] [wsgi:error] [pid 4492] ipa: INFO: *** PROCESS START ***
[Mon Mar 02 09:11:43.039986 2015] [wsgi:error] [pid 4493] ipa: INFO: *** PROCESS START ***
[Mon Mar 02 09:12:07.537342 2015] [auth_kerb:error] [pid 4494] [client 10.16.78.53:39858] gss_accept_sec_context() failed: Unspecified GSS failure.  Minor code may provide more information (, Ticket not yet valid), referer: https://vm-081.idm.lab.bos.redhat.com/ipa/xml

It seems like sometimes the error message spewed by {{{mod_auth_kerb}}} reaches the client and sometimes it remains stuck on the server with client emitting only the generic {{{ipa: ERROR: cannot connect to...}}} error.

I am currently not able to determine the exact conditions that lead to one case or the other, any thoughts on this?

Given that FreeIPA moved to mod_auth_gssapi in #3972 and this seems to be emitted by mod_auth_kerb, I will close this.

Let us reopen it if it is reproducible in FreeIPA 4.2.0+

Metadata Update from @mkosek:
- Issue assigned to mbabinsk
- Issue set to the milestone: FreeIPA 4.2

7 years ago

Login to comment on this ticket.

Metadata