Red Hat Satellite engineering is moving the tracking of its product development work on Satellite to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "Satellite project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs will be migrated starting at the end of May. If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "Satellite project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/SAT-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1455464 - 500 error and pg deadlock
Summary: 500 error and pg deadlock
Keywords:
Status: CLOSED DUPLICATE of bug 1341338
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Foreman Debug
Version: 6.1.9
Hardware: x86_64
OS: Linux
unspecified
urgent
Target Milestone: Unspecified
Assignee: Lukas Zapletal
QA Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-05-25 09:12 UTC by Edu Alcaniz
Modified: 2020-07-16 09:39 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-05-25 10:48:49 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Foreman Issue Tracker 5990 0 None None None 2017-05-25 09:17:23 UTC
Foreman Issue Tracker 11232 0 None None None 2017-05-25 10:05:19 UTC

Description Edu Alcaniz 2017-05-25 09:12:34 UTC 
Description of problem:
From 11/05/2017 we are suffering several 500 errors caused by postgresql pg_deadlocks on our Satellite6.1.9 server (server01) installed on a RHEL6.8 system.
Because of this error some of our customer provisioning executions are failing, living the point of sales that we are trying to provision unusable:  

[PRO] [root@server01 tmp]# grep "PGError: ERROR:  deadlock detected" production.*log*
2017-05-11 14:12:28 [E] PGError: ERROR:  deadlock detected
2017-05-11 14:12:29 [E] PGError: ERROR:  deadlock detected
2017-05-11 14:12:30 [E] PGError: ERROR:  deadlock detected
2017-05-23 19:20:11 [E] PGError: ERROR:  deadlock detected
2017-05-23 19:20:12 [E] PGError: ERROR:  deadlock detected
2017-05-23 19:20:13 [E] PGError: ERROR:  deadlock detected
2017-05-23 19:20:42 [E] PGError: ERROR:  deadlock detected
2017-05-23 19:20:43 [E] PGError: ERROR:  deadlock detected
2017-05-24 09:01:20 [E] PGError: ERROR:  deadlock detected
2017-05-24 09:01:45 [E] PGError: ERROR:  deadlock detected



top - 13:19:32 up 94 days,  8:59,  2 users,  load average: 1.62, 1.33, 1.43
Tasks: 396 total,   3 running, 393 sleeping,   0 stopped,   0 zombie
Cpu(s): 25.6%us,  0.5%sy,  0.0%ni, 73.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16333448k total, 14095452k used,  2237996k free,    78420k buffers
Swap:  4194300k total,    32376k used,  4161924k free,  7077264k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                            
 1284 postgres  20   0  269m  79m  20m R 100.0  0.5 348:04.51 postgres: foreman foreman [local] DELETE


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

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:

Also if we execute top command on satellite6.1.9 server we can see that there is a postgres process  running from  348 minutes (CPU time) consuming 100% of that CPU. Is this the behavior expected ?  

Expected results:


Additional info:
Comment 1 Edu Alcaniz 2017-05-25 09:13:04 UTC 
Also have requested to share output of foreman-tail during provisioning a host so that we can check the logs.

