Log every HotCell call to the Rails log by default

CHANGELOG.md

@@ -18,6 +18,7 @@ gem but are what an operator runs against their own image.
 Some actions that application developers should consider taking when upgrading from an earlier version:
 
 * Replace a cell's copies of `examples/operations/echo.rb` and `reopen.rb` with `require "hot_cell/health_operations"`, and point the application's clients at `health.echo` and `health.reopen`. See the README's "Rails healthcheck".
+* Remove the application's own log line for the `perform.hot_cell` event. `HotCell::LogSubscriber` now writes one. See the README's "Per-call telemetry".
 
 ### HotCell::Server
 
@@ -31,8 +32,13 @@ Some actions that application developers should consider taking when upgrading f
 
 ### HotCell::Client
 
+#### Added
+
+* `HotCell::LogSubscriber` writes one `info` line to the Rails log for each call. The line has the cell, the operation, the code and both durations. It also has the byte counts when the client can measure them. A failed call also has the cause and the `stderr` when it has them. When an exception interrupts the call, the line has the exception's class in place of the code and the cell's duration. The railtie attaches it. Without Rails, require `hot_cell/log_subscriber`, call `HotCell::LogSubscriber.attach_to :hot_cell`, and set `ActiveSupport::LogSubscriber.logger`.
+
 #### Fixed
 
+* The `perform.hot_cell` event now carries `cell` and `operation` when an exception escapes the call. Previously, a subscriber saw neither.
 * The client now returns `capacity` when a full cell closes the connection before the client finishes sending the request. Previously, the client returned `unavailable` for the broken pipe.
 
 ### Tooling

README.md

@@ -557,6 +557,16 @@ Subscribe to the `perform.hot_cell` Active Support Notification for logging, met
 fires on every call, success or failure, and it is the only signal that survives a dead cell -- an
 unreachable socket comes back as code `unavailable`, so the primary alarm belongs here.
 
+In a Rails application, `HotCell::LogSubscriber` already writes one `info` line per call to the Rails log:
+
+```
+  HotCell (41.2ms) {"cell":"images","operation":"active_storage.transformers.image.vips","code":"ok","perform_ms":38,"duration_ms":41.2,"bytes_in":20480,"bytes_out":8192}
+```
+
+A failed call adds `cause` and `stderr` when it has them. A call interrupted by an exception, such as the
+application's own request timeout, logs the exception's class in place of the code. To turn the line off, call
+`HotCell::LogSubscriber.detach_from :hot_cell` in an initializer.
+
 ### Container healthcheck
 
 The installed Dockerfile wires `hotcell-health` up as the Docker `HEALTHCHECK`. It probes the

hotcell-client/lib/hot_cell/client.rb

@@ -96,7 +96,7 @@ def perform_in_hotcell(inputs, outputs, payload = {})
       line = request_line(inputs, outputs, payload)
 
       response = nil
-      ActiveSupport::Notifications.instrument "perform.hot_cell" do |event|
+      ActiveSupport::Notifications.instrument "perform.hot_cell", operation: self.class.operation, cell: cell.name do |event|
         response = verify_output(cell.transport.call(cell, line, descriptors), outputs)
         publish event, cell, response, inputs, outputs
       end
@@ -171,8 +171,6 @@ def verify_output(response, outputs)
       def publish(event, cell, response, inputs, outputs)
         failure = response.failure
 
-        event[:operation] = self.class.operation
-        event[:cell] = cell.name
         event[:code] = failure&.code
         event[:cause] = failure&.cause
         event[:signal] = failure&.signal

hotcell-client/lib/hot_cell/log_subscriber.rb

