Single trusted publisher for many packages causes slow API token creation

[pnacht]

Describe the bug
If a single identity is registered as the "trusted publisher" for many packages (200+), the API token exchange can sometimes take a long time (over 5 seconds). This in conjunction with twine's built-in 5-second timeout causes the publication to fail.

Expected behavior
API token exchange should be consistently fast, at least fast enough for twine's timeout.

To Reproduce
Add an account as trusted publisher for many different packages. I'm not sure how many would be necessary to make it consistent, though... with 200+ packages, the exchange only times out occasionally (10% of the time, maybe?).

My Platform
Uploading with twine 6.10, from a Google Compute Engine instance running a Debian (bookworm) image.

Additional context
This was originally reported in pypa/twine#1261, but I was asked to instead see if something could be diagnosed in Warehouse first.

See below the output from the last time we had this timeout. It may be worth mentioning that other publications (a few hours before and after) succeeded.

Publishing packages in '[...]' using twine:
[...].tar.gz
[...].whl
Uploading distributions to https://upload.pypi.org/legacy/
INFO     [...].whl (51.0 KB)                                                 
INFO     [...].tar.gz (44.6 KB)                                                           
INFO     username set by command options                                        
INFO     Querying keyring for password                                          
Traceback (most recent call last):
  File ".venv/lib/python3.12/site-packages/urllib3/connectionpool.py", line 534, in _make_request
    response = conn.getresponse()
               ^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/urllib3/connection.py", line 516, in getresponse
    httplib_response = super().getresponse()
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/http/client.py", line 1428, in getresponse
    response.begin()
  File "/usr/lib/python3.12/http/client.py", line 331, in begin
    version, status, reason = self._read_status()
                              ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/http/client.py", line 292, in _read_status
    line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1")
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/socket.py", line 707, in readinto
    return self._sock.recv_into(b)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/ssl.py", line 1252, in recv_into
    return self.read(nbytes, buffer)
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/ssl.py", line 1104, in read
    return self._sslobj.read(len, buffer)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
