From 79181072e272242c2e1dc5783f4c7f35dfd79be1 Mon Sep 17 00:00:00 2001 From: Zaiming Shi Date: Mon, 3 May 2021 11:51:26 +0200 Subject: [PATCH] feat(logger): add formatter emqx_logger_jsonfmt --- etc/emqx.conf | 10 +- priv/emqx.schema | 33 +++- src/emqx_logger_jsonfmt.erl | 294 ++++++++++++++++++++++++++++++++++++ 3 files changed, 330 insertions(+), 7 deletions(-) create mode 100644 src/emqx_logger_jsonfmt.erl diff --git a/etc/emqx.conf b/etc/emqx.conf index f45e0eaa0..6bfd541b4 100644 --- a/etc/emqx.conf +++ b/etc/emqx.conf @@ -444,9 +444,15 @@ log.file = emqx.log ## Default: No Limit #log.chars_limit = 8192 -## Log to single line +## Log as JSON objects ## Value: boolean -#log.single_line = false +#log.use_json_formatter = false + +## Log to single line +## Value: formatter_default | true | false +## 'default' is equivalent to 'true' when use_json_formatter is 'true' +## 'default' is equivalent to 'false' when `use_json_formatter is 'false' +#log.single_line = formatter_default ## Enables the log rotation. ## With this enabled, new log files will be created when the current diff --git a/priv/emqx.schema b/priv/emqx.schema index cc1c084fc..b8a15e096 100644 --- a/priv/emqx.schema +++ b/priv/emqx.schema @@ -498,12 +498,18 @@ end}. {datatype, [{enum, [unlimited]}, integer]} ]}. -%% @doc format logs in a single line. -{mapping, "log.single_line", "kernel.logger", [ +%% @doc format logs as JSON objects +{mapping, "log.use_json_formatter", "kernel.logger", [ {default, false}, {datatype, {enum, [true, false]}} ]}. +%% @doc format logs in a single line. +{mapping, "log.single_line", "kernel.logger", [ + {default, formatter_default}, + {datatype, {enum, [formatter_default, true, false]}} +]}. + {mapping, "log.rotation", "kernel.logger", [ {default, on}, {datatype, flag} @@ -600,8 +606,24 @@ end}. -1 -> unlimited; V -> V end, - SingleLine = cuttlefish:conf_get("log.single_line", Conf), - Formatter = {logger_formatter, + SingleLine0 = cuttlefish:conf_get("log.single_line", Conf), + AsJson = cuttlefish:conf_get("log.use_json_formatter", Conf), + SingleLine = case SingleLine0 =:= formatter_default of + true -> + %% single-line when logging in JSON format + AsJson; + false -> + SingleLine0 + end, + Formatter = + case AsJson of + true -> + {emqx_logger_jsonfmt, + #{chars_limit => CharsLimit, + single_line => SingleLine + }}; + false -> + {logger_formatter, #{template => [time," [",level,"] ", {clientid, @@ -614,7 +636,8 @@ end}. msg,"\n"], chars_limit => CharsLimit, single_line => SingleLine - }}, + }} + end, {BustLimitOn, {MaxBurstCount, TimeWindow}} = case string:tokens(cuttlefish:conf_get("log.burst_limit", Conf), ", ") of ["disabled"] -> {false, {20000, 1000}}; diff --git a/src/emqx_logger_jsonfmt.erl b/src/emqx_logger_jsonfmt.erl new file mode 100644 index 000000000..10ae4c50f --- /dev/null +++ b/src/emqx_logger_jsonfmt.erl @@ -0,0 +1,294 @@ +%%-------------------------------------------------------------------- +%% Copyright (c) 2021 EMQ Technologies Co., Ltd. All Rights Reserved. +%% +%% Licensed under the Apache License, Version 2.0 (the "License"); +%% you may not use this file except in compliance with the License. +%% You may obtain a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, software +%% distributed under the License is distributed on an "AS IS" BASIS, +%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +%% See the License for the specific language governing permissions and +%% limitations under the License. +%%-------------------------------------------------------------------- + +%% @doc This logger formatter tries format logs into JSON objects +%% +%% Due to the fact that the `Report' body of log entries are *NOT* +%% structured, we only try to JSON-ify `Meta', +%% +%% `Report' body format is pretty-printed and used as the `msg' +%% JSON field in the finale result. +%% +%% e.g. logger:log(info, _Data = #{foo => bar}, _Meta = #{metaf1 => 2}) +%% will results in a JSON object look like below: +%% +%% {"time": 1620226963427808, "level": "info", msg": "foo: bar", "metaf1": 2} + +-module(emqx_logger_jsonfmt). + +-export([format/2]). + +-ifdef(TEST). +-export([report_cb_1/1, report_cb_2/2, report_cb_crash/2]). +-endif. + +-export_type([config/0]). + +-elvis([{elvis_style, no_nested_try_catch, #{ ignore => [emqx_logger_jsonfmt]}}]). + +-type config() :: #{depth => pos_integer() | unlimited, + report_cb => logger:report_cb(), + single_line => boolean()}. + +-define(IS_STRING(String), (is_list(String) orelse is_binary(String))). + +-spec format(logger:log_event(), config()) -> iodata(). +format(#{level := Level, msg := Msg, meta := Meta}, Config0) when is_map(Config0) -> + Config = add_default_config(Config0), + format(Msg, Meta#{level => Level}, Config). + +format(Msg, Meta, Config) -> + Data0 = + try Meta#{msg => format_msg(Msg, Meta, Config)} + catch + C:R:S -> + Meta#{ msg => "emqx_logger_jsfmt_format_error" + , fmt_raw_input => Msg + , fmt_error => C + , fmt_reason => R + , fmt_stacktrace => S + } + end, + Data = maps:without([report_cb], Data0), + jiffy:encode(json_obj(Data, Config)). + +format_msg({string, Chardata}, Meta, Config) -> + format_msg({"~ts", [Chardata]}, Meta, Config); +format_msg({report, _} = Msg, Meta, #{report_cb := Fun} = Config) + when is_function(Fun,1); is_function(Fun,2) -> + format_msg(Msg, Meta#{report_cb => Fun}, maps:remove(report_cb, Config)); +format_msg({report, Report}, #{report_cb := Fun} = Meta, Config) when is_function(Fun, 1) -> + case Fun(Report) of + {Format, Args} when is_list(Format), is_list(Args) -> + format_msg({Format, Args}, maps:remove(report_cb, Meta), Config); + Other -> + #{ msg => "report_cb_bad_return" + , report_cb_fun => Fun + , report_cb_return => Other + } + end; +format_msg({report, Report}, #{report_cb := Fun}, Config) when is_function(Fun, 2) -> + case Fun(Report, maps:with([depth, single_line], Config)) of + Chardata when ?IS_STRING(Chardata) -> + try + unicode:characters_to_binary(Chardata, utf8) + catch + _:_ -> + #{ msg => "report_cb_bad_return" + , report_cb_fun => Fun + , report_cb_return => Chardata + } + end; + Other -> + #{ msg => "report_cb_bad_return" + , report_cb_fun => Fun + , report_cb_return => Other + } + end; +format_msg({Fmt, Args}, _Meta, Config) -> + do_format_msg(Fmt, Args, Config). + +do_format_msg(Format0, Args, #{depth := Depth, + single_line := SingleLine + }) -> + Format1 = io_lib:scan_format(Format0, Args), + Format = reformat(Format1, Depth, SingleLine), + Text0 = io_lib:build_text(Format, []), + Text = case SingleLine of + true -> re:replace(Text0, ",?\r?\n\s*",", ", [{return, list}, global, unicode]); + false -> Text0 + end, + trim(unicode:characters_to_binary(Text, utf8)). + +%% Get rid of the leading spaces. +%% leave alone the trailing spaces. +trim(<<$\s, Rest/binary>>) -> trim(Rest); +trim(Bin) -> Bin. + +reformat(Format, unlimited, false) -> + Format; +reformat([#{control_char := C} = M | T], Depth, true) when C =:= $p -> + [limit_depth(M#{width => 0}, Depth) | reformat(T, Depth, true)]; +reformat([#{control_char := C} = M | T], Depth, true) when C =:= $P -> + [M#{width => 0} | reformat(T, Depth, true)]; +reformat([#{control_char := C}=M | T], Depth, Single) when C =:= $p; C =:= $w -> + [limit_depth(M, Depth) | reformat(T, Depth, Single)]; +reformat([H | T], Depth, Single) -> + [H | reformat(T, Depth, Single)]; +reformat([], _, _) -> + []. + +limit_depth(M0, unlimited) -> M0; +limit_depth(#{control_char:=C0, args:=Args}=M0, Depth) -> + C = C0 - ($a - $A), %To uppercase. + M0#{control_char := C, args := Args ++ [Depth]}. + +add_default_config(Config0) -> + Default = #{single_line => true}, + Depth = get_depth(maps:get(depth, Config0, undefined)), + maps:merge(Default, Config0#{depth => Depth}). + +get_depth(undefined) -> error_logger:get_format_depth(); +get_depth(S) -> max(5, S). + +best_effort_unicode(Input, Config) -> + try unicode:characters_to_binary(Input, utf8) of + B when is_binary(B) -> B; + _ -> do_format_msg("~p", [Input], Config) + catch + _ : _ -> + do_format_msg("~p", [Input], Config) + end. + +best_effort_json_obj(List, Config) when is_list(List) -> + try + json_obj(maps:from_list(List), Config) + catch + _ : _ -> + [json(I, Config) || I <- List] + end; +best_effort_json_obj(Map, Config) -> + try + json_obj(Map, Config) + catch + _ : _ -> + do_format_msg("~p", [Map], Config) + end. + +json([], _) -> "[]"; +json(<<"">>, _) -> "\"\""; +json(A, _) when is_atom(A) -> atom_to_binary(A, utf8); +json(I, _) when is_integer(I) -> I; +json(F, _) when is_float(F) -> F; +json(P, C) when is_pid(P) -> json(pid_to_list(P), C); +json(P, C) when is_port(P) -> json(port_to_list(P), C); +json(F, C) when is_function(F) -> json(erlang:fun_to_list(F), C); +json(B, Config) when is_binary(B) -> + best_effort_unicode(B, Config); +json(L, Config) when is_list(L), is_integer(hd(L))-> + best_effort_unicode(L, Config); +json(M, Config) when is_list(M), is_tuple(hd(M)), tuple_size(hd(M)) =:= 2 -> + best_effort_json_obj(M, Config); +json(L, Config) when is_list(L) -> + [json(I, Config) || I <- L]; +json(Map, Config) when is_map(Map) -> + best_effort_json_obj(Map, Config); +json(Term, Config) -> + do_format_msg("~p", [Term], Config). + +json_obj(Data, Config) -> + maps:fold(fun (K, V, D) -> + json_kv(K, V, D, Config) + end, maps:new(), Data). + +json_kv(mfa, {M, F, A}, Data, _Config) -> %% emqx/snabbkaffe + maps:put(mfa, <<(atom_to_binary(M, utf8))/binary, $:, + (atom_to_binary(F, utf8))/binary, $/, + (integer_to_binary(A))/binary>>, Data); +json_kv('$kind', Kind, Data, Config) -> %% snabbkaffe + maps:put(msg, json(Kind, Config), Data); +json_kv(K0, V, Data, Config) -> + K = json_key(K0), + case is_map(V) of + true -> maps:put(json(K, Config), json_obj(V, Config), Data); + false -> maps:put(json(K, Config), json(V, Config), Data) + end. + +json_key('') -> throw({badkey, ''}); +json_key("") -> throw({badkey, ""}); +json_key(<<>>) -> throw({badkey, <<>>}); +json_key(A) when is_atom(A) -> atom_to_binary(A, utf8); +json_key(Term) -> + try unicode:characters_to_binary(Term, utf8) of + OK when is_binary(OK) -> OK; + _ -> throw({badkey, Term}) + catch _:_ -> throw({badkey, Term}) + end. + +-ifdef(TEST). +-include_lib("proper/include/proper.hrl"). +-include_lib("eunit/include/eunit.hrl"). + +no_crash_test_() -> + Opts = [{numtests, 1000}, {to_file, user}], + {timeout, 30, + fun() -> ?assert(proper:quickcheck(t_no_crash(), Opts)) end}. + +t_no_crash() -> + ?FORALL({Level, Report, Meta, Config}, + {p_level(), p_report(), p_meta(), p_config()}, + t_no_crash_run(Level, Report, Meta, Config)). + +t_no_crash_run(Level, Report, {undefined, Meta}, Config) -> + t_no_crash_run(Level, Report, maps:from_list(Meta), Config); +t_no_crash_run(Level, Report, {ReportCb, Meta}, Config) -> + t_no_crash_run(Level, Report, maps:from_list([{report_cb, ReportCb} | Meta]), Config); +t_no_crash_run(Level, Report, Meta, Config) -> + Input = #{ level => Level + , msg => {report, Report} + , meta => filter(Meta) + }, + _ = format(Input, maps:from_list(Config)), + true. + +%% assume top level Report and Meta are sane +filter(Map) -> + Keys = lists:filter( + fun(K) -> + try json_key(K), true + catch _ : _ -> false + end + end, maps:keys(Map)), + maps:with(Keys, Map). + +p_report_cb() -> + proper_types:oneof([ fun ?MODULE:report_cb_1/1 + , fun ?MODULE:report_cb_2/2 + , fun ?MODULE:report_cb_crash/2 + , fun logger:format_otp_report/1 + , fun logger:format_report/1 + , format_reportundefined + ]). + +report_cb_1(Input) -> {"~p", [Input]}. + +report_cb_2(Input, _Config) -> io_lib:format("~p", [Input]). + +report_cb_crash(_Input, _Config) -> error(report_cb_crash). + +p_kvlist() -> + proper_types:list({ + proper_types:oneof([proper_types:atom(), + proper_types:binary() + ]), proper_types:term()}). + +%% meta type is 2-tuple, report_cb type, and some random key value pairs +p_meta() -> + {p_report_cb(), p_kvlist()}. + +p_report() -> p_kvlist(). + +p_limit() -> proper_types:oneof([proper_types:pos_integer(), unlimited]). + +p_level() -> proper_types:oneof([info, debug, error, warning, foobar]). + +p_config() -> + proper_types:shrink_list( + [ {depth, p_limit()} + , {single_line, proper_types:boolean()} + ]). + +-endif.