emqx_logger_jsonfmt.erl

%%--------------------------------------------------------------------
%% 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) , "\n"].

format(Msg, Meta, Config) ->
    Data0 =
        try Meta#{msg => format_msg(Msg, Meta, Config)}
        catch
            C:R:S ->
                Meta#{ msg => "emqx_logger_jsonfmt_format_error"
                     , fmt_raw_input => Msg
                     , fmt_error => C
                     , fmt_reason => R
                     , fmt_stacktrace => S
                     }
        end,
    Data = maps:without([report_cb], Data0),
    Payload = jiffy:encode(json_obj(Data, Config)),
    emqx_hooks:run('logger.send',[Meta, Payload]),
    Payload.

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), best_effort_json_obj(V, Config), Data);
        false -> maps:put(json(K, Config), json(V, Config), Data)
    end.

json_key(A) when is_atom(A) -> json_key(atom_to_binary(A, utf8));
json_key(Term) ->
    try unicode:characters_to_binary(Term, utf8) of
        OK when is_binary(OK) andalso 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 throw : {badkey, _} -> 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_report_undefined
                       ]).

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.