Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 8 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
77 changes: 71 additions & 6 deletions lib/http/features/logging.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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 <tt>BINARY DATA (N bytes)</tt>
# - +:base64+ — logs <tt>BINARY DATA (N bytes)\n<base64></tt>
# - +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)

Expand Down Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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

Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
Expand Down
18 changes: 18 additions & 0 deletions lib/http/request/body.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
14 changes: 14 additions & 0 deletions lib/http/response/body.rb
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
13 changes: 11 additions & 2 deletions sig/http.rbs
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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
Expand Down
Loading