Instrument and log the services

6 files changed, 168 insertions, 32 deletions

diff --git a/lib/active_storage/engine.rb b/lib/active_storage/engine.rb
index d066a689eb..adcf42ee58 100644
--- a/lib/active_storage/engine.rb
+++ b/lib/active_storage/engine.rb
@@ -6,6 +6,14 @@ module ActiveStorage
 
     config.eager_load_namespaces << ActiveStorage
 
+    initializer "active_storage.logger" do
+      require "active_storage/service"
+
+      config.after_initialize do |app|
+        ActiveStorage::Service.logger = app.config.active_storage.logger || Rails.logger
+      end
+    end
+
     initializer "active_storage.routes" do
       require "active_storage/disk_controller"
 
diff --git a/lib/active_storage/log_subscriber.rb b/lib/active_storage/log_subscriber.rb
new file mode 100644
index 0000000000..b3f130a572
--- /dev/null
+++ b/lib/active_storage/log_subscriber.rb
@@ -0,0 +1,51 @@
+require "active_support/log_subscriber"
+
+# Implements the ActiveSupport::LogSubscriber for logging notifications when
+# email is delivered or received.
+class ActiveStorage::LogSubscriber < ActiveSupport::LogSubscriber
+  def service_upload(event)
+    message = color("Uploaded file to key: #{key_in(event)}", GREEN)
+    message << color(" (checksum: #{event.payload[:checksum]})", GREEN) if event.payload[:checksum]
+    info event, message
+  end
+
+  def service_download(event)
+    info event, color("Downloaded file from key: #{key_in(event)}", BLUE)
+  end
+
+  def service_delete(event)
+    info event, color("Deleted file from key: #{key_in(event)}", RED)
+  end
+
+  def service_exist(event)
+    debug event, color("Checked if file exist at key: #{key_in(event)} (#{event.payload[:exist] ? "yes" : "no"})", BLUE)
+  end
+
+  def service_url(event)
+    debug event, color("Generated URL for file at key: #{key_in(event)} (#{event.payload[:url]})", BLUE)
+  end
+
+  # Use the logger configured for ActiveStorage::Base.logger
+  def logger
+    ActiveStorage::Service.logger
+  end
+
+  private
+    def info(event, colored_message)
+      super log_prefix_for_service(event) + colored_message
+    end
+
+    def debug(event, colored_message)
+      super log_prefix_for_service(event) + colored_message
+    end
+
+    def log_prefix_for_service(event)
+      color "  #{event.payload[:service]} Storage (#{event.duration.round(1)}ms) ", CYAN
+    end
+
+    def key_in(event)
+      event.payload[:key]
+    end
+end
+
+ActiveStorage::LogSubscriber.attach_to :active_storage
diff --git a/lib/active_storage/service.rb b/lib/active_storage/service.rb
index 86f867c293..f50849b694 100644
--- a/lib/active_storage/service.rb
+++ b/lib/active_storage/service.rb
@@ -1,3 +1,5 @@
+require_relative "log_subscriber"
+
 # Abstract class serving as an interface for concrete services.
 #
 # The available services are:
@@ -35,6 +37,8 @@ class ActiveStorage::Service
   extend ActiveSupport::Autoload
   autoload :Configurator
 
+  class_attribute :logger
+
   class << self
     # Configure an Active Storage service by name from a set of configurations,
     # typically loaded from a YAML file. The Active Storage engine uses this
@@ -73,4 +77,16 @@ class ActiveStorage::Service
   def url(key, expires_in:, disposition:, filename:)
     raise NotImplementedError
   end
+
+  private
+    def instrument(operation, key, payload = {}, &block)
+      ActiveSupport::Notifications.instrument(
+        "service_#{operation}.active_storage", 
+        payload.merge(key: key, service: service_name), &block)
+    end
+
+    def service_name
+      # ActiveStorage::Service::DiskService => Disk
+      self.class.name.split("::").third.remove("Service")
+    end
 end
diff --git a/lib/active_storage/service/disk_service.rb b/lib/active_storage/service/disk_service.rb
index f6c4fd8c4b..e2d9191189 100644
--- a/lib/active_storage/service/disk_service.rb
+++ b/lib/active_storage/service/disk_service.rb
@@ -11,37 +11,60 @@ class ActiveStorage::Service::DiskService < ActiveStorage::Service
   end
 
   def upload(key, io, checksum: nil)
-    IO.copy_stream(io, make_path_for(key))
-    ensure_integrity_of(key, checksum) if checksum
+    instrument :upload, key, checksum: checksum do
+      IO.copy_stream(io, make_path_for(key))
+      ensure_integrity_of(key, checksum) if checksum
+    end
   end
 
   def download(key)
     if block_given?
-      File.open(path_for(key)) do |file|
-        while data = file.binread(64.kilobytes)
-          yield data
+      instrument :streaming_download, key do
+        File.open(path_for(key)) do |file|
+          while data = file.binread(64.kilobytes)
+            yield data
+          end
         end
       end
     else
-      File.binread path_for(key)
+      instrument :download, key do
+        File.binread path_for(key)
+      end
     end
   end
 
   def delete(key)
-    File.delete path_for(key) rescue Errno::ENOENT # Ignore files already deleted
+    instrument :delete, key do
+      begin
+        File.delete path_for(key)
+      rescue Errno::ENOENT
+        # Ignore files already deleted
+      end
+    end
   end
 
   def exist?(key)
