Skip to content

Make debug logs more greppable

Alex Kalderimis requested to merge ajk-query-recorder into master

What does this MR do?

This is a small change so that when debugging query recorder logs, both the SQL and the backtrace can be easily recovered with:

tail -f log/test.log | grep QueryRecorder

Producing the following:

QueryRecorder SQL: SELECT MAX("project_authorizations"."access_level") AS maximum_access_level, "project_authorizations"."user_id" AS project_authorizations_user_id FROM "project_authorizations" WHERE "project_authorizations"."project_id" = 1 AND "project_authorizations"."user_id" = 18 GROUP BY "project_authorizations"."user_id" /*application:test,correlation_id:f851a9841ab8489640a3a72b6b2760c6*/
QueryRecorder backtrace:  --> spec/support/helpers/query_recorder.rb:59:in `callback'
QueryRecorder backtrace:  --> app/models/project_team.rb:178:in `block in max_member_access_for_user_ids'
QueryRecorder backtrace:  --> app/models/concerns/bulk_member_access_load.rb:29:in `max_member_access_for_resource_ids'
QueryRecorder backtrace:  --> app/models/project_team.rb:174:in `max_member_access_for_user_ids'
QueryRecorder backtrace:  --> app/models/project_team.rb:189:in `max_member_access'
QueryRecorder backtrace:  --> app/policies/project_policy.rb:583:in `lookup_access_level!'
QueryRecorder backtrace:  --> ee/app/policies/ee/project_policy.rb:381:in `lookup_access_level!'
QueryRecorder backtrace:  --> app/policies/project_policy.rb:576:in `team_access_level'
QueryRecorder backtrace:  --> app/policies/project_policy.rb:557:in `team_member?'
QueryRecorder backtrace:  --> app/policies/project_policy.rb:44:in `block in <class:ProjectPolicy>'
QueryRecorder backtrace:  --> lib/declarative_policy/condition.rb:23:in `instance_eval'
QueryRecorder backtrace:  --> lib/declarative_policy/condition.rb:23:in `compute'
QueryRecorder backtrace:  --> lib/declarative_policy/condition.rb:44:in `block in pass?'
QueryRecorder backtrace:  --> lib/declarative_policy/base.rb:282:in `cache'
QueryRecorder backtrace:  --> lib/declarative_policy/condition.rb:44:in `pass?'
QueryRecorder backtrace:  --> lib/declarative_policy/rule.rb:81:in `pass?'
QueryRecorder backtrace:  --> lib/declarative_policy/step.rb:81:in `pass?'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:92:in `block in run'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:180:in `block in steps_by_score'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:149:in `loop'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:149:in `steps_by_score'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:82:in `run'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:60:in `pass?'
QueryRecorder backtrace:  --> lib/declarative_policy/base.rb:217:in `block in allowed?'
QueryRecorder backtrace:  --> lib/declarative_policy/base.rb:217:in `all?'
QueryRecorder backtrace:  --> lib/declarative_policy/base.rb:217:in `allowed?'
QueryRecorder backtrace:  --> lib/declarative_policy/rule.rb:159:in `pass?'
QueryRecorder backtrace:  --> lib/declarative_policy/step.rb:81:in `pass?'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:92:in `block in run'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:180:in `block in steps_by_score'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:149:in `loop'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:149:in `steps_by_score'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:82:in `run'
QueryRecorder backtrace:  --> lib/declarative_policy/runner.rb:60:in `pass?'
QueryRecorder backtrace:  --> lib/declarative_policy/base.rb:217:in `block in allowed?'
QueryRecorder backtrace:  --> lib/declarative_policy/base.rb:217:in `all?'
QueryRecorder backtrace:  --> lib/declarative_policy/base.rb:217:in `allowed?'
QueryRecorder backtrace:  --> lib/declarative_policy/base.rb:209:in `can?'
QueryRecorder backtrace:  --> app/models/ability.rb:72:in `allowed?'
QueryRecorder backtrace:  --> app/finders/issuable_finder/params.rb:141:in `block in project'
QueryRecorder backtrace:  --> lib/gitlab/utils/strong_memoize.rb:30:in `strong_memoize'
QueryRecorder backtrace:  --> app/finders/issuable_finder/params.rb:136:in `project'
QueryRecorder backtrace:  --> app/finders/issues_finder/params.rb:36:in `user_can_see_all_confidential_issues?'
QueryRecorder backtrace:  --> app/finders/issues_finder.rb:47:in `with_confidentiality_access_check'
QueryRecorder backtrace:  --> app/finders/issues_finder.rb:67:in `init_collection'
QueryRecorder backtrace:  --> app/finders/issuable_finder.rb:99:in `execute'
QueryRecorder backtrace:  --> app/finders/concerns/finder_with_cross_project_access.rb:37:in `block in execute'
QueryRecorder backtrace:  --> app/finders/concerns/finder_with_cross_project_access.rb:40:in `execute'
QueryRecorder backtrace:  --> app/finders/graphql_issuable_finder.rb:40:in `block in batch_load'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:37:in `sync'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:69:in `block in sync_all'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:69:in `map'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:69:in `sync_all'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:64:in `block in batch_sync'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:47:in `block in batch'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:54:in `block in batch'
QueryRecorder backtrace:  --> spec/support/helpers/query_recorder.rb:16:in `block in initialize'
QueryRecorder backtrace:  --> spec/support/helpers/query_recorder.rb:15:in `initialize'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:37:in `new'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:37:in `recorder'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:32:in `actual_count'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:62:in `verify_count'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:137:in `block (2 levels) in <main>'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:54:in `batch'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:64:in `batch_sync'
QueryRecorder backtrace:  --> spec/graphql/resolvers/issues_resolver_spec.rb:223:in `block (4 levels) in <top (required)>'
QueryRecorder backtrace:  --> spec/spec_helper.rb:306:in `block (3 levels) in <top (required)>'
QueryRecorder backtrace:  --> spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'
QueryRecorder backtrace:  --> spec/spec_helper.rb:297:in `block (2 levels) in <top (required)>'
QueryRecorder backtrace:  --> spec/spec_helper.rb:293:in `block (3 levels) in <top (required)>'
QueryRecorder backtrace:  --> spec/spec_helper.rb:293:in `block (2 levels) in <top (required)>'
QueryRecorder SQL: SELECT "issues".* FROM "issues" WHERE "issues"."project_id" = 1 AND "issues"."iid" IN (1, 2) ORDER BY "issues"."id" DESC /*application:test,correlation_id:f851a9841ab8489640a3a72b6b2760c6*/
QueryRecorder backtrace:  --> spec/support/helpers/query_recorder.rb:59:in `callback'
QueryRecorder backtrace:  --> app/finders/graphql_issuable_finder.rb:40:in `block in batch_load'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:37:in `sync'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:69:in `block in sync_all'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:69:in `map'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:69:in `sync_all'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:64:in `block in batch_sync'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:47:in `block in batch'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:54:in `block in batch'
QueryRecorder backtrace:  --> spec/support/helpers/query_recorder.rb:16:in `block in initialize'
QueryRecorder backtrace:  --> spec/support/helpers/query_recorder.rb:15:in `initialize'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:37:in `new'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:37:in `recorder'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:32:in `actual_count'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:62:in `verify_count'
QueryRecorder backtrace:  --> spec/support/matchers/exceed_query_limit.rb:137:in `block (2 levels) in <main>'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:54:in `batch'
QueryRecorder backtrace:  --> spec/support/helpers/graphql_helpers.rb:64:in `batch_sync'
QueryRecorder backtrace:  --> spec/graphql/resolvers/issues_resolver_spec.rb:223:in `block (4 levels) in <top (required)>'
QueryRecorder backtrace:  --> spec/spec_helper.rb:306:in `block (3 levels) in <top (required)>'
QueryRecorder backtrace:  --> spec/support/sidekiq_middleware.rb:9:in `with_sidekiq_server_middleware'
QueryRecorder backtrace:  --> spec/spec_helper.rb:297:in `block (2 levels) in <top (required)>'
QueryRecorder backtrace:  --> spec/spec_helper.rb:293:in `block (3 levels) in <top (required)>'
QueryRecorder backtrace:  --> spec/spec_helper.rb:293:in `block (2 levels) in <top (required)>'

Screenshots

Does this MR meet the acceptance criteria?

Conformity

Edited by Arturo Herrero

Merge request reports