Skip to content

Improve preciseness of transaction stack logging

Thong Kuah requested to merge improve_transactions_stack_logging into master

What does this MR do and why?

Extending !79709 (merged), we improve the precision of the caller tracing so that we can see better where calls are being made from.

To test locally:

DEBUG_GITLAB_TRANSACTION_STACK=true bin/rspec spec/features/project_variables_spec.rb[1:1:10]

Related issue: #351531 (closed)

Screenshots or screen recordings

{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:6:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:6:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/services/emails/create_service.rb:8:in `execute'","ee/app/services/ee/emails/create_service.rb:10:in `execute'","app/models/user.rb:2073:in `add_primary_email_to_emails!'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/services/emails/create_service.rb:8:in `execute'","ee/app/services/ee/emails/create_service.rb:10:in `execute'","app/models/user.rb:2073:in `add_primary_email_to_emails!'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["spec/features/project_variables_spec.rb:6:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:12:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:403:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:7:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:7:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/services/emails/create_service.rb:8:in `execute'","ee/app/services/ee/emails/create_service.rb:10:in `execute'","app/models/user.rb:2073:in `add_primary_email_to_emails!'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/services/emails/create_service.rb:8:in `execute'","ee/app/services/ee/emails/create_service.rb:10:in `execute'","app/models/user.rb:2073:in `add_primary_email_to_emails!'"],"thread":20520}
{"message":"gitlab_transactions_stack performing end_of_transaction","action":"end_of_transaction","gitlab_transactions_stack":[],"caller":["spec/features/project_variables_spec.rb:7:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:13:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:403: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:7:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:13:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412: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":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:7:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:7: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/features/project_variables_spec.rb:7:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:13:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:403: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:7:in `block (2 levels) in \u003ctop (required)\u003e'","spec/features/project_variables_spec.rb:13:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412: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":["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":["app/models/user.rb:1678:in `global_notification_setting'","app/models/notification_recipient.rb:164:in `find_notification_setting'","app/models/notification_recipient.rb:25:in `notification_setting'","app/models/notification_recipient.rb:29:in `notification_level'","app/models/notification_recipient.rb:51:in `suitable_notification_level?'"],"thread":20520}
{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:8:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:8:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing after_push","action":"after_push","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/services/emails/create_service.rb:8:in `execute'","ee/app/services/ee/emails/create_service.rb:10:in `execute'","app/models/user.rb:2073:in `add_primary_email_to_emails!'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/services/emails/create_service.rb:8:in `execute'","ee/app/services/ee/emails/create_service.rb:10:in `execute'","app/models/user.rb:2073:in `add_primary_email_to_emails!'"],"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:412:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:403: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:412: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":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:8:in `block (2 levels) in \u003ctop (required)\u003e'"],"thread":20520}
{"message":"gitlab_transactions_stack performing before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_main"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","app/models/namespace/traversal_hierarchy.rb:41:in `sync_traversal_ids!'","app/models/namespaces/traversal/linear.rb:189:in `sync_traversal_ids'","spec/features/project_variables_spec.rb:8: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/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:412:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:403: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:412: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:412:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:403: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":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412: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 before_pop","action":"before_pop","gitlab_transactions_stack":["gitlab_ci"],"caller":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412: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":["lib/gitlab/database.rb:265:in `block in transaction'","lib/gitlab/database.rb:264:in `transaction'","spec/features/project_variables_spec.rb:14:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412: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_example in example shows a validation error box about duplicate keys","action":"after_example","gitlab_transactions_stack":[],"caller":["spec/spec_helper.rb:122:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:412:in `block (3 levels) in \u003ctop (required)\u003e'","spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'","spec/spec_helper.rb:403:in `block (2 levels) in \u003ctop (required)\u003e'","spec/spec_helper.rb:399: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.

Merge request reports