Request timeout for Protected Branches creation API
Everyone can contribute. Help move this issue forward while earning points, leveling up and collecting rewards.
Error
Sentry error: https://new-sentry.gitlab.net/organizations/gitlab/issues/173/events/d4d5b2450dcb42619c0e172a310b3269/?project=3
POST /api/:version/projects/:id/protected_branches
Rack::Timeout::RequestTimeoutException: Request ran for longer than 60000ms
from activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:768:in `exec_params'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:768:in `block (2 levels) in exec_no_cache'
from activesupport (7.0.8.1) lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
from activesupport (7.0.8.1) lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:767:in `block in exec_no_cache'
from activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
from activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
from activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
from activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract_adapter.rb:752:in `block in log'
from activesupport (7.0.8.1) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract_adapter.rb:743:in `log'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:766:in `exec_no_cache'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:745:in `execute_and_clear'
from marginalia (1.11.1) lib/marginalia.rb:91:in `execute_and_clear_with_marginalia'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql/database_statements.rb:54:in `exec_query'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/database_statements.rb:560:in `select'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/database_statements.rb:66:in `select_all'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/query_cache.rb:107:in `block in select_all'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/query_cache.rb:137:in `block in cache_sql'
from activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
from activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
from activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
from activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/query_cache.rb:128:in `cache_sql'
from activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/query_cache.rb:107:in `select_all'
from lib/gitlab/database/load_balancing/connection_proxy.rb:107:in `public_send'
from lib/gitlab/database/load_balancing/connection_proxy.rb:107:in `block in read_using_load_balancer'
from lib/gitlab/database/load_balancing/load_balancer.rb:141:in `block in read_write'
from lib/gitlab/database/load_balancing/load_balancer.rb:235:in `retry_with_backoff'
from lib/gitlab/database/load_balancing/load_balancer.rb:130:in `read_write'
from lib/gitlab/database/load_balancing/connection_proxy.rb:106:in `read_using_load_balancer'
from lib/gitlab/database/load_balancing/connection_proxy.rb:48:in `select_all'
from activerecord (7.0.8.1) lib/active_record/querying.rb:54:in `_query_by_sql'
from app/models/concerns/use_sql_function_for_primary_key_lookups.rb:8:in `_query_by_sql'
from activerecord (7.0.8.1) lib/active_record/relation.rb:942:in `block in exec_main_query'
from activerecord (7.0.8.1) lib/active_record/relation.rb:962:in `skip_query_cache_if_necessary'
from activerecord (7.0.8.1) lib/active_record/relation.rb:928:in `exec_main_query'
from activerecord (7.0.8.1) lib/active_record/relation.rb:914:in `block in exec_queries'
from activerecord (7.0.8.1) lib/active_record/relation.rb:962:in `skip_query_cache_if_necessary'
from activerecord (7.0.8.1) lib/active_record/relation.rb:908:in `exec_queries'
from gems/activerecord-gitlab/lib/active_record/gitlab_patches/rescue_from.rb:31:in `exec_queries'
from activerecord (7.0.8.1) lib/active_record/relation.rb:695:in `load'
from activerecord (7.0.8.1) lib/active_record/relation.rb:250:in `records'
from activerecord (7.0.8.1) lib/active_record/relation/delegation.rb:88:in `each'
from activerecord (7.0.8.1) lib/active_record/relation/query_methods.rb:318:in `select'
from activerecord (7.0.8.1) lib/active_record/relation/query_methods.rb:318:in `select'
from ee/lib/gitlab/code_owners/entry.rb:46:in `add_matching_groups_from'
from ee/lib/gitlab/code_owners/groups_loader.rb:14:in `block in load_to'
from ee/lib/gitlab/code_owners/groups_loader.rb:13:in `each'
from ee/lib/gitlab/code_owners/groups_loader.rb:13:in `load_to'
from ee/lib/gitlab/code_owners/loader.rb:26:in `block in entries'
from gems/gitlab-utils/lib/gitlab/utils/strong_memoize.rb:34:in `strong_memoize'
from ee/lib/gitlab/code_owners/loader.rb:17:in `entries'
from ee/lib/gitlab/code_owners.rb:42:in `entries_for_merge_request'
from ee/app/services/merge_requests/sync_code_owner_approval_rules.rb:56:in `code_owner_entries'
from ee/app/services/merge_requests/sync_code_owner_approval_rules.rb:51:in `patterns'
from ee/app/services/merge_requests/sync_code_owner_approval_rules.rb:16:in `execute'
from ee/app/services/ee/protected_branches/create_service.rb:37:in `block in sync_code_owner_approval_rules'
from ee/app/services/ee/protected_branches/create_service.rb:36:in `each'
from ee/app/services/ee/protected_branches/create_service.rb:36:in `sync_code_owner_approval_rules'
from ee/app/services/ee/protected_branches/create_service.rb:26:in `save_protected_branch'
from app/services/protected_branches/create_service.rb:8:in `execute'
from ee/app/services/ee/protected_branches/create_service.rb:12:in `execute'
from app/services/protected_branches/api_service.rb:6:in `create'
{
"json": {
"params": [
{
"key": "name",
"value": "master"
},
{
"key": "allowed_to_merge",
"value": "[{\"access_level\"=>30}]"
},
{
"key": "push_access_level",
"value": "0"
},
{
"key": "allowed_to_unprotect",
"value": "[{\"access_level\"=>40}]"
}
],
"json.db_main_count": [
14498
],
"json.ua": [
"python-gitlab/4.5.0"
],
"json.meta.caller_id.keyword": [
"POST /api/:version/projects/:id/protected_branches"
],
"json.params.key.keyword": [
"name",
"allowed_to_merge",
"push_access_level",
"allowed_to_unprotect"
],
"json.exception.backtrace": [
"lib/gitlab/database.rb:392:in `commit'",
"lib/gitlab/database/load_balancing/connection_proxy.rb:127:in `public_send'",
"lib/gitlab/database/load_balancing/connection_proxy.rb:127:in `block in write_using_load_balancer'",
"lib/gitlab/database/load_balancing/load_balancer.rb:141:in `block in read_write'",
"lib/gitlab/database/load_balancing/load_balancer.rb:235:in `retry_with_backoff'",
"lib/gitlab/database/load_balancing/load_balancer.rb:130:in `read_write'",
"lib/gitlab/database/load_balancing/connection_proxy.rb:126:in `write_using_load_balancer'",
"lib/gitlab/database/load_balancing/connection_proxy.rb:78:in `transaction'",
"ee/app/services/merge_requests/sync_code_owner_approval_rules.rb:30:in `block in execute'",
"ee/app/services/merge_requests/sync_code_owner_approval_rules.rb:21:in `each'",
"ee/app/services/merge_requests/sync_code_owner_approval_rules.rb:21:in `filter_map'",
"ee/app/services/merge_requests/sync_code_owner_approval_rules.rb:21:in `execute'",
"ee/app/services/ee/protected_branches/create_service.rb:37:in `block in sync_code_owner_approval_rules'",
"ee/app/services/ee/protected_branches/create_service.rb:36:in `each'",
"ee/app/services/ee/protected_branches/create_service.rb:36:in `sync_code_owner_approval_rules'",
"ee/app/services/ee/protected_branches/create_service.rb:26:in `save_protected_branch'",
"app/services/protected_branches/create_service.rb:8:in `execute'",
"ee/app/services/ee/protected_branches/create_service.rb:12:in `execute'",
"app/services/protected_branches/api_service.rb:6:in `create'",
"lib/api/protected_branches.rb:101:in `block (2 levels) in <class:ProtectedBranches>'",
"ee/lib/gitlab/middleware/ip_restrictor.rb:14:in `block in call'",
"ee/lib/gitlab/ip_address_state.rb:10:in `with'",
"ee/lib/gitlab/middleware/ip_restrictor.rb:13:in `call'",
"lib/api/api_guard.rb:219:in `call'",
"ee/lib/omni_auth/strategies/group_saml.rb:41:in `other_phase'",
"lib/gitlab/metrics/elasticsearch_rack_middleware.rb:16:in `call'",
"lib/gitlab/middleware/sidekiq_shard_awareness_validation.rb:20:in `block in call'",
"lib/gitlab/sidekiq_sharding/validator.rb:42:in `enabled'",
"lib/gitlab/middleware/sidekiq_shard_awareness_validation.rb:20:in `call'",
"lib/gitlab/middleware/memory_report.rb:13:in `call'",
"lib/gitlab/middleware/speedscope.rb:13:in `call'",
"lib/gitlab/database/load_balancing/rack_middleware.rb:23:in `call'",
"lib/gitlab/middleware/rails_queue_duration.rb:33:in `call'",
"lib/gitlab/etag_caching/middleware.rb:21:in `call'",
"lib/gitlab/metrics/rack_middleware.rb:16:in `block in call'",
"lib/gitlab/metrics/web_transaction.rb:46:in `run'",
"lib/gitlab/metrics/rack_middleware.rb:16:in `call'",
"lib/gitlab/middleware/go.rb:20:in `call'",
"lib/gitlab/middleware/query_analyzer.rb:11:in `block in call'",
"lib/gitlab/database/query_analyzer.rb:40:in `within'",
"lib/gitlab/middleware/query_analyzer.rb:11:in `call'",
"lib/gitlab/middleware/organizations/current.rb:20:in `call'",
"lib/gitlab/middleware/multipart.rb:173:in `call'",
"lib/gitlab/middleware/read_only/controller.rb:50:in `call'",
"lib/gitlab/middleware/read_only.rb:18:in `call'",
"lib/gitlab/middleware/unauthenticated_session_expiry.rb:18:in `call'",
"lib/gitlab/middleware/same_site_cookies.rb:27:in `call'",
"lib/gitlab/middleware/path_traversal_check.rb:14:in `call'",
"lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'",
"lib/gitlab/middleware/basic_health_check.rb:25:in `call'",
"lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'",
"lib/gitlab/middleware/request_context.rb:15:in `call'",
"lib/gitlab/middleware/webhook_recursion_detection.rb:15:in `call'",
"config/initializers/fix_local_cache_middleware.rb:11:in `call'",
"lib/gitlab/middleware/compressed_json.rb:44:in `call'",
"lib/gitlab/middleware/rack_multipart_tempfile_factory.rb:19:in `call'",
"lib/gitlab/middleware/sidekiq_web_static.rb:20:in `call'",
"lib/gitlab/metrics/requests_rack_middleware.rb:79:in `call'",
"lib/gitlab/middleware/release_env.rb:13:in `call'"
],
"json.db_duration_s": [
26.61152
],
"json.view_duration_s": [
33.51382
],
"json.params.key": [
"name",
"allowed_to_merge",
"push_access_level",
"allowed_to_unprotect"
],
"json.exception.message": [
"Request ran for longer than 60000ms "
],
"json.path.keyword": [
"/api/v4/projects/57832508/protected_branches"
],
"json.meta.user.keyword": [
"group_51205714_bot_6b6b9e9b6b6660fca6da67ca846f6c3d"
],
"json.db_primary_count": [
14498
],
"json.db_write_count": [
1393
],
"json.path": [
"/api/v4/projects/<project_id>/protected_branches"
],
"json.cpu_s": [
36.03842
],
"json.subcomponent": [
"api_json"
],
"json.db_main_duration_s": [
24.448
],
"json.method": [
"POST"
],
},
}DB investigation
Number of DB request db_count - 14498.
It's extremely high for this endpoint.
Analysis of why it happens is in this comment
Kibana: https://log.gprd.gitlab.net/app/r/s/tBK30
Fixes considered
Updating the MRs asynchronously
Draft: Sync code owner approval rules async (!155309 - closed) proposed to resolve the issue by making the updates asynchronous instead of synchronous.
There was concern from multiple team members about second-order effects of making the syncing asynchronous, so the MR has been put back in draft while other options are explored.
Concerns:
Resolve through re-architecture
re-architecture epic: Rearchitecting Approval Rules (&12955)
Right now this seems like our best approach because:
-
it's expected that the re-architecture will improve performance in this domain.
-
if re-architecture speeds up operations enough to fix the time out, this issue will be resolved through the re-architecture and no further action would be needed.
-
trying to address this separately from the re-architecture will increase complexity and risk to the re-architecture. Given this is an s3 that risk does not seem worthwhile.
Next steps
-
Once Rearchitecting Approval Rules (&12955) is done, we should check Sentry to see if the timeouts are resolved and then close the issue if they are.
Edited by 🤖 GitLab Bot 🤖