Merge pull request #8 from podium/epinault/improve-logs-details

feat: Adds support for remote_ip, x-forwarded, via and user agent in log

CHANGELOG.md

@@ -1,4 +1,17 @@
  # CHANGELOG
+
+ ## v0.9 - 2022-01-05
+
+### Added
+* adds more fields to the log:
+  * referer
+  * user_agent
+  * x_forwarded_for
+  * x_forwarded_proto
+  * x_forwarded_port
+  * via
+
+
 ## v0.8 - 2021-11-22
 
 ### Added

lib/uinta/plug.ex

@@ -86,6 +86,7 @@ if Code.ensure_loaded?(Plug) do
 
     require Logger
     alias Plug.Conn
+
     @behaviour Plug
 
     @default_filter ~w(password passwordConfirmation idToken refreshToken)
@@ -156,6 +157,13 @@ if Code.ensure_loaded?(Plug) do
         status: Integer.to_string(conn.status),
         timing: formatted_diff(diff),
         duration_ms: diff / 1000,
+        client_ip: conn.remote_ip,
+        user_agent: get_first_value_for_header(conn, "user-agent"),
+        referer: get_first_value_for_header(conn, "referer"),
+        x_forwarded_for: get_first_value_for_header(conn, "x-forwarded-for"),
+        x_forwarded_proto: get_first_value_for_header(conn, "x-forwarded-proto"),
+        x_forwarded_port: get_first_value_for_header(conn, "x-forwarded-port"),
+        via: get_first_value_for_header(conn, "via"),
         variables: variables(graphql_info)
       }
     end
@@ -182,6 +190,12 @@ if Code.ensure_loaded?(Plug) do
       if is_nil(info.query), do: log, else: [log, "\nQuery: ", info.query]
     end
 
+    defp get_first_value_for_header(conn, name) do
+      conn
+      |> Plug.Conn.get_req_header(name)
+      |> List.first()
+    end
+
     @spec method(Plug.Conn.t(), graphql_info()) :: String.t()
     defp method(_, %{type: type}), do: type
     defp method(conn, _), do: conn.method

mix.exs

@@ -8,7 +8,7 @@ defmodule Uinta.MixProject do
       app: :uinta,
       name: "Uinta",
       description: "Simpler structured logs and lower log volume for Elixir apps",
-      version: "0.8.0",
+      version: "0.9.0",
       elixir: "~> 1.8",
       source_url: @project_url,
       homepage_url: @project_url,

mix.lock

@@ -1,5 +1,4 @@
 %{
-  "earmark": {:hex, :earmark, "1.4.3", "364ca2e9710f6bff494117dbbd53880d84bebb692dafc3a78eb50aa3183f2bfd", [:mix], [], "hexpm", "8cf8a291ebf1c7b9539e3cddb19e9cef066c2441b1640f13c34c1d3cfc825fec"},
   "earmark_parser": {:hex, :earmark_parser, "1.4.15", "b29e8e729f4aa4a00436580dcc2c9c5c51890613457c193cc8525c388ccb2f06", [:mix], [], "hexpm", "044523d6438ea19c1b8ec877ec221b008661d3c27e3b848f4c879f500421ca5c"},
   "ex_doc": {:hex, :ex_doc, "0.25.1", "4b736fa38dc76488a937e5ef2944f5474f3eff921de771b25371345a8dc810bc", [:mix], [{:earmark_parser, "~> 1.4.0", [hex: :earmark_parser, repo: "hexpm", optional: false]}, {:makeup_elixir, "~> 0.14", [hex: :makeup_elixir, repo: "hexpm", optional: false]}, {:makeup_erlang, "~> 0.1", [hex: :makeup_erlang, repo: "hexpm", optional: false]}], "hexpm", "3200b0a69ddb2028365281fbef3753ea9e728683863d8cdaa96580925c891f67"},
   "jason": {:hex, :jason, "1.2.2", "ba43e3f2709fd1aa1dce90aaabfd039d000469c05c56f0b8e31978e03fa39052", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "18a228f5f0058ee183f29f9eae0805c6e59d61c3b006760668d8d18ff0d12179"},

test/uinta/plug_test.exs

@@ -146,8 +146,12 @@ defmodule Uinta.PlugTest do
         JsonPlug.call(conn(:get, "/"), [])
       end)
 
-    assert message =~
-             ~r"{\"duration_ms\":[0-9]+\.?[0-9]+,\"method\":\"GET\",\"path\":\"/\",\"status\":\"200\",\"timing\":\"[0-9]+[µm]s\"}"u
+    assert message =~ ~r/client_ip:.+/u
+    assert message =~ ~r/duration_ms: [0-9]+\.?[0-9]+/u
+    assert message =~ ~r/method: \"GET\"/u
+    assert message =~ ~r"path: \"/\""u
+    assert message =~ ~r/status: \"200\"/u
+    assert message =~ ~r/timing: \"[0-9]+[µm]s\"/u
   end
 
   test "logs graphql json to console" do
@@ -159,8 +163,39 @@ defmodule Uinta.PlugTest do
         JsonPlug.call(conn(:post, "/graphql", params), [])
       end)
 
-    assert message =~
-             ~r"{\"duration_ms\":[0-9]+\.?[0-9]+,\"method\":\"QUERY\",\"operation_name\":\"getUser\",\"path\":\"/graphql\",\"status\":\"200\",\"timing\":\"[0-9]+[µm]s\"}"u
+    assert message =~ ~r/client_ip:.+/u
+    assert message =~ ~r/duration_ms: [0-9]+\.?[0-9]+/u
+    assert message =~ ~r/method: \"QUERY\"/u
+    assert message =~ ~r/operation_name: \"getUser\"/u
+    assert message =~ ~r"path: \"/graphql\""u
+    assert message =~ ~r/status: \"200\"/u
+    assert message =~ ~r/timing: \"[0-9]+[µm]s\"/u
+  end
+
+  test "logs graphql json to console with extra headers" do
+    variables = %{"user_uid" => "b1641ddf-b7b0-445e-bcbb-96ef359eae81"}
+    params = %{"operationName" => "getUser", "query" => "query getUser", "variables" => variables}
+
+    conn =
+      :post
+      |> conn("/graphql", params)
+      |> put_req_header("x-forwarded-for", "someip")
+      |> put_req_header("referer", "http://I.am.referer")
+      |> put_req_header("user-agent", "Mozilla")
+      |> put_req_header("x-forwarded-proto", "http")
+      |> put_req_header("x-forwarded-port", "4000")
+
+    message =
+      capture_log(fn ->
+        JsonPlug.call(conn, [])
+      end)
+
+    assert message =~ ~r/client_ip:.+/u
+    assert message =~ ~r/x_forwarded_for: \"someip\"/u
+    assert message =~ ~r"referer: \"http://I.am.referer\""u
+    assert message =~ ~r/user_agent: \"Mozilla\"/u
+    assert message =~ ~r/x_forwarded_proto: \"http\"/u
+    assert message =~ ~r/x_forwarded_port: \"4000\"/u
   end
 
   test "logs paths with double slashes and trailing slash" do