Description of problem:

Not always but sometimes very randomly, the Capsule sync task fails with the following error:

ERF12-9562 [ProxyAPI::ProxyException]: Unable to update the repository list ([RestClient::InternalServerError]: 500 Internal Server Error) for Capsule https://capsule1.example.com:9090/container_gateway/repository_listERF12-9562 [ProxyAPI::ProxyException]: Unable to update the repository list ([RestClient::InternalServerError]: 500 Internal Server Error) for Capsule https://capsule1.example.com:9090/container_gateway/repository_list

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

Satellite Capsule 6.10.6

How reproducible:

In the customer environment ( not always but sometimes )

Steps to Reproduce:

NA at this moment

Actual results:

In production.log of the satellite:

~~~
2022-06-15T05:49:52 [I|aud|770eab6b] Katello::Repository (84060) update event on last_indexed 1970-01-01 00:00:00 UTC, 2022-06-15 03:49:52 UTC
2022-06-15T05:50:00 [I|aud|770eab6b] Katello::Repository (4534) update event on publication_href /pulp/api/v3/publications/rpm/rpm/8f405032-3eb5-49fe-a8c1-68619cb04463/, /pulp/api/v3/publications/rpm/rpm/2eff3b29-5951-4be3-91b2-b73f630d8749/
2022-06-15T05:50:13 [I|aud|770eab6b] Katello::Repository (4534) update event on last_indexed 2022-06-14 03:52:08 UTC, 2022-06-15 03:50:13 UTC
2022-06-15T05:52:14 [I|app|770eab6b] CONTENT_INDEX type=Katello::Rpm success=true duration=190249.76
2022-06-15T05:52:15 [I|app|770eab6b] CONTENT_INDEX type=Katello::ModuleStream success=true duration=333.59
2022-06-15T05:53:31 [I|app|770eab6b] CONTENT_INDEX type=Katello::Erratum success=true duration=76267.65
2022-06-15T05:53:31 [I|app|770eab6b] CONTENT_INDEX type=Katello::PackageGroup success=true duration=415.51
2022-06-15T05:53:32 [I|app|770eab6b] CONTENT_INDEX type=Katello::Srpm success=true duration=237.61
2022-06-15T05:53:32 [I|aud|770eab6b] Katello::Repository (84073) update event on last_indexed 1970-01-01 00:00:00 UTC, 2022-06-15 03:53:32 UTC
2022-06-15T05:53:42 [I|aud|770eab6b] Katello::Repository (4511) update event on publication_href /pulp/api/v3/publications/rpm/rpm/0678f692-610c-4947-a426-77b13a724f06/, /pulp/api/v3/publications/rpm/rpm/5881a659-f82b-4f31-9ee1-d08b6c4ebe8e/
2022-06-15T05:54:03 [I|aud|770eab6b] Katello::Repository (4511) update event on last_indexed 2022-06-14 04:04:40 UTC, 2022-06-15 03:54:03 UTC
2022-06-15T05:54:05 [I|app|770eab6b] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/views/katello/errata_mailer/promote_errata.html.erb within layouts/application_mailer
2022-06-15T05:54:05 [I|app|770eab6b] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/views/katello/errata_mailer/_host_dashboard.html.erb (Duration: 3.3ms | Allocations: 1454)
2022-06-15T05:54:05 [I|app|770eab6b] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/views/katello/errata_mailer/promote_errata.html.erb within layouts/application_mailer (Duration: 6.1ms | Allocations: 3051)
2022-06-15T05:54:05 [I|app|770eab6b] Rendering /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/views/katello/errata_mailer/promote_errata.text.erb
2022-06-15T05:54:05 [I|app|770eab6b] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/views/katello/errata_mailer/promote_errata.text.erb (Duration: 1.3ms | Allocations: 1423)
2022-06-15T05:54:05 [W|app|770eab6b] Scoped order is ignored, it's forced to be batch order.
(33.2ms)
2022-06-15T05:54:09 [I|aud|770eab6b] Katello::ContentViewVersion (10696) update event on content_counts ,

{"ansible collection"=>0, "docker_manifest"=>0, "docker_manifest_list"=>0, "docker_tag"=>0, "file"=>0, "rpm"=>69761, "modulemd"=>0, "erratum"=>4523, "package_group"=>79, "srpm"=>0}

2022-06-15T05:54:09 [I|bac|770eab6b] Task

{label: Actions::Katello::ContentView::CapsuleSync, id: 9343d1bc-bc12-4f5c-9ed8-a8718f39758b, execution_plan_id: f71ce9b4-e9e7-490c-b7a9-48fae99bcc83}

state changed: planning
2022-06-15T05:54:09 [I|bac|770eab6b] Task

{label: Actions::Katello::ContentView::CapsuleSync, id: 9343d1bc-bc12-4f5c-9ed8-a8718f39758b, execution_plan_id: f71ce9b4-e9e7-490c-b7a9-48fae99bcc83}

state changed: planned
2022-06-15T05:54:10 [I|bac|770eab6b] Task

