LDAP group sync got stuck in idle in transaction and caused a backlog of other group sync

  • ZenDesk ticket: https://gitlab.zendesk.com/agent/tickets/118437
  • Slack conversation: https://gitlab.slack.com/archives/C9LUQ335W/p1554755295123600

A customer ran into an issue where all 8 Sidekiq workers to be stuck, and all background jobs stopped functioning as a result. Upon issuing a TTIN signal to Sidekiq, we noticed all threads were stuck waiting for group 20091 to finish:

2019-04-08_20:33:11.36691 2019-04-08T20:33:11.363Z 31448 TID-ovkvm0ers WARN: Thread TID-ovkkdpcqw processor
2019-04-08_20:33:11.36692 2019-04-08T20:33:11.365Z 31448 TID-ovkvm0ers WARN: /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/peek-pg-1.3.0/lib/peek/views/pg.rb:17:in `async_exec'
2019-04-08_20:33:11.36692 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/peek-pg-1.3.0/lib/peek/views/pg.rb:17:in `async_exec'
2019-04-08_20:33:11.36692 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:600:in `block in exec_no_cache'
2019-04-08_20:33:11.36694 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/abstract_adapter.rb:590:in `block in log'
2019-04-08_20:33:11.36695 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
2019-04-08_20:33:11.36696 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/abstract_adapter.rb:583:in `log'
2019-04-08_20:33:11.36696 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:600:in `exec_no_cache'
2019-04-08_20:33:11.36696 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:587:in `execute_and_clear'
2019-04-08_20:33:11.36696 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:116:in `exec_delete'
2019-04-08_20:33:11.36697 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:133:in `update'
2019-04-08_20:33:11.36697 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/abstract/query_cache.rb:17:in `update'
2019-04-08_20:33:11.36697 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/relation.rb:89:in `_update_record'
2019-04-08_20:33:11.36698 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/persistence.rb:559:in `_update_record'
2019-04-08_20:33:11.36698 /opt/gitlab/embedded/service/gitlab-rails/config/initializers/active_record_locking.rb:18:in `_update_record'
2019-04-08_20:33:11.36698 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/attribute_methods/dirty.rb:119:in `_update_record'
2019-04-08_20:33:11.36699 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/callbacks.rb:306:in `block in _update_record'
2019-04-08_20:33:11.36699 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:126:in `call'
2019-04-08_20:33:11.36701 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
2019-04-08_20:33:11.36701 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:455:in `call'
2019-04-08_20:33:11.36702 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
2019-04-08_20:33:11.36703 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:750:in `_run_update_callbacks'
2019-04-08_20:33:11.36704 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/callbacks.rb:306:in `_update_record'
2019-04-08_20:33:11.36706 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/timestamp.rb:81:in `_update_record'
2019-04-08_20:33:11.36707 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/persistence.rb:548:in `create_or_update'
2019-04-08_20:33:11.36707 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/callbacks.rb:298:in `block in create_or_update'
2019-04-08_20:33:11.36708 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:126:in `call'
2019-04-08_20:33:11.36708 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
2019-04-08_20:33:11.36708 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:455:in `call'
2019-04-08_20:33:11.36709 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
2019-04-08_20:33:11.36709 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/callbacks.rb:750:in `_run_save_callbacks'
2019-04-08_20:33:11.36709 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/callbacks.rb:298:in `create_or_update'
2019-04-08_20:33:11.36710 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/persistence.rb:129:in `save'
2019-04-08_20:33:11.36712 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/validations.rb:44:in `save'
2019-04-08_20:33:11.36713 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/attribute_methods/dirty.rb:22:in `save'
2019-04-08_20:33:11.36713 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/transactions.rb:319:in `block (2 levels) in save'
2019-04-08_20:33:11.36713 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/transactions.rb:395:in `block in with_transaction_returning_status'
2019-04-08_20:33:11.36714 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:230:in `transaction'
2019-04-08_20:33:11.36714 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/transactions.rb:211:in `transaction'
2019-04-08_20:33:11.36715 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'
2019-04-08_20:33:11.36715 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/transactions.rb:319:in `block in save'
2019-04-08_20:33:11.36715 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/transactions.rb:334:in `rollback_active_record_state!'
2019-04-08_20:33:11.36716 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/transactions.rb:318:in `save'
2019-04-08_20:33:11.36716 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/suppressor.rb:41:in `save'
2019-04-08_20:33:11.36716 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-activerecord-0.5.1/lib/state_machines/integrations/active_record.rb:509:in `block in save'
2019-04-08_20:33:11.36718 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-activerecord-0.5.1/lib/state_machines/integrations/active_record.rb:528:in `block in around_save'
2019-04-08_20:33:11.36720 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:150:in `block in run_actions'
2019-04-08_20:33:11.36721 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:170:in `catch_exceptions'
2019-04-08_20:33:11.36722 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:148:in `run_actions'
2019-04-08_20:33:11.36723 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:133:in `run_callbacks'
2019-04-08_20:33:11.36723 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:224:in `run_callbacks'
2019-04-08_20:33:11.36723 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:128:in `block in run_callbacks'
2019-04-08_20:33:11.36724 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:371:in `before'
2019-04-08_20:33:11.36724 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:190:in `block in run_callbacks'
2019-04-08_20:33:11.36725 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:292:in `block in pausable'
2019-04-08_20:33:11.36725 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:292:in `catch'
2019-04-08_20:33:11.36725 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:292:in `pausable'
2019-04-08_20:33:11.36725 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:190:in `run_callbacks'
2019-04-08_20:33:11.36726 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:127:in `run_callbacks'
2019-04-08_20:33:11.36728 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:212:in `run_callbacks'
2019-04-08_20:33:11.36729 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:63:in `block (2 levels) in perform'
2019-04-08_20:33:11.36729 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:63:in `catch'
2019-04-08_20:33:11.36729 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:63:in `block in perform'
2019-04-08_20:33:11.36730 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:182:in `block in within_transaction'
2019-04-08_20:33:11.36730 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:171:in `block in within_transaction'
2019-04-08_20:33:11.36730 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/machine.rb:1868:in `block in within_transaction'
2019-04-08_20:33:11.36730 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-activerecord-0.5.1/lib/state_machines/integrations/active_record.rb:555:in `block in transaction'
2019-04-08_20:33:11.36731 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'
2019-04-08_20:33:11.36732 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'
2019-04-08_20:33:11.36733 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
2019-04-08_20:33:11.36735 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/transactions.rb:211:in `transaction'
2019-04-08_20:33:11.36735 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-activerecord-0.5.1/lib/state_machines/integrations/active_record.rb:554:in `transaction'
2019-04-08_20:33:11.36736 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/machine.rb:1868:in `within_transaction'
2019-04-08_20:33:11.36736 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:170:in `within_transaction'
2019-04-08_20:33:11.36736 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:181:in `within_transaction'
2019-04-08_20:33:11.36737 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:62:in `perform'
2019-04-08_20:33:11.36737 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-activerecord-0.5.1/lib/state_machines/integrations/active_record.rb:528:in `around_save'
2019-04-08_20:33:11.36738 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-activerecord-0.5.1/lib/state_machines/integrations/active_record.rb:509:in `save'
2019-04-08_20:33:11.36738 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:154:in `block (2 levels) in run_actions'
2019-04-08_20:33:11.36738 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:154:in `each'
2019-04-08_20:33:11.36738 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:154:in `block in run_actions'
2019-04-08_20:33:11.36739 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:170:in `catch_exceptions'
2019-04-08_20:33:11.36739 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:148:in `run_actions'
2019-04-08_20:33:11.36740 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition_collection.rb:60:in `perform'
2019-04-08_20:33:11.36740 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/transition.rb:163:in `perform'
2019-04-08_20:33:11.36741 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/event.rb:155:in `fire'
2019-04-08_20:33:11.36741 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/event.rb:219:in `block in add_actions'
2019-04-08_20:33:11.36741 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/state_machines-0.5.0/lib/state_machines/machine.rb:729:in `block (2 levels) in define_helper'
2019-04-08_20:33:11.36741 /opt/gitlab/embedded/service/gitlab-rails/ee/app/models/ee/group.rb:135:in `mark_ldap_sync_as_failed'
2019-04-08_20:33:11.36742 /opt/gitlab/embedded/service/gitlab-rails/ee/lib/ee/gitlab/auth/ldap/sync/group.rb:70:in `fail_stuck_group'
2019-04-08_20:33:11.36742 /opt/gitlab/embedded/service/gitlab-rails/ee/lib/ee/gitlab/auth/ldap/sync/group.rb:58:in `ldap_sync_ready?'
2019-04-08_20:33:11.36744 /opt/gitlab/embedded/service/gitlab-rails/ee/lib/ee/gitlab/auth/ldap/sync/group.rb:40:in `execute'
2019-04-08_20:33:11.36745 /opt/gitlab/embedded/service/gitlab-rails/ee/app/workers/ldap_group_sync_worker.rb:30:in `sync_group'
2019-04-08_20:33:11.36745 /opt/gitlab/embedded/service/gitlab-rails/ee/app/workers/ldap_group_sync_worker.rb:23:in `block in sync_groups'
2019-04-08_20:33:11.36745 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/relation/delegation.rb:38:in `each'
2019-04-08_20:33:11.36746 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activerecord-5.0.7.1/lib/active_record/relation/delegation.rb:38:in `each'
2019-04-08_20:33:11.36746 /opt/gitlab/embedded/service/gitlab-rails/ee/app/workers/ldap_group_sync_worker.rb:23:in `sync_groups'
2019-04-08_20:33:11.36746 /opt/gitlab/embedded/service/gitlab-rails/ee/app/workers/ldap_group_sync_worker.rb:14:in `block in perform'
2019-04-08_20:33:11.36746 /opt/gitlab/embedded/service/gitlab-rails/ee/lib/ee/gitlab/auth/ldap/sync/proxy.rb:17:in `block in open'
2019-04-08_20:33:11.36747 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/auth/ldap/adapter.rb:16:in `block in open'
2019-04-08_20:33:11.36747 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/net-ldap-0.16.0/lib/net/ldap.rb:644:in `block in open'
2019-04-08_20:33:11.36747 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/net-ldap-0.16.0/lib/net/ldap.rb:716:in `block in open'
2019-04-08_20:33:11.36748 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/net-ldap-0.16.0/lib/net/ldap/instrumentation.rb:19:in `instrument'
2019-04-08_20:33:11.36748 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/net-ldap-0.16.0/lib/net/ldap.rb:711:in `open'
2019-04-08_20:33:11.36748 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/net-ldap-0.16.0/lib/net/ldap.rb:644:in `open'
2019-04-08_20:33:11.36748 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/auth/ldap/adapter.rb:15:in `open'
2019-04-08_20:33:11.36749 /opt/gitlab/embedded/service/gitlab-rails/ee/lib/ee/gitlab/auth/ldap/sync/proxy.rb:16:in `open'
2019-04-08_20:33:11.36752 /opt/gitlab/embedded/service/gitlab-rails/ee/app/workers/ldap_group_sync_worker.rb:13:in `perform'
2019-04-08_20:33:11.36753 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:185:in `execute_job'
2019-04-08_20:33:11.36755 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:167:in `block (2 levels) in process'
2019-04-08_20:33:11.36756 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
2019-04-08_20:33:11.36756 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/metrics/sidekiq_middleware.rb:15:in `block in call'
2019-04-08_20:33:11.36756 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/metrics/transaction.rb:55:in `run'
2019-04-08_20:33:11.36757 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/metrics/sidekiq_middleware.rb:15:in `call'
2019-04-08_20:33:11.36757 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
2019-04-08_20:33:11.36757 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_status/server_middleware.rb:7:in `call'
2019-04-08_20:33:11.36758 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
2019-04-08_20:33:11.36758 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/correlation_logger.rb:10:in `block in call'
2019-04-08_20:33:11.36758 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/correlation_id.rb:15:in `use_id'
2019-04-08_20:33:11.36758 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/correlation_logger.rb:9:in `call'
2019-04-08_20:33:11.36759 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
2019-04-08_20:33:11.36759 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/batch_loader.rb:7:in `call'
2019-04-08_20:33:11.36761 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
2019-04-08_20:33:11.36762 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/request_store_middleware.rb:8:in `call'
2019-04-08_20:33:11.36762 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
2019-04-08_20:33:11.36762 /opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/memory_killer.rb:18:in `call'
2019-04-08_20:33:11.36763 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
2019-04-08_20:33:11.36763 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sentry-raven-2.7.4/lib/raven/integrations/sidekiq.rb:9:in `call'
2019-04-08_20:33:11.36763 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:130:in `block in invoke'
2019-04-08_20:33:11.36764 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/middleware/chain.rb:133:in `invoke'
2019-04-08_20:33:11.36764 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:166:in `block in process'
2019-04-08_20:33:11.36764 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
2019-04-08_20:33:11.36765 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/job_retry.rb:108:in `local'
2019-04-08_20:33:11.36765 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
2019-04-08_20:33:11.36765 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/rails.rb:43:in `block in call'
2019-04-08_20:33:11.36765 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/execution_wrapper.rb:85:in `wrap'
2019-04-08_20:33:11.36768 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/reloader.rb:68:in `block in wrap'
2019-04-08_20:33:11.36769 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/execution_wrapper.rb:85:in `wrap'
2019-04-08_20:33:11.36770 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/activesupport-5.0.7.1/lib/active_support/reloader.rb:67:in `wrap'
2019-04-08_20:33:11.36770 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/rails.rb:42:in `call'
2019-04-08_20:33:11.36772 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
2019-04-08_20:33:11.36773 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:243:in `stats'
2019-04-08_20:33:11.36773 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
2019-04-08_20:33:11.36774 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/job_logger.rb:8:in `call'
2019-04-08_20:33:11.36775 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
2019-04-08_20:33:11.36775 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/job_retry.rb:73:in `global'
2019-04-08_20:33:11.36775 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:125:in `block in dispatch'
2019-04-08_20:33:11.36776 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/logging.rb:48:in `with_context'
2019-04-08_20:33:11.36777 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
2019-04-08_20:33:11.36779 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:124:in `dispatch'
2019-04-08_20:33:11.36779 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:165:in `process'
2019-04-08_20:33:11.36779 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:83:in `process_one'
2019-04-08_20:33:11.36779 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/processor.rb:71:in `run'
2019-04-08_20:33:11.36780 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/util.rb:16:in `watchdog'
2019-04-08_20:33:11.36781 /opt/gitlab/embedded/lib/ruby/gems/2.5.0/gems/sidekiq-5.2.5/lib/sidekiq/util.rb:25:in `block in safe_thread'

Questions:

  1. Is the LDAP group sync happening inside a transaction? We saw one entry in the pg_stat_activity CSV log:
16394,"gitlabhq_prod_west",36739,16393,"GitlabAurora","sidekiq 5.2.5 gitlab-rails [0 of 30 busy]","144.70.116.66","",53848,"2019-04-08 16:30:43.042302+00","2019-04-08 16:49:41.960337+00","2019-04-08 16:49:42.090195+00","2019-04-08 16:50:05.541902+00","Client","ClientRead","idle in transaction","129637587","","UPDATE ""namespaces"" SET ""ldap_sync_status"" = 'ready', ""updated_at"" = '2019-04-08 16:49:42.090072' WHERE ""namespaces"".""id"" = 20091"
  1. Should there be some lock in the DB/Redis to prevent other group sync workers from trying to run at the same time?

  2. Should we enable idle in transaction timeouts by default to avoid this from happening?

Edited Apr 08, 2019 by Stan Hu
Assignee Loading
Time tracking Loading