Bug 2105349

Summary: "ERF12-9562 [ProxyAPI::ProxyException]: Unable to update the repository list for Capsule https://capsule1.example.com:9090/container_gateway/repository_list" during docker type content sync in Capsule 6.10.6
Product: Red Hat Satellite Reporter: Sayan Das <saydas>
Component: Capsule - ContentAssignee: satellite6-bugs <satellite6-bugs>
Status: NEW --- QA Contact: Satellite QE Team <sat-qe-bz-list>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 6.10.6CC: iballou, sadas, sajha
Target Milestone: UnspecifiedKeywords: Triaged
Target Release: Unused   
Hardware: All   
OS: All   
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 Sayan Das 2022-07-08 15:56:21 UTC 
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.