@@ -0,0 +1,43 @@
+# frozen_string_literal: true
+
+require "json"
+
+# All three, in this order, on Rails main: log_subscriber needs ColorizeLogging, which only the top-level file
+# autoloads, and loading it before deprecation warns of a circular require.
+require "active_support"
+require "active_support/deprecation"
+require "active_support/log_subscriber"
+
+module HotCell
+  # One line per call, success or failure, from the `perform.hot_cell` event. The railtie attaches it; an
+  # application without Rails calls `HotCell::LogSubscriber.attach_to :hot_cell` and sets
+  # `ActiveSupport::LogSubscriber.logger`.
+  #
+  # Two clocks on purpose: `perform_ms` is what the cell measured inside the worker and `duration_ms` is what
+  # this process waited, and their difference is the queue and the socket.
+  #
+  # `stderr` is text a tool wrote while reading a hostile file. It goes into the JSON and nowhere else, so
+  # its newlines arrive escaped rather than as forged log lines. `ascii_only` because JSON leaves U+2028 and
+  # its kin raw, and a log viewer may break a line on them.
+  class LogSubscriber < ActiveSupport::LogSubscriber
+    def perform(event)
+      payload = event.payload
+      duration_ms = event.duration.round(1)
+
+      info do
+        "  HotCell (#{duration_ms}ms) " + JSON.generate({
+          cell: payload[:cell],
+          operation: payload[:operation],
+          code: payload[:code] || ("ok" unless payload[:exception]),
+          exception: payload[:exception]&.first,
+          cause: payload[:cause],
+          perform_ms: payload[:perform_ms],
+          duration_ms: duration_ms,
+          bytes_in: payload[:bytes_in],
+          bytes_out: payload[:bytes_out],
+          stderr: payload[:stderr],
+        }.compact, ascii_only: true)
+      end
+    end
+  end
+end

hotcell-client/lib/hot_cell/railtie.rb

@@ -1,9 +1,15 @@
 # frozen_string_literal: true
 
+require "hot_cell/log_subscriber"
+
 module HotCell
-  # Loads the hotcell:install task into a Rails application. The gem works without Rails, so this file
-  # is required only when Rails::Railtie is already defined.
+  # Loads the hotcell:install task into a Rails application and logs each call. The gem works without
+  # Rails, so this file is required only when Rails::Railtie is already defined.
   class Railtie < ::Rails::Railtie
+    initializer "hot_cell.log_subscriber" do
+      HotCell::LogSubscriber.attach_to :hot_cell
+    end
+
     rake_tasks do
       load File.expand_path("tasks/hotcell.rake", __dir__)
     end

hotcell-client/test/log_subscriber_test.rb

