Logs: use logfmt

Show logs in logfmt format (now you can use humanlog, and even see the date of a log line, wohooo). Moreover, make sure via a runtime configuration that displayed logs are only from level info or higher. Signed-off-by: Arnaldo Cesco <arnaldo.cesco@secomind.com>
astarte-platform · Annopaolo · Jan 11, 2025 · Dec 12, 2024 · Dec 12, 2024 · 2ebbe2be63c2ad9e8386bd4cbfe85f01ee9359a8
commit 2ebbe2be63c2ad9e8386bd4cbfe85f01ee9359a8
diff --git a/mix.exs b/mix.exs
@@ -91,6 +91,7 @@ defmodule Astarte.VMQ.Plugin.Mixfile do
       {:excoveralls, "~> 0.15", only: :test},
       {:mississippi, github: "secomind/mississippi"},
       {:pretty_log, "~> 0.1"},
+      {:flatlog, github: "annopaolo/flatlog"},
       {:dialyxir, "~> 1.4", only: [:dev, :ci], runtime: false},
       {:xandra, "~> 0.14"}
     ]

diff --git a/mix.lock b/mix.lock
@@ -18,6 +18,7 @@
   "ex_rabbit_pool": {:git, "https://github.com/leductam/ex_rabbit_pool.git", "9951452ab51d36648b9a9d3373609e48d1379a0d", []},
   "excoveralls": {:hex, :excoveralls, "0.16.1", "0bd42ed05c7d2f4d180331a20113ec537be509da31fed5c8f7047ce59ee5a7c5", [:mix], [{:hackney, "~> 1.16", [hex: :hackney, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: false]}], "hexpm", "dae763468e2008cf7075a64cb1249c97cb4bc71e236c5c2b5e5cdf1cfa2bf138"},
   "exprotobuf": {:hex, :exprotobuf, "1.2.17", "3003937da617f588a8fb63ebdd7b127a18d78d6502623c272076fd54c07c4de1", [:mix], [{:gpb, "~> 4.0", [hex: :gpb, repo: "hexpm", optional: false]}], "hexpm", "e07ec1e5ae6f8c1c8521450d5f6b658c8c700b1f34c70356e91ece0766f4361a"},
+  "flatlog": {:git, "https://github.com/annopaolo/flatlog.git", "a176d09120bbe557d50a0e1b6eb0686c58d93e63", []},
   "goldrush": {:hex, :goldrush, "0.1.9", "f06e5d5f1277da5c413e84d5a2924174182fb108dabb39d5ec548b27424cd106", [:rebar3], [], "hexpm", "99cb4128cffcb3227581e5d4d803d5413fa643f4eb96523f77d9e6937d994ceb"},
   "hackney": {:hex, :hackney, "1.18.1", "f48bf88f521f2a229fc7bae88cf4f85adc9cd9bcf23b5dc8eb6a1788c662c4f6", [:rebar3], [{:certifi, "~>2.9.0", [hex: :certifi, repo: "hexpm", optional: false]}, {:idna, "~>6.1.0", [hex: :idna, repo: "hexpm", optional: false]}, {:metrics, "~>1.0.0", [hex: :metrics, repo: "hexpm", optional: false]}, {:mimerl, "~>1.1", [hex: :mimerl, repo: "hexpm", optional: false]}, {:parse_trans, "3.3.1", [hex: :parse_trans, repo: "hexpm", optional: false]}, {:ssl_verify_fun, "~>1.1.0", [hex: :ssl_verify_fun, repo: "hexpm", optional: false]}, {:unicode_util_compat, "~>0.7.0", [hex: :unicode_util_compat, repo: "hexpm", optional: false]}], "hexpm", "a4ecdaff44297e9b5894ae499e9a070ea1888c84afdd1fd9b7b2bc384950128e"},
   "idna": {:hex, :idna, "6.1.1", "8a63070e9f7d0c62eb9d9fcb360a7de382448200fbbd1b106cc96d3d8099df8d", [:rebar3], [{:unicode_util_compat, "~>0.7.0", [hex: :unicode_util_compat, repo: "hexpm", optional: false]}], "hexpm", "92376eb7894412ed19ac475e4a86f7b413c1b9fbb5bd16dccd57934157944cea"},

diff --git a/src/astarte_vmq_plugin.erl b/src/astarte_vmq_plugin.erl
@@ -28,6 +28,20 @@ start() ->
     % name as the application, which can't be an Elixir module due to naming
     % constraints.
     {ok, _} = application:ensure_all_started(astarte_vmq_plugin, permanent),
+    ok = logger:update_handler_config(default, #{level => info}),
+    ok = logger:set_handler_config(default, formatter, {flatlog,
+                                #{template =>
+                                ["level=", level, " "
+                                 "time=", time, " ",
+                                 "pid=", pid, " ",
+                                 "mfa=", mfa, " ",
+                                 "line=", line, " ",
+                                 {realm, ["realm=", realm], []}, " ",
+                                 {device_id, ["device_id=", device_id], []}, " ",
+                                 msg, "\n"
+                                ],
+                              single_line => true}
+                            }),
     ok.
 
 stop() ->

diff --git a/lib/astarte_vmq_plugin.ex b/lib/astarte_vmq_plugin.ex
  end

  defp randomize_interval(interval, tolerance) do
    multiplier = 1 + (tolerance * 2 * :random.uniform() - tolerance)

    (interval * multiplier)
    |> Float.round()
