Mute ActiveStorage Logs

One thing I've done to make the logs slightly quieter is to filter some ActiveStorage-related parameters from the logs. I added :encoded_key, :signed_blob_id, and :variation_key to the filtered parameters in config/initializers/filter_parameter_logging.rb:

Rails.application.config.filter_parameters += [
  :password,
  # Filter ActiveStorage blob keys so that the logs aren't full of as much stuff.
  :encoded_key,
  :signed_blob_id,
  :variation_key
]

Before:

Started GET "/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSm5kbUZ5YVdGdWRITXZiMDVvUjNCblJIQm9RVWd6YWtGeFFWUlpPV0Z3U2tWSUwyRTBZemd3WVRCallUUTJZalJtWmpObE16Vm1aV1l5TVRFelltWmxPREptWlRsalpUbGhNalE0WmpWaE9UZ3hZVEk1WkdVek5XUmxNemt4Wm1VNE1HUUdPZ1pGVkRvUVpHbHpjRzl6YVhScGIyNUpJazFwYm14cGJtVTdJR1pwYkdWdVlXMWxQU0kzWDJaaGEyVnlYMk52ZG1WeUxtcHdaeUk3SUdacGJHVnVZVzFsS2oxVlZFWXRPQ2NuTjE5bVlXdGxjbDlqYjNabGNpNXFjR2NHT3daVU9oRmpiMjUwWlc1MFgzUjVjR1ZKSWc5cGJXRm5aUzlxY0dWbkJqc0dWQT09IiwiZXhwIjoiMjAxOS0wMi0yNFQyMDoxNTo1MS45OTFaIiwicHVyIjoiYmxvYl9rZXkifX0=--c8b11cdaa201d28d585f62aaa7c8cf6af75e7cab/7_faker_cover.jpg?content_type=image%2Fjpeg&disposition=inline%3B+filename%3D%227_faker_cover.jpg%22%3B+filename%2A%3DUTF-8%27%277_faker_cover.jpg" for 127.0.0.1 at 2019-02-24 13:10:52 -0700
Processing by ActiveStorage::DiskController#show as JPEG
  Parameters: {"content_type"=>"image/jpeg", "disposition"=>"inline; filename=\"7_faker_cover.jpg\"; filename*=UTF-8''7_faker_cover.jpg", "encoded_key"=>"eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSm5kbUZ5YVdGdWRITXZiMDVvUjNCblJIQm9RVWd6YWtGeFFWUlpPV0Z3U2tWSUwyRTBZemd3WVRCallUUTJZalJtWmpObE16Vm1aV1l5TVRFelltWmxPREptWlRsalpUbGhNalE0WmpWaE9UZ3hZVEk1WkdVek5XUmxNemt4Wm1VNE1HUUdPZ1pGVkRvUVpHbHpjRzl6YVhScGIyNUpJazFwYm14cGJtVTdJR1pwYkdWdVlXMWxQU0kzWDJaaGEyVnlYMk52ZG1WeUxtcHdaeUk3SUdacGJHVnVZVzFsS2oxVlZFWXRPQ2NuTjE5bVlXdGxjbDlqYjNabGNpNXFjR2NHT3daVU9oRmpiMjUwWlc1MFgzUjVjR1ZKSWc5cGJXRm5aUzlxY0dWbkJqc0dWQT09IiwiZXhwIjoiMjAxOS0wMi0yNFQyMDoxNTo1MS45OTFaIiwicHVyIjoiYmxvYl9rZXkifX0=--c8b11cdaa201d28d585f62aaa7c8cf6af75e7cab", "filename"=>"7_faker_cover"}
Completed 200 OK in 2ms (ActiveRecord: 0.0ms)

After:

