From ce32ea7334da3cdb925d0c556f3e7d1a6dca98dc Mon Sep 17 00:00:00 2001
From: Zhongwen Deng <zhongwencool@gmail.com>
Date: Mon, 30 Jan 2023 12:18:22 +0800
Subject: [PATCH] feat: Make the log output format order fixed

---
 apps/emqx/include/logger.hrl          |  4 +-
 apps/emqx/src/emqx_cm.erl             |  2 +-
 apps/emqx/src/emqx_logger_textfmt.erl | 65 ++++++++++++++-------------
 apps/emqx/test/emqx_mqtt_SUITE.erl    |  2 +-
 4 files changed, 39 insertions(+), 34 deletions(-)

diff --git a/apps/emqx/include/logger.hrl b/apps/emqx/include/logger.hrl
index e93aa46f4..27ffc6cc0 100644
--- a/apps/emqx/include/logger.hrl
+++ b/apps/emqx/include/logger.hrl
@@ -48,9 +48,9 @@
 -define(TRACE(Level, Tag, Msg, Meta), begin
     case persistent_term:get(?TRACE_FILTER, []) of
         [] -> ok;
-        %% We can't bind filter list to a variablebecause we pollute the calling scope with it.
+        %% We can't bind filter list to a variable because we pollute the calling scope with it.
         %% We also don't want to wrap the macro body in a fun
-        %% beacause this adds overhead to the happy path.
+        %% because this adds overhead to the happy path.
         %% So evaluate `persistent_term:get` twice.
         _ -> emqx_trace:log(persistent_term:get(?TRACE_FILTER, []), Msg, (Meta)#{trace_tag => Tag})
     end,
diff --git a/apps/emqx/src/emqx_cm.erl b/apps/emqx/src/emqx_cm.erl
index 66e9a2aee..77bc44eeb 100644
--- a/apps/emqx/src/emqx_cm.erl
+++ b/apps/emqx/src/emqx_cm.erl
@@ -152,7 +152,7 @@ start_link() ->
 insert_channel_info(ClientId, Info, Stats) ->
     Chan = {ClientId, self()},
     true = ets:insert(?CHAN_INFO_TAB, {Chan, Info, Stats}),
-    ?tp(debug, insert_channel_info, #{client_id => ClientId}),
+    ?tp(debug, insert_channel_info, #{clientid => ClientId}),
     ok.
 
 %% @private
diff --git a/apps/emqx/src/emqx_logger_textfmt.erl b/apps/emqx/src/emqx_logger_textfmt.erl
index 3695929d9..c1d85f341 100644
--- a/apps/emqx/src/emqx_logger_textfmt.erl
+++ b/apps/emqx/src/emqx_logger_textfmt.erl
@@ -22,20 +22,49 @@
 
 check_config(X) -> logger_formatter:check_config(X).
 
-format(#{msg := {report, Report0}, meta := Meta} = Event, Config) when is_map(Report0) ->
-    Report1 = enrich_report_mfa(Report0, Meta),
-    Report2 = enrich_report_clientid(Report1, Meta),
-    Report3 = enrich_report_peername(Report2, Meta),
-    Report4 = enrich_report_topic(Report3, Meta),
-    logger_formatter:format(Event#{msg := {report, Report4}}, Config);
+format(#{msg := {report, ReportMap}, meta := Meta} = Event, Config) when is_map(ReportMap) ->
+    Report = enrich_report(ReportMap, Meta),
+    logger_formatter:format(Event#{msg := {report, Report}}, Config);
 format(#{msg := {string, String}} = Event, Config) ->
     format(Event#{msg => {"~ts ", [String]}}, Config);
+%% trace
 format(#{msg := Msg0, meta := Meta} = Event, Config) ->
     Msg1 = enrich_client_info(Msg0, Meta),
     Msg2 = enrich_mfa(Msg1, Meta),
     Msg3 = enrich_topic(Msg2, Meta),
     logger_formatter:format(Event#{msg := Msg3}, Config).
 
+enrich_report(ReportRaw, Meta) ->
+    %% clientid and peername always in emqx_conn's process metadata.
+    %% topic can be put in meta using ?SLOG/3, or put in msg's report by ?SLOG/2
+    Topic =
+        case maps:get(topic, Meta, undefined) of
+            undefined -> maps:get(topic, ReportRaw, undefined);
+            Topic0 -> Topic0
+        end,
+    ClientId = maps:get(clientid, Meta, undefined),
+    Peer = maps:get(peername, Meta, undefined),
+    MFA = maps:get(mfa, Meta, undefined),
+    Line = maps:get(line, Meta, undefined),
+    Msg = maps:get(msg, ReportRaw, undefined),
+    lists:foldl(
+        fun
+            ({_, undefined}, Acc) -> Acc;
+            (Item, Acc) -> [Item | Acc]
+        end,
+        maps:to_list(maps:without([topic, msg, clientid], ReportRaw)),
+        [
+            {topic, try_format_unicode(Topic)},
+            {clientid, try_format_unicode(ClientId)},
+            {peername, Peer},
+            {line, Line},
+            {mfa, mfa(MFA)},
+            {msg, Msg}
+        ]
+    ).
+
+try_format_unicode(undefined) ->
+    undefined;
 try_format_unicode(Char) ->
     List =
         try
@@ -53,30 +82,6 @@ try_format_unicode(Char) ->
         _ -> List
     end.
 
-enrich_report_mfa(Report, #{mfa := Mfa, line := Line}) ->
-    Report#{mfa => mfa(Mfa), line => Line};
-enrich_report_mfa(Report, _) ->
-    Report.
-
-enrich_report_clientid(Report, #{clientid := ClientId}) ->
-    Report#{clientid => try_format_unicode(ClientId)};
-enrich_report_clientid(Report, _) ->
-    Report.
-
-enrich_report_peername(Report, #{peername := Peername}) ->
-    Report#{peername => Peername};
-enrich_report_peername(Report, _) ->
-    Report.
-
-%% clientid and peername always in emqx_conn's process metadata.
-%% topic can be put in meta using ?SLOG/3, or put in msg's report by ?SLOG/2
-enrich_report_topic(Report, #{topic := Topic}) ->
-    Report#{topic => try_format_unicode(Topic)};
-enrich_report_topic(Report = #{topic := Topic}, _) ->
-    Report#{topic => try_format_unicode(Topic)};
-enrich_report_topic(Report, _) ->
-    Report.
-
 enrich_mfa({Fmt, Args}, #{mfa := Mfa, line := Line}) when is_list(Fmt) ->
     {Fmt ++ " mfa: ~ts line: ~w", Args ++ [mfa(Mfa), Line]};
 enrich_mfa(Msg, _) ->
diff --git a/apps/emqx/test/emqx_mqtt_SUITE.erl b/apps/emqx/test/emqx_mqtt_SUITE.erl
index 287d7fdba..d0162b34b 100644
--- a/apps/emqx/test/emqx_mqtt_SUITE.erl
+++ b/apps/emqx/test/emqx_mqtt_SUITE.erl
@@ -237,7 +237,7 @@ do_async_set_keepalive() ->
     {ok, _} = ?block_until(
         #{
             ?snk_kind := insert_channel_info,
-            client_id := ClientID
+            clientid := ClientID
         },
         2000,
         100