diff --git a/examples/snippets/query-logs/README.md b/examples/snippets/query-logs/README.md new file mode 100644 index 00000000..a441e87f --- /dev/null +++ b/examples/snippets/query-logs/README.md @@ -0,0 +1,43 @@ +# Sample - Query Logs + +__NOTE__: Query logs require additional configuration for Cloud Spanner. Please read the entire file. + +Rails 7.0 and higher supports [Query Logs](https://api.rubyonrails.org/classes/ActiveRecord/QueryLogs.html). Query Logs +can be used to automatically annotate all queries that are executed based on the current execution context. + +The Cloud Spanner ActiveRecord provider can be used in combination with Query Logs. The query logs are automatically +translated to request tags for the queries. +See https://cloud.google.com/spanner/docs/introspection/troubleshooting-with-tags for more +information about request and transaction tags in Cloud Spanner. + +## Configuration +Using Query Logs with Cloud Spanner requires some specific configuration: +1. You must set `ActiveRecord::QueryLogs.prepend_comment = true` +2. You must include `{ request_tag: "true" }` as the first tag in your configuration. + +```ruby +ActiveRecord::QueryLogs.prepend_comment = true +config.active_record.query_log_tags = [ + { + request_tag: "true", + }, + :namespaced_controller, + :action, + :job, + { + request_id: ->(context) { context[:controller]&.request&.request_id }, + job_id: ->(context) { context[:job]&.job_id }, + tenant_id: -> { Current.tenant&.id }, + static: "value", + }, +] +``` + +The sample will automatically start a Spanner Emulator in a docker container and execute the sample +against that emulator. The emulator will automatically be stopped when the application finishes. + +Run the application with the command + +```bash +bundle exec rake run +``` diff --git a/examples/snippets/query-logs/Rakefile b/examples/snippets/query-logs/Rakefile new file mode 100644 index 00000000..009be88b --- /dev/null +++ b/examples/snippets/query-logs/Rakefile @@ -0,0 +1,13 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +require_relative "../config/environment" +require "sinatra/activerecord/rake" + +desc "Sample showing how to use automatic query log tagging on Cloud Spanner with ActiveRecord." +task :run do + Dir.chdir("..") { sh "bundle exec rake run[query-logs]" } +end diff --git a/examples/snippets/query-logs/application.rb b/examples/snippets/query-logs/application.rb new file mode 100644 index 00000000..73a910c5 --- /dev/null +++ b/examples/snippets/query-logs/application.rb @@ -0,0 +1,63 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +require "io/console" +require_relative "../config/environment" +require_relative "models/singer" +require_relative "models/album" + +class Application + def self.run + enable_query_logs + + puts "" + puts "Query all Albums and include an automatically generated request tag" + albums = Album.all + puts "Queried #{albums.length} albums using an automatically generated request tag" + + puts "" + puts "Press any key to end the application" + STDIN.getch + end + + def self.enable_query_logs + # Enables Query Logs in a non-Rails application. Normally, this should be done + # as described here: https://api.rubyonrails.org/classes/ActiveRecord/QueryLogs.html + ActiveRecord.query_transformers << ActiveRecord::QueryLogs + + # Query log comments *MUST* be prepended to be included as a request tag. + ActiveRecord::QueryLogs.prepend_comment = true + + # This block manually enables Query Logs without a full Rails application. + # This should normally not be needed in your application. + ActiveRecord::QueryLogs.taggings.merge!( + application: "example-app", + action: "run-test-application", + pid: -> { Process.pid.to_s }, + socket: ->(context) { context[:connection].pool.db_config.socket }, + db_host: ->(context) { context[:connection].pool.db_config.host }, + database: ->(context) { context[:connection].pool.db_config.database } + ) + + ActiveRecord::QueryLogs.tags = [ + # The first tag *MUST* be the fixed value 'request_tag:true'. + { + request_tag: "true" + }, + :controller, + :action, + :job, + { + request_id: ->(context) { context[:controller]&.request&.request_id }, + job_id: ->(context) { context[:job]&.job_id } + }, + :db_host, + :database + ] + end +end + +Application.run diff --git a/examples/snippets/query-logs/config/database.yml b/examples/snippets/query-logs/config/database.yml new file mode 100644 index 00000000..905be603 --- /dev/null +++ b/examples/snippets/query-logs/config/database.yml @@ -0,0 +1,8 @@ +development: + adapter: spanner + emulator_host: localhost:9010 + project: test-project + instance: test-instance + database: testdb + pool: 5 + timeout: 5000 diff --git a/examples/snippets/query-logs/db/migrate/01_create_tables.rb b/examples/snippets/query-logs/db/migrate/01_create_tables.rb new file mode 100644 index 00000000..14750674 --- /dev/null +++ b/examples/snippets/query-logs/db/migrate/01_create_tables.rb @@ -0,0 +1,21 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +class CreateTables < ActiveRecord::Migration[6.0] + def change + connection.ddl_batch do + create_table :singers do |t| + t.string :first_name + t.string :last_name + end + + create_table :albums do |t| + t.string :title + t.references :singer, index: false, foreign_key: true + end + end + end +end diff --git a/examples/snippets/query-logs/db/schema.rb b/examples/snippets/query-logs/db/schema.rb new file mode 100644 index 00000000..dc7b860a --- /dev/null +++ b/examples/snippets/query-logs/db/schema.rb @@ -0,0 +1,31 @@ +# This file is auto-generated from the current state of the database. Instead +# of editing this file, please use the migrations feature of Active Record to +# incrementally modify your database, and then regenerate this schema definition. +# +# This file is the source Rails uses to define your schema when running `bin/rails +# db:schema:load`. When creating a new database, `bin/rails db:schema:load` tends to +# be faster and is potentially less error prone than running all of your +# migrations from scratch. Old migrations may fail to apply correctly if those +# migrations use external dependencies or application code. +# +# It's strongly recommended that you check this file into your version control system. + +ActiveRecord::Schema[7.1].define(version: 1) do + connection.start_batch_ddl + + create_table "albums", force: :cascade do |t| + t.string "title" + t.integer "singer_id", limit: 8 + end + + create_table "singers", force: :cascade do |t| + t.string "first_name" + t.string "last_name" + end + + add_foreign_key "albums", "singers" + connection.run_batch +rescue + abort_batch + raise +end diff --git a/examples/snippets/query-logs/db/seeds.rb b/examples/snippets/query-logs/db/seeds.rb new file mode 100644 index 00000000..e085f8e0 --- /dev/null +++ b/examples/snippets/query-logs/db/seeds.rb @@ -0,0 +1,24 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +require_relative "../../config/environment.rb" +require_relative "../models/singer" +require_relative "../models/album" + +first_names = ["Pete", "Alice", "John", "Ethel", "Trudy", "Naomi", "Wendy", "Ruben", "Thomas", "Elly"] +last_names = ["Wendelson", "Allison", "Peterson", "Johnson", "Henderson", "Ericsson", "Aronson", "Tennet", "Courtou"] + +adjectives = ["daily", "happy", "blue", "generous", "cooked", "bad", "open"] +nouns = ["windows", "potatoes", "bank", "street", "tree", "glass", "bottle"] + +5.times do + Singer.create first_name: first_names.sample, last_name: last_names.sample +end + +20.times do + singer_id = Singer.all.sample.id + Album.create title: "#{adjectives.sample} #{nouns.sample}", singer_id: singer_id +end diff --git a/examples/snippets/query-logs/models/album.rb b/examples/snippets/query-logs/models/album.rb new file mode 100644 index 00000000..0d953c83 --- /dev/null +++ b/examples/snippets/query-logs/models/album.rb @@ -0,0 +1,9 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +class Album < ActiveRecord::Base + belongs_to :singer +end diff --git a/examples/snippets/query-logs/models/singer.rb b/examples/snippets/query-logs/models/singer.rb new file mode 100644 index 00000000..389329ef --- /dev/null +++ b/examples/snippets/query-logs/models/singer.rb @@ -0,0 +1,9 @@ +# Copyright 2023 Google LLC +# +# Use of this source code is governed by an MIT-style +# license that can be found in the LICENSE file or at +# https://opensource.org/licenses/MIT. + +class Singer < ActiveRecord::Base + has_many :albums +end diff --git a/lib/active_record/connection_adapters/spanner/database_statements.rb b/lib/active_record/connection_adapters/spanner/database_statements.rb index 9872fbd4..a44b8dfa 100644 --- a/lib/active_record/connection_adapters/spanner/database_statements.rb +++ b/lib/active_record/connection_adapters/spanner/database_statements.rb @@ -13,6 +13,7 @@ module ConnectionAdapters module Spanner module DatabaseStatements VERSION_7_1_0 = Gem::Version.create "7.1.0" + RequestOptions = Google::Cloud::Spanner::V1::RequestOptions # DDL, DML and DQL Statements @@ -30,6 +31,8 @@ def internal_exec_query sql, name = "SQL", binds = [], prepare: false, async: fa def internal_execute sql, name = "SQL", binds = [], prepare: false, async: false # rubocop:disable Lint/UnusedMethodArgument statement_type = sql_statement_type sql + sql = transform sql + append_request_tag_from_query_logs sql, binds if preventing_writes? && [:dml, :ddl].include?(statement_type) raise ActiveRecord::ReadOnlyError( @@ -40,40 +43,69 @@ def internal_execute sql, name = "SQL", binds = [], if statement_type == :ddl execute_ddl sql else - transaction_required = statement_type == :dml - materialize_transactions - - # First process and remove any hints in the binds that indicate that - # a different read staleness should be used than the default. - staleness_hint = binds.find { |b| b.is_a? Arel::Visitors::StalenessHint } - if staleness_hint - selector = Google::Cloud::Spanner::Session.single_use_transaction staleness_hint.value - binds.delete staleness_hint - end - request_options = binds.find { |b| b.is_a? Google::Cloud::Spanner::V1::RequestOptions } - if request_options - binds.delete request_options - end + execute_query_or_dml statement_type, sql, name, binds + end + end + + def execute_query_or_dml statement_type, sql, name, binds + transaction_required = statement_type == :dml + materialize_transactions - log_args = [sql, name] - log_args.concat [binds, type_casted_binds(binds)] if log_statement_binds - - log(*log_args) do - types, params = to_types_and_params binds - ActiveSupport::Dependencies.interlock.permit_concurrent_loads do - if transaction_required - transaction do - @connection.execute_query sql, params: params, types: types, request_options: request_options - end - else - @connection.execute_query sql, params: params, types: types, single_use_selector: selector, - request_options: request_options + # First process and remove any hints in the binds that indicate that + # a different read staleness should be used than the default. + staleness_hint = binds.find { |b| b.is_a? Arel::Visitors::StalenessHint } + if staleness_hint + selector = Google::Cloud::Spanner::Session.single_use_transaction staleness_hint.value + binds.delete staleness_hint + end + request_options = binds.find { |b| b.is_a? Google::Cloud::Spanner::V1::RequestOptions } + if request_options + binds.delete request_options + end + + log_args = [sql, name] + log_args.concat [binds, type_casted_binds(binds)] if log_statement_binds + + log(*log_args) do + types, params = to_types_and_params binds + ActiveSupport::Dependencies.interlock.permit_concurrent_loads do + if transaction_required + transaction do + @connection.execute_query sql, params: params, types: types, request_options: request_options end + else + @connection.execute_query sql, params: params, types: types, single_use_selector: selector, + request_options: request_options end end end end + def append_request_tag_from_query_logs sql, binds + legacy_formatter_prefix = "/*request_tag:true," + sql_commenter_prefix = "/*request_tag='true'," + if sql.start_with? legacy_formatter_prefix + append_request_tag_from_query_logs_with_format sql, binds, legacy_formatter_prefix + elsif sql.start_with? sql_commenter_prefix + append_request_tag_from_query_logs_with_format sql, binds, sql_commenter_prefix + end + end + + def append_request_tag_from_query_logs_with_format sql, binds, prefix + end_of_comment = sql.index "*/", prefix.length + return unless end_of_comment + + request_tag = sql[prefix.length, end_of_comment - prefix.length] + options = binds.find { |bind| bind.is_a? RequestOptions } || RequestOptions.new + if options.request_tag == "" + options.request_tag = request_tag + else + options.request_tag += "," + request_tag + end + + binds.append options + end + # The method signatures for executing queries and DML statements changed between Rails 7.0 and 7.1. if ActiveRecord.gem_version >= VERSION_7_1_0 diff --git a/lib/active_record/connection_adapters/spanner_adapter.rb b/lib/active_record/connection_adapters/spanner_adapter.rb index b8e9b140..bdbc565b 100644 --- a/lib/active_record/connection_adapters/spanner_adapter.rb +++ b/lib/active_record/connection_adapters/spanner_adapter.rb @@ -261,6 +261,14 @@ def type_map include TypeMapBuilder end + def transform sql + if ActiveRecord::VERSION::MAJOR >= 7 + transform_query sql + else + sql + end + end + # Overwrite the standard log method to be able to translate exceptions. def log sql, name = "SQL", binds = [], type_casted_binds = [], statement_name = nil, *args super diff --git a/test/activerecord_spanner_mock_server/spanner_active_record_with_mock_server_test.rb b/test/activerecord_spanner_mock_server/spanner_active_record_with_mock_server_test.rb index 8322c5ef..41fe404f 100644 --- a/test/activerecord_spanner_mock_server/spanner_active_record_with_mock_server_test.rb +++ b/test/activerecord_spanner_mock_server/spanner_active_record_with_mock_server_test.rb @@ -10,6 +10,7 @@ module MockServerTests CommitRequest = Google::Cloud::Spanner::V1::CommitRequest + ExecuteSqlRequest = Google::Cloud::Spanner::V1::ExecuteSqlRequest class SpannerActiveRecordMockServerTest < BaseSpannerMockServerTest VERSION_7_1_0 = Gem::Version.create('7.1.0') @@ -956,6 +957,90 @@ def test_query_annotate_request_and_transaction_tag_and_binds end end + def test_query_logs + skip "Requires Rails version 7.0 or higher" if ActiveRecord::VERSION::MAJOR < 7 + + begin + current_query_transformers = _enable_query_logs + + sql = "/*request_tag:true,action:test_query_logs,database:testdb*/ SELECT `singers`.* FROM `singers`" + @mock.put_statement_result sql, MockServerTests::create_random_singers_result(4) + Singer.all.each do |singer| + refute_nil singer.id, "singer.id should not be nil" + end + select_requests = @mock.requests.select { |req| req.is_a?(ExecuteSqlRequest) && req.sql == sql } + select_requests.each do |request| + assert request.request_options + assert_equal "action:test_query_logs,database:testdb", request.request_options.request_tag + end + ensure + _disable_query_logs current_query_transformers + end + end + + def test_query_logs_combined_with_request_tag + skip "Requires Rails version 7.0 or higher" if ActiveRecord::VERSION::MAJOR < 7 + + begin + current_query_transformers = _enable_query_logs + + sql = "/*request_tag:true,action:test_query_logs,database:testdb*/ SELECT `singers`.* FROM `singers` /* request_tag: selecting all singers */" + @mock.put_statement_result sql, MockServerTests::create_random_singers_result(4) + Singer.annotate("request_tag: selecting all singers").all.each do |singer| + refute_nil singer.id, "singer.id should not be nil" + end + select_requests = @mock.requests.select { |req| req.is_a?(ExecuteSqlRequest) && req.sql == sql } + select_requests.each do |request| + assert request.request_options + assert_equal "selecting all singers,action:test_query_logs,database:testdb", request.request_options.request_tag + end + ensure + _disable_query_logs current_query_transformers + end + end + + def _enable_query_logs + # Make sure that the comment that is added by query_logs is actually added to the query string. + # The comment is not translated to a request tag, because the comment is added at a too late moment. + # Instead, we need to add that at a lower level in the Spanner connection. + + # Simulate that query_logs has been enabled. + current_query_transformers = ActiveRecord.query_transformers + + ActiveRecord.query_transformers << ActiveRecord::QueryLogs + ActiveRecord::QueryLogs.prepend_comment = true + ActiveRecord::QueryLogs.taggings.merge!( + application: "test-app", + action: "test_query_logs", + pid: -> { Process.pid.to_s }, + socket: ->(context) { context[:connection].pool.db_config.socket }, + db_host: ->(context) { context[:connection].pool.db_config.host }, + database: ->(context) { context[:connection].pool.db_config.database }, + ) + ActiveRecord::QueryLogs.tags = [ + { + request_tag: "true", + }, + :controller, + :action, + :job, + { + request_id: ->(context) { context[:controller]&.request&.request_id }, + job_id: ->(context) { context[:job]&.job_id }, + }, + :db_host, + :database + ] + + current_query_transformers + end + + def _disable_query_logs current_query_transformers + current_query_transformers.each do |transformer| + ActiveRecord.query_transformers.delete transformer + end + end + def test_insert_all values = [ {id: 1, first_name: "Dave", last_name: "Allison"},