Debug gitlab transactions stack
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.
-
I have evaluated the MR acceptance checklist for this MR.