diff --git a/.travis.yml b/.travis.yml index a8a0f95..8d14536 100644 --- a/.travis.yml +++ b/.travis.yml @@ -1,8 +1,6 @@ language: elixir elixir: - - 1.3.0 - 1.4.0 - 1.5.0 otp_release: - 18.0 - diff --git a/README.md b/README.md index ec55fd8..825225c 100644 --- a/README.md +++ b/README.md @@ -16,6 +16,8 @@ that will send logs to the [Logstash UDP input](https://www.elastic.co/guide/en/ be merged with the metadata sent in every log message. * **level**: Atom. Minimum level for this backend. * **type**: String.t. Type of logs. Useful to filter in logstash. + * **timezone**: String.t. Server timezone. Used to convert from naive timestamp. Default `"Etc/UTC"`. + * **json_encoder**: Atom. Module to be used for JSON encoding. The default is `Jason`, add it to your mix deps to use. ## Sample Logstash config ``` @@ -51,7 +53,7 @@ Add logger and tzdata as applications: ```elixir def application do - [applications: [:logger, :timex]] + [applications: [:logger]] end ``` @@ -81,5 +83,7 @@ config :logger, :error_log, type: "my_type_of_app_or_node", metadata: [ extra_fields: "go here" - ] + ], + timezone: "Etc/UTC", + json_encoder: Jason ``` diff --git a/lib/logger_logstash_backend.ex b/lib/logger_logstash_backend.ex index 905adaa..9fe8d0b 100644 --- a/lib/logger_logstash_backend.ex +++ b/lib/logger_logstash_backend.ex @@ -15,13 +15,15 @@ ################################################################################ defmodule LoggerLogstashBackend do @behaviour :gen_event - use Timex + + require Logger def init({__MODULE__, name}) do {:ok, configure(name, [])} end - def handle_call({:configure, opts}, %{name: name}) do + def handle_call({:configure, opts}, %{name: name} = state) do + close_socket(state) {:ok, :ok, configure(name, opts)} end @@ -34,12 +36,19 @@ defmodule LoggerLogstashBackend do end def handle_event( - {level, _gl, {Logger, msg, ts, md}}, %{level: min_level} = state - ) do - if is_nil(min_level) or Logger.compare_levels(level, min_level) != :lt do - log_event level, msg, ts, md, state - end - {:ok, state} + {level, _gl, {Logger, msg, ts, md}}, + %{level: min_level} = state + ) do + new_state = open_socket(state) + + new_state = + if is_nil(min_level) or Logger.compare_levels(level, min_level) != :lt do + log_event(level, msg, ts, md, new_state) + else + new_state + end + + {:ok, new_state} end def code_change(_old_vsn, state, _extra) do @@ -51,64 +60,193 @@ defmodule LoggerLogstashBackend do end defp log_event( - level, msg, ts, md, %{ - host: host, - port: port, - type: type, - metadata: metadata, - socket: socket - } - ) do - fields = md - |> Keyword.merge(metadata) - |> Enum.into(%{}) - |> Map.put(:level, to_string(level)) - |> inspect_pids - - {{year, month, day}, {hour, minute, second, milliseconds}} = ts - {:ok, ts} = NaiveDateTime.new( - year, month, day, hour, minute, second, (milliseconds * 1000) - ) - ts = Timex.to_datetime ts, Timezone.local - {:ok, json} = JSX.encode %{ - type: type, - "@timestamp": Timex.format!(ts, "{ISO:Extended}"), - message: to_string(msg), - fields: fields - } - :gen_udp.send socket, host, port, to_charlist(json) + level, + msg, + ts, + md, + %{type: type, metadata: metadata, timezone: timezone, json_encoder: json_encoder} = state + ) do + fields = + md + |> Keyword.merge(metadata) + |> Enum.into(%{}) + |> Map.put(:level, to_string(level)) + |> inspect_pids + + {{year, month, day}, {hour, minute, second, microseconds}} = ts + + {:ok, ts} = + NaiveDateTime.new( + year, + month, + day, + hour, + minute, + second, + microseconds * 1000 + ) + + {:ok, datetime} = DateTime.from_naive(ts, timezone) + + message = + Map.merge( + %{ + type: type, + "@timestamp": DateTime.to_iso8601(datetime), + message: to_string(msg) + }, + fields + ) + + {:ok, json} = json_encoder.encode(message) + + send_log(state, json) + end + + defp send_log(%{socket: nil} = state, _json), do: state + + defp send_log(%{protocol: :udp, socket: socket, host: host, port: port} = state, json) do + case :gen_udp.send(socket, host, port, [json, "\n"]) do + :ok -> + state + + {:error, :closed} -> + log_error(:closed, state) + %{state | socket: nil} + end + end + + defp send_log(%{protocol: :tcp, ssl: true, socket: socket} = state, json) do + case :ssl.send(socket, [json, "\n"]) do + :ok -> + state + + {:error, :closed} -> + log_error(:closed, state) + %{state | socket: nil} + end + end + + defp send_log(%{protocol: :tcp, socket: socket} = state, json) do + case :gen_tcp.send(socket, [json, "\n"]) do + :ok -> + state + + {:error, :closed} -> + log_error(:closed, state) + %{state | socket: nil} + end end defp configure(name, opts) do - env = Application.get_env :logger, name, [] - opts = Keyword.merge env, opts - Application.put_env :logger, name, opts - - level = Keyword.get opts, :level, :debug - metadata = Keyword.get opts, :metadata, [] - type = Keyword.get opts, :type, "elixir" - host = Keyword.get opts, :host - port = Keyword.get opts, :port - {:ok, socket} = :gen_udp.open 0 + env = Application.get_env(:logger, name, []) + opts = Keyword.merge(env, opts) + Application.put_env(:logger, name, opts) + + level = Keyword.get(opts, :level, :debug) + metadata = Keyword.get(opts, :metadata, []) + type = Keyword.get(opts, :type, "elixir") + host = Keyword.get(opts, :host) + port = Keyword.get(opts, :port) + timezone = Keyword.get(opts, :timezone, "Etc/UTC") + json_encoder = Keyword.get(opts, :json_encoder, Jason) + protocol = Keyword.get(opts, :protocol, :udp) + ssl = Keyword.get(opts, :ssl, false) + + if ssl && protocol == :udp do + raise ArgumentError, message: "cannot use SSL in combination with UDP. Use TCP instead" + end + %{ name: name, host: to_charlist(host), port: port, level: level, - socket: socket, type: type, - metadata: metadata + metadata: metadata, + timezone: timezone, + json_encoder: json_encoder, + protocol: protocol, + ssl: ssl, + socket: nil, + recorded_error: false } end + defp close_socket(%{socket: nil} = state), do: state + + defp close_socket(%{protocol: :udp} = state) do + :ok = :gen_udp.close(state.socket) + %{state | socket: nil} + end + + defp close_socket(%{protocol: :tcp} = state) do + :gen_tcp.shutdown(state.socket, :write) + %{state | socket: nil} + end + + defp log_error(error, %{recorded_error: false} = state) do + Logger.error( + "could not connect to logstash via #{inspect(state.protocol)}, reason: #{inspect(error)}" + ) + + %{state | recorded_error: true} + end + + defp log_error(_error, state), do: state + + defp open_socket(%{protocol: :udp, socket: nil} = state) do + case :gen_udp.open(0) do + {:ok, socket} -> Map.merge(state, %{socket: socket, recorded_error: false}) + {:error, reason} -> log_error(reason, state) + end + end + + defp open_socket(%{protocol: :tcp, ssl: true, socket: nil} = state) do + with {:ok, socket} <- + :gen_tcp.connect(state.host, state.port, [ + {:active, true}, + :binary, + {:keepalive, true}, + {:send_timeout, 5000}, + {:send_timeout_close, true} + ]), + {:ok, socket} <- :ssl.connect(socket, [fail_if_no_peer_cert: true], 5000) do + Map.merge(state, %{socket: socket, recorded_error: false}) + else + {:error, reason} -> log_error(reason, state) + end + end + + defp open_socket(%{protocol: :tcp, socket: nil} = state) do + :gen_tcp.connect( + state.host, + state.port, + [ + {:active, true}, + :binary, + {:keepalive, true}, + {:send_timeout, 5000}, + {:send_timeout_close, true} + ], + 5000 + ) + |> case do + {:ok, socket} -> Map.merge(state, %{socket: socket, recorded_error: false}) + {:error, reason} -> log_error(reason, state) + end + end + + defp open_socket(state), do: state + # inspects the argument only if it is a pid defp inspect_pid(pid) when is_pid(pid), do: inspect(pid) defp inspect_pid(other), do: other # inspects the field values only if they are pids defp inspect_pids(fields) when is_map(fields) do - Enum.into fields, %{}, fn {key, value} -> + Enum.into(fields, %{}, fn {key, value} -> {key, inspect_pid(value)} - end + end) end end diff --git a/mix.exs b/mix.exs index 97ebf83..7657755 100644 --- a/mix.exs +++ b/mix.exs @@ -2,26 +2,27 @@ defmodule LoggerLogstashBackend.Mixfile do use Mix.Project def project do - [app: :logger_logstash_backend, - name: "logger_logstash_backend", - source_url: "https://github.com/marcelog/logger_logstash_backend", - version: "5.0.0", - elixir: "~> 1.3", - description: description(), - package: package(), - deps: deps()] + [ + app: :logger_logstash_backend, + name: "logger_logstash_backend", + source_url: "https://github.com/marcelog/logger_logstash_backend", + version: "5.0.0", + elixir: "~> 1.4", + description: description(), + package: package(), + deps: deps() + ] end def application do - [applications: [:logger, :timex, :exjsx]] + [applications: [:logger]] end defp deps do [ {:earmark, "~> 1.0.3", only: :dev}, {:ex_doc, "~> 0.14.5", only: :dev}, - {:exjsx, "~> 3.2.1"}, - {:timex, "~> 3.1.8"} + {:jason, "~> 1.0", only: [:test]} ] end diff --git a/mix.lock b/mix.lock index 7183b40..afe91c3 100644 --- a/mix.lock +++ b/mix.lock @@ -1,14 +1,5 @@ -%{"certifi": {:hex, :certifi, "0.7.0", "861a57f3808f7eb0c2d1802afeaae0fa5de813b0df0979153cbafcd853ababaf", [:rebar3], []}, - "combine": {:hex, :combine, "0.9.6", "8d1034a127d4cbf6924c8a5010d3534d958085575fa4d9b878f200d79ac78335", [:mix], []}, +%{ "earmark": {:hex, :earmark, "1.0.3", "89bdbaf2aca8bbb5c97d8b3b55c5dd0cff517ecc78d417e87f1d0982e514557b", [:mix], []}, "ex_doc": {:hex, :ex_doc, "0.14.5", "c0433c8117e948404d93ca69411dd575ec6be39b47802e81ca8d91017a0cf83c", [:mix], [{:earmark, "~> 1.0", [hex: :earmark, optional: false]}]}, - "exjsx": {:hex, :exjsx, "3.2.1", "1bc5bf1e4fd249104178f0885030bcd75a4526f4d2a1e976f4b428d347614f0f", [:mix], [{:jsx, "~> 2.8.0", [hex: :jsx, optional: false]}]}, - "gettext": {:hex, :gettext, "0.13.0", "daafbddc5cda12738bb93b01d84105fe75b916a302f1c50ab9fb066b95ec9db4", [:mix], []}, - "hackney": {:hex, :hackney, "1.6.5", "8c025ee397ac94a184b0743c73b33b96465e85f90a02e210e86df6cbafaa5065", [:rebar3], [{:certifi, "0.7.0", [hex: :certifi, optional: false]}, {:idna, "1.2.0", [hex: :idna, optional: false]}, {:metrics, "1.0.1", [hex: :metrics, optional: false]}, {:mimerl, "1.0.2", [hex: :mimerl, optional: false]}, {:ssl_verify_fun, "1.1.1", [hex: :ssl_verify_fun, optional: false]}]}, - "idna": {:hex, :idna, "1.2.0", "ac62ee99da068f43c50dc69acf700e03a62a348360126260e87f2b54eced86b2", [:rebar3], []}, - "jsx": {:hex, :jsx, "2.8.1", "1453b4eb3615acb3e2cd0a105d27e6761e2ed2e501ac0b390f5bbec497669846", [:mix, :rebar3], []}, - "metrics": {:hex, :metrics, "1.0.1", "25f094dea2cda98213cecc3aeff09e940299d950904393b2a29d191c346a8486", [:rebar3], []}, - "mimerl": {:hex, :mimerl, "1.0.2", "993f9b0e084083405ed8252b99460c4f0563e41729ab42d9074fd5e52439be88", [:rebar3], []}, - "ssl_verify_fun": {:hex, :ssl_verify_fun, "1.1.1", "28a4d65b7f59893bc2c7de786dec1e1555bd742d336043fe644ae956c3497fbe", [:make, :rebar], []}, - "timex": {:hex, :timex, "3.1.8", "a32f636c4260dd7515a3767be3d3a163dc09d15f0e9e689254b7bab152b29209", [:mix], [{:combine, "~> 0.7", [hex: :combine, optional: false]}, {:gettext, "~> 0.10", [hex: :gettext, optional: false]}, {:tzdata, "~> 0.1.8 or ~> 0.5", [hex: :tzdata, optional: false]}]}, - "tzdata": {:hex, :tzdata, "0.5.10", "087e8dfe8c0283473115ad8ca6974b898ecb55ca5c725427a142a79593391e90", [:mix], [{:hackney, "~> 1.0", [hex: :hackney, optional: false]}]}} + "jason": {:hex, :jason, "1.0.0", "0f7cfa9bdb23fed721ec05419bcee2b2c21a77e926bce0deda029b5adc716fe2", [:mix], [{:decimal, "~> 1.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm"}, +} diff --git a/test/logger_logstash_backend_test.exs b/test/logger_logstash_backend_test.exs index 20ea190..6dcac91 100644 --- a/test/logger_logstash_backend_test.exs +++ b/test/logger_logstash_backend_test.exs @@ -16,13 +16,13 @@ defmodule LoggerLogstashBackendTest do use ExUnit.Case, async: false require Logger - use Timex @backend {LoggerLogstashBackend, :test} - Logger.add_backend @backend + Logger.add_backend(@backend) setup do - Logger.configure_backend @backend, [ + Logger.configure_backend( + @backend, host: "127.0.0.1", port: 10001, level: :info, @@ -30,69 +30,79 @@ defmodule LoggerLogstashBackendTest do metadata: [ some_metadata: "go here" ] - ] - {:ok, socket} = :gen_udp.open 10001, [:binary, {:active, true}] - on_exit fn -> - :ok = :gen_udp.close socket - end + ) + + {:ok, socket} = :gen_udp.open(10001, [:binary, {:active, true}]) + + on_exit(fn -> + :ok = :gen_udp.close(socket) + end) + :ok end test "can log" do - Logger.info "hello world", [key1: "field1"] + Logger.info("hello world", key1: "field1") json = get_log() - {:ok, data} = JSX.decode json + {:ok, data} = Jason.decode(json) assert data["type"] === "some_app" assert data["message"] === "hello world" + expected = %{ "function" => "test can log/1", "level" => "info", "module" => "Elixir.LoggerLogstashBackendTest", - "pid" => (inspect self()), + "pid" => inspect(self()), "some_metadata" => "go here", - "line" => 42, + "line" => 45, "key1" => "field1" } - assert contains?(data["fields"], expected) - {:ok, ts} = Timex.parse data["@timestamp"], "{ISO:Extended}" - ts = Timex.to_unix ts - now = Timex.to_unix Timex.local - assert (now - ts) < 1000 + assert data["line"] == expected["line"] + assert contains?(data, expected) + {:ok, dt, _tz_offset} = DateTime.from_iso8601(data["@timestamp"]) + ts = DateTime.to_unix(dt) + + now = DateTime.utc_now() |> DateTime.to_unix() + assert now - ts < 1000 end test "can log pids" do - Logger.info "pid", [pid_key: self()] + Logger.info("pid", pid_key: self()) json = get_log() - {:ok, data} = JSX.decode json + {:ok, data} = Jason.decode(json) assert data["type"] === "some_app" assert data["message"] === "pid" + expected = %{ "function" => "test can log pids/1", "level" => "info", "module" => "Elixir.LoggerLogstashBackendTest", - "pid" => (inspect self()), + "pid" => inspect(self()), "pid_key" => inspect(self()), "some_metadata" => "go here", - "line" => 65 + "line" => 71 } - assert contains?(data["fields"], expected) - {:ok, ts} = Timex.parse data["@timestamp"], "{ISO:Extended}" - ts = Timex.to_unix ts - now = Timex.to_unix Timex.local - assert (now - ts) < 1000 + assert data["line"] == expected["line"] + assert contains?(data, expected) + {:ok, dt, _tz_offset} = DateTime.from_iso8601(data["@timestamp"]) + ts = DateTime.to_unix(dt) + + now = DateTime.utc_now() |> DateTime.to_unix() + assert now - ts < 1000 end test "cant log when minor levels" do - Logger.debug "hello world", [key1: "field1"] + Logger.debug("hello world", key1: "field1") :nothing_received = get_log() end defp get_log do receive do {:udp, _, _, _, json} -> json - after 500 -> :nothing_received + after + 500 -> :nothing_received end end