PR#2826: Add kerberos debug message - koji

koji

#2826 Add kerberos debug message

Merged a year ago by tkopecek. Opened a year ago by jcupova.

jcupova/koji issue-2063 into master

doc: extend gssapi debug docs

Tomas Kopecek • a year ago

029f19c

Add kerberos debug message

Jana Cupova • a year ago

a446cdf

docs/source/index.rst

file modified

		`@@ -25,6 +25,7 @@`
		`access_controls`
		`permissions`
		`defining_hub_policies`
		`+ kerberos_gssapi_debug`
		`external_repo_server_bootstrap`
		`image_build`
		`winbuild`

docs/source/kerberos_gssapi_debug.rst

file added

+134

		`@@ -0,0 +1,134 @@`
		`+ ==============================`
		`+ Koji Kerberos/GSSAPI debugging`
		`+ ==============================`
		`+`
		`+ Run basic command Koji with debug option isn't help to debug Kerberos/GSSAPI issue.`
		`+ In successful call you'll see what authentication method was used and was is the`
		`+ koji server connected to:`
		`+`
		`+ ::`
		`+`
		`+ $ kinit my_account@FEDORAPROJECT.ORG`
		`+ Password for my_account@FEDORAPROJECT.ORG:`
		`+`
		`+ $ koji hello`
		`+ successfully connected to hub`
		`+ dobrý den, my_account!`
		`+`
		`+ You are using the hub at https://koji.fedoraproject.org/kojihub`
		`+ Authenticated via GSSAPI`
		`+`
		`+ ...or you can get some error:`
		`+`
		`+ ::`
		`+`
		`+ $ koji hello`
		`+ 2021-04-23 09:45:22,732 [ERROR] koji: (gssapi auth failed: requests.exceptions.HTTPError: 401 Client Error: Unauthorized for url: https://koji.fedoraproject.org/kojihub/ssllogin)`
		`+ Use following documentation to debug kerberos/gssapi auth issues. https://docs.pagure.org/koji/kerberos_gssapi_debug/`
		`+ 2021-04-23 09:45:22,734 [ERROR] koji: GSSAPIAuthError: unable to obtain a session (gssapi auth failed: requests.exceptions.HTTPError: 401 Client Error: Unauthorized for url: https://koji.fedoraproject.org/kojihub/ssllogin)`
		`+ Use following documentation to debug kerberos/gssapi auth issues. https://docs.pagure.org/koji/kerberos_gssapi_debug/`
		`+`
		`+ In this case we see not one but two errors while trying to authenticate. Let's`
		`+ see what more info we can get:`
		`+`
		`+ ::`
		`+`
		`+ $ KRB5_TRACE=/dev/stdout python koji -d hello`
		`+ 2021-04-23 09:47:58,730 [DEBUG] koji: Opening new requests session`
		`+ 2021-04-23 09:47:58,731 [DEBUG] koji: Opening new requests session`
		`+ 2021-04-23 09:47:59,446 [DEBUG] koji: Opening new requests session`
		`+ 2021-04-23 09:47:59,446 [ERROR] koji: (gssapi auth failed: requests.exceptions.HTTPError: 401 Client Error: Unauthorized for url: https://koji.fedoraproject.org/kojihub/ssllogin)`
		`+ Use following documentation to debug kerberos/gssapi auth issues. https://docs.pagure.org/koji/kerberos_gssapi_debug/`
		`+ Traceback (most recent call last):`
		`+ File "/usr/bin/koji", line 335, in <module>`
		`+ rv = locals()[command].__call__(options, session, args)`
		`+ File "/home/tkopecek/cvs/koji/cli/koji_cli/commands.py", line 7496, in handle_moshimoshi`
		`+ activate_session(session, options)`
		`+ File "/home/tkopecek/cvs/koji/cli/koji_cli/lib.py", line 749, in activate_session`
		`+ session.gssapi_login(proxyuser=runas)`
		`+ File "/home/tkopecek/cvs/koji/koji/__init__.py", line 2513, in gssapi_login`
		`+ raise GSSAPIAuthError(err)`
		`+ koji.GSSAPIAuthError: unable to obtain a session (gssapi auth failed: requests.exceptions.HTTPError: 401 Client Error: Unauthorized for url: https://koji.fedoraproject.org/kojihub/ssllogin)`
		`+ Use following documentation to debug kerberos/gssapi auth issues. https://docs.pagure.org/koji/kerberos_gssapi_debug/`
		`+`
		`+ We see no output from krbV library. It indicates that there was no significant`
		+ interaction with the library. Main reason would be missing ``kinit``. Fixing
		`+ this problem is pretty easy. What about other problems?`
		`+`
		`+ You can see wrong URL for the hub. Check if it is coming from system-wide config`
		+ ``/etc/koji.conf`` or anything in ``/etc/koji.conf.d`` or ``~/.koji/config``.
		`+ Maybe URL for your instance has changed or some old config was forgotten in`
		`+ place.`
		`+`
		`+ Compare with successful output when krbV library does its work:`
		`+`
		`+ ::`
		`+`
		`+ $ KRB5_TRACE=/dev/stdout koji -d hello`
		`+ 2021-04-23 09:50:34,442 [DEBUG] koji: Opening new requests session`
		`+ 2021-04-23 09:50:34,442 [DEBUG] koji: Opening new requests session`
		`+ [36315] 1619164236.523876: TXT record _kerberos.koji.fedoraproject.org. not found`
		`+ [36315] 1619164236.523877: TXT record _kerberos.fedoraproject.org. found: FEDORAPROJECT.ORG`
		`+ [36315] 1619164236.523878: ccselect module realm chose cache FILE:/tmp/krb5cc_1000 with client principal my_account@FEDORAPROJECT.ORG for server principal HTTP/koji.fedoraproject.org@FEDORAPROJECT.ORG`
		`+ [36315] 1619164236.523879: Getting credentials my_account@FEDORAPROJECT.ORG -> HTTP/koji.fedoraproject.org@ using ccache FILE:/tmp/krb5cc_1000`
		`+ [36315] 1619164236.523880: Retrieving my_account@FEDORAPROJECT.ORG -> HTTP/koji.fedoraproject.org@ from FILE:/tmp/krb5cc_1000 with result: -1765328243/Matching credential not found (filename: /tmp/krb5cc_1000)`
		`+ [36315] 1619164236.523881: Retrying my_account@FEDORAPROJECT.ORG -> HTTP/koji.fedoraproject.org@FEDORAPROJECT.ORG with result: -1765328243/Matching credential not found (filename: /tmp/krb5cc_1000)`
		`+ [36315] 1619164236.523882: Server has referral realm; starting with HTTP/koji.fedoraproject.org@FEDORAPROJECT.ORG`
		`+ [36315] 1619164236.523883: Retrieving my_account@FEDORAPROJECT.ORG -> krbtgt/FEDORAPROJECT.ORG@FEDORAPROJECT.ORG from FILE:/tmp/krb5cc_1000 with result: 0/Success`
		`+ [36315] 1619164236.523884: Starting with TGT for client realm: my_account@FEDORAPROJECT.ORG -> krbtgt/FEDORAPROJECT.ORG@FEDORAPROJECT.ORG`
		`+ [36315] 1619164236.523885: Requesting tickets for HTTP/koji.fedoraproject.org@FEDORAPROJECT.ORG, referrals on`
		`+ [36315] 1619164236.523886: Generated subkey for TGS request: aes256-cts/A108`
		`+ [36315] 1619164236.523887: etypes requested in TGS request: aes256-cts, aes128-cts, aes256-sha2, aes128-sha2, rc4-hmac, camellia128-cts, camellia256-cts`
		`+ [36315] 1619164236.523889: Encoding request body and padata into FAST request`
		`+ [36315] 1619164236.523890: Sending request (977 bytes) to FEDORAPROJECT.ORG`
		`+ [36315] 1619164236.523891: Sending DNS URI query for _kerberos.FEDORAPROJECT.ORG.`
		`+ [36315] 1619164236.523892: URI answer: 10 1 "krb5srv:m:kkdcp:https://id.fedoraproject.org/KdcProxy/"`
		`+ [36315] 1619164236.523893: Resolving hostname id.fedoraproject.org`
		`+ [36315] 1619164236.523894: TLS certificate name matched "id.fedoraproject.org"`
		`+ [36315] 1619164236.523895: Sending HTTPS request to https 152.19.134.142:443`
		`+ [36315] 1619164237.522076: Received answer (929 bytes) from https 152.19.134.142:443`
		`+ [36315] 1619164237.522077: Terminating TCP connection to https 152.19.134.142:443`
		`+ [36315] 1619164237.522078: Response was from master KDC`
		`+ [36315] 1619164237.522079: Decoding FAST response`
		`+ [36315] 1619164237.522080: FAST reply key: aes256-cts/F6DC`
		`+ [36315] 1619164237.522081: TGS reply is for my_account@FEDORAPROJECT.ORG -> HTTP/koji.fedoraproject.org@FEDORAPROJECT.ORG with session key aes256-cts/A3FF`
		`+ [36315] 1619164237.522082: TGS request result: 0/Success`
		`+ [36315] 1619164237.522083: Received creds for desired service HTTP/koji.fedoraproject.org@FEDORAPROJECT.ORG`
		`+ [36315] 1619164237.522084: Storing my_account@FEDORAPROJECT.ORG -> HTTP/koji.fedoraproject.org@ in FILE:/tmp/krb5cc_1000`
		`+ [36315] 1619164237.522086: Creating authenticator for my_account@FEDORAPROJECT.ORG -> HTTP/koji.fedoraproject.org@, seqnum 742219461, subkey aes256-cts/1CC1, session key aes256-cts/A3FF`
		`+ successfully connected to hub`
		`+ dobrý den, my_account!`
		`+`
		`+ You are using the hub at https://koji.fedoraproject.org/kojihub`
		`+ Authenticated via GSSAPI`
		`+`
		`+`
		`+ Most problems could be tracked down by this command plus kinit/klist tools. for`
		`+ list of these consult next section.`
		`+`
		`+ General problems`
		`+ ================`
		+ * No KRB5_TRACE output - You've not run ``kinit`` in first place, run ``kinit``.
		+ * If yes, maybe ticket is no longer valid - check ``klist`` + run ``kinit``
		`+ * Hub URL is wrong - check configs, find out right URL for your environment,`
		+ update related packages (e.g. ``fedora-packager``)
		`+ * Wrong service ticket E.g because your instance is hidden behing`
		`+ the proxy. In such case you'll see in output wrong principal. Right one would`
		+ look like ``HTTP/koji.fedoraproject.org@FEDORAPROJECT.ORG`` in our example.
		+ (You can also check output of ``klist`` which will list it as "Ticket
		`+ Server"). Wrong one would be e.g.`
		+ ``HTTP/proxy10.fedoraproject.org@FEDORAPROJECT.ORG``. Kerberos authentication
		`+ will fail in such case becase krbV library will not be able to get right`
		+ ticket. It could be caused by wrong ``/etc/krb5.conf`` settings. Typical
		+ error in this case would be that line ``dns_canonicalize_hostname = true`` is
		+ missing. ``krbV`` will try to fetch service ticket for PTR instead of A DNS
		`+ record effectively asking for wrong service.`
		+ * You can't get service ticket at all. You've not set up the ``/etc/krb5.conf``
		+ for relevant KDC/REALM. It shouldn't happen if you were able to ``kinit`` with
		`+ the correct credentials (It means that you've already set up something).`
		`+ Anyway, you'll see following in the debug output`
		`+ * Your user account was disabled This error is not krbV specific. But you can`
		+ hit it. In such case you will see simple message ``koji: AuthError: unable to
		+ obtain a session``. From security reasons we don't display it differently from
		`+ non-existent account. If you've suspicion that it could be the reason you need`
		`+ to check with your koji instance admin.`

koji/__init__.py

file modified

+12 -5

		`@@ -415,6 +415,11 @@`
		`faultCode = 1022`


		`+ class GSSAPIAuthError(AuthError):`
		`+ """Raised when GSSAPI issue in authentication"""`
		`+ faultCode = 1023`
		`+`
		`+`
		`class MultiCallInProgress(object):`
		`"""`
		`Placeholder class to be returned by method calls when in the process of`
		`@@ -2487,9 +2492,11 @@`
		`# will fail with a handshake failure, which is retried by default.`
		`sinfo = self._callMethod('sslLogin', [proxyuser], retry=False)`
		`except Exception as e:`
		`- e_str = ''.join(traceback.format_exception_only(type(e), e))`
		`- e_str = 'gssapi auth failed: %s' % e_str`
		`- self.logger.debug(e_str)`
		`+ e_str = ''.join(traceback.format_exception_only(type(e), e)).strip('\n')`
		`+ e_str = '(gssapi auth failed: %s)\n' % e_str`
		`+ e_str += 'Use following documentation to debug kerberos/gssapi auth issues. ' \`
		`+ 'https://docs.pagure.org/koji/kerberos_gssapi_debug/'`
		`+ self.logger.error(e_str)`
		`# Auth with https didn't work. Restore for the next attempt.`
		`self.baseurl = old_baseurl`
		`finally:`
		`@@ -2502,8 +2509,8 @@`
		`if not sinfo:`
		`err = 'unable to obtain a session'`
		`if e_str:`
		`- err += ' (%s)' % e_str`
		`- raise AuthError(err)`
		`+ err += ' %s' % e_str`
		`+ raise GSSAPIAuthError(err)`

		`self.setSession(sinfo)`

tests/test_lib/test_gssapi.py

file modified

+2 -2

		`@@ -82,7 +82,7 @@`
		`def test_gssapi_login_error(self):`
		`old_environ = dict(**os.environ)`
		`self.session._callMethod.side_effect = Exception('login failed')`
		`- with self.assertRaises(koji.AuthError):`
		`+ with self.assertRaises(koji.GSSAPIAuthError):`
		`self.session.gssapi_login()`
		`self.session._callMethod.assert_called_once_with('sslLogin', [None],`
		`retry=False)`
		`@@ -101,7 +101,7 @@`
		`# failed gssapi auth should leave the url alone`
		`self.session.baseurl = url1`
		`self.session._callMethod.side_effect = Exception('login failed')`
		`- with self.assertRaises(koji.AuthError):`
		`+ with self.assertRaises(koji.GSSAPIAuthError):`
		`self.session.gssapi_login()`
		`self.assertEqual(self.session.baseurl, url1)`
		`self.assertEqual(old_environ, dict(**os.environ))`

jcupova commented a year ago

Fixes: https://pagure.io/koji/issue/2063

tkopecek commented a year ago

:thumbsup:

Metadata Update from @tkopecek:
- Pull-request tagged with: testing-ready

a year ago

julian8628 commented on line 10 of koji/__init__.py a year ago

python seems redundant here

ktdreyer commented on line 10 of koji/__init__.py a year ago

I don't know if this really helps. It directs users to run "koji", which is not really applicable for commands where that's symlinked or aliased to something else.

I think we should update this PR to stop logging this at "debug" level and make it "error" level.

ktdreyer commented a year ago

I think the biggest change we should make here would be to update AuthError to mention the authentication type, and then add a document that describes "how to troubleshoot Kerberos authentication" with a walkthrough.

ktdreyer commented a year ago

One problem is that Koji catches a base Exception class here, and then we hide that information behind the "-d" flag. It's more work for the user to re-run with "-d".

Catching the base Exception and then raising a single AuthError is not great. If this were entirely new code it would be great to simply raise the original exception here, but I understand there are some API considerations here (because clients might expect to catch AuthError).

What if we we sub-class AuthError to something like GSSAPIAuthError and include the error message from requests-gssapi in that?

Metadata Update from @tkopecek:
- Pull-request untagged with: testing-ready

a year ago

rebased onto f75fed4bad85df5fc44e226fb46046b05b1c98d6

a year ago

rebased onto 5509c7b06177e1df15ce05c050d5cd3e4cff3a84

a year ago

rebased onto 54fcb941cbb458a92467dda6d94a38c6eb815c8c

a year ago

rebased onto 0a9fe6cbe3afc3819745640378b38ee9b4bc63c0

a year ago

rebased onto a446cdf