Remap duration_us to spec-compliant fields for Elastic and DataDog formatters (#132)

* fix(elastic): encode LoggerJSON.Plug's duration_us field as event.duration (in nanoseconds)

* fix(datadog): encode LoggerJSON.Plug's duration_us field as  (in nanoseconds)

---------

Co-authored-by: Bart van Oort <bart.van.oort@opinity.nl>

Author: bvobart

lib/logger_json/formatters/datadog.ex

@@ -197,7 +197,7 @@ defmodule LoggerJSON.Formatters.Datadog do
   defp safe_chardata_to_string(other), do: other
 
   if Code.ensure_loaded?(Plug.Conn) do
-    defp format_http_request(%{conn: %Plug.Conn{} = conn} = meta) do
+    defp format_http_request(%{conn: %Plug.Conn{} = conn, duration_us: duration_us} = meta) do
       request_url = Plug.Conn.request_url(conn)
       user_agent = LoggerJSON.Formatter.Plug.get_header(conn, "user-agent")
       remote_ip = LoggerJSON.Formatter.Plug.remote_ip(conn)
@@ -223,8 +223,14 @@ defmodule LoggerJSON.Formatters.Datadog do
           ),
         network: Jason.Helpers.json_map(client: Jason.Helpers.json_map(ip: remote_ip))
       }
+      |> maybe_put(:duration, to_nanosecs(duration_us))
     end
+
+    defp format_http_request(%{conn: %Plug.Conn{} = conn}), do: format_http_request(%{conn: conn, duration_us: nil})
   end
 
   defp format_http_request(_meta), do: nil
+
+  defp to_nanosecs(duration_us) when is_number(duration_us), do: duration_us * 1000
+  defp to_nanosecs(_), do: nil
 end

lib/logger_json/formatters/elastic.ex

@@ -261,7 +261,8 @@ defmodule LoggerJSON.Formatters.Elastic do
     # - http.*: https://www.elastic.co/guide/en/ecs/8.11/ecs-http.html
     # - url.path: https://www.elastic.co/guide/en/ecs/8.11/ecs-url.html
     # - user_agent.original: https://www.elastic.co/guide/en/ecs/8.11/ecs-user_agent.html
-    defp format_http_request(%{conn: %Plug.Conn{} = conn}) do
+    # - event.duration (note: ns, not μs): https://www.elastic.co/guide/en/ecs/current/ecs-event.html#field-event-duration
+    defp format_http_request(%{conn: %Plug.Conn{} = conn, duration_us: duration_us}) do
       %{
         "client.ip": LoggerJSON.Formatter.Plug.remote_ip(conn),
         "http.version": Plug.Conn.get_http_protocol(conn),
@@ -271,7 +272,10 @@ defmodule LoggerJSON.Formatters.Elastic do
         "url.path": conn.request_path,
         "user_agent.original": LoggerJSON.Formatter.Plug.get_header(conn, "user-agent")
       }
+      |> maybe_put(:"event.duration", to_nanosecs(duration_us))
     end
+
+    defp format_http_request(%{conn: %Plug.Conn{} = conn}), do: format_http_request(%{conn: conn, duration_us: nil})
   end
 
   defp format_http_request(_meta), do: nil
@@ -289,4 +293,7 @@ defmodule LoggerJSON.Formatters.Elastic do
   end
 
   defp safe_chardata_to_string(other), do: other
+
+  defp to_nanosecs(duration_us) when is_number(duration_us), do: duration_us * 1000
+  defp to_nanosecs(_), do: nil
 end

test/logger_json/formatters/datadog_test.exs

@@ -307,7 +307,7 @@ defmodule LoggerJSON.Formatters.DatadogTest do
       |> Plug.Conn.put_req_header("x-forwarded-for", "127.0.0.1")
       |> Plug.Conn.send_resp(200, "Hi!")
 
-    Logger.metadata(conn: conn)
+    Logger.metadata(conn: conn, duration_us: 1337)
 
     log =
       capture_log(fn ->
@@ -332,6 +332,47 @@ defmodule LoggerJSON.Formatters.DatadogTest do
              },
              "useragent" => "Mozilla/5.0"
            }
+
+    assert log["duration"] == 1_337_000
+  end
+
+  test "logs exception http context" do
+    conn =
+      Plug.Test.conn("patch", "/", "")
+      |> Plug.Conn.put_req_header("user-agent", "Mozilla/5.0")
+      |> Plug.Conn.put_req_header("referer", "http://www.example.com/")
+      |> Plug.Conn.put_req_header("x-forwarded-for", "127.0.0.1")
+      |> Plug.Conn.send_resp(503, "oops")
+
+    Logger.metadata(crash_reason: {{:EXIT, self()}, :foo}, conn: conn)
+
+    log =
+      capture_log(fn ->
+        Logger.debug("Hello")
+      end)
+      |> decode_or_print_error()
+
+    assert log["error"] == %{"message" => "Hello"}
+
+    assert log["network"] == %{"client" => %{"ip" => "127.0.0.1"}}
+
+    assert log["http"] == %{
+             "referer" => "http://www.example.com/",
+             "method" => "PATCH",
+             "request_id" => nil,
+             "status_code" => 503,
+             "url" => "http://www.example.com/",
+             "url_details" => %{
+               "host" => "www.example.com",
+               "path" => "/",
+               "port" => 80,
+               "queryString" => "",
+               "scheme" => "http"
+             },
+             "useragent" => "Mozilla/5.0"
+           }
+
+    assert log["duration"] == nil
   end
 
   test "logs throws" do

test/logger_json/formatters/elastic_test.exs

@@ -368,7 +368,7 @@ defmodule LoggerJSON.Formatters.ElasticTest do
       |> Plug.Conn.put_req_header("x-forwarded-for", "")
       |> Plug.Conn.send_resp(200, "Hi!")
 
-    Logger.metadata(conn: conn)
+    Logger.metadata(conn: conn, duration_us: 1337)
 
     log_entry =
       capture_log(fn ->
@@ -378,6 +378,7 @@ defmodule LoggerJSON.Formatters.ElasticTest do
 
     assert %{
              "client.ip" => "",
+             "event.duration" => 1_337_000,
              "http.version" => "HTTP/1.1",
              "http.request.method" => "GET",
              "http.request.referrer" => "http://www.example2.com/",