Merge pull request #9876 from zmstone/0131-avoid-persisting-logging-configs-if-no-change

0131 avoid persisting logging configs if no change

apps/emqx/src/config/emqx_config_logger.erl

@@ -18,6 +18,7 @@
 -behaviour(emqx_config_handler).
 
 %% API
+-export([tr_handlers/1, tr_level/1]).
 -export([add_handler/0, remove_handler/0, refresh_config/0]).
 -export([post_config_update/5]).
 
@@ -37,38 +38,224 @@ remove_handler() ->
 %% so we need to refresh the logger config after this node starts.
 %% It will not affect the logger config when cluster-override.conf is unchanged.
 refresh_config() ->
-    case emqx:get_raw_config(?LOG, undefined) of
-        %% no logger config when CT is running.
-        undefined ->
-            ok;
-        Log ->
-            {ok, _} = emqx:update_config(?LOG, Log),
-            ok
-    end.
+    Overrides = emqx_config:read_override_confs(),
+    refresh_config(Overrides).
+
+refresh_config(#{<<"log">> := _}) ->
+    %% read the checked config
+    LogConfig = emqx:get_config(?LOG, undefined),
+    Conf = #{log => LogConfig},
+    ok = do_refresh_config(Conf);
+refresh_config(_) ->
+    %% No config override found for 'log', do nothing
+    %% because the 'kernel' app should already be configured
+    %% from the base configs. i.e. emqx.conf + env vars
+    ok.
 
-post_config_update(?LOG, _Req, _NewConf, _OldConf, AppEnvs) ->
-    Kernel = proplists:get_value(kernel, AppEnvs),
-    NewHandlers = proplists:get_value(logger, Kernel, []),
-    Level = proplists:get_value(logger_level, Kernel, warning),
-    ok = update_log_handlers(NewHandlers),
-    ok = emqx_logger:set_primary_log_level(Level),
-    application:set_env(kernel, logger_level, Level),
-    ok;
+%% this call is shared between initial config refresh at boot
+%% and dynamic config update from HTTP API
+do_refresh_config(Conf) ->
+    Handlers = tr_handlers(Conf),
+    ok = update_log_handlers(Handlers),
+    Level = tr_level(Conf),
+    ok = maybe_update_log_level(Level),
+    ok.
+
+post_config_update(?LOG, _Req, NewConf, _OldConf, _AppEnvs) ->
+    ok = do_refresh_config(#{log => NewConf});
 post_config_update(_ConfPath, _Req, _NewConf, _OldConf, _AppEnvs) ->
     ok.
 
+maybe_update_log_level(NewLevel) ->
+    OldLevel = application:get_env(kernel, logger_level, warning),
+    case OldLevel =:= NewLevel of
+        true ->
+            %% no change
+            ok;
+        false ->
+            log_to_console("Config override: log level is set to '~p'~n", [NewLevel])
+    end.
+
+log_to_console(Fmt, Args) ->
+    io:format(standard_error, Fmt, Args).
+
 update_log_handlers(NewHandlers) ->
     OldHandlers = application:get_env(kernel, logger, []),
-    lists:foreach(
-        fun({handler, HandlerId, _Mod, _Conf}) ->
-            logger:remove_handler(HandlerId)
+    NewHandlersIds = lists:map(fun({handler, Id, _Mod, _Conf}) -> Id end, NewHandlers),
+    OldHandlersIds = lists:map(fun({handler, Id, _Mod, _Conf}) -> Id end, OldHandlers),
+    Removes = lists:map(fun(Id) -> {removed, Id} end, OldHandlersIds -- NewHandlersIds),
+    MapFn = fun({handler, Id, Mod, Conf} = Handler) ->
+        case lists:keyfind(Id, 2, OldHandlers) of
+            {handler, Id, Mod, Conf} ->
+                %% no change
+                false;
+            {handler, Id, _Mod, _Conf} ->
+                {true, {updated, Handler}};
+            false ->
+                {true, {enabled, Handler}}
+        end
+    end,
+    AddsAndUpdates = lists:filtermap(MapFn, NewHandlers),
+    lists:foreach(fun update_log_handler/1, Removes ++ AddsAndUpdates),
+    _ = application:set_env(kernel, logger, NewHandlers),
+    ok.
+
+update_log_handler({removed, Id}) ->
+    log_to_console("Config override: ~s is removed~n", [id_for_log(Id)]),
+    logger:remove_handler(Id);
+update_log_handler({Action, {handler, Id, Mod, Conf}}) ->
+    log_to_console("Config override: ~s is ~p~n", [id_for_log(Id), Action]),
+    % may return {error, {not_found, Id}}
+    _ = logger:remove_handler(Id),
+    ok = logger:add_handler(Id, Mod, Conf).
+
+id_for_log(console) -> "log.console_handler";
+id_for_log(Other) -> "log.file_handlers." ++ atom_to_list(Other).
+
+atom(Id) when is_binary(Id) -> binary_to_atom(Id, utf8);
+atom(Id) when is_atom(Id) -> Id.
+
+%% @doc Translate raw config to app-env conpatible log handler configs list.
+tr_handlers(Conf) ->
+    %% mute the default handler
+    tr_console_handler(Conf) ++
+        tr_file_handlers(Conf).
+
+%% For the default logger that outputs to console
+tr_console_handler(Conf) ->
+    case conf_get("log.console_handler.enable", Conf) of
+        true ->
+            ConsoleConf = conf_get("log.console_handler", Conf),
+            [
+                {handler, console, logger_std_h, #{
+                    level => conf_get("log.console_handler.level", Conf),
+                    config => (log_handler_conf(ConsoleConf))#{type => standard_io},
+                    formatter => log_formatter(ConsoleConf),
+                    filters => log_filter(ConsoleConf)
+                }}
+            ];
+        false ->
+            []
+    end.
+
+%% For the file logger
+tr_file_handlers(Conf) ->
+    Handlers = logger_file_handlers(Conf),
+    lists:map(fun tr_file_handler/1, Handlers).
+
+tr_file_handler({HandlerName, SubConf}) ->
+    {handler, atom(HandlerName), logger_disk_log_h, #{
+        level => conf_get("level", SubConf),
+        config => (log_handler_conf(SubConf))#{
+            type =>
+                case conf_get("rotation.enable", SubConf) of
+                    true -> wrap;
+                    _ -> halt
+                end,
+            file => conf_get("file", SubConf),
+            max_no_files => conf_get("rotation.count", SubConf),
+            max_no_bytes => conf_get("max_size", SubConf)
+        },
+        formatter => log_formatter(SubConf),
+        filters => log_filter(SubConf),
+        filesync_repeat_interval => no_repeat
+    }}.
+
+logger_file_handlers(Conf) ->
+    Handlers = maps:to_list(conf_get("log.file_handlers", Conf, #{})),
+    lists:filter(
+        fun({_Name, Opts}) ->
+            B = conf_get("enable", Opts),
+            true = is_boolean(B),
+            B
+        end,
+        Handlers
+    ).
+
+conf_get(Key, Conf) -> emqx_schema:conf_get(Key, Conf).
+conf_get(Key, Conf, Default) -> emqx_schema:conf_get(Key, Conf, Default).
+
+log_handler_conf(Conf) ->
+    SycModeQlen = conf_get("sync_mode_qlen", Conf),
+    DropModeQlen = conf_get("drop_mode_qlen", Conf),
+    FlushQlen = conf_get("flush_qlen", Conf),
+    Overkill = conf_get("overload_kill", Conf),
+    BurstLimit = conf_get("burst_limit", Conf),
+    #{
+        sync_mode_qlen => SycModeQlen,
+        drop_mode_qlen => DropModeQlen,
+        flush_qlen => FlushQlen,
+        overload_kill_enable => conf_get("enable", Overkill),
+        overload_kill_qlen => conf_get("qlen", Overkill),
+        overload_kill_mem_size => conf_get("mem_size", Overkill),
+        overload_kill_restart_after => conf_get("restart_after", Overkill),
+        burst_limit_enable => conf_get("enable", BurstLimit),
+        burst_limit_max_count => conf_get("max_count", BurstLimit),
+        burst_limit_window_time => conf_get("window_time", BurstLimit)
+    }.
+
+log_formatter(Conf) ->
+    CharsLimit =
+        case conf_get("chars_limit", Conf) of
+            unlimited -> unlimited;
+            V when V > 0 -> V
         end,
-        OldHandlers -- NewHandlers
-    ),
-    lists:foreach(
-        fun({handler, HandlerId, Mod, Conf}) ->
-            logger:add_handler(HandlerId, Mod, Conf)
+    TimeOffSet =
+        case conf_get("time_offset", Conf) of
+            "system" -> "";
+            "utc" -> 0;
+            OffSetStr -> OffSetStr
+        end,
+    SingleLine = conf_get("single_line", Conf),
+    Depth = conf_get("max_depth", Conf),
+    do_formatter(conf_get("formatter", Conf), CharsLimit, SingleLine, TimeOffSet, Depth).
+
+%% helpers
+do_formatter(json, CharsLimit, SingleLine, TimeOffSet, Depth) ->
+    {emqx_logger_jsonfmt, #{
+        chars_limit => CharsLimit,
+        single_line => SingleLine,
+        time_offset => TimeOffSet,
+        depth => Depth
+    }};
+do_formatter(text, CharsLimit, SingleLine, TimeOffSet, Depth) ->
+    {emqx_logger_textfmt, #{
+        template => [time, " [", level, "] ", msg, "\n"],
+        chars_limit => CharsLimit,
+        single_line => SingleLine,
+        time_offset => TimeOffSet,
+        depth => Depth
+    }}.
+
+log_filter(Conf) ->
+    case conf_get("supervisor_reports", Conf) of
+        error -> [{drop_progress_reports, {fun logger_filters:progress/2, stop}}];
+        progress -> []
+    end.
+
+tr_level(Conf) ->
+    ConsoleLevel = conf_get("log.console_handler.level", Conf, undefined),
+    FileLevels = [
+        conf_get("level", SubConf)
+     || {_, SubConf} <-
+            logger_file_handlers(Conf)
+    ],
+    case FileLevels ++ [ConsoleLevel || ConsoleLevel =/= undefined] of
+        %% warning is the default level we should use
+        [] -> warning;
+        Levels -> least_severe_log_level(Levels)
+    end.
+
+least_severe_log_level(Levels) ->
+    hd(sort_log_levels(Levels)).
+
+sort_log_levels(Levels) ->
+    lists:sort(
+        fun(A, B) ->
+            case logger:compare_levels(A, B) of
+                R when R == lt; R == eq -> true;
+                gt -> false
+            end
         end,
-        NewHandlers -- OldHandlers
-    ),
-    application:set_env(kernel, logger, NewHandlers).
+        Levels
+    ).

