From 95c0c44002b78bea3b8fc7df805d62d55b9b0fd2 Mon Sep 17 00:00:00 2001 From: Erik Berlin Date: Tue, 10 Mar 2026 10:07:37 -0700 Subject: [PATCH] Add binary body formatting to the logging feature MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Binary request bodies (IO/Enumerable sources and binary-encoded strings) and binary-encoded response bodies are now formatted instead of dumped raw, preventing unreadable log output when transferring files. Add `Request::Body#loggable?` and `Response::Body#loggable?` predicates to detect inspectable body content, and a `binary_formatter` option on the Logging feature with three modes: * `:stats` (default) — logs "BINARY DATA (N bytes)" * `:base64` — logs base64-encoded content with byte count * `Proc` — custom formatting via a callable Closes https://github.com/httprb/http/issues/784. --- CHANGELOG.md | 8 + lib/http/features/logging.rb | 77 +++++++++- lib/http/request/body.rb | 18 +++ lib/http/response/body.rb | 14 ++ sig/http.rbs | 13 +- test/http/features/logging_test.rb | 235 ++++++++++++++++++++++++++++- test/http/request/body_test.rb | 46 ++++++ test/http/response/body_test.rb | 18 +++ 8 files changed, 420 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 756cd594..f0e5cda2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,6 +27,14 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 per RFC 3986. Supports chaining (`HTTP.base_uri("https://api.example.com/v1") .get("users")`), and integrates with `persistent` connections by deriving the host when omitted (#519, #512, #493) +- `Request::Body#loggable?` and `Response::Body#loggable?` predicates, and a + `binary_formatter` option for the logging feature. Binary bodies + (IO/Enumerable request sources, binary-encoded request strings, and + binary-encoded responses) are now formatted instead of dumped raw, + preventing unreadable log output when transferring files like images or + audio. Available formatters: `:stats` (default, logs byte count), + `:base64` (logs base64-encoded content), or a custom `Proc`. Invalid + formatter values raise `ArgumentError` (#784) - `Feature#on_request` and `Feature#around_request` lifecycle hooks, called before/around each request attempt (including retries), for per-attempt side effects like instrumentation spans and circuit breakers (#826) diff --git a/lib/http/features/logging.rb b/lib/http/features/logging.rb index 48257424..74d783d7 100644 --- a/lib/http/features/logging.rb +++ b/lib/http/features/logging.rb @@ -9,6 +9,17 @@ module Features # # HTTP.use(logging: {logger: Logger.new(STDOUT)}).get("https://example.com/") # + # Binary bodies (IO/Enumerable request sources and binary-encoded + # responses) are formatted using the +binary_formatter+ option instead + # of being dumped raw. Available formatters: + # + # - +:stats+ (default) — logs BINARY DATA (N bytes) + # - +:base64+ — logs BINARY DATA (N bytes)\n + # - +Proc+ — calls the proc with the raw binary string + # + # @example Custom binary formatter + # HTTP.use(logging: {logger: Logger.new(STDOUT), binary_formatter: :base64}) + # class Logging < Feature HTTP::Options.register_feature(:logging, self) @@ -39,12 +50,17 @@ class NullLogger # @example # Logging.new(logger: Logger.new(STDOUT)) # + # @example With binary formatter + # Logging.new(logger: Logger.new(STDOUT), binary_formatter: :base64) + # # @param logger [#info, #debug] logger instance + # @param binary_formatter [:stats, :base64, #call] how to log binary bodies # @return [Logging] # @api public - def initialize(logger: NullLogger.new) + def initialize(logger: NullLogger.new, binary_formatter: :stats) super() @logger = logger + @binary_formatter = validate_binary_formatter!(binary_formatter) end # Logs and returns the request @@ -57,7 +73,7 @@ def initialize(logger: NullLogger.new) # @api public def wrap_request(request) logger.info { "> #{request.verb.to_s.upcase} #{request.uri}" } - logger.debug { "#{stringify_headers(request.headers)}\n\n#{request.body.source}" } + log_request_details(request) request end @@ -83,11 +99,43 @@ def wrap_response(response) private + # Validate and return the binary_formatter option + # @return [:stats, :base64, #call] + # @raise [ArgumentError] if the formatter is not a valid option + # @api private + def validate_binary_formatter!(formatter) + return formatter if formatter == :stats || formatter == :base64 || formatter.respond_to?(:call) + + raise ArgumentError, + "binary_formatter must be :stats, :base64, or a callable " \ + "(got #{formatter.inspect})" + end + + # Log request headers and body (when loggable) + # @return [void] + # @api private + def log_request_details(request) + headers = stringify_headers(request.headers) + if request.body.loggable? + source = request.body.source + body = source.encoding == Encoding::BINARY ? format_binary(source) : source # steep:ignore + logger.debug { "#{headers}\n\n#{body}" } + else + logger.debug { headers } + end + end + # Log response with body inline (for non-streaming string bodies) # @return [HTTP::Response] # @api private def log_response_body_inline(response) - logger.debug { "#{stringify_headers(response.headers)}\n\n#{response.body}" } + body = response.body + headers = stringify_headers(response.headers) + if body.respond_to?(:encoding) && body.encoding == Encoding::BINARY # steep:ignore + logger.debug { "#{headers}\n\n#{format_binary(body)}" } # steep:ignore + else + logger.debug { "#{headers}\n\n#{body}" } + end response end @@ -110,10 +158,25 @@ def logged_response_options(response) # @return [HTTP::Response::Body] # @api private def logged_body(body) - stream = BodyLogger.new(body.instance_variable_get(:@stream), logger) + formatter = body.loggable? ? nil : method(:format_binary) # steep:ignore + stream = BodyLogger.new(body.instance_variable_get(:@stream), logger, formatter: formatter) # steep:ignore Response::Body.new(stream, encoding: body.encoding) end + # Format binary data according to the configured binary_formatter + # @return [String] + # @api private + def format_binary(data) + case @binary_formatter + when :stats + format("BINARY DATA (%d bytes)", data.bytesize) + when :base64 + format("BINARY DATA (%d bytes)\n%s", data.bytesize, [data].pack("m0")) + else + @binary_formatter.call(data) # steep:ignore + end + end + # Convert headers to a string representation # @return [String] # @api private @@ -139,12 +202,14 @@ class BodyLogger # # @param stream [#readpartial] the stream to wrap # @param logger [#debug] the logger instance + # @param formatter [#call, nil] optional formatter for each chunk # @return [BodyLogger] # @api public - def initialize(stream, logger) + def initialize(stream, logger, formatter: nil) @stream = stream @connection = stream.respond_to?(:connection) ? stream.connection : stream @logger = logger + @formatter = formatter end # Read a chunk from the underlying stream and log it @@ -157,7 +222,7 @@ def initialize(stream, logger) # @api public def readpartial(*) chunk = @stream.readpartial(*) - @logger.debug { chunk } + @logger.debug { @formatter ? @formatter.call(chunk) : chunk } # steep:ignore chunk end end diff --git a/lib/http/request/body.rb b/lib/http/request/body.rb index cbaaa6fd..9d260ee0 100644 --- a/lib/http/request/body.rb +++ b/lib/http/request/body.rb @@ -37,6 +37,24 @@ def empty? @source.nil? end + # Whether the body content can be accessed for logging + # + # Returns true for String sources (the content can be inspected). + # Returns false for IO streams and Enumerables (which cannot be + # read without consuming them), and for nil bodies. + # + # The logging feature checks the string encoding separately to + # decide whether to log the content as text or format it as binary. + # + # @example + # body.loggable? # => true + # + # @return [Boolean] + # @api public + def loggable? + @source.is_a?(String) + end + # Returns size for the "Content-Length" header # # @example diff --git a/lib/http/response/body.rb b/lib/http/response/body.rb index 7bbc6a5c..3c70e4c1 100644 --- a/lib/http/response/body.rb +++ b/lib/http/response/body.rb @@ -115,6 +115,20 @@ def stream! @streaming = true end + # Whether the body content is suitable for logging + # + # Returns true when the body encoding is not binary. Binary responses + # (images, audio, compressed data) produce unreadable log output. + # + # @example + # body.loggable? # => true + # + # @return [Boolean] + # @api public + def loggable? + @encoding != Encoding::BINARY + end + # Easier to interpret string inspect # # @example diff --git a/sig/http.rbs b/sig/http.rbs index 79410c7e..012a3e3e 100644 --- a/sig/http.rbs +++ b/sig/http.rbs @@ -395,21 +395,28 @@ module HTTP attr_reader logger: untyped - def initialize: (?logger: untyped) -> void + @binary_formatter: :stats | :base64 | ^(String) -> String + + def initialize: (?logger: untyped, ?binary_formatter: :stats | :base64 | ^(String) -> String) -> void def wrap_request: (Request request) -> Request def wrap_response: (Response response) -> Response private + def validate_binary_formatter!: (:stats | :base64 | ^(String) -> String formatter) -> (:stats | :base64 | ^(String) -> String) + def log_request_details: (Request request) -> void def log_response_body_inline: (Response response) -> Response def logged_response_options: (Response response) -> Hash[Symbol, untyped] def logged_body: (Response::Body body) -> Response::Body + def format_binary: (String data) -> String def stringify_headers: (Headers headers) -> String class BodyLogger attr_reader connection: untyped - def initialize: (untyped stream, untyped logger) -> void + @formatter: (^(String) -> String)? + + def initialize: (untyped stream, untyped logger, ?formatter: (^(String) -> String)?) -> void def readpartial: (?Integer size, ?String? outbuf) -> String end end @@ -741,6 +748,7 @@ module HTTP def initialize: (untyped source) -> void def empty?: () -> bool + def loggable?: () -> bool def size: () -> Integer def each: () { (String) -> void } -> self | () -> Enumerator[String, self] @@ -881,6 +889,7 @@ module HTTP def to_s: () -> untyped alias to_str to_s def stream!: () -> untyped + def loggable?: () -> bool def inspect: () -> String private diff --git a/test/http/features/logging_test.rb b/test/http/features/logging_test.rb index efd7a265..92260e78 100644 --- a/test/http/features/logging_test.rb +++ b/test/http/features/logging_test.rb @@ -57,6 +57,50 @@ end end + describe "logging the request with non-loggable IO body" do + let(:request) do + HTTP::Request.new( + verb: :post, + uri: "https://example.com/upload", + headers: { content_type: "application/octet-stream" }, + body: FakeIO.new("binary data") + ) + end + + it "logs headers without the body" do + feature.wrap_request(request) + + expected = <<~OUTPUT + ** INFO ** + > POST https://example.com/upload + ** DEBUG ** + Content-Type: application/octet-stream + Host: example.com + User-Agent: http.rb/#{HTTP::VERSION} + OUTPUT + assert_equal expected, logdev.string + end + end + + describe "logging the request with binary-encoded string body" do + let(:binary_data) { String.new("\x89PNG\r\n", encoding: Encoding::BINARY) } + let(:request) do + HTTP::Request.new( + verb: :post, + uri: "https://example.com/upload", + headers: { content_type: "application/octet-stream" }, + body: binary_data + ) + end + + it "logs binary stats instead of raw content" do + feature.wrap_request(request) + + assert_includes logdev.string, "BINARY DATA (6 bytes)" + refute_includes logdev.string, "\x89PNG" + end + end + describe "logging the response" do context "with a string body" do let(:response) do @@ -93,7 +137,7 @@ closed?: true ) end - let(:body) { HTTP::Response::Body.new(stream) } + let(:body) { HTTP::Response::Body.new(stream, encoding: Encoding::UTF_8) } let(:response) do HTTP::Response.new( version: "1.1", @@ -126,6 +170,61 @@ end end + context "with a binary string body" do + let(:binary_data) { String.new("\x89PNG\r\n\x1A\n", encoding: Encoding::BINARY) } + let(:response) do + HTTP::Response.new( + version: "1.1", + status: 200, + headers: { content_type: "application/octet-stream" }, + body: binary_data, + request: HTTP::Request.new(verb: :get, uri: "https://example.com") + ) + end + + it "logs binary stats instead of raw content" do + feature.wrap_response(response) + + assert_includes logdev.string, "BINARY DATA (8 bytes)" + refute_includes logdev.string, "\x89PNG" + end + end + + context "with a binary streaming body" do + let(:chunks) { [String.new("\x89PNG\r\n", encoding: Encoding::BINARY)] } + let(:stream) do + fake( + readpartial: proc { chunks.shift or raise EOFError }, + close: nil, + closed?: true + ) + end + let(:body) { HTTP::Response::Body.new(stream) } + let(:response) do + HTTP::Response.new( + version: "1.1", + status: 200, + headers: { content_type: "application/octet-stream" }, + body: body, + request: HTTP::Request.new(verb: :get, uri: "https://example.com") + ) + end + + it "logs binary stats for each chunk instead of raw content" do + wrapped = feature.wrap_response(response) + wrapped.body.to_s + + assert_includes logdev.string, "BINARY DATA (6 bytes)" + refute_includes logdev.string, "\x89PNG" + end + + it "preserves the full body content" do + wrapped = feature.wrap_response(response) + + assert_equal String.new("\x89PNG\r\n", encoding: Encoding::BINARY), wrapped.body.to_s + end + end + context "when logger level is above debug" do let(:feature) do logger = Logger.new(logdev) @@ -161,6 +260,129 @@ end end + describe "binary_formatter validation" do + it "raises ArgumentError for unsupported values" do + err = assert_raises(ArgumentError) do + HTTP::Features::Logging.new(binary_formatter: :unsupported) + end + assert_includes err.message, "binary_formatter must be :stats, :base64, or a callable" + assert_includes err.message, ":unsupported" + end + + it "accepts :stats" do + HTTP::Features::Logging.new(binary_formatter: :stats) + end + + it "accepts :base64" do + HTTP::Features::Logging.new(binary_formatter: :base64) + end + + it "accepts a callable" do + HTTP::Features::Logging.new(binary_formatter: ->(data) { data }) + end + end + + describe "binary_formatter option" do + context "with :base64 formatter" do + let(:feature) do + logger = Logger.new(logdev) + logger.formatter = ->(severity, _, _, message) { format("** %s **\n%s\n", severity, message) } + + HTTP::Features::Logging.new(logger: logger, binary_formatter: :base64) + end + + let(:binary_data) { String.new("\x89PNG\r\n\x1A\n", encoding: Encoding::BINARY) } + let(:response) do + HTTP::Response.new( + version: "1.1", + status: 200, + headers: { content_type: "image/png" }, + body: binary_data, + request: HTTP::Request.new(verb: :get, uri: "https://example.com") + ) + end + + it "logs base64-encoded body" do + feature.wrap_response(response) + + assert_includes logdev.string, "BINARY DATA (8 bytes)" + assert_includes logdev.string, [binary_data].pack("m0") + end + + it "base64-encodes streaming binary chunks" do + chunks = [String.new("\xFF\xD8\xFF", encoding: Encoding::BINARY)] + stream = fake( + readpartial: proc { chunks.shift or raise EOFError }, + close: nil, + closed?: true + ) + body = HTTP::Response::Body.new(stream) + resp = HTTP::Response.new( + version: "1.1", + status: 200, + headers: { content_type: "image/jpeg" }, + body: body, + request: HTTP::Request.new(verb: :get, uri: "https://example.com") + ) + + wrapped = feature.wrap_response(resp) + wrapped.body.to_s + + assert_includes logdev.string, "BINARY DATA (3 bytes)" + assert_includes logdev.string, ["\xFF\xD8\xFF"].pack("m0") + end + end + + context "with Proc formatter" do + let(:feature) do + logger = Logger.new(logdev) + logger.formatter = ->(severity, _, _, message) { format("** %s **\n%s\n", severity, message) } + + formatter = ->(data) { "[#{data.bytesize} bytes hidden]" } + HTTP::Features::Logging.new(logger: logger, binary_formatter: formatter) + end + + let(:binary_data) { String.new("\x00\x01\x02", encoding: Encoding::BINARY) } + let(:response) do + HTTP::Response.new( + version: "1.1", + status: 200, + headers: { content_type: "application/octet-stream" }, + body: binary_data, + request: HTTP::Request.new(verb: :get, uri: "https://example.com") + ) + end + + it "uses the custom formatter" do + feature.wrap_response(response) + + assert_includes logdev.string, "[3 bytes hidden]" + end + + it "uses the custom formatter for streaming chunks" do + chunks = [String.new("\xDE\xAD", encoding: Encoding::BINARY)] + stream = fake( + readpartial: proc { chunks.shift or raise EOFError }, + close: nil, + closed?: true + ) + body = HTTP::Response::Body.new(stream) + resp = HTTP::Response.new( + version: "1.1", + status: 200, + headers: { content_type: "application/octet-stream" }, + body: body, + request: HTTP::Request.new(verb: :get, uri: "https://example.com") + ) + + wrapped = feature.wrap_response(resp) + wrapped.body.to_s + + assert_includes logdev.string, "[2 bytes hidden]" + end + end + end + describe "BodyLogger" do let(:logger) do logger = Logger.new(logdev) @@ -181,6 +403,17 @@ assert_includes logdev.string, "world" end + it "applies formatter when provided" do + chunks = %w[hello world] + stream = fake(readpartial: proc { chunks.shift or raise EOFError }) + formatter = ->(data) { "FORMATTED: #{data}" } + + body_logger = HTTP::Features::Logging::BodyLogger.new(stream, logger, formatter: formatter) + + assert_equal "hello", body_logger.readpartial + assert_includes logdev.string, "FORMATTED: hello" + end + it "exposes the underlying connection" do connection = Object.new stream = fake( diff --git a/test/http/request/body_test.rb b/test/http/request/body_test.rb index d2a83311..87a730e6 100644 --- a/test/http/request/body_test.rb +++ b/test/http/request/body_test.rb @@ -124,6 +124,48 @@ end end + describe "#loggable?" do + context "when body is a text string" do + let(:body) { "text content" } + + it "returns true" do + assert_predicate subject_under_test, :loggable? + end + end + + context "when body is a binary-encoded string" do + let(:body) { String.new("\x89PNG\r\n", encoding: Encoding::BINARY) } + + it "returns true" do + assert_predicate subject_under_test, :loggable? + end + end + + context "when body is nil" do + let(:body) { nil } + + it "returns false" do + refute_predicate subject_under_test, :loggable? + end + end + + context "when body is an IO" do + let(:body) { FakeIO.new("IO body") } + + it "returns false" do + refute_predicate subject_under_test, :loggable? + end + end + + context "when body is an Enumerable" do + let(:body) { %w[bees cows] } + + it "returns false" do + refute_predicate subject_under_test, :loggable? + end + end + end + describe "#each" do let(:chunks) do subject_under_test.enum_for(:each).map(&:dup) @@ -324,6 +366,10 @@ assert_equal ["subclass body"], chunks end + + it "is loggable" do + assert_predicate subject_under_test, :loggable? + end end context "when comparing with a Body subclass" do diff --git a/test/http/response/body_test.rb b/test/http/response/body_test.rb index 90671a96..30ea7117 100644 --- a/test/http/response/body_test.rb +++ b/test/http/response/body_test.rb @@ -107,6 +107,24 @@ end end + describe "#loggable?" do + context "with text encoding" do + let(:body) { HTTP::Response::Body.new(connection, encoding: Encoding::UTF_8) } + + it "returns true" do + assert_predicate body, :loggable? + end + end + + context "with binary encoding" do + let(:body) { HTTP::Response::Body.new(connection) } + + it "returns false" do + refute_predicate body, :loggable? + end + end + end + describe "#inspect" do it "includes streaming state" do assert_match(/@streaming=false/, body.inspect)