Skip to content

Commit

Permalink
Logging: Add configuration variables to set various formats
Browse files Browse the repository at this point in the history
In addition to the existing configuration variables to configure
logging, the following variables were added to extend the settings.

log.*.formatter = plaintext | json
  Selects between the plain text (default) and JSON formatters.

log.*.formatter.time_format = rfc3339_space | rfc3339_T | epoch_usecs | epoch_secs | lager_default
  Configures how the timestamp should be formatted. It has several
  values to get RFC3339 date & time, Epoch-based integers and Lager
  default format.

log.*.formatter.level_format = lc | uc | lc3 | uc3 | lc4 | uc4
  Configures how to format the level. Things like uppercase vs.
  lowercase, full vs. truncated.
  Examples:
    lc: debug
    uc: DEBUG
    lc3: dbg
    uc3: DBG
    lw4: dbug
    uc4: DBUG

log.*.formatter.single_line = on | off
  Indicates if multi-line messages should be reformatted as a
  single-line message. A multi-line message is converted to a
  single-line message by joining all lines and separating them
  with ", ".

log.*.formatter.plaintext.format
  Set to a pattern to indicate the format of the entire message. The
  format pattern is a string with $-based variables. Each variable
  corresponds to a field in the log event. Here is a non-exhaustive list
  of common fields:
    time
    level
    msg
    pid
    file
    line
  Example:
    $time [$level] $pid $msg

log.*.formatter.json.field_map
  Indicates if fields should be renamed or removed, and the ordering
  which they should appear in the final JSON object. The order is set by
  the order of fields in that coniguration variable.
  Example:
    time:ts level msg *:-
  In this example, `time` is renamed to `ts`. `*:-` tells to remove all
  fields not mentionned in the list. In the end the JSON object will
  contain the fields in the following order: ts, level, msg.

log.*.formatter.json.verbosity_map
  Indicates if a verbosity field should be added and how it should be
  derived from the level. If the verbosity map is not set, no verbosity
  field is added to the JSON object.
  Example:
    debug:2 info:1 notice:1 *:0
  In this example, debug verbosity is 2, info and notice verbosity is 1,
  other levels have a verbosity of 0.

All of them work with the console, exchange, file and syslog outputs.

The console output has specific variables too:

log.console.stdio = stdout | stderr
  Indicates if stdout or stderr should be used. The default is stdout.

log.console.use_colors = on | off
  Indicates if colors should be used in log messages. The default
  depends on the environment.

