diff --git a/README.md b/README.md index 52c83cd..3144132 100644 --- a/README.md +++ b/README.md @@ -189,6 +189,22 @@ HTTP.Telemetry.request_stop(200, URI.parse("https://example.com"), 1024, 1500) HTTP.Telemetry.request_exception(URI.parse("https://example.com"), :timeout, 5000) ``` +### HTTP.Logger +The library includes a logger that can be attached to telemetry events to provide detailed logging of HTTP requests. To enable the logger, simply call `HTTP.Logger.attach()` in your application's startup code, for example in `application.ex`: + +```elixir +defmodule MyApp.Application do + use Application + + def start(_type, _args) do + # Enable HTTP fetch logging + HTTP.Logger.attach() + + # ... rest of your application startup + end +end +``` + ### HTTP.Request Request configuration struct. diff --git a/lib/http/logger.ex b/lib/http/logger.ex new file mode 100644 index 0000000..84bb37e --- /dev/null +++ b/lib/http/logger.ex @@ -0,0 +1,91 @@ +defmodule HTTP.Logger do + @moduledoc """ + Attaches to HTTP telemetry events and logs them. + """ + require Logger + + @doc """ + Attaches the logger to the telemetry events. + """ + def attach do + :telemetry.attach_many( + "http-logger", + [ + [:http_fetch, :request, :start], + [:http_fetch, :request, :stop], + [:http_fetch, :request, :exception], + [:http_fetch, :response, :body_read_start], + [:http_fetch, :response, :body_read_stop], + [:http_fetch, :streaming, :start], + [:http_fetch, :streaming, :chunk], + [:http_fetch, :streaming, :stop] + ], + &__MODULE__.handle_event/4, + nil + ) + end + + def handle_event([:http_fetch, :request, :start], _measurements, metadata, _config) do + Logger.info( + "#{metadata.method} #{metadata.url} - Request started", + request_id: metadata.url + ) + end + + def handle_event([:http_fetch, :request, :stop], measurements, metadata, _config) do + Logger.info( + "#{metadata.status} #{metadata.url} - Request completed in #{measurements.duration}µs", + request_id: metadata.url, + duration: measurements.duration, + status: measurements.status, + response_size: measurements.response_size + ) + end + + def handle_event([:http_fetch, :request, :exception], measurements, metadata, _config) do + Logger.error( + "Request to #{metadata.url} failed: #{inspect(metadata.error)}", + request_id: metadata.url, + duration: measurements.duration, + error: metadata.error + ) + end + + def handle_event([:http_fetch, :response, :body_read_start], measurements, _metadata, _config) do + Logger.debug( + "Response body reading started. Content-Length: #{measurements.content_length}", + content_length: measurements.content_length + ) + end + + def handle_event([:http_fetch, :response, :body_read_stop], measurements, _metadata, _config) do + Logger.debug( + "Response body reading stopped. Bytes read: #{measurements.bytes_read} in #{measurements.duration}µs", + bytes_read: measurements.bytes_read, + duration: measurements.duration + ) + end + + def handle_event([:http_fetch, :streaming, :start], measurements, _metadata, _config) do + Logger.debug( + "Streaming started. Content-Length: #{measurements.content_length}", + content_length: measurements.content_length + ) + end + + def handle_event([:http_fetch, :streaming, :chunk], measurements, _metadata, _config) do + Logger.debug( + "Streaming chunk received. Bytes: #{measurements.bytes_received}/#{measurements.total_bytes}", + bytes_received: measurements.bytes_received, + total_bytes: measurements.total_bytes + ) + end + + def handle_event([:http_fetch, :streaming, :stop], measurements, _metadata, _config) do + Logger.debug( + "Streaming stopped. Total bytes: #{measurements.total_bytes} in #{measurements.duration}µs", + total_bytes: measurements.total_bytes, + duration: measurements.duration + ) + end +end diff --git a/test/http/logger_test.exs b/test/http/logger_test.exs new file mode 100644 index 0000000..91175ae --- /dev/null +++ b/test/http/logger_test.exs @@ -0,0 +1,42 @@ +defmodule HTTP.LoggerTest do + use ExUnit.Case, async: true + + import ExUnit.CaptureLog + + alias HTTP.Logger + alias HTTP.Telemetry + + setup do + # It's already attached by the application, but we can re-attach for the test + # to be sure. This is safe to do. + Logger.attach() + :ok + end + + test "logs request start event" do + log = + capture_log(fn -> + Telemetry.request_start("GET", URI.parse("http://example.com"), %{}) + end) + + assert log =~ "GET http://example.com - Request started" + end + + test "logs request stop event" do + log = + capture_log(fn -> + Telemetry.request_stop(200, URI.parse("http://example.com"), 1024, 123) + end) + + assert log =~ "200 http://example.com - Request completed in 123µs" + end + + test "logs request exception event" do + log = + capture_log(fn -> + Telemetry.request_exception(URI.parse("http://example.com"), :timeout, 456) + end) + + assert log =~ "Request to http://example.com failed: :timeout" + end +end diff --git a/test/http/telemetry_test.exs b/test/http/telemetry_test.exs index 062146a..50c79cf 100644 --- a/test/http/telemetry_test.exs +++ b/test/http/telemetry_test.exs @@ -3,9 +3,6 @@ defmodule HTTP.TelemetryTest do doctest HTTP.Telemetry setup do - # Capture telemetry events - events = [] - # Start telemetry event capture :telemetry.attach_many( "test_handler",