@@ -0,0 +1,93 @@
+# frozen_string_literal: true
+
+require "test_helper"
+require "hot_cell/log_subscriber"
+require "stringio"
+require "timeout"
+
+class LogSubscriberTest < HotCellClientTest
+  FORGERY = "libgomp: Thread creation failed\nforged\u0085forged\u2028forged\u2029forged"
+
+  def setup
+    super
+    @previous_logger = ActiveSupport::LogSubscriber.logger
+    @log = StringIO.new
+    ActiveSupport::LogSubscriber.logger = Logger.new(@log, formatter: ->(severity, _, _, message) { "#{severity} #{message}\n" })
+    HotCell::LogSubscriber.attach_to :hot_cell
+  end
+
+  def teardown
+    HotCell::LogSubscriber.detach_from :hot_cell
+    ActiveSupport::LogSubscriber.logger = @previous_logger
+    super
+  end
+
+  def test_a_call_logs_one_line_with_the_cell_the_operation_and_both_clocks
+    with_cell do
+      with_files("hello") do |source, destination|
+        reading(source) { |input| writing(destination) { |output| Uppercase.perform_in_hotcell input, output } }
+      end
+    end
+
+    assert_equal 1, @log.string.lines.size
+    assert_match(/\AINFO   HotCell \(\d+\.\dms\) \{/, @log.string)
+
+    fields = logged_fields
+    assert_equal "test", fields["cell"]
+    assert_equal "test.uppercase", fields["operation"]
+    assert_equal "ok", fields["code"]
+    assert_equal 5, fields["bytes_in"]
+    assert_equal 5, fields["bytes_out"]
+    assert_kind_of Numeric, fields["perform_ms"]
+    assert_kind_of Numeric, fields["duration_ms"]
+  end
+
+  # The line is the only record of a crash's diagnosis when the caller discards the failure rather than
+  # retrying it. The stderr is hostile text, so it must arrive escaped inside the one line, including the
+  # Unicode line separators that JSON leaves raw and that a log viewer may still break on.
+  def test_a_failed_call_logs_its_code_its_cause_and_its_stderr
+    with_cell do
+      assert_raises TemporarilyUnavailable do
+        StderrWriter.perform_in_hotcell [], [], text: FORGERY, fatal: true
+      end
+    end
+
+    assert_equal 1, @log.string.split(/\R/).size
+
+    fields = logged_fields
+    assert_equal "killed", fields["code"]
+    assert_equal "crashed", fields["cause"]
+    assert_match FORGERY, fields["stderr"]
+  end
+
+  # An exception that escapes the call, such as the application's own request timeout, still fires the event,
+  # but before the client has recorded any verdict.
+  def test_a_call_interrupted_by_an_exception_logs_the_exception_rather_than_ok
+    HotCell.root = "/nowhere"
+    HotCell.register "test", permanent: Unprocessable, transient: TemporarilyUnavailable,
+                             transport: ->(*) { raise Timeout::Error, "the request ran out of time" }
+
+    assert_raises(Timeout::Error) { Uppercase.perform_in_hotcell [], [], {} }
+
+    fields = logged_fields
+    assert_equal "test", fields["cell"]
+    assert_equal "test.uppercase", fields["operation"]
+    assert_equal "Timeout::Error", fields["exception"]
+    assert_nil fields["code"]
+  end
+
+  class Uppercase < HotCell::Client
+    hotcell "test"
+    operation "test.uppercase"
+  end
+
+  class StderrWriter < HotCell::Client
+    hotcell "test"
+    operation "test.stderr_writer"
+  end
+
+  private
+    def logged_fields
+      JSON.parse(@log.string[/\{.*\}/])
+    end
+end

hotcell-client/test/railtie_test.rb

@@ -0,0 +1,57 @@
+# frozen_string_literal: true
+
+require "test_helper"
+require "stringio"
+
+begin
+  require "rails"
+rescue LoadError
+  # The gem does not depend on Rails; railties rides in through the development bundle.
+end
+
+require "hot_cell/railtie" if defined?(Rails::Railtie)
+
+# A Rails application initializes once per process, so this boots one and asserts everything the railtie
+# does at boot.
+class RailtieTest < HotCellClientTest
+  def setup
+    skip "railties is not in this bundle" unless defined?(Rails::Railtie)
+    super
+    @previous_logger = ActiveSupport::LogSubscriber.logger
+    @root = Dir.mktmpdir("hotcell-railtie")
+  end
+
+  def teardown
+    HotCell::LogSubscriber.detach_from :hot_cell
+    ActiveSupport::LogSubscriber.logger = @previous_logger
+    FileUtils.rm_rf @root if @root
+    super
+  end
+
+  def test_boot_logs_each_call_to_the_rails_logger
+    log = StringIO.new
+    application(log).initialize!
+
+    with_cell { Echo.perform_in_hotcell [], [], {} }
+
+    lines = log.string.lines.grep(/HotCell \(\d+\.\dms\)/)
+    assert_equal 1, lines.size, "expected one line for one call"
+    assert_match '"operation":"test.echo"', lines.first
+  end
+
+  class Echo < HotCell::Client
+    hotcell "test"
+    operation "test.echo"
+  end
+
+  private
+    def application(log)
+      root = @root
+      Class.new(Rails::Application) do
+        config.eager_load = false
+        config.root = root
+        config.logger = Logger.new(log)
+        config.active_support.deprecation = :silence
+      end.instance
+    end
+end