-    File.exist? path_for(key)
+    instrument :exist, key do |payload|
+      answer = File.exist? path_for(key)
+      payload[:exist] = answer
+      answer
+    end
   end
 
   def url(key, expires_in:, disposition:, filename:)
-    verified_key_with_expiration = ActiveStorage::VerifiedKeyWithExpiration.encode(key, expires_in: expires_in)
+    instrument :url, key do |payload|
+      verified_key_with_expiration = ActiveStorage::VerifiedKeyWithExpiration.encode(key, expires_in: expires_in)
 
-    if defined?(Rails) && defined?(Rails.application)
-      Rails.application.routes.url_helpers.rails_disk_blob_path(verified_key_with_expiration, disposition: disposition, filename: filename)
-    else
-      "/rails/blobs/#{verified_key_with_expiration}/#{filename}?disposition=#{disposition}"
+      generated_url = 
+        if defined?(Rails) && defined?(Rails.application)
+          Rails.application.routes.url_helpers.rails_disk_blob_path(verified_key_with_expiration, disposition: disposition, filename: filename)
+        else
+          "/rails/blobs/#{verified_key_with_expiration}/#{filename}?disposition=#{disposition}"
+        end
+
+      payload[:url] = generated_url
+      
+      generated_url
     end
   end
 
diff --git a/lib/active_storage/service/gcs_service.rb b/lib/active_storage/service/gcs_service.rb
index e09fa484ff..bca4ab5331 100644
--- a/lib/active_storage/service/gcs_service.rb
+++ b/lib/active_storage/service/gcs_service.rb
@@ -10,29 +10,47 @@ class ActiveStorage::Service::GCSService < ActiveStorage::Service
   end
 
   def upload(key, io, checksum: nil)
-    bucket.create_file(io, key, md5: checksum)
-  rescue Google::Cloud::InvalidArgumentError
-    raise ActiveStorage::IntegrityError
+    instrument :upload, key, checksum: checksum do
+      begin
+        bucket.create_file(io, key, md5: checksum)
+      rescue Google::Cloud::InvalidArgumentError
+        raise ActiveStorage::IntegrityError
+      end
+    end
   end
 
   # FIXME: Add streaming when given a block
   def download(key)
-    io = file_for(key).download
-    io.rewind
-    io.read
+    instrument :download, key do
+      io = file_for(key).download
+      io.rewind
+      io.read
+    end
   end
 
   def delete(key)
-    file_for(key)&.delete
+    instrument :delete, key do
+      file_for(key)&.delete
+    end
   end
 
   def exist?(key)
-    file_for(key).present?
+    instrument :exist, key do |payload|
+      answer = file_for(key).present?
+      payload[:exist] = answer
+      answer
+    end
   end
 
   def url(key, expires_in:, disposition:, filename:)
-    file_for(key).signed_url(expires: expires_in) + "&" +
-      { "response-content-disposition" => "#{disposition}; filename=\"#{filename}\"" }.to_query
+    instrument :url, key do |payload|
+      generated_url = file_for(key).signed_url(expires: expires_in) + "&" +
+        { "response-content-disposition" => "#{disposition}; filename=\"#{filename}\"" }.to_query
+      
+      payload[:url] = generated_url
+      
+      generated_url
+    end
   end
 
   private
diff --git a/lib/active_storage/service/s3_service.rb b/lib/active_storage/service/s3_service.rb
index 09886ca863..53890751ee 100644
--- a/lib/active_storage/service/s3_service.rb
+++ b/lib/active_storage/service/s3_service.rb
@@ -10,30 +10,50 @@ class ActiveStorage::Service::S3Service < ActiveStorage::Service
   end
 
   def upload(key, io, checksum: nil)
-    object_for(key).put(body: io, content_md5: checksum)
-  rescue Aws::S3::Errors::BadDigest
-    raise ActiveStorage::IntegrityError
+    instrument :upload, key, checksum: checksum do
+      begin
+        object_for(key).put(body: io, content_md5: checksum)
+      rescue Aws::S3::Errors::BadDigest
+        raise ActiveStorage::IntegrityError
+      end
+    end
   end
 
   def download(key)
     if block_given?
-      stream(key, &block)
+      instrument :streaming_download, key do
+        stream(key, &block)
+      end
     else
-      object_for(key).get.body.read.force_encoding(Encoding::BINARY)
+      instrument :download, key do
+        object_for(key).get.body.read.force_encoding(Encoding::BINARY)
+      end
     end
   end
 
   def delete(key)
-    object_for(key).delete
+    instrument :delete, key do
+      object_for(key).delete
+    end
   end
 
   def exist?(key)
-    object_for(key).exists?
+    instrument :exist, key do |payload|
+      answer = object_for(key).exists?
+      payload[:exist] = answer
+      answer
+    end
   end
 
   def url(key, expires_in:, disposition:, filename:)
-    object_for(key).presigned_url :get, expires_in: expires_in,
-      response_content_disposition: "#{disposition}; filename=\"#{filename}\""
+    instrument :url, key do |payload|
+      generated_url = object_for(key).presigned_url :get, expires_in: expires_in,
+        response_content_disposition: "#{disposition}; filename=\"#{filename}\""
+      
+      payload[:url] = generated_url
+      
+      generated_url
+    end
   end
 
   private