Skip to content

Debug gitlab transactions stack

Thong Kuah requested to merge debug_gitlab_transactions_stack into master

What does this MR do and why?

Describe in detail what your merge request does and why.

To help troubleshoot flaky failures caused by CrossDatabaseModificationAcrossUnsupportedTablesError in CI, we log each action to the gitlab_transactions_stack to help determine where it went wrong

  • everytime we push to the stack
  • everytime we pop from the stack
  • when we think we have reached the end of the transaction
  • after each example.

So far the flakiness seems to be only happening on system specs, so I have only enabled this logging for system specs.

To run locally:

DEBUG_GITLAB_TRANSACTION_STACK=1 bin/rspec spec/features/project_variables_spec.rb

Then check:

tail -f log/gitlab_transaction_stack.log

Related issue: #351531 (closed)

Screenshots or screen recordings

These are strongly recommended to assist reviewers and reduce the time to merge your change.

Example log:

{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["app/models/concerns/cross_database_modification.rb:38:in `initialize'","app/models/concerns/cross_database_modification.rb:83:in `new'","app/models/concerns/cross_database_modification.rb:83:in `block in transaction'","lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["app/models/concerns/cross_database_modification.rb:45:in `done!'","app/models/concerns/cross_database_modification.rb:90:in `block in transaction'","lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/concerns/cross_database_modification.rb:79:in `transaction'"],"thread":20520}
{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["app/models/concerns/cross_database_modification.rb:38:in `initialize'","app/models/concerns/cross_database_modification.rb:83:in `new'","app/models/concerns/cross_database_modification.rb:83:in `block in transaction'","lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["app/models/concerns/cross_database_modification.rb:45:in `done!'","app/models/concerns/cross_database_modification.rb:90:in `block in transaction'","lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/concerns/cross_database_modification.rb:79:in `transaction'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["spec/features/project_variables_spec.rb:8:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:417:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:408:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["spec/factories/namespaces.rb:19:in `block (3 levels) in \u003cmain\u003e'","spec/features/project_variables_spec.rb:8:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:417:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'"],"thread":20520}
{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["app/models/concerns/cross_database_modification.rb:38:in `initialize'","app/models/concerns/cross_database_modification.rb:83:in `new'","app/models/concerns/cross_database_modification.rb:83:in `block in transaction'","lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["app/models/concerns/cross_database_modification.rb:45:in `done!'","app/models/concerns/cross_database_modification.rb:90:in `block in transaction'","lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/concerns/cross_database_modification.rb:79:in `transaction'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["spec/features/project_variables_spec.rb:8:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:417:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:408:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["app/services/members/creator_service.rb:46:in `update_member'","app/services/members/creator_service.rb:28:in `execute'","app/models/project_team.rb:60:in `add_user'","ee/app/models/ee/project_team.rb:21:in `add_user'","app/models/project_team.rb:23:in `add_maintainer'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["spec/factories/projects.rb:110:in `block (3 levels) in \u003cmain\u003e'","spec/features/project_variables_spec.rb:8:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:417:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["spec/features/project_variables_spec.rb:8:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:417:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:408:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_ci"],"caller":["app/models/concerns/cross_database_modification.rb:38:in `initialize'","app/models/concerns/cross_database_modification.rb:83:in `new'","app/models/concerns/cross_database_modification.rb:83:in `block in transaction'","lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_ci"],"caller":["app/models/concerns/cross_database_modification.rb:45:in `done!'","app/models/concerns/cross_database_modification.rb:90:in `block in transaction'","lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/concerns/cross_database_modification.rb:79:in `transaction'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/concerns/cross_database_modification.rb:79:in `transaction'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:417:in `block (3 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["app/services/users/activity_service.rb:36:in `record_activity'","app/services/users/activity_service.rb:20:in `block in execute'","app/services/users/activity_service.rb:20:in `execute'","lib/api/api.rb:153:in `block (2 levels) in \u003cclass:API\u003e'","ee/lib/gitlab/ip_address_state.rb:10:in `with'"],"thread":1111860}
{"message":"gitlab_transactions_stack performing after_example in example reveals and hides variables","action":"after_example","gitlab_transactions_stack":[],"caller":["spec/spec_helper.rb:122:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:417:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:408:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:404:in `block (3 levels) in \u003ctop (required)\u003e'"],"thread":20520}

How to set up and validate locally

Numbered steps to set up and validate the change are strongly suggested.

MR acceptance checklist

This checklist encourages us to confirm any changes have been analyzed to reduce risks in quality, performance, reliability, security, and maintainability.

Edited by Thong Kuah

Merge request reports