{label: Actions::Katello::ContentView::Publish, id: eb616392-fb7f-45a6-8784-f6dbcddc609f, execution_plan_id: f4a69cbc-8759-4a7c-85e5-3d087b7182ad}

state changed: stopped result: success
2022-06-15T05:54:10 [I|bac|770eab6b] Task

{label: Actions::Katello::ContentView::Publish, id: eb616392-fb7f-45a6-8784-f6dbcddc609f, execution_plan_id: f4a69cbc-8759-4a7c-85e5-3d087b7182ad}

state changed: stopped result: success
2022-06-15T05:54:10 [I|bac|770eab6b] Task

{label: Actions::Katello::ContentView::CapsuleSync, id: 9343d1bc-bc12-4f5c-9ed8-a8718f39758b, execution_plan_id: f71ce9b4-e9e7-490c-b7a9-48fae99bcc83}

state changed: running
2022-06-15T05:54:12 [I|bac|770eab6b] Task

{label: Actions::Katello::CapsuleContent::Sync, id: f6d55e44-100a-4aac-b88e-b6c09c74ff7b, execution_plan_id: b42e4c25-a5cd-4f59-9c87-ce2c029ee0c6}

state changed: planning
2022-06-15T05:54:43 [I|bac|770eab6b] Task

{label: Actions::Katello::CapsuleContent::Sync, id: f6d55e44-100a-4aac-b88e-b6c09c74ff7b, execution_plan_id: b42e4c25-a5cd-4f59-9c87-ce2c029ee0c6}

state changed: planned
2022-06-15T05:54:43 [I|bac|770eab6b] Task

{label: Actions::Katello::CapsuleContent::Sync, id: f6d55e44-100a-4aac-b88e-b6c09c74ff7b, execution_plan_id: b42e4c25-a5cd-4f59-9c87-ce2c029ee0c6}

state changed: running
2022-06-15T05:54:43 [I|bac|770eab6b] Task

{label: Actions::Katello::CapsuleContent::Sync, id: 79d01289-a6a3-4d18-97eb-74930ec6ce8b, execution_plan_id: a51f9e34-20cf-4be0-9c77-d4ef6bfa74ee}

state changed: planning
2022-06-15T05:55:08 [I|bac|770eab6b] Task

{label: Actions::Katello::CapsuleContent::Sync, id: 79d01289-a6a3-4d18-97eb-74930ec6ce8b, execution_plan_id: a51f9e34-20cf-4be0-9c77-d4ef6bfa74ee}

state changed: planned
2022-06-15T05:55:08 [I|bac|770eab6b] Task

{label: Actions::Katello::CapsuleContent::Sync, id: a0d3d929-b0b6-4a11-ba0b-2d89e2e2d481, execution_plan_id: e1fbe852-5221-4585-8982-44512d71ff46}

state changed: planning
2022-06-15T05:55:08 [I|bac|770eab6b] Task

{label: Actions::Katello::CapsuleContent::Sync, id: 79d01289-a6a3-4d18-97eb-74930ec6ce8b, execution_plan_id: a51f9e34-20cf-4be0-9c77-d4ef6bfa74ee}