apps/emqx/src/emqx_app.erl

@@ -42,6 +42,7 @@
 start(_Type, _Args) ->
     ok = maybe_load_config(),
     ok = emqx_persistent_session:init_db_backend(),
+    ok = emqx_config_logger:refresh_config(),
     ok = maybe_start_quicer(),
     ok = emqx_bpapi:start(),
     wait_boot_shards(),

apps/emqx/src/emqx_config.erl

@@ -24,6 +24,7 @@
     init_load/2,
     init_load/3,
     read_override_conf/1,
+    read_override_confs/0,
     delete_override_conf_files/0,
     check_config/2,
     fill_defaults/1,
@@ -326,9 +327,7 @@ init_load(SchemaMod, RawConf, Opts) when is_map(RawConf) ->
     ok = save_schema_mod_and_names(SchemaMod),
     %% Merge environment variable overrides on top
     RawConfWithEnvs = merge_envs(SchemaMod, RawConf),
-    ClusterOverrides = read_override_conf(#{override_to => cluster}),
-    LocalOverrides = read_override_conf(#{override_to => local}),
-    Overrides = hocon:deep_merge(ClusterOverrides, LocalOverrides),
+    Overrides = read_override_confs(),
     RawConfWithOverrides = hocon:deep_merge(RawConfWithEnvs, Overrides),
     RootNames = get_root_names(),
     RawConfAll = raw_conf_with_default(SchemaMod, RootNames, RawConfWithOverrides, Opts),
@@ -337,6 +336,12 @@ init_load(SchemaMod, RawConf, Opts) when is_map(RawConf) ->
     save_to_app_env(AppEnvs),
     ok = save_to_config_map(CheckedConf, RawConfAll).
 
+%% @doc Read merged cluster + local overrides.
+read_override_confs() ->
+    ClusterOverrides = read_override_conf(#{override_to => cluster}),
+    LocalOverrides = read_override_conf(#{override_to => local}),
+    hocon:deep_merge(ClusterOverrides, LocalOverrides).
+
 %% keep the raw and non-raw conf has the same keys to make update raw conf easier.
 raw_conf_with_default(SchemaMod, RootNames, RawConf, #{raw_with_default := true}) ->
     Fun = fun(Name, Acc) ->
@@ -587,7 +592,6 @@ save_to_override_conf(RawConf, Opts) ->
 add_handlers() ->
     ok = emqx_config_logger:add_handler(),
     emqx_sys_mon:add_handler(),
-    emqx_config_logger:refresh_config(),
     ok.
 
 remove_handlers() ->
@@ -599,8 +603,16 @@ load_hocon_file(FileName, LoadType) ->
     case filelib:is_regular(FileName) of
         true ->
             Opts = #{include_dirs => include_dirs(), format => LoadType},
-            {ok, Raw0} = hocon:load(FileName, Opts),
-            Raw0;
+            case hocon:load(FileName, Opts) of
+                {ok, Raw0} ->
+                    Raw0;
+                {error, Reason} ->
+                    throw(#{
+                        msg => failed_to_load_conf,
+                        reason => Reason,
+                        file => FileName
+                    })
+            end;
         false ->
             #{}
     end.

apps/emqx/src/emqx_schema.erl

@@ -1815,16 +1815,12 @@ desc(_) ->
 %% utils
 -spec conf_get(string() | [string()], hocon:config()) -> term().
 conf_get(Key, Conf) ->
-    V = hocon_maps:get(Key, Conf),
-    case is_binary(V) of
-        true ->
-            binary_to_list(V);
-        false ->
-            V
-    end.
+    ensure_list(hocon_maps:get(Key, Conf)).
 
 conf_get(Key, Conf, Default) ->
-    V = hocon_maps:get(Key, Conf, Default),
+    ensure_list(hocon_maps:get(Key, Conf, Default)).
+
+ensure_list(V) ->
     case is_binary(V) of
         true ->
             binary_to_list(V);

apps/emqx_conf/src/emqx_conf_schema.erl

@@ -993,7 +993,7 @@ translation("ekka") ->
 translation("kernel") ->
     [
         {"logger_level", fun tr_logger_level/1},
-        {"logger", fun tr_logger/1},
+        {"logger", fun tr_logger_handlers/1},
         {"error_logger", fun(_) -> silent end}
     ];
 translation("emqx") ->
@@ -1065,70 +1065,10 @@ tr_cluster_discovery(Conf) ->
 
 -spec tr_logger_level(hocon:config()) -> logger:level().
 tr_logger_level(Conf) ->
-    ConsoleLevel = conf_get("log.console_handler.level", Conf, undefined),
-    FileLevels = [
-        conf_get("level", SubConf)
-     || {_, SubConf} <-
-            logger_file_handlers(Conf)
-    ],
-    case FileLevels ++ [ConsoleLevel || ConsoleLevel =/= undefined] of
-        %% warning is the default level we should use
-        [] -> warning;
-        Levels -> least_severe_log_level(Levels)
-    end.
-
-logger_file_handlers(Conf) ->
-    Handlers = maps:to_list(conf_get("log.file_handlers", Conf, #{})),
-    lists:filter(
-        fun({_Name, Opts}) ->
-            B = conf_get("enable", Opts),
-            true = is_boolean(B),
-            B
-        end,
-        Handlers
-    ).
+    emqx_config_logger:tr_level(Conf).
 
-tr_logger(Conf) ->
-    %% For the default logger that outputs to console
-    ConsoleHandler =
-        case conf_get("log.console_handler.enable", Conf) of
-            true ->
-                ConsoleConf = conf_get("log.console_handler", Conf),
-                [
-                    {handler, console, logger_std_h, #{
-                        level => conf_get("log.console_handler.level", Conf),
-                        config => (log_handler_conf(ConsoleConf))#{type => standard_io},
-                        formatter => log_formatter(ConsoleConf),
-                        filters => log_filter(ConsoleConf)
-                    }}
-                ];
-            false ->
-                []
-        end,
-    %% For the file logger
-    FileHandlers =
-        [
-            begin
-                {handler, to_atom(HandlerName), logger_disk_log_h, #{
-                    level => conf_get("level", SubConf),
-                    config => (log_handler_conf(SubConf))#{
-                        type =>
-                            case conf_get("rotation.enable", SubConf) of
-                                true -> wrap;
-                                _ -> halt
-                            end,
-                        file => conf_get("file", SubConf),
-                        max_no_files => conf_get("rotation.count", SubConf),
-                        max_no_bytes => conf_get("max_size", SubConf)
-                    },
-                    formatter => log_formatter(SubConf),
-                    filters => log_filter(SubConf),
-                    filesync_repeat_interval => no_repeat
-                }}
-            end
-         || {HandlerName, SubConf} <- logger_file_handlers(Conf)
-        ],
-    [{handler, default, undefined}] ++ ConsoleHandler ++ FileHandlers.
+tr_logger_handlers(Conf) ->
+    emqx_config_logger:tr_handlers(Conf).
 
 log_handler_common_confs(Enable) ->
     [
@@ -1225,78 +1165,6 @@ log_handler_common_confs(Enable) ->
             )}
     ].
 
-log_handler_conf(Conf) ->
-    SycModeQlen = conf_get("sync_mode_qlen", Conf),
-    DropModeQlen = conf_get("drop_mode_qlen", Conf),
-    FlushQlen = conf_get("flush_qlen", Conf),
-    Overkill = conf_get("overload_kill", Conf),
-    BurstLimit = conf_get("burst_limit", Conf),
-    #{
-        sync_mode_qlen => SycModeQlen,
-        drop_mode_qlen => DropModeQlen,
-        flush_qlen => FlushQlen,
-        overload_kill_enable => conf_get("enable", Overkill),
-        overload_kill_qlen => conf_get("qlen", Overkill),
-        overload_kill_mem_size => conf_get("mem_size", Overkill),
-        overload_kill_restart_after => conf_get("restart_after", Overkill),
-        burst_limit_enable => conf_get("enable", BurstLimit),
-        burst_limit_max_count => conf_get("max_count", BurstLimit),
-        burst_limit_window_time => conf_get("window_time", BurstLimit)
-    }.
-
-log_formatter(Conf) ->
-    CharsLimit =
-        case conf_get("chars_limit", Conf) of
-            unlimited -> unlimited;
-            V when V > 0 -> V
-        end,
-    TimeOffSet =
-        case conf_get("time_offset", Conf) of
-            "system" -> "";
-            "utc" -> 0;
-            OffSetStr -> OffSetStr
-        end,
-    SingleLine = conf_get("single_line", Conf),
-    Depth = conf_get("max_depth", Conf),
-    do_formatter(conf_get("formatter", Conf), CharsLimit, SingleLine, TimeOffSet, Depth).
-
-%% helpers
-do_formatter(json, CharsLimit, SingleLine, TimeOffSet, Depth) ->
-    {emqx_logger_jsonfmt, #{
-        chars_limit => CharsLimit,
-        single_line => SingleLine,
-        time_offset => TimeOffSet,
-        depth => Depth
-    }};
-do_formatter(text, CharsLimit, SingleLine, TimeOffSet, Depth) ->
-    {emqx_logger_textfmt, #{
-        template => [time, " [", level, "] ", msg, "\n"],
-        chars_limit => CharsLimit,
-        single_line => SingleLine,
-        time_offset => TimeOffSet,
-        depth => Depth
-    }}.
-
-log_filter(Conf) ->
-    case conf_get("supervisor_reports", Conf) of
-        error -> [{drop_progress_reports, {fun logger_filters:progress/2, stop}}];
-        progress -> []
-    end.
-
-least_severe_log_level(Levels) ->
-    hd(sort_log_levels(Levels)).
-
-sort_log_levels(Levels) ->
-    lists:sort(
-        fun(A, B) ->
-            case logger:compare_levels(A, B) of
-                R when R == lt; R == eq -> true;
-                gt -> false
-            end
-        end,
-        Levels
-    ).
-
 crash_dump_file_default() ->
     case os:getenv("RUNNER_LOG_DIR") of
         false ->
@@ -1308,11 +1176,9 @@ crash_dump_file_default() ->
 
 %% utils
 -spec conf_get(string() | [string()], hocon:config()) -> term().
-conf_get(Key, Conf) ->
-    ensure_list(hocon_maps:get(Key, Conf)).
+conf_get(Key, Conf) -> emqx_schema:conf_get(Key, Conf).
 
-conf_get(Key, Conf, Default) ->
-    ensure_list(hocon_maps:get(Key, Conf, Default)).
+conf_get(Key, Conf, Default) -> emqx_schema:conf_get(Key, Conf, Default).
 
 filter(Opts) ->
     [{K, V} || {K, V} <- Opts, V =/= undefined].
@@ -1376,15 +1242,6 @@ to_atom(Str) when is_list(Str) ->
 to_atom(Bin) when is_binary(Bin) ->
     binary_to_atom(Bin, utf8).
 
--spec ensure_list(binary() | list(char())) -> list(char()).
-ensure_list(V) ->
-    case is_binary(V) of
-        true ->
-            binary_to_list(V);
-        false ->
-            V
-    end.
-
 roots(Module) ->
     lists:map(fun({_BinName, Root}) -> Root end, hocon_schema:roots(Module)).