==========================================================================
2017-05-24 12:25:51 [I]   Parameters: {"id"=>"3cd98762-5aa9-4a51-820a-e975e8ab62d7"}
2017-05-24 12:25:51 [E] PGError: ERROR:  deadlock detected
DETAIL:  Process 8571 waits for ShareLock on transaction 78753194; blocked by process 8547.
Process 8547 waits for ShareLock on transaction 78753199; blocked by process 8571.
HINT:  See server log for query details.
: UPDATE "environments" SET "hosts_count" = 3 WHERE "environments"."id" = 1208 (ActiveRecord::StatementInvalid)
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/postgresql_adapter.rb:1158:in `async_exec'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/postgresql_adapter.rb:1158:in `exec_no_cache'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/postgresql_adapter.rb:675:in `block in exec_delete'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract_adapter.rb:280:in `block in log'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract_adapter.rb:275:in `log'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/postgresql_adapter.rb:674:in `exec_delete'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:96:in `update'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/query_cache.rb:14:in `update'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/counter_cache.rb:37:in `block in reset_counters'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/counter_cache.rb:19:in `each'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/counter_cache.rb:19:in `reset_counters'
/usr/share/foreman/app/models/concerns/counter_cache_fix.rb:18:in `block in update_counter_caches'
/usr/share/foreman/app/models/concerns/counter_cache_fix.rb:13:in `each'
/usr/share/foreman/app/models/concerns/counter_cache_fix.rb:13:in `update_counter_caches'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:427:in `_run__3421215209278113916__update__2265741195532505060__callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_update_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/callbacks.rb:272:in `update'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/persistence.rb:347:in `create_or_update'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/callbacks.rb:264:in `block in create_or_update'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:722:in `_run__3421215209278113916__save__2265741195532505060__callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_save_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/callbacks.rb:264:in `create_or_update'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/persistence.rb:84:in `save'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/validations.rb:50:in `save'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/attribute_methods/dirty.rb:22:in `save'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:241:in `block (2 levels) in save'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:295:in `block in with_transaction_returning_status'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:208:in `transaction'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:241:in `block in save'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:252:in `rollback_active_record_state!'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:240:in `save'
/usr/share/foreman/app/models/concerns/foreman/sti.rb:29:in `save_with_type'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/persistence.rb:216:in `block in update_attributes'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:295:in `block in with_transaction_returning_status'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:192:in `transaction'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:208:in `transaction'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/persistence.rb:214:in `update_attributes'
/usr/share/foreman/app/controllers/api/v2/hosts_controller.rb:92:in `update'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/base.rb:167:in `process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rendering.rb:10:in `process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/callbacks.rb:18:in `block in process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:572:in `block (4 levels) in _run__3838501541687198815__process_action__942956618
312393239__callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_11474'
/usr/share/foreman/app/controllers/api/v2/base_controller.rb:151:in `disable_json_root'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_11474'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:527:in `block (3 levels) in _run__3838501541687198815__process_action__942956618
312393239__callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_11473'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in `around'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in `_callback_around_3947'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_11473'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:504:in `block (2 levels) in _run__3838501541687198815__process_action__942956618
312393239__callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_11472'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:33:in `clear_thread'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_11472'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:426:in `block in _run__3838501541687198815__process_action__942956618312393239__
callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in `block in _conditional_callback_around_11471'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in `around'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in `_callback_around_13'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_11471'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:414:in `_run__3838501541687198815__process_action__942956618312393239__callbacks
'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/callbacks.rb:17:in `process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rescue.rb:29:in `process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in `block in instrument'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in `instrument'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/base.rb:121:in `process'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/rendering.rb:45:in `process'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal.rb:203:in `dispatch'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal.rb:246:in `block in action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:73:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:36:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/mapper.rb:42:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:68:in `block in call'
/opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:56:in `each'
/opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:56:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:600:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/apipie-rails-0.2.5/lib/apipie/extractor/recorder.rb:97:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/apipie-rails-0.2.5/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/etag.rb:23:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/conditionalget.rb:35:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/head.rb:14:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
/usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:9:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/flash.rb:242:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/cookies.rb:339:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/query_cache.rb:64:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/connection_pool.rb:473:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `_run__1439394396977692385__call__2265741195532505060__callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in `__run_callback'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in `run_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/katello-2.2.0.89/lib/katello/middleware/silenced_logger.rb:29:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/request_id.rb:22:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/runtime.rb:17:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/lock.rb:15:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in `pass'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in `invalidate'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in `call!'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/engine.rb:479:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/application.rb:223:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/railtie/configurable.rb:30:in `method_missing'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/builder.rb:134:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:64:in `block in call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:49:in `each'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:49:in `call'
/usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/rack/thread_handler_extension.rb:77:in `process_request'
/usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:140:in `accept_and_process_next_request'
/usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:108:in `main_loop'
/usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler.rb:441:in `block (3 levels) in start_threads'
/opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
caused by: (PGError) ERROR:  deadlock detected
DETAIL:  Process 8571 waits for ShareLock on transaction 78753194; blocked by process 8547.
Process 8547 waits for ShareLock on transaction 78753199; blocked by process 8571.
HINT:  See server log for query details.

    ... skipped 150 lines