Started GET "/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSm5kbUZ5YVdGdWRITXZiMDVvUjNCblJIQm9RVWd6YWtGeFFWUlpPV0Z3U2tWSUwyRTBZemd3WVRCallUUTJZalJtWmpObE16Vm1aV1l5TVRFelltWmxPREptWlRsalpUbGhNalE0WmpWaE9UZ3hZVEk1WkdVek5XUmxNemt4Wm1VNE1HUUdPZ1pGVkRvUVpHbHpjRzl6YVhScGIyNUpJazFwYm14cGJtVTdJR1pwYkdWdVlXMWxQU0kzWDJaaGEyVnlYMk52ZG1WeUxtcHdaeUk3SUdacGJHVnVZVzFsS2oxVlZFWXRPQ2NuTjE5bVlXdGxjbDlqYjNabGNpNXFjR2NHT3daVU9oRmpiMjUwWlc1MFgzUjVjR1ZKSWc5cGJXRm5aUzlxY0dWbkJqc0dWQT09IiwiZXhwIjoiMjAxOS0wMi0yNFQyMDoxNjozNy43MTlaIiwicHVyIjoiYmxvYl9rZXkifX0=--223b806011854805e1e50ca952099bcdbc4d8bdd/7_faker_cover.jpg?content_type=image%2Fjpeg&disposition=inline%3B+filename%3D%227_faker_cover.jpg%22%3B+filename%2A%3DUTF-8%27%277_faker_cover.jpg" for 127.0.0.1 at 2019-02-24 13:11:37 -0700
Processing by ActiveStorage::DiskController#show as JPEG
  Parameters: {"content_type"=>"image/jpeg", "disposition"=>"inline; filename=\"7_faker_cover.jpg\"; filename*=UTF-8''7_faker_cover.jpg", "encoded_key"=>"[FILTERED]", "filename"=>"7_faker_cover"}
Completed 200 OK in 1ms (ActiveRecord: 0.0ms)

Most of the change is in the third line, the parameters are a lot shorter. Unfortunately that's pretty much all I could figure out

I am curious if it'd be possible to silence any logs tagged as Disk Storage (the 'Checked if file exists at key:' and 'Generated URL for file at key:' lines):

