PulpRpmClient::ApiError HTTP 500 during sync repository

Good morning,

in may case I have problems with Red Hat repositories,
weirdly enough only with the RHEL 7 repositories, as far as I can see it.

The second repository is not public.
I store Centos 6 repositories for backward compatibility. For example, to restore an old system from a backup and have repositories working right away.

The only two using that particular client cert?

No, other repositories with this client certs sync succesfully.

What happens if you remove them?

The same error in /var/log/messages.

After upgrading from 4.2 to 4.3 I see the same error for the following repositories:

https://download.postgresql.org/pub/repos/yum/common/redhat/rhel-7-x86_64/
https://cdn.redhat.com/content/dist/rhel/server/7/7Server/x86_64/os
http://mirror.centos.org/centos/7/storage/x86_64/samba-411/
http://mirror.centos.org/centos/7/cloud/x86_64/openstack-queens/
http://mirror.centos.org/centos/7/cloud/x86_64/openstack-rocky/
http://mirror.centos.org/centos/7/cloud/x86_64/openstack-stein/
https://download.fedoraproject.org/pub/epel/8/Everything/x86_64/

All except the redhat repo are simple, public repositories.

O.K. Did some more testing, e.g. the postgresql repository https://download.postgresql.org/pub/repos/yum/common/redhat/rhel-7-x86_64/:

Sync always fails with traceback:

Mar 11 07:52:19 foreman pulpcore-api: pulp [1ad0f0ec-2c4b-49eb-9c5e-53c82afa8763]: django.request:ERROR: Internal Server Error: /pulp/api/v3/remotes/rpm/rpm/e49f9e02-43c5-41ac-8ed3-9a491e31c609/
Mar 11 07:52:19 foreman pulpcore-api: Traceback (most recent call last):
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/core/handlers/exception.py", line 47, in inner
Mar 11 07:52:19 foreman pulpcore-api: response = get_response(request)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/core/handlers/base.py", line 181, in _get_response
Mar 11 07:52:19 foreman pulpcore-api: response = wrapped_callback(request, *callback_args, **callback_kwargs)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
Mar 11 07:52:19 foreman pulpcore-api: return view_func(*args, **kwargs)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/viewsets.py", line 125, in view
Mar 11 07:52:19 foreman pulpcore-api: return self.dispatch(request, *args, **kwargs)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/views.py", line 509, in dispatch
Mar 11 07:52:19 foreman pulpcore-api: response = self.handle_exception(exc)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/views.py", line 469, in handle_exception
Mar 11 07:52:19 foreman pulpcore-api: self.raise_uncaught_exception(exc)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/views.py", line 480, in raise_uncaught_exception
Mar 11 07:52:19 foreman pulpcore-api: raise exc
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/views.py", line 506, in dispatch
Mar 11 07:52:19 foreman pulpcore-api: response = handler(request, *args, **kwargs)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/app/viewsets/base.py", line 470, in partial_update
Mar 11 07:52:19 foreman pulpcore-api: return self.update(request, *args, **kwargs)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/app/viewsets/base.py", line 452, in update
Mar 11 07:52:19 foreman pulpcore-api: instance = self.get_object()
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/generics.py", line 96, in get_object
Mar 11 07:52:19 foreman pulpcore-api: obj = get_object_or_404(queryset, **filter_kwargs)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/generics.py", line 19, in get_object_or_404
Mar 11 07:52:19 foreman pulpcore-api: return _get_object_or_404(queryset, *filter_args, **filter_kwargs)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/shortcuts.py", line 76, in get_object_or_404
Mar 11 07:52:19 foreman pulpcore-api: return queryset.get(*args, **kwargs)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/query.py", line 431, in get
Mar 11 07:52:19 foreman pulpcore-api: num = len(clone)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/query.py", line 262, in __len__
Mar 11 07:52:19 foreman pulpcore-api: self._fetch_all()
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/query.py", line 1324, in _fetch_all
Mar 11 07:52:19 foreman pulpcore-api: self._result_cache = list(self._iterable_class(self))
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/query.py", line 68, in __iter__
Mar 11 07:52:19 foreman pulpcore-api: for row in compiler.results_iter(results):
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1122, in apply_converters
Mar 11 07:52:19 foreman pulpcore-api: value = converter(value, expression, connection)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/app/models/fields.py", line 104, in from_db_value
Mar 11 07:52:19 foreman pulpcore-api: return force_str(self._fernet.decrypt(force_bytes(value)))
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib64/python3.8/site-packages/cryptography/fernet.py", line 75, in decrypt
Mar 11 07:52:19 foreman pulpcore-api: timestamp, data = Fernet._get_unverified_token_data(token)
Mar 11 07:52:19 foreman pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib64/python3.8/site-packages/cryptography/fernet.py", line 101, in _get_unverified_token_data
Mar 11 07:52:19 foreman pulpcore-api: raise InvalidToken
Mar 11 07:52:19 foreman pulpcore-api: cryptography.fernet.InvalidToken

