Bug 2105349 - "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
Summary: "ERF12-9562 [ProxyAPI::ProxyException]: Unable to update the repository list ...
Keywords:
Status: NEW
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Capsule - Content
Version: 6.10.6
Hardware: All
OS: All
unspecified
medium
Target Milestone: Unspecified
Assignee: satellite6-bugs
QA Contact: Satellite QE Team
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-07-08 15:56 UTC by Sayan Das
Modified: 2023-08-02 19:29 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker SAT-11453 0 None None None 2023-08-02 19:29:53 UTC

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.
Note You need to log in before you can comment on or make changes to this bug.