Started GET "/rails/active_storage/representations/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBGQT09IiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--6b1335aa96f07d0e8a19178e8d4c65d4a6b6ec60/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdCam9MY21WemFYcGxTU0lOTXpBd2VEVXdNRDRHT2daRlZBPT0iLCJleHAiOm51bGwsInB1ciI6InZhcmlhdGlvbiJ9fQ==--aca35120fd4bdbafe23b34690fa45f96280194c4/7_faker_cover.jpg" for 127.0.0.1 at 2019-02-24 13:11:37 -0700
Processing by ActiveStorage::RepresentationsController#show as JPEG
  Parameters: {"signed_blob_id"=>"[FILTERED]", "variation_key"=>"[FILTERED]", "filename"=>"7_faker_cover"}
  ActiveStorage::Blob Load (1.1ms)  SELECT  "active_storage_blobs".* FROM "active_storage_blobs" WHERE "active_storage_blobs"."id" = $1 LIMIT $2  [["id", 15], ["LIMIT", 1]]
  ↳ /Users/connorshea/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activerecord-5.2.2/lib/active_record/log_subscriber.rb:98
  Disk Storage (0.1ms) Checked if file exists at key: variants/oNhGpgDphAH3jAqATY9apJEH/a4c80a0ca46b4ff3e35fef2113bfe82fe9ce9a248f5a981a29de35de391fe80d (yes)
  Disk Storage (276.0ms) Generated URL for file at key: variants/oNhGpgDphAH3jAqATY9apJEH/a4c80a0ca46b4ff3e35fef2113bfe82fe9ce9a248f5a981a29de35de391fe80d (http://localhost:3000/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSm5kbUZ5YVdGdWRITXZiMDVvUjNCblJIQm9RVWd6YWtGeFFWUlpPV0Z3U2tWSUwyRTBZemd3WVRCallUUTJZalJtWmpObE16Vm1aV1l5TVRFelltWmxPREptWlRsalpUbGhNalE0WmpWaE9UZ3hZVEk1WkdVek5XUmxNemt4Wm1VNE1HUUdPZ1pGVkRvUVpHbHpjRzl6YVhScGIyNUpJazFwYm14cGJtVTdJR1pwYkdWdVlXMWxQU0kzWDJaaGEyVnlYMk52ZG1WeUxtcHdaeUk3SUdacGJHVnVZVzFsS2oxVlZFWXRPQ2NuTjE5bVlXdGxjbDlqYjNabGNpNXFjR2NHT3daVU9oRmpiMjUwWlc1MFgzUjVjR1ZKSWc5cGJXRm5aUzlxY0dWbkJqc0dWQT09IiwiZXhwIjoiMjAxOS0wMi0yNFQyMDoxNjozNy43MTlaIiwicHVyIjoiYmxvYl9rZXkifX0=--223b806011854805e1e50ca952099bcdbc4d8bdd/7_faker_cover.jpg?content_type=image%2Fjpeg&disposition=inline%3B+filename%3D%227_faker_cover.jpg%22%3B+filename%2A%3DUTF-8%27%277_faker_cover.jpg)
Redirected to http://localhost:3000/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSm5kbUZ5YVdGdWRITXZiMDVvUjNCblJIQm9RVWd6YWtGeFFWUlpPV0Z3U2tWSUwyRTBZemd3WVRCallUUTJZalJtWmpObE16Vm1aV1l5TVRFelltWmxPREptWlRsalpUbGhNalE0WmpWaE9UZ3hZVEk1WkdVek5XUmxNemt4Wm1VNE1HUUdPZ1pGVkRvUVpHbHpjRzl6YVhScGIyNUpJazFwYm14cGJtVTdJR1pwYkdWdVlXMWxQU0kzWDJaaGEyVnlYMk52ZG1WeUxtcHdaeUk3SUdacGJHVnVZVzFsS2oxVlZFWXRPQ2NuTjE5bVlXdGxjbDlqYjNabGNpNXFjR2NHT3daVU9oRmpiMjUwWlc1MFgzUjVjR1ZKSWc5cGJXRm5aUzlxY0dWbkJqc0dWQT09IiwiZXhwIjoiMjAxOS0wMi0yNFQyMDoxNjozNy43MTlaIiwicHVyIjoiYmxvYl9rZXkifX0=--223b806011854805e1e50ca952099bcdbc4d8bdd/7_faker_cover.jpg?content_type=image%2Fjpeg&disposition=inline%3B+filename%3D%227_faker_cover.jpg%22%3B+filename%2A%3DUTF-8%27%277_faker_cover.jpg
Completed 302 Found in 300ms (ActiveRecord: 16.7ms)

I assumed these were using Rails' TaggedLogging functionality, but it doesn't look like they are (see the source code). Short of monkey-patching ActiveStorage's logger (which seems like a pretty bad idea) I'm not sure of a good way to improve this situation.


According to the article of EvilMartians I've set

config.active_record.verbose_query_logs option to false inside application.rb.

It partly solves the problem.

It seems like Active Storage people consider the most verbose logging very important. So now logs about files take the same size on the disk as stored files.

And the most irritating thing is the level of these messages is INFO. I can't understand why it's not DEBUG...


I'm using Lograge Gem to hide those requests.

config.lograge.ignore_actions = [
  "ActiveStorage::DiskController#show",
  "ActiveStorage::RepresentationsController#show"
]

I found this as simplest (maybe but not bulletproof) solution for easier development. It uses standard Rails log and only replaces its default formatter. Works on Rails 6, probably will work on Rails 5 too.

Place code bellow into config/environments/development.rb:

Rails.application.configure do
    .
    .
    .

  class MyLogFormatter
    def initialize
      # Suppress is an array of request uuids. Each listed uuid means no messages from this request.
      @suppress = []
    end

    def call(severity, datetime, progname, message)
      # Get uuid, which we need to properly distinguish between parallel requests.
      # Also remove uuid information from log (that's why we match the rest of message)
      matches = /\[([0-9a-zA-Z\-_]+)\] (.*)/m.match(message)

      if matches
        uuid = matches[1]
        message = matches[2]

        if @suppress.include?(uuid) && message.start_with?("Completed ")
          # Each request in Rails log ends with "Completed ..." message, so do suppressed messages.
          @suppress.delete(uuid)
          return nil

        elsif message.start_with?("Processing by ActiveStorage::DiskController#show", "Processing by ActiveStorage::BlobsController#show", "Processing by ActiveStorage::RepresentationsController#show", "Started GET \"/rails/active_storage/disk/", "Started GET \"/rails/active_storage/blobs/", "Started GET \"/rails/active_storage/representations/")
          # When we use ActiveStorage disk provider, there are three types of request: Disk requests, Blobs requests and Representation requests.
          # These three types we would like to hide.
          @suppress << uuid
          return nil

        elsif [email protected]?(uuid)
          # All messages, which are not suppressed, print. New line must be added here.
          return "#{message}\n"
        end

      else
        # Return message as it is (including new line at the end)
        return "#{message}\n"
      end

    end
  end

  config.log_tags = [:uuid]
  config.log_formatter = MyLogFormatter.new
    .
    .
    .
end

Tags:

Ruby On Rails

Rails Activestorage

Recent Posts