Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add ability to set the tags_format for QueryLogs #45081

Merged

Conversation

iheanyi
Copy link
Contributor

@iheanyi iheanyi commented May 12, 2022

Summary

This pull request adds a new option called tags_format to ActiveRecord::QueryLogs. In some cases, we may not want to use a : as the separator for the key-value pairs, like in the case of sqlcommenter, which uses = as separator and single quotes around values.. Therefore, we can set a new tags_format option that lets users specify if they want to use the :default functionality or :sqlcommenter.

Other Information

This was literally copied from this pull request for Marginalia, credits to @modulitos for the original implementation.

@iheanyi
Copy link
Contributor Author

iheanyi commented May 12, 2022

I just realized that this requires it to be of a format key="tag" to be spec-compliant. Will close for now and re-open when it's ready for review.

@iheanyi iheanyi closed this May 12, 2022
@iheanyi iheanyi changed the title Add a custom tag separator option for query logs. Add ability to set the tags_format to QueryLog tags May 12, 2022
@iheanyi iheanyi reopened this May 12, 2022
@iheanyi
Copy link
Contributor Author

iheanyi commented May 12, 2022

All right, revamped and took a different direction for this!

@iheanyi iheanyi changed the title Add ability to set the tags_format to QueryLog tags Add ability to set the tags_format for QueryLogs May 12, 2022
Copy link
Member

@tenderlove tenderlove left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've left some comments. One "big picture" question though: should all values be quoted? I see that you preserved the existing behavior, but is the existing behavior correct?

activerecord/lib/active_record/query_logs_formatter.rb Outdated Show resolved Hide resolved
activerecord/lib/active_record/query_logs_formatter.rb Outdated Show resolved Hide resolved
activerecord/lib/active_record/query_logs_formatter.rb Outdated Show resolved Hide resolved
activerecord/lib/active_record/query_logs_formatter.rb Outdated Show resolved Hide resolved
activerecord/lib/active_record/query_logs_formatter.rb Outdated Show resolved Hide resolved
activerecord/lib/active_record/query_logs_formatter.rb Outdated Show resolved Hide resolved
activerecord/lib/active_record/query_logs_formatter.rb Outdated Show resolved Hide resolved
activerecord/test/cases/query_logs_formatter_test.rb Outdated Show resolved Hide resolved
activerecord/test/cases/query_logs_formatter_test.rb Outdated Show resolved Hide resolved
@tenderlove
Copy link
Member

I don't know why all of my comments are doubled up and I'm really sorry about it 😫

@modulitos
Copy link
Contributor

One "big picture" question though: should all values be quoted? I see that you preserved the existing behavior, but is the existing behavior correct?

Ooh thanks for bringing this up. I can't think of a reason why the existing behavior would be preferable over the new format (other than perhaps breaking a parser relying on the old format).

I'll ask around and see what other folks in the community think about changing this. If the old behavior is considered incorrect, then maybe we can have everyone use the new format as part of a patch release instead of a breaking change.

@@ -130,7 +131,7 @@ def tag_content
else
handler
end
"#{key}:#{val}" unless val.nil?
"#{key}='#{val.gsub("'", "\\\\'")}'" unless val.nil?
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This change introduces a requirement that val must be a string, which is documented above in the comments. I opted for having this requirement because I think the logic is more readable/maintainable, but I'm open to feedback of course. An alternative is to call .to_s on val here, or perhaps adding a check to only call .gsub when val is a string.

@modulitos
Copy link
Contributor

modulitos commented May 20, 2022

@tenderlove I believe this is ready for another review!

Here's a summary of the changes:

  1. Checked in with the community about correcting the formatting behavior, which I summarized in this issue: Proposal: Improve logging format from QueryLogs #45139
    I feel confident that moving to sqlcommenter format and dropping support for the existing format is the right way to go. It also feels like a good time to correct this because it's relatively new functionality. As one fellow Rubyist mentioned: "Easiest to change before too many folks develop a dependency on the format!"
  2. Now that we aren't supporting multiple formats, I removed the ActiveRecord::QueryLogs::Formatter class, which simplifies the implementation 🎉