state changed: running
2022-06-15T05:55:22 [E|bac|770eab6b] ERF12-9562 [ProxyAPI::ProxyException]: Unable to update the repository list ([RestClient::InternalServerError]: 500 Internal Server Error) for Capsule https://capsule1.example.com:9090/container_gateway/repository_list (ProxyAPI::ProxyException)
770eab6b | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/lib/proxy_api/container_gateway.rb:13:in `rescue in repository_list'
770eab6b | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/lib/proxy_api/container_gateway.rb:8:in `repository_list'
770eab6b | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/models/katello/concerns/smart_proxy_extensions.rb:118:in `update_container_repo_list'
770eab6b | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/lib/actions/katello/capsule_content/sync_capsule.rb:63:in `update_container_repo_list'
770eab6b | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/lib/actions/katello/capsule_content/sync_capsule.rb:44:in `sync_container_gateway'
770eab6b | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/app/lib/actions/katello/capsule_content/sync_capsule.rb:39:in `plan'
..
..
2022-06-15T05:55:22 [E|bac|770eab6b] ERF12-9562 [ProxyAPI::ProxyException]: Unable to update the repository list ([RestClient::InternalServerError]: 500 Internal Server Error) for Capsule https://capsule1.example.com:9090/container_gateway/repository_list (ProxyAPI::ProxyException)
770eab6b | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.1.57/lib/proxy_api/container_gateway.rb:13:in `rescue in repository_list'

~~~

In proxy.log of capsule [ the time stamps won't match as the capsule logs are from a different failed task ]

~~~
2022-07-04T15:55:29 645743e1 [I] Finished PUT /container_gateway/repository_list/ with 200 (4264.87 ms)
2022-07-04T15:55:29 645743e1 [I] Started GET /container_gateway/users
2022-07-04T15:55:29 645743e1 [I] Finished GET /container_gateway/users with 200 (2.99 ms)
2022-07-04T15:57:26 645743e1 [I] Started PUT /container_gateway/repository_list/
2022-07-04T15:57:35 645743e1 [I] Finished PUT /container_gateway/repository_list/ with 200 (8318.3 ms)
2022-07-04T15:57:35 645743e1 [I] Started GET /container_gateway/users
2022-07-04T15:57:35 645743e1 [I] Finished GET /container_gateway/users with 200 (0.64 ms)
2022-07-04T16:00:41 645743e1 [I] Started PUT /container_gateway/repository_list/
2022-07-04T16:00:49 645743e1 [I] Started PUT /container_gateway/repository_list/
2022-07-04T16:00:56 645743e1 [W] Error processing request '645743e1-7a7d-4156-8fd5-d782b748bba2: <Sequel::DatabaseError>: SQLite3::BusyException: database is locked
/opt/theforeman/tfm/root/usr/share/gems/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:108:in `step'
/opt/theforeman/tfm/root/usr/share/gems/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:108:in `block in each'
/opt/theforeman/tfm/root/usr/share/gems/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:107:in `loop'
/opt/theforeman/tfm/root/usr/share/gems/gems/sqlite3-1.3.13/lib/sqlite3/statement.rb:107:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:156:in `to_a'
/opt/theforeman/tfm/root/usr/share/gems/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:156:in `block in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:95:in `prepare'
/opt/theforeman/tfm/root/usr/share/gems/gems/sqlite3-1.3.13/lib/sqlite3/database.rb:137:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/adapters/sqlite.rb:202:in `block (2 levels) in _execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/database/logging.rb:38:in `log_connection_yield'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/adapters/sqlite.rb:202:in `block in _execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/connection_pool/threaded.rb:88:in `hold'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/database/connecting.rb:269:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/adapters/sqlite.rb:193:in `_execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/adapters/sqlite.rb:159:in `execute_insert'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/dataset/actions.rb:1109:in `execute_insert'
..
..
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/model/base.rb:1488:in `block in save'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/model/base.rb:1930:in `checked_save_failure'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/model/base.rb:1488:in `save'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/model/base.rb:254:in `create'
/opt/theforeman/tfm/root/usr/share/gems/gems/sequel-5.42.0/lib/sequel/model/base.rb:425:in `find_or_create'
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_container_gateway-1.0.6/lib/smart_proxy_container_gateway/container_gateway_main.rb:82:in `block in update_repository_list'
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_container_gateway-1.0.6/lib/smart_proxy_container_gateway/container_gateway_main.rb:81:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_container_gateway-1.0.6/lib/smart_proxy_container_gateway/container_gateway_main.rb:81:in `update_repository_list'
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_container_gateway-1.0.6/lib/smart_proxy_container_gateway/container_gateway_api.rb:131:in `block in <class:Api>'
/opt/theforeman/tfm/root/usr/share/gems/gems/sinatra-2.1.0/lib/sinatra/base.rb:1675:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/sinatra-2.1.0/lib/sinatra/base.rb:1675:in `block in compile!'
/opt/theforeman/tfm/root/usr/share/gems/gems/sinatra-2.1.0/lib/sinatra/base.rb:1013:in `block (3 levels) in route!'
/opt/theforeman/tfm/root/usr/share/gems/gems/sinatra-2.1.0/lib/sinatra/base.rb:1032:in `route_eval'
/opt/theforeman/tfm/root/usr/share/gems/gems/sinatra-2.1.0/lib/sinatra/base.rb:1013:in `block (2 levels) in route!'
..
..
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.3/lib/rack/builder.rb:244:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.3/lib/rack/handler/webrick.rb:95:in `service'
/opt/rh/rh-ruby27/root/usr/share/ruby/webrick/httpserver.rb:140:in `service'
/opt/rh/rh-ruby27/root/usr/share/ruby/webrick/httpserver.rb:96:in `run'
/opt/rh/rh-ruby27/root/usr/share/ruby/webrick/server.rb:307:in `block in start_thread'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2022-07-04T16:00:56 645743e1 [I] Finished PUT /container_gateway/repository_list/ with 500 (15334.02 ms)
2022-07-04T16:01:04 645743e1 [I] Finished PUT /container_gateway/repository_list/ with 200 (15027.93 ms)
2022-07-04T16:01:05 645743e1 [I] Started GET /container_gateway/users
2022-07-04T16:01:05 645743e1 [I] Finished GET /container_gateway/users with 200 (0.8 ms)

~~~

Expected results:

No such transaction locks and clean\uninterrputed capsule syncs.

Additional info:

Even in the customer's own infra, this issue is not always reproducible:

A) I noticed that usually most of the auto-generated capsule sync tasks are completed fine.

B) I tried a manual "Optimized Sync" of the same capsule but it was completed successfully without any issues.

So no idea how and why that transaction lock is getting created in the sqlite DB that is used by the container_gateway plugin on capsule.