log.console.color_esc_seqs.*
  Indicates how each level is mapped to a color. The value can be any
  string but the idea is to use an ANSI escape sequence.
  Example:
    log.console.color_esc_seqs.error = \033[1;31m

V2: A custom time format pattern was introduced, first using variables,
    then a reference date & time (e.g. "Mon 2 Jan 2006"), thanks to
    @ansd. However, we decided to remove it for now until we have a
    better implementation of the reference date & time parser.

V3: The testsuite was extended to cover new settings as well as the
    syslog output. To test it, a fake syslogd server was added (Erlang
    process, part of the testsuite).

V4: The dependency to cuttlefish is moved to rabbitmq_prelaunch which
    actually uses the library. The version is updated to 3.0.1 because
    we need Kyorai/cuttlefish#25.
  • Loading branch information
dumbbell committed Mar 29, 2021
1 parent 80845de commit 55f258a
Show file tree
Hide file tree
Showing 9 changed files with 1,943 additions and 489 deletions.
3 changes: 1 addition & 2 deletions deps/rabbit/Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -133,12 +133,11 @@ APPS_DIR := $(CURDIR)/apps
LOCAL_DEPS = sasl rabbitmq_prelaunch os_mon inets compiler public_key crypto ssl syntax_tools xmerl

BUILD_DEPS = rabbitmq_cli
DEPS = cuttlefish ranch rabbit_common ra sysmon_handler stdout_formatter recon observer_cli osiris amqp10_common syslog
DEPS = ranch rabbit_common ra sysmon_handler stdout_formatter recon observer_cli osiris amqp10_common syslog
TEST_DEPS = rabbitmq_ct_helpers rabbitmq_ct_client_helpers amqp_client meck proper

PLT_APPS += mnesia

dep_cuttlefish = git https://github.com/Kyorai/cuttlefish master
dep_syslog = git https://github.com/schlagert/syslog 4.0.0
dep_osiris = git https://github.com/rabbitmq/osiris master

Expand Down
3 changes: 2 additions & 1 deletion deps/rabbit/apps/rabbitmq_prelaunch/Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,8 @@ PROJECT_DESCRIPTION = RabbitMQ prelaunch setup
PROJECT_VERSION = 1.0.0
PROJECT_MOD = rabbit_prelaunch_app

DEPS = rabbit_common jsx
DEPS = rabbit_common cuttlefish jsx
dep_cuttlefish = hex 3.0.1

DEP_PLUGINS = rabbit_common/mk/rabbitmq-build.mk

Expand Down
187 changes: 187 additions & 0 deletions deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_fmt_helpers.erl
Original file line number Diff line number Diff line change
@@ -0,0 +1,187 @@
%% This Source Code Form is subject to the terms of the Mozilla Public
%% License, v. 2.0. If a copy of the MPL was not distributed with this
%% file, You can obtain one at https://mozilla.org/MPL/2.0/.
%%
%% Copyright (c) 2021 VMware, Inc. or its affiliates. All rights reserved.
%%

-module(rabbit_logger_fmt_helpers).

-export([format_time/2,
format_level/2,
format_msg/3]).

format_time(Timestamp, #{time_format := Format}) ->
format_time1(Timestamp, Format);
format_time(Timestamp, _) ->
format_time1(Timestamp, {rfc3339, $\s}).

format_time1(Timestamp, {rfc3339, Sep}) ->
Options = [{unit, microsecond},
{time_designator, Sep}],
calendar:system_time_to_rfc3339(Timestamp, Options);
format_time1(Timestamp, {epoch, secs, int}) ->
Timestamp / 1000000;
format_time1(Timestamp, {epoch, usecs, int}) ->
Timestamp;
format_time1(Timestamp, {epoch, secs, binary}) ->
io_lib:format("~.6.0f", [Timestamp / 1000000]);
format_time1(Timestamp, {epoch, usecs, binary}) ->
io_lib:format("~b", [Timestamp]);
format_time1(Timestamp, {Format, Args}) ->
%% The format string and the args list is prepared by
%% `rabbit_prelaunch_early_logging:translate_generic_conf()'.
{{Year, Month, Day},
{Hour, Minute, Second}} = calendar:system_time_to_local_time(
Timestamp, microsecond),
Args1 = lists:map(
fun
(year) -> Year;
(month) -> Month;
(day) -> Day;
(hour) -> Hour;
(minute) -> Minute;
(second) -> Second;
({second_fractional,
Decimals}) -> second_fractional(Timestamp, Decimals)
end, Args),
io_lib:format(Format, Args1).

second_fractional(Timestamp, Decimals) ->
(Timestamp rem 1000000) div (1000000 div round(math:pow(10, Decimals))).

format_level(Level, Config) ->
format_level1(Level, Config).

format_level1(Level, #{level_format := lc}) ->
level_lc_name(Level);
format_level1(Level, #{level_format := uc}) ->
level_uc_name(Level);
format_level1(Level, #{level_format := lc3}) ->
level_3letter_lc_name(Level);
format_level1(Level, #{level_format := uc3}) ->
level_3letter_uc_name(Level);
format_level1(Level, #{level_format := lc4}) ->
level_4letter_lc_name(Level);
format_level1(Level, #{level_format := uc4}) ->
level_4letter_uc_name(Level);
format_level1(Level, _) ->
level_4letter_lc_name(Level).

level_lc_name(debug) -> "debug";
level_lc_name(info) -> "info";
level_lc_name(notice) -> "notice";
level_lc_name(warning) -> "warning";
level_lc_name(error) -> "error";
level_lc_name(critical) -> "critical";
level_lc_name(alert) -> "alert";
level_lc_name(emergency) -> "emergency".

level_uc_name(debug) -> "DEBUG";
level_uc_name(info) -> "INFO";
level_uc_name(notice) -> "NOTICE";
level_uc_name(warning) -> "WARNING";
level_uc_name(error) -> "ERROR";
level_uc_name(critical) -> "CRITICAL";
level_uc_name(alert) -> "ALERT";
level_uc_name(emergency) -> "EMERGENCY".

level_3letter_lc_name(debug) -> "dbg";
level_3letter_lc_name(info) -> "inf";
level_3letter_lc_name(notice) -> "ntc";
level_3letter_lc_name(warning) -> "wrn";
level_3letter_lc_name(error) -> "err";
level_3letter_lc_name(critical) -> "crt";
level_3letter_lc_name(alert) -> "alt";
level_3letter_lc_name(emergency) -> "emg".

level_3letter_uc_name(debug) -> "DBG";
level_3letter_uc_name(info) -> "INF";
level_3letter_uc_name(notice) -> "NTC";
level_3letter_uc_name(warning) -> "WRN";
level_3letter_uc_name(error) -> "ERR";
level_3letter_uc_name(critical) -> "CRT";
level_3letter_uc_name(alert) -> "ALT";
level_3letter_uc_name(emergency) -> "EMG".

level_4letter_lc_name(debug) -> "dbug";
level_4letter_lc_name(info) -> "info";
level_4letter_lc_name(notice) -> "noti";
level_4letter_lc_name(warning) -> "warn";
level_4letter_lc_name(error) -> "erro";
level_4letter_lc_name(critical) -> "crit";
level_4letter_lc_name(alert) -> "alrt";
level_4letter_lc_name(emergency) -> "emgc".

level_4letter_uc_name(debug) -> "DBUG";
level_4letter_uc_name(info) -> "INFO";
level_4letter_uc_name(notice) -> "NOTI";
level_4letter_uc_name(warning) -> "WARN";
level_4letter_uc_name(error) -> "ERRO";
level_4letter_uc_name(critical) -> "CRIT";
level_4letter_uc_name(alert) -> "ALRT";
level_4letter_uc_name(emergency) -> "EMGC".

format_msg(Msg, Meta, #{single_line := true} = Config) ->
FormattedMsg = format_msg1(Msg, Meta, Config),
%% The following behavior is the same as the one in the official
%% `logger_formatter'; the code is taken from that module (as of
%% c5ed910098e9c2787e2c3f9f462c84322064e00d in the master branch).
FormattedMsg1 = string:strip(FormattedMsg, both),
re:replace(
FormattedMsg1,
",?\r?\n\s*",
", ",
[{return, list}, global, unicode]);
format_msg(Msg, Meta, Config) ->
format_msg1(Msg, Meta, Config).

format_msg1({string, Chardata}, Meta, Config) ->
format_msg1({"~ts", [Chardata]}, Meta, Config);
format_msg1({report, Report}, Meta, Config) ->
FormattedReport = format_report(Report, Meta, Config),
format_msg1(FormattedReport, Meta, Config);
format_msg1({Format, Args}, _, _) ->
io_lib:format(Format, Args).

format_report(
#{label := {application_controller, _}} = Report, Meta, Config) ->
format_application_progress(Report, Meta, Config);
format_report(
#{label := {supervisor, progress}} = Report, Meta, Config) ->
format_supervisor_progress(Report, Meta, Config);
format_report(
Report, #{report_cb := Cb} = Meta, Config) ->
try
case erlang:fun_info(Cb, arity) of
{arity, 1} -> Cb(Report);
{arity, 2} -> {"~ts", [Cb(Report, #{})]}
end
catch
_:_:_ ->
format_report(Report, maps:remove(report_cb, Meta), Config)
end;
format_report(Report, _, _) ->
logger:format_report(Report).

format_application_progress(#{label := {_, progress},
report := InternalReport}, _, _) ->
Application = proplists:get_value(application, InternalReport),
StartedAt = proplists:get_value(started_at, InternalReport),
{"Application ~w started on ~0p",
[Application, StartedAt]};
format_application_progress(#{label := {_, exit},
report := InternalReport}, _, _) ->
Application = proplists:get_value(application, InternalReport),
Exited = proplists:get_value(exited, InternalReport),
{"Application ~w exited with reason: ~0p",
[Application, Exited]}.

format_supervisor_progress(#{report := InternalReport}, _, _) ->
Supervisor = proplists:get_value(supervisor, InternalReport),
Started = proplists:get_value(started, InternalReport),
Id = proplists:get_value(id, Started),
Pid = proplists:get_value(pid, Started),
Mfa = proplists:get_value(mfargs, Started),
{"Supervisor ~w: child ~w started (~w): ~0p",
[Supervisor, Id, Pid, Mfa]}.
118 changes: 53 additions & 65 deletions deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_json_fmt.erl
Original file line number Diff line number Diff line change
Expand Up @@ -12,79 +12,42 @@
format(
#{msg := Msg,
level := Level,
meta := #{time := Timestamp} = Meta},
meta := Meta},
Config) ->
FormattedTimestamp = unicode:characters_to_binary(
format_time(Timestamp, Config)),
FormattedMsg = unicode:characters_to_binary(
format_msg(Msg, Meta, Config)),
FormattedLevel = unicode:characters_to_binary(
rabbit_logger_fmt_helpers:format_level(Level, Config)),
FormattedMeta = format_meta(Meta, Config),
Json = jsx:encode(
[{time, FormattedTimestamp},
{level, Level},
{msg, FormattedMsg},
{meta, FormattedMeta}]),
%% We need to call `unicode:characters_to_binary()' here and several other
%% places because `jsx:encode()' will format a string as a list of
%% integers (we don't blame it for that, it makes sense).
FormattedMsg = unicode:characters_to_binary(
rabbit_logger_fmt_helpers:format_msg(Msg, Meta, Config)),
InitialDoc0 = FormattedMeta#{level => FormattedLevel,
msg => FormattedMsg},
InitialDoc = case level_to_verbosity(Level, Config) of
undefined -> InitialDoc0;
Verbosity -> InitialDoc0#{verbosity => Verbosity}
end,
DocAfterMapping = apply_mapping_and_ordering(InitialDoc, Config),
Json = jsx:encode(DocAfterMapping),
[Json, $\n].

format_time(Timestamp, _) ->
Options = [{unit, microsecond}],
calendar:system_time_to_rfc3339(Timestamp, Options).

format_msg({string, Chardata}, Meta, Config) ->
format_msg({"~ts", [Chardata]}, Meta, Config);
format_msg({report, Report}, Meta, Config) ->
FormattedReport = format_report(Report, Meta, Config),
format_msg(FormattedReport, Meta, Config);
format_msg({Format, Args}, _, _) ->
io_lib:format(Format, Args).

format_report(
#{label := {application_controller, _}} = Report, Meta, Config) ->
format_application_progress(Report, Meta, Config);
format_report(
#{label := {supervisor, progress}} = Report, Meta, Config) ->
format_supervisor_progress(Report, Meta, Config);
format_report(
Report, #{report_cb := Cb} = Meta, Config) ->
try
case erlang:fun_info(Cb, arity) of
{arity, 1} -> Cb(Report);
{arity, 2} -> {"~ts", [Cb(Report, #{})]}
end
catch
_:_:_ ->
format_report(Report, maps:remove(report_cb, Meta), Config)
level_to_verbosity(Level, #{verbosity_map := Mapping}) ->
case maps:is_key(Level, Mapping) of
true -> maps:get(Level, Mapping);
false -> undefined
end;
format_report(Report, _, _) ->
logger:format_report(Report).

format_application_progress(#{label := {_, progress},
report := InternalReport}, _, _) ->
Application = proplists:get_value(application, InternalReport),
StartedAt = proplists:get_value(started_at, InternalReport),
{"Application ~w started on ~0p",
[Application, StartedAt]};
format_application_progress(#{label := {_, exit},
report := InternalReport}, _, _) ->
Application = proplists:get_value(application, InternalReport),
Exited = proplists:get_value(exited, InternalReport),
{"Application ~w exited with reason: ~0p",
[Application, Exited]}.

format_supervisor_progress(#{report := InternalReport}, _, _) ->
Supervisor = proplists:get_value(supervisor, InternalReport),
Started = proplists:get_value(started, InternalReport),
Id = proplists:get_value(id, Started),
Pid = proplists:get_value(pid, Started),
Mfa = proplists:get_value(mfargs, Started),
{"Supervisor ~w: child ~w started (~w): ~0p",
[Supervisor, Id, Pid, Mfa]}.
level_to_verbosity(_, _) ->
undefined.

format_meta(Meta, _) ->
format_meta(Meta, Config) ->
maps:fold(
fun
(time, _, Acc) ->
Acc;
(time, Timestamp, Acc) ->
FormattedTime = unicode:characters_to_binary(
rabbit_logger_fmt_helpers:format_time(
Timestamp, Config)),
Acc#{time => FormattedTime};
(domain = Key, Components, Acc) ->
Term = unicode:characters_to_binary(
string:join(
Expand Down Expand Up @@ -125,3 +88,28 @@ convert_to_types_accepted_by_jsx(Term) when is_reference(Term) ->
unicode:characters_to_binary(String);
convert_to_types_accepted_by_jsx(Term) ->
Term.

apply_mapping_and_ordering(Doc, #{field_map := Mapping}) ->
apply_mapping_and_ordering(Mapping, Doc, []);
apply_mapping_and_ordering(Doc, _) ->
maps:to_list(Doc).

apply_mapping_and_ordering([{'$REST', false} | Rest], _, Result) ->
apply_mapping_and_ordering(Rest, #{}, Result);
apply_mapping_and_ordering([{Old, false} | Rest], Doc, Result)
when is_atom(Old) ->
Doc1 = maps:remove(Old, Doc),
apply_mapping_and_ordering(Rest, Doc1, Result);
apply_mapping_and_ordering([{Old, New} | Rest], Doc, Result)
when is_atom(Old) andalso is_atom(New) ->
case maps:is_key(Old, Doc) of
true ->
Value = maps:get(Old, Doc),
Doc1 = maps:remove(Old, Doc),
Result1 = [{New, Value} | Result],
apply_mapping_and_ordering(Rest, Doc1, Result1);
false ->
apply_mapping_and_ordering(Rest, Doc, Result)
end;
apply_mapping_and_ordering([], Doc, Result) ->
lists:reverse(Result) ++ maps:to_list(Doc).
Loading

0 comments on commit 55f258a

Please sign in to comment.