@p8 p8 linked an issue May 31, 2022 that may be closed by this pull request
@modulitos modulitos force-pushed the iheanyi/custom-query-log-tags-separators branch from 8c7c270 to b534f6f Compare June 16, 2022 05:52
@iheanyi iheanyi requested a review from tenderlove June 16, 2022 23:33
@tenderlove
Copy link
Member

It looks good, but as I said here, we really do need to support both formats. Can you bring back the old one in addition to this one please?

Thanks, and sorry for taking so long to review this. 🙇🏻‍♀️

@modulitos modulitos force-pushed the iheanyi/custom-query-log-tags-separators branch 2 times, most recently from f0a5bcd to a57fcbc Compare June 22, 2022 00:19

class QuotingFormatter < Formatter # :nodoc:
def format_value(value)
"'#{value.to_s.gsub("'", "\\\\'")}'"
Copy link
Contributor

@modulitos modulitos Jun 22, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note that I discovered one edge case since the last review of this implementation - if value isn't a string, it'll cause a runtime error unless we call value.to_s here.

An example is when someone passes a value like Process.pid (which we're doing in the tests and railtie below). I'm on the fence about it, but decided to coerce into a string because it's more user-friendly, and consistent with the legacy implementation (see related comment).

We can easily remove this .to_s call if we want to enforce that value must always be a string:

Suggested change
"'#{value.to_s.gsub("'", "\\\\'")}'"
"'#{value.gsub("'", "\\\\'")}'"

I'm fine with either approach :)

@@ -130,7 +143,7 @@ def tag_content
else
handler
end
"#{key}:#{val}" unless val.nil?
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note how the legacy implementation coerces val into a string. I'm preserving this behavior in QuotingFormatter.format_value (see related comment)

@@ -368,7 +370,7 @@ class Railtie < Rails::Railtie # :nodoc:
ActiveRecord.query_transformers << ActiveRecord::QueryLogs
ActiveRecord::QueryLogs.taggings.merge!(
application: Rails.application.class.name.split("::").first,
pid: -> { Process.pid },
pid: -> { Process.pid.to_s },
Copy link
Contributor

@modulitos modulitos Jun 22, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm converting this into a string, since that's the desired type for our query log values. This removes any question about whether it gets coerced into a string later on.

@modulitos
Copy link
Contributor

@tenderlove

It looks good, but as I said here, we really do need to support both formats. Can you bring back the old one in addition to this one please?

Your reasoning makes sense - I re-added the ability to select between the two formats. If there's anything else, lmk!

Thanks, and sorry for taking so long to review this. 🙇🏻‍♀️

Better late than never! I appreciate you taking the time 🙌

@@ -1,6 +1,7 @@
# frozen_string_literal: true

require "active_support/core_ext/module/attribute_accessors_per_thread"
require_relative "query_logs_formatter"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think rails only uses require and not require_relative

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed - it seems like require is more consistent with the existing code. I changed this to require "active_record/query_logs_formatter".

Note that there are a couple places where require_relative is being used within Rails:

require_relative "autoloaders/inflector"

and here:

require_relative "credentials_command/diffing"

but the usages are few and far between.

thread_mattr_accessor :cached_comment, instance_accessor: false
thread_mattr_accessor :tags_formatter, instance_accessor: false
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What's the purpose of making the formatter per thread?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmmm good question - I don't think this needs to be per thread. I updated this to use mattr_accessor instead, and was also able to remove the ActiveSupport::ExecutionContext.after_change { ActiveRecord::QueryLogs.update_formatter } hook below. I think the implementation is simpler now.

@@ -73,7 +74,9 @@ module QueryLogs
mattr_accessor :tags, instance_accessor: false, default: [ :application ]
mattr_accessor :prepend_comment, instance_accessor: false, default: false
mattr_accessor :cache_query_log_tags, instance_accessor: false, default: false
mattr_accessor :tags_format, instance_accessor: false, default: :default
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure it makes sense to store both the format and the formatter on QueryLogs, I would think only the formatter is necessary

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great idea - I was able to remove tags_format and kept everything working correctly 😃

guides/source/configuring.md Outdated Show resolved Hide resolved
Copy link
Contributor

@modulitos modulitos left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@skipkayhil Thanks for the feedback! It led me to dig a little deeper and make some neat improvements 🙌

If there's anything else I can address, please lmk!

@@ -1,6 +1,7 @@
# frozen_string_literal: true

require "active_support/core_ext/module/attribute_accessors_per_thread"
require_relative "query_logs_formatter"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed - it seems like require is more consistent with the existing code. I changed this to require "active_record/query_logs_formatter".

Note that there are a couple places where require_relative is being used within Rails:

require_relative "autoloaders/inflector"

and here:

require_relative "credentials_command/diffing"

but the usages are few and far between.

@@ -73,7 +74,9 @@ module QueryLogs
mattr_accessor :tags, instance_accessor: false, default: [ :application ]
mattr_accessor :prepend_comment, instance_accessor: false, default: false
mattr_accessor :cache_query_log_tags, instance_accessor: false, default: false
mattr_accessor :tags_format, instance_accessor: false, default: :default
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great idea - I was able to remove tags_format and kept everything working correctly 😃

thread_mattr_accessor :cached_comment, instance_accessor: false
thread_mattr_accessor :tags_formatter, instance_accessor: false
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmmm good question - I don't think this needs to be per thread. I updated this to use mattr_accessor instead, and was also able to remove the ActiveSupport::ExecutionContext.after_change { ActiveRecord::QueryLogs.update_formatter } hook below. I think the implementation is simpler now.

@modulitos
Copy link
Contributor

@tenderlove
@skipkayhil
I believe all of the feedback has been addressed and that this PR is ready to merge/review.

Please lmk if there's anything I can do to help move this along! Happy to smoke test, etc.
I really appreciate all the feedback I've received so far.

Really looking forward to adding this Open Telemetry SQLCommenter feature to Rails 😀

@modulitos
Copy link
Contributor

modulitos commented Sep 2, 2022

Here's a summary of the context, as this PR has gotten a bit long:

  1. This PR doesn't cause any behavioral changes by default: the new SQLCommenter format is opt-in by configuring the ActiveRecord::Railtie like so: config.active_record.query_log_tags_format = :sqlcommenter
  2. All code changes are covered by unit tests
  3. My company has been using this feature (which I implemented on a fork of Marginalia) since February, and it regularly helps us associate long-running database queries to the source code 🎉
  4. The :sqlcommenter formatting changes the SQL comments from this:
"select id from posts /*application:Joe's app,controller:my_controller*/"

to this:

"select id from posts /*application='Joe\\'s app',controller='my_controller*/"

@bdewater
Copy link
Contributor

Thank you! I was looking for this myself :)

I believe the only things missing are squashing the commits and a CHANGELOG entry for Active Record, see https://edgeguides.rubyonrails.org/contributing_to_ruby_on_rails.html#updating-the-documentation

@modulitos modulitos force-pushed the iheanyi/custom-query-log-tags-separators branch 2 times, most recently from cce20fa to 024523f Compare September 27, 2022 07:17
@modulitos
Copy link
Contributor

@bdewater Thank you for the tips 😀

Commits are squashed and the Active Record CHANGELOG has been updated. Looking forward to any next steps!

@modulitos modulitos force-pushed the iheanyi/custom-query-log-tags-separators branch 3 times, most recently from 5c4237b to c0b8999 Compare September 27, 2022 20:01
Co-authored-by: Iheanyi Ekechukwu <iekechukwu@gmail.com>
@modulitos modulitos force-pushed the iheanyi/custom-query-log-tags-separators branch from c0b8999 to 6df894f Compare September 27, 2022 21:39
@tenderlove tenderlove merged commit 2fb72f5 into rails:main Sep 28, 2022
@iheanyi iheanyi deleted the iheanyi/custom-query-log-tags-separators branch September 28, 2022 02:19
yahonda added a commit to yahonda/rails that referenced this pull request Oct 4, 2022
…rmatter

This commit addresses the `warning: mismatched indentations` below.

```ruby
$ bundle exec ruby -w -Itest test/cases/query_logs_formatter_test.rb -n test_factory_invalid_formatter
test/cases/query_logs_formatter_test.rb:10: warning: mismatched indentations at 'end' with 'def' at 6
Using sqlite3
Run options: -n test_factory_invalid_formatter --seed 48904

.

Finished in 0.008743s, 114.3776 runs/s, 114.3776 assertions/s.
1 runs, 1 assertions, 0 failures, 0 errors, 0 skips
$
```

Follow-up rails#45081
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Proposal: Improve logging format from QueryLogs
5 participants