Comment 2 Edu Alcaniz 2017-05-25 09:13:40 UTC 
The error 'PGError: ERROR:  deadlock detected' in not happening always, the test done yesterday and reported with foreman-debug.log file in this case was executed OK with no errors. Apparently the error is happening randomly when we try to provision different POS from Satellite6 and it is not happening always with the same POS.

I believe the reason that in almost all cases the error is happening in a system create/destroy/update task is because it happens during the execution of 'subscription-manager register' of the kickstart provisioning process, also keep in mind that we are doing a lot of POS reinstallations where the same POS is fully reinstalled without changing the POS fqdn using a KS template associated with a new CV.
Comment 3 Edu Alcaniz 2017-05-25 09:14:02 UTC 
It seems same error of http://projects.theforeman.org/issues/5990
Comment 5 Pavel Moravec 2017-05-25 10:00:51 UTC 
I think rather upstream #11232 matches more.

postgres deadlock:

ERROR:  deadlock detected
DETAIL:  Process 25167 waits for ShareLock on transaction 78704085; blocked by process 24992.
        Process 24992 waits for ShareLock on transaction 78704084; blocked by process 25167.
        Process 25167: UPDATE "environments" SET "hosts_count" = 4 WHERE "environments"."id" = 1208
        Process 24992: UPDATE "environments" SET "hosts_count" = 10 WHERE "environments"."id" = 1162
HINT:  See server log for query details.
STATEMENT:  UPDATE "environments" SET "hosts_count" = 4 WHERE "environments"."id" = 1208
ERROR:  deadlock detected
DETAIL:  Process 30372 waits for ShareLock on transaction 78704253; blocked by process 25167.
        Process 25167 waits for ShareLock on transaction 78704265; blocked by process 30372.
        Process 30372: UPDATE "environments" SET "hosts_count" = 5 WHERE "environments"."id" = 1208
        Process 25167: UPDATE "environments" SET "hosts_count" = 9 WHERE "environments"."id" = 1162
HINT:  See server log for query details.
STATEMENT:  UPDATE "environments" SET "hosts_count" = 5 WHERE "environments"."id" = 1208
ERROR:  deadlock detected
DETAIL:  Process 8571 waits for ShareLock on transaction 78753194; blocked by process 8547.
        Process 8547 waits for ShareLock on transaction 78753199; blocked by process 8571.
        Process 8571: UPDATE "environments" SET "hosts_count" = 3 WHERE "environments"."id" = 1208
        Process 8547: UPDATE "environments" SET "hosts_count" = 2 WHERE "environments"."id" = 1212
HINT:  See server log for query details.
STATEMENT:  UPDATE "environments" SET "hosts_count" = 3 WHERE "environments"."id" = 1208


backtrace
Comment 6 Pavel Moravec 2017-05-25 10:19:27 UTC 
2017-05-24 12:25:33 [I] Processing by Api::V2::HostsController#update as JSON
2017-05-24 12:25:33 [I]   Parameters: {"host"=>{"environment_id"=>"1212", "hostgroup_id"=>"1131"}, "apiv"=>"v2", "id"=>"1588"}

is in deadlock with:

2017-05-24 12:25:51 [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#consumer_destroy as JSON
2017-05-24 12:25:51 [I]   Parameters: {"id"=>"3cd98762-5aa9-4a51-820a-e975e8ab62d7"}


At least the 2nd deadlocks while the 1st hadnt finished until then (and such a call usually takes 22s, per production.log)
Comment 7 Tomer Brisker 2017-05-25 10:48:49 UTC 

*** This bug has been marked as a duplicate of bug 1341338 ***
Note You need to log in before you can comment on or make changes to this bug.