Bug 2227109

Summary:	`podman login` against the container registry returns 500 intermittently
Product:	Red Hat Satellite	Reporter:	matt jia <mjia>
Component:	Container Management - Content	Assignee:	satellite6-bugs <satellite6-bugs>
Status:	NEW ---	QA Contact:	Satellite QE Team <sat-qe-bz-list>
Severity:	high	Docs Contact:
Priority:	high
Version:	6.13.0	CC:	ahumbe, iballou, rlavi, saydas
Target Milestone:	Unspecified	Keywords:	Triaged
Target Release:	Unused
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:		Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description matt jia 2023-07-28 01:28:56 UTC

Description of problem:

As $summary,

podman login example.capsule.com -u admin

Error: error authenticating creds for "example.capsule.com": Requesting bear token: invalid status code from registry 500 (Internal Server Error)


Version-Release number of selected component (if applicable):

6.13

How reproducible:

Easy

Steps to Reproduce:
1. Run `podman login` on multiple hosts at the same time
2.
3.

Actual results:

Sometimes login failed with:

Error: error authenticating creds for "example.satellite.com": Requesting bear token: invalid status code from registry 500 (Internal Server Error)


Expected results:

Login should succeed


Additional info:

Traceback on the smart proxy:

2300:2023-07-27T10:52:59 1aff9aac [I] Started GET /container_gateway/v2/token account=admin&service=example.capsule.com
2023-07-27T10:53:17 1aff9aac [W] Error processing request '1aff9aac-4d4b-4582-a23f-ec310fc95b8e: <Sequel::DatabaseError>: SQLite3::BusyException: database is locked
/usr/share/gems/gems/sqlite3-1.4.2/lib/sqlite3/resultset.rb:108:in `step'
/usr/share/gems/gems/sqlite3-1.4.2/lib/sqlite3/resultset.rb:108:in `next'
/usr/share/gems/gems/sqlite3-1.4.2/lib/sqlite3/resultset.rb:133:in `each'
/usr/share/gems/gems/sqlite3-1.4.2/lib/sqlite3/database.rb:202:in `to_a'
/usr/share/gems/gems/sqlite3-1.4.2/lib/sqlite3/database.rb:202:in `block in execute'
/usr/share/gems/gems/sqlite3-1.4.2/lib/sqlite3/database.rb:151:in `prepare'
/usr/share/gems/gems/sqlite3-1.4.2/lib/sqlite3/database.rb:193:in `execute'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/adapters/sqlite.rb:218:in `block (2 levels) in _execute'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/database/logging.rb:38:in `log_connection_yield'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/adapters/sqlite.rb:218:in `block in _execute'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/database/connecting.rb:293:in `synchronize'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/adapters/sqlite.rb:209:in `_execute'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/adapters/sqlite.rb:176:in `execute_insert'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/dataset/actions.rb:1178:in `execute_insert'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/dataset/actions.rb:409:in `insert'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/model/associations.rb:2252:in `block in def_many_to_many'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/model/associations.rb:2599:in `add_associated_object'
/usr/share/gems/gems/sequel-5.62.0/lib/sequel/model/associations.rb:2069:in `block in def_association_instance_methods'
/usr/share/gems/gems/smart_proxy_container_gateway-1.0.7/lib/smart_proxy_container_gateway/container_gateway_main.rb:126:in `block in update_user_repositories'
/usr/share/gems/gems/smart_proxy_container_gateway-1.0.7/lib/smart_proxy_container_gateway/container_gateway_main.rb:121:in `each'
/usr/share/gems/gems/smart_proxy_container_gateway-1.0.7/lib/smart_proxy_container_gateway/container_gateway_main.rb:121:in `update_user_repositories'
/usr/share/gems/gems/smart_proxy_container_gateway-1.0.7/lib/smart_proxy_container_gateway/container_gateway_api.rb:112:in `block in <class:Api>'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1686:in `call'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1686:in `block in compile!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1023:in `block (3 levels) in route!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1042:in `route_eval'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1023:in `block (2 levels) in route!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1071:in `block in process_route'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1069:in `catch'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1069:in `process_route'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1021:in `block in route!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1018:in `each'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1018:in `route!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1140:in `block in dispatch!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1112:in `block in invoke'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1112:in `catch'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1112:in `invoke'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1135:in `dispatch!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:949:in `block in call!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1112:in `block in invoke'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1112:in `catch'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1112:in `invoke'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:949:in `call!'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:938:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:101:in `call'
/usr/share/foreman-proxy/lib/proxy/request_id_middleware.rb:11:in `call'
/usr/share/gems/gems/rack-protection-2.2.2/lib/rack/protection/xss_header.rb:18:in `call'
/usr/share/gems/gems/rack-protection-2.2.2/lib/rack/protection/path_traversal.rb:16:in `call'
/usr/share/gems/gems/rack-protection-2.2.2/lib/rack/protection/json_csrf.rb:26:in `call'
/usr/share/gems/gems/rack-protection-2.2.2/lib/rack/protection/base.rb:50:in `call'
/usr/share/gems/gems/rack-protection-2.2.2/lib/rack/protection/base.rb:50:in `call'
/usr/share/gems/gems/rack-protection-2.2.2/lib/rack/protection/frame_options.rb:31:in `call'
/usr/share/gems/gems/rack-2.2.4/lib/rack/null_logger.rb:11:in `call'
/usr/share/gems/gems/rack-2.2.4/lib/rack/head.rb:12:in `call'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/show_exceptions.rb:22:in `call'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:218:in `call'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1993:in `call'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1553:in `block in call'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1769:in `synchronize'
/usr/share/gems/gems/sinatra-2.2.2/lib/sinatra/base.rb:1553:in `call'
/usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:74:in `block in call'
/usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:58:in `each'
/usr/share/gems/gems/rack-2.2.4/lib/rack/urlmap.rb:58:in `call'
/usr/share/gems/gems/rack-2.2.4/lib/rack/builder.rb:244:in `call'
/usr/share/gems/gems/rack-2.2.4/lib/rack/handler/webrick.rb:95:in `service'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httpserver.rb:140:in `service'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/httpserver.rb:96:in `run'
/usr/share/gems/gems/webrick-1.7.0/lib/webrick/server.rb:310:in `block in start_thread'
/usr/share/gems/gems/logging-2.3.1/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2023-07-27T10:53:17 1aff9aac [I] Finished GET /container_gateway/v2/token with 500 (18361.06 ms)

Comment 1 matt jia 2023-07-28 01:31:27 UTC

The strange part is why update_user_repositories is called when doing `podman login`? It clearly seems like a bug to me.

Comment 2 Ian Ballou 2023-08-02 19:27:50 UTC

When a user authenticates to the smart proxy container gateway, we need to update what repositories they have access to in case anything changed on the Foreman. That's why update_user_repositories is run.

The bug here is that sometimes SQLite locks up when multiple requests happen at once. This popped up before: https://bugzilla.redhat.com/show_bug.cgi?id=2105349

Comment 3 matt jia 2023-08-02 21:53:42 UTC

(In reply to Ian Ballou from comment #2)
> When a user authenticates to the smart proxy container gateway, we need to
> update what repositories they have access to in case anything changed on the
> Foreman. That's why update_user_repositories is run.
> The bug here is that sometimes SQLite locks up when multiple requests happen
> at once. This popped up before:
> https://bugzilla.redhat.com/show_bug.cgi?id=2105349

Right. Do we have any workaround here as this is significantly impacting the customer's Openstack deployment.