diff --git a/CHANGELOG.md b/CHANGELOG.md index 3d61e0b..7b4fc79 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/lib/uinta/plug.ex b/lib/uinta/plug.ex index 5447937..203a3e0 100644 --- a/lib/uinta/plug.ex +++ b/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 diff --git a/mix.exs b/mix.exs index 3f6b014..9edcce4 100644 --- a/mix.exs +++ b/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, diff --git a/mix.lock b/mix.lock index 3e2ee6f..f8efb18 100644 --- a/mix.lock +++ b/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"}, diff --git a/test/uinta/plug_test.exs b/test/uinta/plug_test.exs index 5b100ce..6e69d97 100644 --- a/test/uinta/plug_test.exs +++ b/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