|
| 1 | +defmodule LoggerJSON.Formatters.Elastic do |
| 2 | + @moduledoc """ |
| 3 | + Custom Erlang's [`:logger` formatter](https://www.erlang.org/doc/apps/kernel/logger_chapter.html#formatters) which |
| 4 | + writes logs in a JSON-structured format that conforms to the Elastic Common Schema (ECS), so it can be consumed by |
| 5 | + ElasticSearch, LogStash, FileBeat and Kibana. |
| 6 | +
|
| 7 | + ## Formatter Configuration |
| 8 | +
|
| 9 | + For list of options see "Shared options" in `LoggerJSON`. |
| 10 | +
|
| 11 | + ## Metadata |
| 12 | +
|
| 13 | + For list of other well-known metadata keys see "Metadata" in `LoggerJSON`. |
| 14 | +
|
| 15 | + Any custom metadata that you set with `Logger.metadata/1` will be included top-level in the log entry. |
| 16 | +
|
| 17 | + ## Examples |
| 18 | +
|
| 19 | + Example of an info log (`Logger.info("Hello")` without any metadata): |
| 20 | +
|
| 21 | + %{ |
| 22 | + "@timestamp" => "2024-05-17T16:20:00.000Z", |
| 23 | + "ecs.version" => "8.11.0", |
| 24 | + "log.level" => "info", |
| 25 | + "log.logger" => "Elixir.LoggerJSON.Formatters.ElasticTest", |
| 26 | + "log.origin" => %{ |
| 27 | + "file.name" => ~c"/app/logger_json/test/formatters/elastic_test.exs", |
| 28 | + "file.line" => 18, |
| 29 | + "function" => "test logs an LogEntry of every level/1" |
| 30 | + }, |
| 31 | + "message" => "Hello" |
| 32 | + } |
| 33 | +
|
| 34 | + Example of logging by keywords or by map (Logger.info(%{message: "Hello", foo: :bar, fiz: %{buz: "buz"}})). |
| 35 | + The keywords or map items are added to the top-level of the log entry: |
| 36 | +
|
| 37 | + %{ |
| 38 | + "@timestamp" => "2024-05-17T16:20:00.000Z", |
| 39 | + "ecs.version" => "8.11.0", |
| 40 | + "fiz" => %{"buz" => "buz"}, |
| 41 | + "foo" => "bar", |
| 42 | + "log.level" => "debug", |
| 43 | + "log.logger" => "Elixir.LoggerJSON.Formatters.ElasticTest", |
| 44 | + "log.origin" => %{ |
| 45 | + "file.line" => 68, |
| 46 | + "file.name" => ~c"/app/logger_json/test/formatters/elastic_test.exs", |
| 47 | + "function" => "test logs an LogEntry with a map payload containing message/1"}, |
| 48 | + "message" => "Hello" |
| 49 | + } |
| 50 | +
|
| 51 | + Example of logging due to raising an exception (`raise RuntimeError`): |
| 52 | +
|
| 53 | + %{ |
| 54 | + "@timestamp" => "2024-05-17T16:20:00.000Z", |
| 55 | + "ecs.version" => "8.11.0", |
| 56 | + "error.message" => "runtime error", |
| 57 | + "error.stack_trace" => "** (RuntimeError) runtime error\\n Elixir.LoggerJSON.Formatters.ElasticTest.erl:159: anonymous fn/4 in LoggerJSON.Formatters.ElasticTest.\\"test logs exceptions\\"/1\\n", |
| 58 | + "error.type" => "Elixir.RuntimeError", |
| 59 | + "log.level" => "error", |
| 60 | + "message" => "runtime error" |
| 61 | + } |
| 62 | +
|
| 63 | + Note that if you raise an exception that contains an `id` or a `code` property, they will be included in the log entry as `error.id` and `error.code` respectively. |
| 64 | +
|
| 65 | + Example: |
| 66 | +
|
| 67 | + defmodule TestException do |
| 68 | + defexception [:message, :id, :code] |
| 69 | + end |
| 70 | +
|
| 71 | + ... |
| 72 | +
|
| 73 | + raise TestException, id: :oops_id, code: 42, message: "oops!" |
| 74 | +
|
| 75 | + results in: |
| 76 | +
|
| 77 | + %{ |
| 78 | + "@timestamp" => "2024-05-17T16:20:00.000Z", |
| 79 | + "ecs.version" => "8.11.0", |
| 80 | + "error.code" => 42, |
| 81 | + "error.id" => "oops_id", |
| 82 | + "error.message" => "oops!", |
| 83 | + "error.stack_trace" => "** (LoggerJSON.Formatters.ElasticTest.TestException) oops!\n test/formatters/elastic_test.exs:190: anonymous fn/0 in LoggerJSON.Formatters.ElasticTest.\"test logs exceptions with id and code\"/1\n", |
| 84 | + "error.type" => "Elixir.LoggerJSON.Formatters.ElasticTest.TestException", |
| 85 | + "log.level" => "error", |
| 86 | + "message" => "oops!" |
| 87 | + } |
| 88 | + """ |
| 89 | + import Jason.Helpers, only: [json_map: 1] |
| 90 | + import LoggerJSON.Formatter.{MapBuilder, DateTime, Message, Metadata, Plug, RedactorEncoder} |
| 91 | + |
| 92 | + @behaviour LoggerJSON.Formatter |
| 93 | + |
| 94 | + @ecs_version "8.11.0" |
| 95 | + |
| 96 | + @processed_metadata_keys ~w[file line mfa domain error_logger |
| 97 | + otel_span_id span_id |
| 98 | + otel_trace_id trace_id |
| 99 | + conn]a |
| 100 | + |
| 101 | + @impl LoggerJSON.Formatter |
| 102 | + def format(%{level: level, meta: meta, msg: msg}, opts) do |
| 103 | + metadata_keys_or_selector = Keyword.get(opts, :metadata, []) |
| 104 | + metadata_selector = update_metadata_selector(metadata_keys_or_selector, @processed_metadata_keys) |
| 105 | + redactors = Keyword.get(opts, :redactors, []) |
| 106 | + |
| 107 | + message = |
| 108 | + format_message(msg, meta, %{ |
| 109 | + binary: &format_binary_message/1, |
| 110 | + structured: &format_structured_message/1, |
| 111 | + crash: &format_crash_reason(&1, &2, meta) |
| 112 | + }) |
| 113 | + |
| 114 | + line = |
| 115 | + %{ |
| 116 | + "@timestamp": utc_time(meta), |
| 117 | + "log.level": Atom.to_string(level), |
| 118 | + "ecs.version": @ecs_version |
| 119 | + } |
| 120 | + |> maybe_merge(encode(message, redactors)) |
| 121 | + |> maybe_merge(encode(take_metadata(meta, metadata_selector), redactors)) |
| 122 | + |> maybe_merge(format_logger_fields(meta)) |
| 123 | + |> maybe_merge(format_http_request(meta)) |
| 124 | + |> maybe_put(:"span.id", format_span_id(meta)) |
| 125 | + |> maybe_put(:"trace.id", format_trace_id(meta)) |
| 126 | + |> Jason.encode_to_iodata!() |
| 127 | + |
| 128 | + [line, "\n"] |
| 129 | + end |
| 130 | + |
| 131 | + @doc false |
| 132 | + def format_binary_message(binary) do |
| 133 | + %{message: IO.chardata_to_string(binary)} |
| 134 | + end |
| 135 | + |
| 136 | + @doc false |
| 137 | + def format_structured_message(map) when is_map(map) do |
| 138 | + map |
| 139 | + end |
| 140 | + |
| 141 | + def format_structured_message(keyword) do |
| 142 | + Enum.into(keyword, %{}) |
| 143 | + end |
| 144 | + |
| 145 | + @doc false |
| 146 | + def format_crash_reason(message, {{:EXIT, pid}, reason}, _meta) do |
| 147 | + stacktrace = Exception.format_banner({:EXIT, pid}, reason, []) |
| 148 | + error_message = "process #{inspect(pid)} exit: #{inspect(reason)}" |
| 149 | + format_error_fields(message, error_message, stacktrace, "EXIT") |
| 150 | + end |
| 151 | + |
| 152 | + def format_crash_reason(message, {:exit, reason}, _meta) do |
| 153 | + stacktrace = Exception.format_banner(:exit, reason, []) |
| 154 | + error_message = "exit: #{inspect(reason)}" |
| 155 | + format_error_fields(message, error_message, stacktrace, "exit") |
| 156 | + end |
| 157 | + |
| 158 | + def format_crash_reason(message, {:throw, reason}, _meta) do |
| 159 | + stacktrace = Exception.format_banner(:throw, reason, []) |
| 160 | + error_message = "throw: #{inspect(reason)}" |
| 161 | + format_error_fields(message, error_message, stacktrace, "throw") |
| 162 | + end |
| 163 | + |
| 164 | + def format_crash_reason(_message, {%type{} = exception, stacktrace}, _meta) do |
| 165 | + message = Exception.message(exception) |
| 166 | + |
| 167 | + formatted_stacktrace = |
| 168 | + [ |
| 169 | + Exception.format_banner(:error, exception, stacktrace), |
| 170 | + Exception.format_stacktrace(stacktrace) |
| 171 | + ] |
| 172 | + |> Enum.join("\n") |
| 173 | + |
| 174 | + format_error_fields(message, message, formatted_stacktrace, type) |
| 175 | + |> maybe_put(:"error.id", get_exception_id(exception)) |
| 176 | + |> maybe_put(:"error.code", get_exception_code(exception)) |
| 177 | + end |
| 178 | + |
| 179 | + def format_crash_reason(message, {error, reason}, _meta) do |
| 180 | + stacktrace = "** (#{error}) #{inspect(reason)}" |
| 181 | + error_message = "#{error}: #{inspect(reason)}" |
| 182 | + format_error_fields(message, error_message, stacktrace, error) |
| 183 | + end |
| 184 | + |
| 185 | + defp get_exception_id(%{id: id}), do: id |
| 186 | + defp get_exception_id(_), do: nil |
| 187 | + |
| 188 | + defp get_exception_code(%{code: code}), do: code |
| 189 | + defp get_exception_code(_), do: nil |
| 190 | + |
| 191 | + @doc """ |
| 192 | + Formats the error fields as specified in https://www.elastic.co/guide/en/ecs/8.11/ecs-error.html |
| 193 | + """ |
| 194 | + def format_error_fields(message, error_message, stacktrace, type) do |
| 195 | + %{ |
| 196 | + message: message, |
| 197 | + "error.message": error_message, |
| 198 | + "error.stack_trace": stacktrace, |
| 199 | + "error.type": type |
| 200 | + } |
| 201 | + end |
| 202 | + |
| 203 | + @doc """ |
| 204 | + Formats the log.logger and log.origin fields as specified in https://www.elastic.co/guide/en/ecs/8.11/ecs-log.html |
| 205 | + """ |
| 206 | + def format_logger_fields(%{file: file, line: line, mfa: {module, function, arity}}) do |
| 207 | + %{ |
| 208 | + "log.logger": module, |
| 209 | + "log.origin": %{ |
| 210 | + "file.name": to_string(file), |
| 211 | + "file.line": line, |
| 212 | + function: "#{function}/#{arity}" |
| 213 | + } |
| 214 | + } |
| 215 | + end |
| 216 | + |
| 217 | + def format_logger_fields(_meta), do: nil |
| 218 | + |
| 219 | + if Code.ensure_loaded?(Plug.Conn) do |
| 220 | + # See the formats for the following fields in ECS: |
| 221 | + # - client.ip: https://www.elastic.co/guide/en/ecs/8.11/ecs-client.html |
| 222 | + # - http.*: https://www.elastic.co/guide/en/ecs/8.11/ecs-http.html |
| 223 | + # - url.path: https://www.elastic.co/guide/en/ecs/8.11/ecs-url.html |
| 224 | + # - user_agent.original: https://www.elastic.co/guide/en/ecs/8.11/ecs-user_agent.html |
| 225 | + defp format_http_request(%{conn: %Plug.Conn{} = conn}) do |
| 226 | + json_map( |
| 227 | + "client.ip": remote_ip(conn), |
| 228 | + "http.version": Plug.Conn.get_http_protocol(conn), |
| 229 | + "http.request.method": conn.method, |
| 230 | + "http.request.referrer": get_header(conn, "referer"), |
| 231 | + "http.response.status_code": conn.status, |
| 232 | + "url.path": conn.request_path, |
| 233 | + "user_agent.original": get_header(conn, "user-agent") |
| 234 | + ) |
| 235 | + end |
| 236 | + end |
| 237 | + |
| 238 | + defp format_http_request(_meta), do: nil |
| 239 | + |
| 240 | + defp format_span_id(%{otel_span_id: otel_span_id}), do: safe_chardata_to_string(otel_span_id) |
| 241 | + defp format_span_id(%{span_id: span_id}), do: span_id |
| 242 | + defp format_span_id(_meta), do: nil |
| 243 | + |
| 244 | + defp format_trace_id(%{otel_trace_id: otel_trace_id}), do: safe_chardata_to_string(otel_trace_id) |
| 245 | + defp format_trace_id(%{trace_id: trace_id}), do: trace_id |
| 246 | + defp format_trace_id(_meta), do: nil |
| 247 | + |
| 248 | + def safe_chardata_to_string(chardata) when is_list(chardata) or is_binary(chardata) do |
| 249 | + IO.chardata_to_string(chardata) |
| 250 | + end |
| 251 | + |
| 252 | + def safe_chardata_to_string(other), do: other |
| 253 | +end |
0 commit comments