I cannot even do a simple GET on the remote:

# curl --cert /etc/pki/katello/certs/pulp-client.crt --key /etc/pki/katello/private/pulp-client.key https://foreman.example.com/pulp/api/v3/remotes/rpm/rpm/e49f9e02-43c5-41ac-8ed3-9a491e31c609/

<!doctype html>
<html lang="en">
<head>
  <title>Server Error (500)</title>
</head>
<body>
  <h1>Server Error (500)</h1><p></p>
</body>
</html>

It’s always throwing the same exception.

The exact same curl call works fine on my 4.2 installation before the upgrade and returns a nice json:

katello-4.2:# curl --cert /etc/pki/katello/certs/pulp-client.crt --key /etc/pki/katello/private/pulp-client.key https://foreman.example.com/pulp/api/v3/remotes/rpm/rpm/e49f9e02-43c5-41ac-8ed3-9a491e31c609/  | python -m json.tool
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   602  100   602    0     0   3205      0 --:--:-- --:--:-- --:--:--  3236
{
    "ca_cert": null,
    "client_cert": null,
    "connect_timeout": null,
    "download_concurrency": 20,
    "headers": null,
    "max_retries": null,
    "name": "pgdg-common-el7-779671",
    "policy": "immediate",
    "proxy_url": null,
    "pulp_created": "2021-07-07T05:10:41.647207Z",
    "pulp_href": "/pulp/api/v3/remotes/rpm/rpm/e49f9e02-43c5-41ac-8ed3-9a491e31c609/",
    "pulp_labels": {},
    "pulp_last_updated": "2022-03-11T00:33:23.360558Z",
    "rate_limit": null,
    "sles_auth_token": null,
    "sock_connect_timeout": null,
    "sock_read_timeout": null,
    "tls_validation": true,
    "total_timeout": 300.0,
    "url": "https://download.postgresql.org/pub/repos/yum/common/redhat/rhel-7-x86_64/"
}
1 Like

I think I have found something in the database which may be the cause for this issue. From pulpcore 3.14 to 3.16 it seems some fields in the database are encrypted with a symmetric key in the file /etc/pulp/certs/database_fields.symmetric.key. The migration seems to be broken for some remotes:

pulpcore=# select pulp_id, name, url, username, length(username) from core_remote where username is not null and length(username) = 0;
               pulp_id                |           name            |                                    url                                     | username | length 
--------------------------------------+---------------------------+----------------------------------------------------------------------------+----------+--------
 e49f9e02-43c5-41ac-8ed3-9a491e31c609 | pgdg-common-el7-775402    | https://download.postgresql.org/pub/repos/yum/common/redhat/rhel-7-x86_64/ |          |      0
 1597297f-6333-4585-bb4e-7eeccf22be28 | samba-411-76723158        | http://mirror.centos.org/centos/7/storage/x86_64/samba-411/                |          |      0
 89758522-8af3-44fc-8ec0-26615664494c | openstack-rocky-7674227   | http://mirror.centos.org/centos/7/cloud/x86_64/openstack-rocky/            |          |      0
 27a18f61-21da-449a-965b-c68938e7ba34 | openstack-stein-76759204  | http://mirror.centos.org/centos/7/cloud/x86_64/openstack-stein/            |          |      0
 84e1651a-7fb0-4618-ae60-5bd7adb6b93f | openstack-queens-76733362 | http://mirror.centos.org/centos/7/cloud/x86_64/openstack-queens/           |          |      0
 57e722fc-ecf9-4daa-babb-249ca8d87668 | AppStream_x86_64-1715630  | http://mirror.centos.org/centos/8/AppStream/x86_64/os/                     |          |      0
 6f1837c9-d88f-42c2-861d-ff7e931885b9 | epel-1779394              | https://download.fedoraproject.org/pub/epel/8/Everything/x86_64/           |          |      0
(7 rows)

I haven’t checked all fields in the database which seem to be encrypted now.

