From eefe81a13dcf23ae0f23d7bf9cde5ec88c93094d Mon Sep 17 00:00:00 2001 From: Mike Dalessio Date: Mon, 28 Sep 2026 17:30:39 -0400 Subject: [PATCH 1/2] Log every HotCell call to the Rails log by default Each application that wanted a log line per call had to write its own `perform.hot_cell` subscriber. Add `HotCell::LogSubscriber`, which the railtie attaches, and describe its line in the README. [Fix #10] --- CHANGELOG.md | 5 ++ README.md | 9 +++ hotcell-client/lib/hot_cell/log_subscriber.rb | 42 ++++++++++ hotcell-client/lib/hot_cell/railtie.rb | 10 ++- hotcell-client/test/log_subscriber_test.rb | 76 +++++++++++++++++++ hotcell-client/test/railtie_test.rb | 57 ++++++++++++++ 6 files changed, 197 insertions(+), 2 deletions(-) create mode 100644 hotcell-client/lib/hot_cell/log_subscriber.rb create mode 100644 hotcell-client/test/log_subscriber_test.rb create mode 100644 hotcell-client/test/railtie_test.rb diff --git a/CHANGELOG.md b/CHANGELOG.md index 6dd7a8e..e45077f 100644 --- a/CHANGELOG.md +++ b/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,6 +32,10 @@ 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. 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 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. diff --git a/README.md b/README.md index c25f265..7ba3b1e 100644 --- a/README.md +++ b/README.md @@ -557,6 +557,15 @@ 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. To turn it 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 diff --git a/hotcell-client/lib/hot_cell/log_subscriber.rb b/hotcell-client/lib/hot_cell/log_subscriber.rb new file mode 100644 index 0000000..9896609 --- /dev/null +++ b/hotcell-client/lib/hot_cell/log_subscriber.rb @@ -0,0 +1,42 @@ +# 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", + 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 diff --git a/hotcell-client/lib/hot_cell/railtie.rb b/hotcell-client/lib/hot_cell/railtie.rb index c8660da..e7ad1c5 100644 --- a/hotcell-client/lib/hot_cell/railtie.rb +++ b/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 diff --git a/hotcell-client/test/log_subscriber_test.rb b/hotcell-client/test/log_subscriber_test.rb new file mode 100644 index 0000000..c5ec74f --- /dev/null +++ b/hotcell-client/test/log_subscriber_test.rb @@ -0,0 +1,76 @@ +# frozen_string_literal: true + +require "test_helper" +require "hot_cell/log_subscriber" +require "stringio" + +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 + + 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 diff --git a/hotcell-client/test/railtie_test.rb b/hotcell-client/test/railtie_test.rb new file mode 100644 index 0000000..0c6df0c --- /dev/null +++ b/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 From 79bda12e1542b15d9d502493141d35a3ba0d0b77 Mon Sep 17 00:00:00 2001 From: Mike Dalessio Date: Tue, 29 Sep 2026 17:58:09 -0400 Subject: [PATCH 2/2] Log an interrupted HotCell call as its exception, not ok When an exception escaped the call, such as the application's own request timeout, `HotCell::LogSubscriber` logged the call as `"code":"ok"` with no cell and no operation. Put the cell and the operation on the event before the call, and log the exception's class in place of the code. --- CHANGELOG.md | 3 ++- README.md | 3 ++- hotcell-client/lib/hot_cell/client.rb | 4 +--- hotcell-client/lib/hot_cell/log_subscriber.rb | 3 ++- hotcell-client/test/log_subscriber_test.rb | 17 +++++++++++++++++ 5 files changed, 24 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e45077f..a19268c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -34,10 +34,11 @@ Some actions that application developers should consider taking when upgrading f #### 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. The railtie attaches it. Without Rails, require `hot_cell/log_subscriber`, call `HotCell::LogSubscriber.attach_to :hot_cell`, and set `ActiveSupport::LogSubscriber.logger`. +* `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 diff --git a/README.md b/README.md index 7ba3b1e..d94dbf7 100644 --- a/README.md +++ b/README.md @@ -563,7 +563,8 @@ In a Rails application, `HotCell::LogSubscriber` already writes one `info` line 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. To turn it off, call +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 diff --git a/hotcell-client/lib/hot_cell/client.rb b/hotcell-client/lib/hot_cell/client.rb index b40364d..d59c732 100644 --- a/hotcell-client/lib/hot_cell/client.rb +++ b/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 diff --git a/hotcell-client/lib/hot_cell/log_subscriber.rb b/hotcell-client/lib/hot_cell/log_subscriber.rb index 9896609..ffdd28e 100644 --- a/hotcell-client/lib/hot_cell/log_subscriber.rb +++ b/hotcell-client/lib/hot_cell/log_subscriber.rb @@ -28,7 +28,8 @@ def perform(event) " HotCell (#{duration_ms}ms) " + JSON.generate({ cell: payload[:cell], operation: payload[:operation], - code: payload[:code] || "ok", + code: payload[:code] || ("ok" unless payload[:exception]), + exception: payload[:exception]&.first, cause: payload[:cause], perform_ms: payload[:perform_ms], duration_ms: duration_ms, diff --git a/hotcell-client/test/log_subscriber_test.rb b/hotcell-client/test/log_subscriber_test.rb index c5ec74f..fd87a3f 100644 --- a/hotcell-client/test/log_subscriber_test.rb +++ b/hotcell-client/test/log_subscriber_test.rb @@ -3,6 +3,7 @@ require "test_helper" require "hot_cell/log_subscriber" require "stringio" +require "timeout" class LogSubscriberTest < HotCellClientTest FORGERY = "libgomp: Thread creation failed\nforged\u0085forged\u2028forged\u2029forged" @@ -59,6 +60,22 @@ def test_a_failed_call_logs_its_code_its_cause_and_its_stderr 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"