Issue #7458: Bodhi: Frequent koji.AuthError since switching to Python 3 - fedora-infrastructure

fedora-infrastructure

#7458 Bodhi: Frequent koji.AuthError since switching to Python 3

Closed: Fixed 5 years ago by codeblock. Opened 5 years ago by bowlofeggs.

Describe what you need us to do:
Bodhi has not run a compose in two days and it turns out that nobody was on pushduty this week, so I took a look and saw that an EPEL 6 compose had failed a couple days ago. I resumed it, and it failed again with the same error:

koji.AuthError: unable to obtain a session

I've noticed that this error started happening when I switched Bodhi to use Python 3, and I've filed this issue about it:

https://github.com/fedora-infra/bodhi/issues/2870

However, to date it's always seemed possible to resume the compose to get it to succeed, so today I resumed the compose and got the same error. I've now resumed it three times and it failed with that error every time.

I'm now wondering if there is a problem with Bodhi's keytab (it uses Kerberos to authenticate to Koji), or something else.

Possibly related but maybe not: I did have some trouble getting Koji to accept my personal Kerberos token this week that went away on its own: https://pagure.io/fedora-infrastructure/issue/7448

I am not sure what else to try or how to debug this further. Koji does not give any other information that I can find to help debug this.

When do you need this? (YYYY/MM/DD)
ASAP
When is this no longer needed or useful? (YYYY/MM/DD)
If we stop doing updates in Fedora. QA said that Fedora 29 was gold, so what do we need updates for?
If we cannot complete your request, what is the impact?
We cannot release updates to stable Fedora releases or EPEL.

bowlofeggs commented 5 years ago

I observed this in the logs:

Dec 20 16:30:44 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[16441]: [2018-12-20 16:30:44][      koji   ERROR]dist-6E-epel gssapi auth failed: requests.exceptions.ConnectionError: ('Connection aborted.',
RemoteDisconnected('Remote end closed connection without response'))

That's the same error message from https://bugzilla.redhat.com/show_bug.cgi?id=1609298

bowlofeggs commented 5 years ago

Patrick noticed that our proxy servers were under heavy load. There was an httpd update available and after applying that update, the server load decreased and we were able to run the compose.

Metadata Update from @bowlofeggs:
- Issue close_status updated to: Fixed
- Issue status updated to: Closed (was: Open)

5 years ago

bowlofeggs commented 5 years ago

This issue has returned - last night's compose failed with this same error. Also I have still been observing this error when I use the Koji CLI, and two users reported it yesterday on IRC as well.

I think what we did before probably lessened the frequency of the problem, but did not completely stop it.

Metadata Update from @bowlofeggs:
- Issue status updated to: Open (was: Closed)

5 years ago

adamwill commented 5 years ago

I think it's plausible that this may be the same as https://pagure.io/koji/issue/1192 , and thus https://pagure.io/koji/pull-request/1203 may fix it.

kevin commented 5 years ago

I have applied the fixed koji package updates to bodhi-backend01.

kevin commented 5 years ago

We got another one of these after that...

Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]: Traceback (most recent call last):
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/consumers/masher.py", line 344, in run
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     self.work()
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/consumers/masher.py", line 415, in work
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     self._compose_updates()
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/consumers/masher.py", line 949, in _compose_updates
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     uinfo = self._generate_updateinfo()
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/consumers/masher.py", line 1018, in _generate_updateinfo
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     self.db, self.mash_dir)
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/metadata.py", line 149, in __init__
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     self.add_update(update)
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/metadata.py", line 235, in add_update
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     koji = get_session()
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/buildsys.py", line 639, in get_session
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     return _buildsystem()
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/buildsys.py", line 672, in get_koji_login
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     return koji_login(config=settings, authenticate=authenticate)
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/bodhi/server/buildsys.py", line 596, in koji_login
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     if authenticate and not koji_client.krb_login(**get_krb_conf(config)):
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/koji/__init__.py", line 2122, in krb_login
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     except Exception as e:
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:   File "/usr/lib/python3.7/site-packages/koji/__init__.py", line 2274, in gssapi_login
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]:     self.setSession(sinfo)
Jan 10 21:13:17 bodhi-backend01.phx2.fedoraproject.org fedmsg-hub-3[99434]: koji.AuthError: unable to obtain a session

adamwill commented 5 years ago

Guess it's something else, then :/ looking at the traceback, this does seem to happen during login, so it is unlikely that it's the same bug. Not sure why I thought it looked similar initially, I may have confused two tabs, it's happened before :)

adamwill commented 5 years ago

@kevin do you have debug logs from this? there's a debug line that logs the error when gssapi auth fails, in this block:

        try:
            # Depending on the server configuration, we might not be able to
            # connect without client certificate, which means that the conn
            # 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))
            self.logger.debug('gssapi auth failed: %s', e_str)

it'd probably be useful to have that log message...