What did notice, though, is that on the old 4.2 server with pulpcore 3.14 all those remotes have an empty username and password set, i.e. an empty string “” and not NULL like many others. However, the list of remotes on the old server with empty string username is longer than the affected ones on my 4.3 server.

So it seems to be an issue with the database migration from 3.14 to 3.16 and encryption of some fields in the database. The migration/encryption seems to fail is some cases and the original content remains in the database which makes decryption failed. This is also true for my affected rhel repository: I can see in the database that the remote contains the RSA private key in client_key, unlike the other rhel repos which contain some base64 encoded string in the client_key fields.

Thus the problem is that for some rows in the database (at least the core_remote table) encryption of the fields client_key, username, password, (proxy_username, proxy_password, too, I guess) fails during migration from 3.14 to 3.16 leaving the original content in the database. This leads to decryption failure in 3.16.

For whatever reason only a few repos are affected, mostly those which have empty strings for username, password instead of NULL like many others. However, even with empty strings for some remotes the encryption works while it doesn’t for others.

I hope it’s clear what I wrote and at least @dralley understands me…

1 Like

I think that makes some sense - I’ve filed Migration of encrypted fields between 3.14 and 3.16 is broken for some remotes · Issue #2327 · pulp/pulpcore · GitHub to track this upstream.

Thanks.

I was looking through the foreman-installer log from the upgrade but didn’t really find anything showing any problem. It’s not fully clear to me which step during foreman-install does the migration on the database and more important: it’s unclear to me if there is any low-level log of the migration process which may indicate some errors.

On a sidenote: I think pulpcore should consolidate the representation of “no username”, “no password”, etc. in the database. It’s pretty weird that some remotes in 3.14 use an empty string “” while others use NULL. In 3.16 the empty string gets encrypted which also doesn’t seem very useful…

I guess, in the future some database migration should consolidate this, probably setting NULL on the columns with the empty string…

@Justin_Sherrill

I guess this should also be filed as katello bug because anyone with more than 100 repositories/remotes in the database should probably defer upgrading from 4.2 to 4.3 until this has been fixed…

anyone with more than 100 repositories/remotes in the database should probably defer upgrading from 4.2 to 4.3 until this has been fixed…

I’m in general agreement with this

I don’t know if 100 was actually hit in my environment, but I am getting the same issue, 1 foreman server + 1 smart proxy, maybe 60 hosts. Repos are less than 30.

If it’s less then 100 remote repositories I can’t be really the exact same issue. You can easily check the total number in the database as root on your foreman server:

[root@foreman ~]# sudo -u postgres psql pulpcore -c 'select count(*) from core_remote;'
could not change directory to "/root": Permission denied
 count 
-------
   117
(1 row)

If that’s less than 100 (and you didn’t remove lots of repositories since the upgrade to 4.3 of course) I’d say it’s something else. If you have the same cryptography.fernet.InvalidToken although you had less than 100 rows in the table during migration from 4.2 to 4.3 it would require a closer look.

@gvde My count is 35. Indeed, I have removed a few repositories (got rid of CentOS 8) but I would reckon about 15 or so.

Here is what I see when syncing the smart proxy:

Mar  9 20:16:38 proxy pulpcore-api: pulp [fd038a28-78a8-4d5e-8ced-f5acfb108681]:  - - [09/Mar/2022:18:16:38 +0000] "GET /pulp/api/v3/remotes/rpm/rpm/?name=1-_CV_Subversion_CentOS_7-Production-1236c46e-6338-4e72-b7fa-598b57a91631 HTTP/1.1" 500 145 "-" "OpenAPI-Generator/3.16.1/ruby"
Mar  9 20:16:38 proxy pulpcore-api: pulp [fd038a28-78a8-4d5e-8ced-f5acfb108681]: django.request:ERROR: Internal Server Error: /pulp/api/v3/remotes/rpm/rpm/
Mar  9 20:16:38 proxy pulpcore-api: Traceback (most recent call last):
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/core/handlers/exception.py", line 47, in inner
Mar  9 20:16:38 proxy pulpcore-api: response = get_response(request)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/core/handlers/base.py", line 181, in _get_response
Mar  9 20:16:38 proxy pulpcore-api: response = wrapped_callback(request, *callback_args, **callback_kwargs)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
Mar  9 20:16:38 proxy pulpcore-api: return view_func(*args, **kwargs)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/viewsets.py", line 125, in view
Mar  9 20:16:38 proxy pulpcore-api: return self.dispatch(request, *args, **kwargs)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/views.py", line 509, in dispatch
Mar  9 20:16:38 proxy pulpcore-api: response = self.handle_exception(exc)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/proxy/views.py", line 469, in handle_exception
Mar  9 20:16:38 proxy pulpcore-api: self.raise_uncaught_exception(exc)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/views.py", line 480, in raise_uncaught_exception
Mar  9 20:16:38 proxy pulpcore-api: raise exc
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/views.py", line 506, in dispatch
Mar  9 20:16:38 proxy pulpcore-api: response = handler(request, *args, **kwargs)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/mixins.py", line 40, in list
Mar  9 20:16:38 proxy pulpcore-api: page = self.paginate_queryset(queryset)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/generics.py", line 171, in paginate_queryset
Mar  9 20:16:38 proxy pulpcore-api: return self.paginator.paginate_queryset(queryset, self.request, view=self)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/rest_framework/pagination.py", line 395, in paginate_queryset
Mar  9 20:16:38 proxy pulpcore-api: return list(queryset[self.offset:self.offset + self.limit])
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/query.py", line 262, in __len__
Mar  9 20:16:38 proxy pulpcore-api: self._fetch_all()
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/query.py", line 1324, in _fetch_all
Mar  9 20:16:38 proxy pulpcore-api: self._result_cache = list(self._iterable_class(self))
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/query.py", line 68, in __iter__
Mar  9 20:16:38 proxy pulpcore-api: for row in compiler.results_iter(results):
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/django/db/models/sql/compiler.py", line 1122, in apply_converters
Mar  9 20:16:38 proxy pulpcore-api: value = converter(value, expression, connection)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/app/models/fields.py", line 104, in from_db_value
Mar  9 20:16:38 proxy pulpcore-api: return force_str(self._fernet.decrypt(force_bytes(value)))
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib64/python3.8/site-packages/cryptography/fernet.py", line 75, in decrypt
Mar  9 20:16:38 proxy pulpcore-api: timestamp, data = Fernet._get_unverified_token_data(token)
Mar  9 20:16:38 proxy pulpcore-api: File "/opt/theforeman/tfm-pulpcore/root/usr/lib64/python3.8/site-packages/cryptography/fernet.py", line 101, in _get_unverified_token_data
Mar  9 20:16:38 proxy pulpcore-api: raise InvalidToken
Mar  9 20:16:38 proxy pulpcore-api: cryptography.fernet.InvalidToken
Mar  9 20:16:38 proxy pulpcore-api: pulp [fd038a28-78a8-4d5e-8ced-f5acfb108681]:  - - [09/Mar/2022:18:16:38 +0000] "GET /pulp/api/v3/remotes/rpm/rpm/?name=1-CentOS_7-Production-1236c46e-6338-4e72-b7fa-598b57a91631 HTTP/1.1" 500 145 "-" "OpenAPI-Generator/3.16.1/ruby"

O.K. That’s on the proxy. Run the psql command on the proxy and it’ll show a much larger number. It’s the same problem. The proxy loads each publication from the main server, i.e. it has remotes for each content view in each lifecycle environment.

That means for the content proxy, the whole problem is much bigger…

236 … doh … :frowning:

Katello updates a remote with the latest remote configuration options during every sync. That’s done in the RefreshRemote action. Are these bad remote options not being updated when Katello runs RefreshRemote? If not then that may be part of the issue as well.

What we’re looking for is the first step on a repo sync dynflow task:

Clicking on it, you should see a pulp task:

I don‘t quite understand: should Katello update the username, password, client key during each sync? I don’t think it does. If it would, the sync should work just fine and double encryption or missing encryption in the pulp database shouldn’t matter, because it would be overwritten immediately… Instead, each sync fails.

We call the Pulp remote update API through the RefreshRemote task that @Justin_Sherrill pointed out above. It should be updating all of those fields every time. We don’t update the fields for remotes immediately when remote configuration is changed in Katello, rather we defer it until sync time.

So, if these fields are still bad, then either the update isn’t working in Pulp, or there’s a Katello bug that’s skipping the update.

Ah okay, the username and password aren’t updated if there aren’t any set for a repository. That is likely related. katello/repository.rb at master · Katello/katello · GitHub

The keys should be updated, however: katello/repository.rb at master · Katello/katello · GitHub

This PR may help if anyone is able to test it: Fixes #34619 - Remotes should have username and password cleared out if set blank by ianballou · Pull Request #10018 · Katello/katello · GitHub

Ignore the test files when patching.