Bug 1455464

Summary: 500 error and pg deadlock
Product: Red Hat Satellite Reporter: Edu Alcaniz <ealcaniz>
Component: Foreman DebugAssignee: Lukas Zapletal <lzap>
Status: CLOSED DUPLICATE QA Contact:
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 6.1.9CC: bchardim, ealcaniz, pmoravec, tbrisker
Target Milestone: Unspecified   
Target Release: Unused   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-05-25 10:48:49 UTC 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 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 ***