TimeoutError: The read operation timed out

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File ".venv/lib/python3.12/site-packages/requests/adapters.py", line 667, in send
    resp = conn.urlopen(
           ^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/urllib3/connectionpool.py", line 841, in urlopen
    retries = retries.increment(
              ^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/urllib3/util/retry.py", line 474, in increment
    raise reraise(type(error), error, _stacktrace)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/urllib3/util/util.py", line 39, in reraise
    raise value
  File ".venv/lib/python3.12/site-packages/urllib3/connectionpool.py", line 787, in urlopen
    response = self._make_request(
               ^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/urllib3/connectionpool.py", line 536, in _make_request
    self._raise_timeout(err=e, url=url, timeout_value=read_timeout)
  File ".venv/lib/python3.12/site-packages/urllib3/connectionpool.py", line 367, in _raise_timeout
    raise ReadTimeoutError(
urllib3.exceptions.ReadTimeoutError: HTTPSConnectionPool(host='upload.pypi.org', port=443): Read timed out. (read timeout=5)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File ".venv/bin/twine", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/__main__.py", line 33, in main
    error = cli.dispatch(sys.argv[1:])
            ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/cli.py", line 139, in dispatch
    return main(args.args)
           ^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/commands/upload.py", line 258, in main
    return upload(upload_settings, parsed_args.dists)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/commands/upload.py", line 181, in upload
    repository = upload_settings.create_repository()
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/settings.py", line 336, in create_repository
    self.password,
    ^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/settings.py", line 140, in password
    return self.auth.password
           ^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/auth.py", line 68, in password
    return utils.get_userpass_value(
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/utils.py", line 282, in get_userpass_value
    value = prompt_strategy()
            ^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/auth.py", line 185, in password_from_keyring_or_trusted_publishing_or_prompt
    if (token := self.make_trusted_publishing_token()) is not None:
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/twine/auth.py", line 106, in make_trusted_publishing_token
    mint_token_resp = session.post(
                      ^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/requests/sessions.py", line 637, in post
    return self.request("POST", url, data=data, json=json, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/requests/sessions.py", line 589, in request
    resp = self.send(prep, **send_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/requests/sessions.py", line 703, in send
    r = adapter.send(request, **kwargs)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File ".venv/lib/python3.12/site-packages/requests/adapters.py", line 713, in send
    raise ReadTimeout(e, request=request)
requests.exceptions.ReadTimeout: HTTPSConnectionPool(host='upload.pypi.org', port=443): Read timed out. (read timeout=5)

[di]

The root cause is likely #18229, we should resolve this by fixing that issue.

[woodruffw]

For context as well: here's where the publisher-to-project lookup happens:

warehouse/warehouse/oidc/views.py

Lines 246 to 298 in 0d2d625

	# We either don't have a pending OIDC publisher, or we *did*
	# have one and we've just converted it. Either way, look for a full publisher
	# to actually do the macaroon minting with.
	try:
	publisher = oidc_service.find_publisher(claims, pending=False)
	# NOTE: assert to persuade mypy of the correct type here.
	assert isinstance(publisher, OIDCPublisher)
	except ReusedTokenError:
	return _invalid(
	errors=[
	{
	"code": "invalid-reuse-token",
	"description": "invalid token: already used",
	}
	],
	request=request,
	)
	except InvalidPublisherError as e:
	return _invalid(
	errors=[
	{
	"code": "invalid-publisher",
	"description": f"valid token, but no corresponding publisher ({e})",
	}
	],
	request=request,
	)
	# At this point, we've verified that the given JWT is valid for the given
	# project. All we need to do is mint a new token.
	# NOTE: For OIDC-minted API tokens, the Macaroon's description string
	# is purely an implementation detail and is not displayed to the user.
	macaroon_service: DatabaseMacaroonService = request.find_service(
	IMacaroonService, context=None
	)
	not_before = int(time.time())
	expires_at = not_before + 900
	serialized, dm = macaroon_service.create_macaroon(
	request.domain,
	(
	f"OpenID token: {str(publisher)} "
	f"({datetime.fromtimestamp(not_before).isoformat()})"
	),
	[
	caveats.OIDCPublisher(
	oidc_publisher_id=str(publisher.id),
	),
	caveats.ProjectID(project_ids=[str(p.id) for p in publisher.projects]),
	caveats.Expiration(expires_at=expires_at, not_before=not_before),
	],
	oidc_publisher_id=str(publisher.id),
	additional={"oidc": publisher.stored_claims(claims)},
	)

It's possible the emitted SQL for this is really suboptimal, but I'm pretty surprised this would ever take >5s: the publisher lookup itself should be 2 scalar queries in the worst case (GitHub/GitLab with the environment fallback), and then the project association should be a join through the association table (which isn't light, but shouldn't be super heavy either).

I suppose it's possible that we're eagerly loading more we actually need though, i.e. more attributes/relations from Project than just Project.id.

[miketheman]

The slowness isn't in the SQL lookup, rather the way the OIDC publisher emits events for projects.

warehouse/warehouse/oidc/views.py

Lines 307 to 317 in 41b3aba

	for project in publisher.projects:
	project.record_event(
	tag=EventTag.Project.ShortLivedAPITokenAdded,
	request=request,
	additional={
	"expires": expires_at,
	"publisher_name": publisher.publisher_name,
	"publisher_url": publisher.publisher_url(),
	"reusable_workflow_used": is_from_reusable_workflow(publisher, claims),
	},
	)

In this case, there's some ~290 projects associated with this specific publisher, so the code iterates through each, which adds just enough time to put this over a 5 second threshold.

[woodruffw]

In this case, there's some ~290 projects associated with this specific publisher, so the code iterates through each, which adds just enough time to put this over a 5 second threshold.

...oof. I hadn't considered that adding those events would be slow, but it makes perfect sense.

Looking at record_event itself, I see a few places where we could probably optimize things -- we're doing a ton of duplicated processing of user agents, geocoding, etc.

(We could also maybe linearize the events here and then do request.db.add_all, although I'm not sure the single add(...) is actually a major performance problem within a pre-committed transaction?)

[woodruffw]

Summarizing a call I had with @miketheman: we looked at the waterfall for this a bit and determined that the bulk of the slowdown is coming from events that SQLAlchemy dispatches on flushes/commits. Warehouse uses these events to perform downstream changes, e.g. reindexing a project in the search index if it was changed (or removing it if it was deleted/quarantined).

Specifically, these two event sites look like a strong candidate for at least some of the query amplification:

warehouse/warehouse/search/__init__.py

Lines 20 to 65 in 0d2d625

	@db.listens_for(db.Session, "after_flush")
	def store_projects_for_project_reindex(config, session, flush_context):
	# We'll (ab)use the session.info dictionary to store a list of pending
	# Project updates to the session.
	projects_to_update = session.info.setdefault(
	"warehouse.search.project_updates", set()
	)
	projects_to_delete = session.info.setdefault(
	"warehouse.search.project_deletes", set()
	)
	# Go through each new, changed, and deleted object and attempt to store
	# a Project to reindex for when the session has been committed.
	for obj in session.new | session.dirty:
	if obj.__class__ == Project:
	# Un-index archived/quarantined projects
	if obj.lifecycle_status in [
	LifecycleStatus.QuarantineEnter,
	LifecycleStatus.ArchivedNoindex,
	]:
	projects_to_delete.add(obj)
	else:
	projects_to_update.add(obj)
	if obj.__class__ == Release:
	projects_to_update.add(obj.project)
	for obj in session.deleted:
	if obj.__class__ == Project:
	projects_to_delete.add(obj)
	if obj.__class__ == Release:
	projects_to_update.add(obj.project)
	@db.listens_for(db.Session, "after_commit")
	def execute_project_reindex(config, session):
	try:
	search_service_factory = config.find_service_factory(ISearchService)
	except LookupError:
	return
	projects_to_update = session.info.pop("warehouse.search.project_updates", set())
	projects_to_delete = session.info.pop("warehouse.search.project_deletes", set())
	search_service = search_service_factory(None, config)
	search_service.reindex(config, projects_to_update)
	search_service.unindex(config, projects_to_delete)

(In this case, OIDC minting results in ~300 projects being marked as "dirty" because of their event changes, which in turn results in multiplied queries via reindex -> _project_docs):

warehouse/warehouse/search/tasks.py

Line 31 in b71031f

def _project_docs(db, project_name: str | None = None):

Edit: There are a few potential solutions to the above:

1. We could have APIs like record_event place some kind of marker on the Session to tell it that the related objects aren't "really" dirty for the purpose of reindexing. This seems like a bit of a hack.
2. The event receiver itself could use the Session history APIs to look at the changes, and only proceed with reindexing if they're relevant. In other words, if all of the changes concern events, then the reindex can be skipped.
3. We could address this laterally, e.g. by allowing the OIDC token minting flow to intersect between the TP's associated projects and the uploader's requested projects. In other words if the TP is registered for {a, b, c, d} but the uploading client only requests {b, d}, then we'd only record events for {b, d} instead of multiplying across {a, b, c, d}.