diff --git a/lib/astarte_vmq_plugin/rpc/handler.ex b/lib/astarte_vmq_plugin/rpc/handler.ex
  end

  defp extract_call_tuple(%Call{call: nil}) do
    Logger.warn("Received empty call", tag: "received_empty_call")
    {:error, :empty_call}
  end

  end

  defp call_rpc({:disconnect, %Disconnect{client_id: ""}}) do
    Logger.warn("Disconnect with empty client_id", tag: "disconnect_empty_client_id")
    generic_error(:client_id_is_empty, "client_id is \"\"")
  end

  defp call_rpc({:disconnect, %Disconnect{discard_state: ""}}) do
    Logger.warn("Disconnect with empty discard_state", tag: "disconnect_empty_discard_state")
    generic_error(:discard_state_is_empty, "discard_state is \"\"")
  end

  end

  defp call_rpc({:publish, %Publish{topic_tokens: []}}) do
    Logger.warn("Publish with empty topic_tokens", tag: "publish_empty_topic_tokens")
    generic_error(:empty_topic_tokens, "empty topic tokens")
  end

  # This also handles the case of qos == nil, that is > 2
  defp call_rpc({:publish, %Publish{qos: qos}}) when qos > 2 or qos < 0 do
    Logger.warn("Publish with invalid QoS", tag: "publish_invalid_qos")
    generic_error(:invalid_qos, "invalid QoS")
  end

        publish_reply(local_matches, remote_matches)

      {:error, reason} ->
        Logger.warn("Publish failed with reason: #{inspect(reason)}", tag: "publish_failed")
        generic_error(reason)

      other_err ->
        Logger.warn("Unknown error in publish: #{inspect(other_err)}",
          tag: "publish_failed_unknown_error"
        )
	end

	defp randomize_interval(interval, tolerance) do
	multiplier = 1 + (tolerance * 2 * :random.uniform() - tolerance)
Check warning on line 193 in lib/astarte_vmq_plugin.ex GitHub Actions / Check Dialyzer `:random.uniform/0 is deprecated. Use the 'rand' module instead` Check warning on line 193 in lib/astarte_vmq_plugin.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, scylladb/scylla:5.2.2) `:random.uniform/0 is deprecated. Use the 'rand' module instead` Check warning on line 193 in lib/astarte_vmq_plugin.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, cassandra:3.11.15) `:random.uniform/0 is deprecated. Use the 'rand' module instead`

	(interval * multiplier)
	\|> Float.round()
	end

	defp extract_call_tuple(%Call{call: nil}) do
	Logger.warn("Received empty call", tag: "received_empty_call")
Check warning on line 45 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Check Dialyzer `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 45 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, scylladb/scylla:5.2.2) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 45 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, cassandra:3.11.15) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead`
	{:error, :empty_call}
	end

	end

	defp call_rpc({:disconnect, %Disconnect{client_id: ""}}) do
	Logger.warn("Disconnect with empty client_id", tag: "disconnect_empty_client_id")
Check warning on line 54 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Check Dialyzer `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 54 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, scylladb/scylla:5.2.2) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 54 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, cassandra:3.11.15) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead`
	generic_error(:client_id_is_empty, "client_id is \"\"")
	end

	defp call_rpc({:disconnect, %Disconnect{discard_state: ""}}) do
	Logger.warn("Disconnect with empty discard_state", tag: "disconnect_empty_discard_state")
Check warning on line 59 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Check Dialyzer `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 59 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, scylladb/scylla:5.2.2) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 59 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, cassandra:3.11.15) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead`
	generic_error(:discard_state_is_empty, "discard_state is \"\"")
	end

	end

	defp call_rpc({:publish, %Publish{topic_tokens: []}}) do
	Logger.warn("Publish with empty topic_tokens", tag: "publish_empty_topic_tokens")
Check warning on line 83 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Check Dialyzer `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 83 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, scylladb/scylla:5.2.2) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 83 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, cassandra:3.11.15) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead`
	generic_error(:empty_topic_tokens, "empty topic tokens")
	end

	# This also handles the case of qos == nil, that is > 2
	defp call_rpc({:publish, %Publish{qos: qos}}) when qos > 2 or qos < 0 do
	Logger.warn("Publish with invalid QoS", tag: "publish_invalid_qos")
Check warning on line 89 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Check Dialyzer `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 89 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, scylladb/scylla:5.2.2) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 89 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, cassandra:3.11.15) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead`
	generic_error(:invalid_qos, "invalid QoS")
	end

	publish_reply(local_matches, remote_matches)

	{:error, reason} ->
	Logger.warn("Publish failed with reason: #{inspect(reason)}", tag: "publish_failed")
Check warning on line 99 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Check Dialyzer `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 99 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, scylladb/scylla:5.2.2) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 99 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, cassandra:3.11.15) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead`
	generic_error(reason)

	other_err ->
	Logger.warn("Unknown error in publish: #{inspect(other_err)}",
Check warning on line 103 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Check Dialyzer `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 103 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, scylladb/scylla:5.2.2) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead` Check warning on line 103 in lib/astarte_vmq_plugin/rpc/handler.ex GitHub Actions / Build and Test (rabbitmq:3.12.0-management, cassandra:3.11.15) `Logger.warn/2 is deprecated. Use Logger.warning/2 instead`
	tag: "publish_failed_unknown_error"
	)