Timeout exception when removing a billable member via the API/UI
Summary
When utilizing the remove billable member API call, a Rack::Timeout::RequestTimeoutException can occur if the user has membership within a large number of projects.
This same exception occurs when attempting to remove the user via the UI.
Steps to reproduce
Perform the relevant request on a user with membership in a large number of projects. This occurred in this ticket (internal use) for a user who had 1,000+ project memberships.
What is the current bug behavior?
Attempting to remove a billable member via this call can result in a Rack::Timeout::RequestTimeoutException with the user's memberships remaining unaffected.
What is the expected correct behavior?
The request is appropriately processed and the target user memberships are removed.
Relevant logs and/or screenshots
Logs can be seen (for now) in Kibana (internal use). Otherwise, the exception can be seen below.
Exception logs
"json": {
"exception.class": "Rack::Timeout::RequestTimeoutException",
"exception.message": "Request ran for longer than 60000ms ",
"method": "DELETE",
"route": "/api/:version/groups/:id/billable_members/:user_id",
"meta.caller_id": "DELETE /api/:version/groups/:id/billable_members/:user_id",
"exception.backtrace": [
"activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:768:in `exec_params'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:768:in `block (2 levels) in exec_no_cache'",
"activesupport (7.0.8.1) lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'",
"activesupport (7.0.8.1) lib/active_support/dependencies/interlock.rb:41:in `permit_concurrent_loads'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:767:in `block in exec_no_cache'",
"activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'",
"activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'",
"activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'",
"activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract_adapter.rb:752:in `block in log'",
"activesupport (7.0.8.1) lib/active_support/notifications/instrumenter.rb:24:in `instrument'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract_adapter.rb:743:in `log'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:766:in `exec_no_cache'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql_adapter.rb:745:in `execute_and_clear'",
"marginalia (1.11.1) lib/marginalia.rb:91:in `execute_and_clear_with_marginalia'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/postgresql/database_statements.rb:54:in `exec_query'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/database_statements.rb:560:in `select'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/database_statements.rb:66:in `select_all'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/query_cache.rb:107:in `block in select_all'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/query_cache.rb:137:in `block in cache_sql'",
"activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'",
"activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'",
"activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'",
"activesupport (7.0.8.1) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/query_cache.rb:128:in `cache_sql'",
"activerecord (7.0.8.1) lib/active_record/connection_adapters/abstract/query_cache.rb:107:in `select_all'",
"lib/gitlab/database/load_balancing/connection_proxy.rb:107:in `public_send'",
"lib/gitlab/database/load_balancing/connection_proxy.rb:107:in `block in read_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:106:in `read_using_load_balancer'",
"lib/gitlab/database/load_balancing/connection_proxy.rb:48:in `select_all'",
"activerecord (7.0.8.1) lib/active_record/relation/calculations.rb:250:in `block in pluck'",
"activerecord (7.0.8.1) lib/active_record/relation.rb:962:in `skip_query_cache_if_necessary'",
"activerecord (7.0.8.1) lib/active_record/relation/calculations.rb:246:in `pluck'",
"lockbox (1.3.0) lib/lockbox/calculations.rb:4:in `pluck'",
"ee/app/finders/namespaces/billed_users_finder.rb:34:in `block in calculate_user_ids'",
"lib/gitlab/database.rb:217:in `allow_cross_joins_across_databases'",
"ee/app/finders/namespaces/billed_users_finder.rb:32:in `calculate_user_ids'",
"ee/app/finders/namespaces/billed_users_finder.rb:13:in `block in execute'",
"ee/app/finders/namespaces/billed_users_finder.rb:12:in `each_key'",
"ee/app/finders/namespaces/billed_users_finder.rb:12:in `execute'",
"ee/app/models/ee/group.rb:1070:in `block in billed_user_ids_including_guests'",
"gems/gitlab-utils/lib/gitlab/utils/strong_memoize.rb:34:in `strong_memoize'",
"ee/app/models/ee/group.rb:1069:in `billed_user_ids_including_guests'",
"ee/app/models/ee/group.rb:597:in `billed_user_ids'",
"ee/app/models/ee/user.rb:464:in `using_gitlab_com_seat?'",
"ee/app/models/ee/member.rb:154:in `is_using_seat'",
"ee/app/services/ee/members/destroy_service.rb:22:in `after_execute'",
"app/services/members/destroy_service.rb:101:in `delete_member_associations'",
"app/services/members/destroy_service.rb:85:in `destroy_data_related_to_member'",
"ee/app/services/ee/members/destroy_service.rb:112:in `destroy_data_related_to_member'",
"app/services/members/destroy_service.rb:29:in `execute'",
"ee/app/services/billable_members/destroy_service.rb:45:in `block in remove_user_from_resources'",
"activerecord (7.0.8.1) lib/active_record/relation/batches.rb:71:in `each'",
"activerecord (7.0.8.1) lib/active_record/relation/batches.rb:71:in `block in find_each'",
"activerecord (7.0.8.1) lib/active_record/relation/batches.rb:138:in `block in find_in_batches'",
"activerecord (7.0.8.1) lib/active_record/relation/batches.rb:245:in `block in in_batches'",
"activerecord (7.0.8.1) lib/active_record/relation/batches.rb:229:in `loop'",
"activerecord (7.0.8.1) lib/active_record/relation/batches.rb:229:in `in_batches'",
"activerecord (7.0.8.1) lib/active_record/relation/batches.rb:137:in `find_in_batches'",
"activerecord (7.0.8.1) lib/active_record/relation/batches.rb:70:in `find_each'",
"ee/app/services/billable_members/destroy_service.rb:43:in `remove_user_from_resources'",
"ee/app/services/billable_members/destroy_service.rb:27:in `execute'",
"ee/lib/ee/api/members.rb:227:in `block (3 levels) in <module:Members>'",
"grape (2.0.0) lib/grape/endpoint.rb:58:in `call'",
"grape (2.0.0) lib/grape/endpoint.rb:58:in `block (2 levels) in generate_api_method'",
"activesupport (7.0.8.1) lib/active_support/notifications.rb:208:in `instrument'",
"grape (2.0.0) lib/grape/endpoint.rb:57:in `block in generate_api_method'",
"grape (2.0.0) lib/grape/endpoint.rb:328:in `execute'",
"grape (2.0.0) lib/grape/endpoint.rb:260:in `block in run'",
"activesupport (7.0.8.1) lib/active_support/notifications.rb:208:in `instrument'",
"grape (2.0.0) lib/grape/endpoint.rb:240:in `run'",
"grape (2.0.0) lib/grape/endpoint.rb:316:in `block in build_stack'",
"grape (2.0.0) lib/grape/middleware/base.rb:36:in `call!'",
"grape (2.0.0) lib/grape/middleware/base.rb:29:in `call'",
"grape (2.0.0) lib/grape/middleware/base.rb:36:in `call!'",
"grape (2.0.0) lib/grape/middleware/base.rb:29:in `call'",
"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'",
"grape (2.0.0) lib/grape/middleware/base.rb:36:in `call!'",
"grape (2.0.0) lib/grape/middleware/base.rb:29:in `call'",
"lib/api/api_guard.rb:219:in `call'",
"grape (2.0.0) lib/grape/middleware/base.rb:36:in `call!'",
"grape (2.0.0) lib/grape/middleware/base.rb:29:in `call'",
"rack-oauth2 (1.21.3) lib/rack/oauth2/server/resource.rb:20:in `_call'",
"rack-oauth2 (1.21.3) lib/rack/oauth2/server/resource/bearer.rb:8:in `_call'",
"rack-oauth2 (1.21.3) lib/rack/oauth2/server/abstract/handler.rb:17:in `call'",
"grape (2.0.0) lib/grape/middleware/error.rb:39:in `block in call!'",
"grape (2.0.0) lib/grape/middleware/error.rb:38:in `catch'",
"grape (2.0.0) lib/grape/middleware/error.rb:38:in `call!'",
"grape (2.0.0) lib/grape/middleware/base.rb:29:in `call'",
"grape_logging (1.8.4) lib/grape_logging/middleware/request_logger.rb:60:in `block in call!'",
"grape_logging (1.8.4) lib/grape_logging/middleware/request_logger.rb:58:in `catch'",
"grape_logging (1.8.4) lib/grape_logging/middleware/request_logger.rb:58:in `call!'",
"grape (2.0.0) lib/grape/middleware/base.rb:29:in `call'",
"rack (2.2.8.1) lib/rack/head.rb:12:in `call'",
"grape (2.0.0) lib/grape/endpoint.rb:224:in `call!'",
"grape (2.0.0) lib/grape/endpoint.rb:218:in `call'",
"grape (2.0.0) lib/grape/router/route.rb:58:in `exec'",
"grape (2.0.0) lib/grape/router.rb:120:in `process_route'",
"grape (2.0.0) lib/grape/router.rb:74:in `block in identity'",
"grape (2.0.0) lib/grape/router.rb:94:in `transaction'",
"grape (2.0.0) lib/grape/router.rb:72:in `identity'",
"grape (2.0.0) lib/grape/router.rb:56:in `block in call'",
"grape (2.0.0) lib/grape/router.rb:136:in `with_optimization'",
"grape (2.0.0) lib/grape/router.rb:55:in `call'",
"grape (2.0.0) lib/grape/api/instance.rb:165:in `call'",
"grape (2.0.0) lib/grape/api/instance.rb:70:in `call!'",
"grape (2.0.0) lib/grape/api/instance.rb:65:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'",
"actionpack (7.0.8.1) lib/action_dispatch/routing/mapper.rb:48:in `serve'",
"actionpack (7.0.8.1) lib/action_dispatch/journey/router.rb:50:in `block in serve'",
"actionpack (7.0.8.1) lib/action_dispatch/journey/router.rb:32:in `each'",
"actionpack (7.0.8.1) lib/action_dispatch/journey/router.rb:32:in `serve'",
"actionpack (7.0.8.1) lib/action_dispatch/routing/route_set.rb:852:in `call'",
"gitlab-experiment (0.9.1) lib/gitlab/experiment/middleware.rb:19:in `call'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:202:in `call!'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:169:in `call'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:470:in `call_app!'",
"ee/lib/omni_auth/strategies/group_saml.rb:41:in `other_phase'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:195:in `call!'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:169:in `call'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:202:in `call!'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:169:in `call'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:202:in `call!'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:169:in `call'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:202:in `call!'",
"omniauth (2.1.0) lib/omniauth/strategy.rb:169:in `call'",
"flipper (0.26.2) lib/flipper/middleware/memoizer.rb:72:in `memoized_call'",
"flipper (0.26.2) lib/flipper/middleware/memoizer.rb:37:in `call'",
"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'",
"batch-loader (2.0.5) lib/batch_loader/middleware.rb:11:in `call'",
"rack-attack (6.7.0) lib/rack/attack.rb:103:in `call'",
"apollo_upload_server (2.1.6) lib/apollo_upload_server/middleware.rb:19:in `call'",
"lib/gitlab/middleware/multipart.rb:173:in `call'",
"rack-attack (6.7.0) lib/rack/attack.rb:127:in `call'",
"warden (1.2.9) lib/warden/manager.rb:36:in `block in call'",
"warden (1.2.9) lib/warden/manager.rb:34:in `catch'",
"warden (1.2.9) lib/warden/manager.rb:34:in `call'",
"rack-cors (2.0.1) lib/rack/cors.rb:102:in `call'",
"rack (2.2.8.1) lib/rack/tempfile_reaper.rb:15:in `call'",
"rack (2.2.8.1) lib/rack/etag.rb:27:in `call'",
"rack (2.2.8.1) lib/rack/conditional_get.rb:40:in `call'",
"rack (2.2.8.1) lib/rack/head.rb:12:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/http/permissions_policy.rb:38:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/http/content_security_policy.rb:36: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'",
"rack (2.2.8.1) lib/rack/session/abstract/id.rb:266:in `context'",
"rack (2.2.8.1) lib/rack/session/abstract/id.rb:260:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/cookies.rb:704:in `call'",
"lib/gitlab/middleware/same_site_cookies.rb:27:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'",
"activesupport (7.0.8.1) lib/active_support/callbacks.rb:99:in `run_callbacks'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/callbacks.rb:26:in `call'",
"sentry-rails (5.17.3) lib/sentry/rails/rescued_exception_interceptor.rb:12:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'",
"lib/gitlab/middleware/path_traversal_check.rb:21:in `call'",
"lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'",
"sentry-ruby (5.17.3) lib/sentry/rack/capture_exceptions.rb:29:in `block (2 levels) in call'",
"sentry-ruby (5.17.3) lib/sentry/hub.rb:251:in `with_session_tracking'",
"sentry-ruby (5.17.3) lib/sentry-ruby.rb:403:in `with_session_tracking'",
"sentry-ruby (5.17.3) lib/sentry/rack/capture_exceptions.rb:20:in `block in call'",
"sentry-ruby (5.17.3) lib/sentry/hub.rb:59:in `with_scope'",
"sentry-ruby (5.17.3) lib/sentry-ruby.rb:383:in `with_scope'",
"sentry-ruby (5.17.3) lib/sentry/rack/capture_exceptions.rb:19:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/show_exceptions.rb:29:in `call'",
"lib/gitlab/middleware/basic_health_check.rb:25:in `call'",
"lograge (0.11.2) lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'",
"railties (7.0.8.1) lib/rails/rack/logger.rb:25:in `block in call'",
"activesupport (7.0.8.1) lib/active_support/tagged_logging.rb:99:in `block in tagged'",
"activesupport (7.0.8.1) lib/active_support/tagged_logging.rb:37:in `tagged'",
"activesupport (7.0.8.1) lib/active_support/tagged_logging.rb:99:in `tagged'",
"railties (7.0.8.1) lib/rails/rack/logger.rb:25:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/remote_ip.rb:93: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'",
"request_store (1.5.1) lib/request_store/middleware.rb:19:in `call'",
"rack (2.2.8.1) lib/rack/method_override.rb:24:in `call'",
"rack (2.2.8.1) lib/rack/runtime.rb:22:in `call'",
"rack-timeout (0.6.3) lib/rack/timeout/core.rb:148:in `block in call'",
"rack-timeout (0.6.3) lib/rack/timeout/support/timeout.rb:19:in `timeout'",
"rack-timeout (0.6.3) lib/rack/timeout/core.rb:147:in `call'",
"config/initializers/fix_local_cache_middleware.rb:11:in `call'",
"lib/gitlab/middleware/compressed_json.rb:44:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/executor.rb:14:in `call'",
"lib/gitlab/middleware/rack_multipart_tempfile_factory.rb:19:in `call'",
"rack (2.2.8.1) lib/rack/sendfile.rb:110:in `call'",
"lib/gitlab/middleware/sidekiq_web_static.rb:20:in `call'",
"lib/gitlab/metrics/requests_rack_middleware.rb:79:in `call'",
"gitlab-labkit (0.36.0) lib/labkit/middleware/rack.rb:22:in `block in call'",
"gitlab-labkit (0.36.0) lib/labkit/context.rb:35:in `with_context'",
"gitlab-labkit (0.36.0) lib/labkit/middleware/rack.rb:21:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/request_id.rb:26:in `call'",
"actionpack (7.0.8.1) lib/action_dispatch/middleware/host_authorization.rb:131:in `call'",
"railties (7.0.8.1) lib/rails/engine.rb:530:in `call'",
"railties (7.0.8.1) lib/rails/railtie.rb:226:in `public_send'",
"railties (7.0.8.1) lib/rails/railtie.rb:226:in `method_missing'",
"lib/gitlab/middleware/release_env.rb:13:in `call'",
"rack (2.2.8.1) lib/rack/urlmap.rb:74:in `block in call'",
"rack (2.2.8.1) lib/rack/urlmap.rb:58:in `each'",
"rack (2.2.8.1) lib/rack/urlmap.rb:58:in `call'",
"puma (6.4.0) lib/puma/configuration.rb:272:in `call'",
"puma (6.4.0) lib/puma/request.rb:100:in `block in handle_request'",
"puma (6.4.0) lib/puma/thread_pool.rb:378:in `with_force_shutdown'",
"puma (6.4.0) lib/puma/request.rb:99:in `handle_request'",
"puma (6.4.0) lib/puma/server.rb:443:in `process_client'",
"puma (6.4.0) lib/puma/server.rb:241:in `block in run'",
"puma (6.4.0) lib/puma/thread_pool.rb:155:in `block in spawn_thread'"
]
}Output of checks
This bug happens on GitLab.com
Possible fixes
Iteration Plan
- Wait for [Gitlab.com] Automatic removal of dormant members (&7533) to be complete. This will help remove billable members without having to leverage the API/UI.
- The actual longer term fix to the timeout problem when removing billable members will involve optimizing the members tables:
- Once
2is complete, then this problem outlined in this issue should no longer be a problem
Initial Iteration Plan
Phase 1: immediate customer concerns
-
backend: Create background job for billable member deletion
- deduplicate the job (incase of deletion spam)
- consider overall run time - we might want a limited capacity worker or to modify worker approach accordingly
-
backend: Modify API endpoint to support async
- new param to indicate async
- trigger async job
- return appropriate response (e.g. a helpful message to explain delayed deletion)
Phase 2: UI (to be split into a separate issue and deferred until API is available)
Edited by Alex Martin