diff options
author | Jean-Sébastien Pédron <jean-sebastien.pedron@dumbbell.fr> | 2021-03-23 16:56:20 +0100 |
---|---|---|
committer | Jean-Sébastien Pédron <jean-sebastien.pedron@dumbbell.fr> | 2021-03-29 11:59:03 +0200 |
commit | 55f258a4bbae1e8313fabf8e82e1acb67022536c (patch) | |
tree | 602847627812e601ce2a3144ca8cf7da3108ff63 | |
parent | 80845dec418d3d6f5bff0eb7c30f4c17d6376625 (diff) | |
download | rabbitmq-server-git-add-logging-config-support.tar.gz |
Logging: Add configuration variables to set various formatsadd-logging-config-support
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.
-rw-r--r-- | deps/rabbit/Makefile | 3 | ||||
-rw-r--r-- | deps/rabbit/apps/rabbitmq_prelaunch/Makefile | 3 | ||||
-rw-r--r-- | deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_fmt_helpers.erl | 187 | ||||
-rw-r--r-- | deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_json_fmt.erl | 118 | ||||
-rw-r--r-- | deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_text_fmt.erl | 201 | ||||
-rw-r--r-- | deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_prelaunch_early_logging.erl | 361 | ||||
-rw-r--r-- | deps/rabbit/priv/schema/rabbit.schema | 168 | ||||
-rw-r--r-- | deps/rabbit/src/rabbit_prelaunch_logging.erl | 293 | ||||
-rw-r--r-- | deps/rabbit/test/logging_SUITE.erl | 1080 |
9 files changed, 1934 insertions, 480 deletions
diff --git a/deps/rabbit/Makefile b/deps/rabbit/Makefile index 259a7c9123..0e7f98815a 100644 --- a/deps/rabbit/Makefile +++ b/deps/rabbit/Makefile @@ -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 diff --git a/deps/rabbit/apps/rabbitmq_prelaunch/Makefile b/deps/rabbit/apps/rabbitmq_prelaunch/Makefile index 54d4e199f7..c95d097907 100644 --- a/deps/rabbit/apps/rabbitmq_prelaunch/Makefile +++ b/deps/rabbit/apps/rabbitmq_prelaunch/Makefile @@ -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 diff --git a/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_fmt_helpers.erl b/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_fmt_helpers.erl new file mode 100644 index 0000000000..b4976d2962 --- /dev/null +++ b/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_fmt_helpers.erl @@ -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]}. diff --git a/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_json_fmt.erl b/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_json_fmt.erl index d621de13ea..46863754ad 100644 --- a/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_json_fmt.erl +++ b/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_json_fmt.erl @@ -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( @@ -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). diff --git a/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_text_fmt.erl b/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_text_fmt.erl index 30cf16fb34..5e703d2fc2 100644 --- a/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_text_fmt.erl +++ b/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_text_fmt.erl @@ -12,130 +12,50 @@ format(#{msg := Msg, meta := Meta} = LogEvent, Config) -> Prefix = format_prefix(LogEvent, Config), Color = pick_color(LogEvent, Config), - FormattedMsg = format_msg(Msg, Meta, Config), - prepend_prefix_to_msg_and_add_color(Prefix, Color, FormattedMsg, Config). - -format_prefix(_, #{prefix := false}) -> - none; -format_prefix(#{level := Level, - meta := #{time := Timestamp, - pid := Pid}}, - Config) -> - Time = format_time(Timestamp, Config), - LevelName = level_name(Level, Config), - io_lib:format("~ts [~ts] ~p", [Time, LevelName, Pid]). - -level_name(Level, #{level_name := full}) -> - Level; -level_name(Level, #{level_name := uc3}) -> - level_3letter_uc_name(Level); -level_name(Level, #{level_name := lc3}) -> - level_3letter_lc_name(Level); -level_name(Level, #{level_name := uc4}) -> - level_4letter_uc_name(Level); -level_name(Level, #{level_name := lc4}) -> - level_4letter_lc_name(Level); -level_name(Level, _) -> - Level. - -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_time(Timestamp, _) -> - Options = [{unit, microsecond}, - {time_designator, $\s}], - 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) - 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]}. - -pick_color(_, #{color := false}) -> - {"", ""}; -pick_color(#{level := Level}, #{color := true} = Config) -> + FormattedMsg = rabbit_logger_fmt_helpers:format_msg(Msg, Meta, Config), + prepend_prefix_to_msg_and_add_color( + Prefix, Color, FormattedMsg, LogEvent, Config). + +format_prefix(LogEvent, #{prefix_format := PrefixFormat} = Config) -> + format_prefix(PrefixFormat, LogEvent, Config, []); +format_prefix(LogEvent, Config) -> + %% Default prefix format. + format_prefix([time, " [", level, "] ", pid, " "], LogEvent, Config, []). + +format_prefix([String | Rest], LogEvent, Config, Prefix) + when is_list(String) -> + format_prefix(Rest, LogEvent, Config, [String | Prefix]); +format_prefix([Var | Rest], LogEvent, Config, Prefix) + when is_atom(Var) -> + String = format_var(Var, LogEvent, Config), + format_prefix(Rest, LogEvent, Config, [String | Prefix]); +format_prefix([], _, _, Prefix) -> + lists:reverse(Prefix). + +format_var(level, #{level := Level}, Config) -> + rabbit_logger_fmt_helpers:format_level(Level, Config); +format_var(time, #{meta := #{time := Timestamp}}, Config) -> + rabbit_logger_fmt_helpers:format_time(Timestamp, Config); +format_var(Var, #{meta := Meta}, _) -> + case maps:get(Var, Meta, undefined) of + undefined -> + io_lib:format("<unknown ~s>", [Var]); + Value -> + case io_lib:char_list(Value) of + true -> io_lib:format("~s", [Value]); + false -> io_lib:format("~p", [Value]) + end + end. + +pick_color(#{level := Level}, #{use_colors := true} = Config) -> ColorStart = level_to_color(Level, Config), ColorEnd = "\033[0m", - {ColorStart, ColorEnd}. + {ColorStart, ColorEnd}; +pick_color(_, _) -> + {"", ""}. +level_to_color(Level, #{color_esc_seqs := ColorEscSeqs}) -> + maps:get(Level, ColorEscSeqs); level_to_color(debug, _) -> "\033[38;5;246m"; level_to_color(info, _) -> ""; level_to_color(notice, _) -> "\033[38;5;87m"; @@ -146,22 +66,35 @@ level_to_color(alert, _) -> "\033[1;37m\033[48;5;93m"; level_to_color(emergency, _) -> "\033[1;37m\033[48;5;196m". prepend_prefix_to_msg_and_add_color( - none, {ColorStart, ColorEnd}, FormattedMsg, Config) -> + Prefix, {ColorStart, ColorEnd}, FormattedMsg, LogEvent, Config) -> Lines = split_lines(FormattedMsg, Config), - [case Line of - "" -> [$\n]; - _ -> [ColorStart, Line, ColorEnd, $\n] - end - || Line <- Lines]; -prepend_prefix_to_msg_and_add_color( - Prefix, {ColorStart, ColorEnd}, FormattedMsg, Config) -> - Lines = split_lines(FormattedMsg, Config), - [case Line of - "" -> [ColorStart, Prefix, ColorEnd, $\n]; - _ -> [ColorStart, Prefix, " ", Line, ColorEnd, $\n] - end + [[ColorStart, + format_line(Prefix, Line, LogEvent, Config), + ColorEnd, + $\n] || Line <- Lines]. split_lines(FormattedMsg, _) -> FlattenMsg = lists:flatten(FormattedMsg), string:split(FlattenMsg, [$\n], all). + +format_line(Prefix, Msg, LogEvent, #{line_format := Format} = Config) -> + format_line(Format, Msg, LogEvent, Config, [Prefix]); +format_line(Prefix, Msg, LogEvent, Config) -> + format_line([msg], Msg, LogEvent, Config, [Prefix]). + +format_line([msg | Rest], Msg, LogEvent, Config, Line) -> + format_line(Rest, Msg, LogEvent, Config, [Msg | Line]); +format_line([String | Rest], Msg, LogEvent, Config, Line) + when is_list(String) -> + format_line(Rest, Msg, LogEvent, Config, [String | Line]); +format_line([Var | Rest], Msg, LogEvent, Config, Line) + when is_atom(Var) -> + String = format_var(Var, LogEvent, Config), + format_line(Rest, Msg, LogEvent, Config, [String | Line]); +format_line([], _, _, _, Line) -> + remove_trailing_whitespaces(Line). + +remove_trailing_whitespaces([Tail | Line]) -> + Tail1 = string:strip(Tail, right), + lists:reverse([Tail1 | Line]). diff --git a/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_prelaunch_early_logging.erl b/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_prelaunch_early_logging.erl index 7d9d7f263a..89c5c6c3d5 100644 --- a/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_prelaunch_early_logging.erl +++ b/deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_prelaunch_early_logging.erl @@ -18,9 +18,15 @@ default_syslog_formatter/1, enable_quick_dbg/1, use_colored_logging/0, - use_colored_logging/1]). + use_colored_logging/1, + translate_formatter_conf/2]). -export([filter_log_event/2]). +-ifdef(TEST). +-export([levels/0, + determine_prefix/1]). +-endif. + -define(CONFIGURED_KEY, {?MODULE, configured}). setup_early_logging(#{log_levels := undefined} = Context) -> @@ -107,7 +113,7 @@ default_formatter(#{log_levels := #{json := true}}) -> {rabbit_logger_json_fmt, #{}}; default_formatter(Context) -> Color = use_colored_logging(Context), - {rabbit_logger_text_fmt, #{color => Color}}. + {rabbit_logger_text_fmt, #{use_colors => Color}}. default_console_formatter(Context) -> default_formatter(Context). @@ -118,7 +124,7 @@ default_file_formatter(Context) -> default_syslog_formatter(Context) -> {Module, Config} = default_file_formatter(Context), case Module of - rabbit_logger_text_fmt -> {Module, Config#{prefix => false}}; + rabbit_logger_text_fmt -> {Module, Config#{prefix_format => []}}; rabbit_logger_json_fmt -> {Module, Config} end. @@ -140,3 +146,352 @@ enable_quick_dbg(#{dbg_output := Output, dbg_mods := Mods}) -> end, {ok, _} = dbg:p(all, c), lists:foreach(fun(M) -> {ok, _} = dbg:tp(M, cx) end, Mods). + +%% ------------------------------------------------------------------- +%% Internal function used by our Cuttlefish schema. +%% ------------------------------------------------------------------- + +-spec translate_formatter_conf(string(), cuttlefish_conf:conf()) -> + {rabbit_logger_text_fmt, formatter_plaintext_conf()} | + {rabbit_logger_json_fmt, formatter_json_conf()}. +%% @doc +%% Called from the Cuttlefish schema to derive the actual configuration from +%% several Cuttlefish variables. + +translate_formatter_conf(Var, Conf) when is_list(Var) -> + try + %% Part of the formatter configuration is common to all the + %% formatters, the rest is formatter-specific. + GenericConfig = translate_generic_conf(Var, Conf), + case cuttlefish:conf_get(Var, Conf) of + plaintext -> + translate_plaintext_formatter_conf(Var, Conf, GenericConfig); + json -> + translate_json_formatter_conf(Var, Conf, GenericConfig) + end + catch + Class:Reason:Stacktrace -> + ?LOG_ERROR( + rabbit_prelaunch_errors:format_exception( + Class, Reason, Stacktrace), + #{domain => ?RMQLOG_DOMAIN_PRELAUNCH}), + throw({configuration_translation_failure, Reason}) + end. + +-type time_format_string_arg() :: year | month | day | + hour | minute | second | + {second_fractional, non_neg_integer()}. +-type time_format() :: {rfc3339, char()} | + {epoch, secs | usecs, binary | int} | + {string(), [time_format_string_arg()]}. +-type level_format() :: lc | uc | lc3 | uc3 | lc4 | uc4. +-type formatter_generic_conf() :: #{time_format := time_format(), + level_format := level_format(), + single_line := boolean()}. + +-spec translate_generic_conf(string(), cuttlefish_conf:conf()) -> + formatter_generic_conf(). +%% @doc +%% Handles variables common to all formatters. + +translate_generic_conf(Var, Conf) -> + %% log.*.formatter.time_format + %% It accepts either a "named pattern" like `rfc3339_T' or a custom + %% pattern. + Formatter = cuttlefish:conf_get(Var, Conf), + TimeFormat = case cuttlefish:conf_get(Var ++ ".time_format", Conf) of + rfc3339_T -> + {rfc3339, $T}; + rfc3339_space -> + {rfc3339, $\s}; + epoch_secs when Formatter =:= json -> + {epoch, secs, int}; + epoch_usecs when Formatter =:= json -> + {epoch, usecs, int}; + epoch_secs -> + {epoch, secs, binary}; + epoch_usecs -> + {epoch, usecs, binary}; + lager_default -> + {"~4..0b-~2..0b-~2..0b " + "~2..0b:~2..0b:~2..0b.~3..0b", + [year, month, day, + hour, minute, second, + {second_fractional, 3}]} + end, + + %% log.*.formatter.level_format + %% It determines basically if the level should be printed in lowercase or + %% uppercase, and fully or truncated (to align messages horizontally). + LevelFormat = cuttlefish:conf_get(Var ++ ".level_format", Conf), + + %% log.*.formatter.single_line + %% It tells if multi-line messages should be kept as-is or reformatted to + %% stay on a single line. + SingleLine = cuttlefish:conf_get(Var ++ ".single_line", Conf), + + #{time_format => TimeFormat, + level_format => LevelFormat, + single_line => SingleLine}. + +-type line_format() :: [atom() | string()]. +-type color_esc_seqs() :: #{logger:level() => string()}. +-type formatter_plaintext_conf() :: #{time_format := time_format(), + level_format := level_format(), + single_line := boolean(), + prefix_format := line_format(), + line_format := line_format(), + use_colors := boolean(), + color_esc_seqs := color_esc_seqs()}. + +-spec translate_plaintext_formatter_conf( + string(), cuttlefish_conf:conf(), formatter_generic_conf()) -> + {rabbit_logger_text_fmt, formatter_plaintext_conf()}. +%% @doc +%% Handles variables specific to the plaintext formatter. + +translate_plaintext_formatter_conf(Var, Conf, GenericConfig) -> + %% log.*.formatter.plaintext.format + %% This is a variable-based string used to indicate the message format. + %% Here, we parse that pattern to make it easier and more efficient for + %% the formatter to format the final message. + Format0 = cuttlefish:conf_get(Var ++ ".plaintext.format", Conf), + Format = prepare_fmt_format(Format0), + {PrefixFormat, LineFormat} = determine_prefix(Format), + + %% log.console.use_colors + %% log.console.color_esc_seqs + %% Those variables indicates if colors should be used and which one. They + %% are specific to the console handler. + {UseColors, ColorEscSeqs} = translate_colors_conf(Var, Conf), + + Mod = rabbit_logger_text_fmt, + Config = GenericConfig#{prefix_format => PrefixFormat, + line_format => LineFormat, + use_colors => UseColors, + color_esc_seqs => ColorEscSeqs}, + {Mod, Config}. + +-spec prepare_fmt_format(string()) -> [atom() | string()]. +%% @doc +%% Parse the pattern and prepare a list which makes it easy for the formatter +%% to format the final message. +%% +%% The initial pattern will use variables; for example: +%% `$time [$level] $pid - $msg' +%% +%% Once parsed, the pattern will look like: +%% `[time, " [", level, "] ", pid, " - ", msg]' +%% +%% Variables are taken from the log event structure: `msg' and `level' are +%% taken from the top-level, other variables come from the `meta' map. + +prepare_fmt_format(Format) -> + prepare_fmt_format(Format, []). + +prepare_fmt_format([$$ | Rest], Parsed) -> + {match, [Var, Rest1]} = re:run(Rest, "^([a-zA_Z0-9_]+)(.*)", + [{capture, all_but_first, list}]), + Var1 = list_to_atom(Var), + prepare_fmt_format(Rest1, [Var1 | Parsed]); +prepare_fmt_format(Rest, Parsed) when Rest =/= "" -> + %% We made sure in the guard expression that `Rest' contains at least + %% onecharacter. The following regex "eats" at least that character. This + %% avoids an infinite loop which would happen if the returned `String' was + %% empty and `Rest1' would be the same as `Rest'. + {match, [String, Rest1]} = re:run(Rest, "^(.[^$]*)(.*)", + [{capture, all_but_first, list}]), + prepare_fmt_format(Rest1, [String | Parsed]); +prepare_fmt_format("", Parsed) -> + lists:reverse(Parsed). + +determine_prefix(Format) -> + %% Based on where the `msg' variable is, we determine the prefix of the + %% message. This is later used by the formatter to repeat the prefix for + %% each line making a multi-line message. + %% + %% If `msg' is not logged at all, we consider the line has no prefix. + {PrefixFormat0, LineFormat0} = + lists:foldl( + fun + (msg, {PF, LF}) -> {PF, LF ++ [msg]}; + (Elem, {PF, [] = LF}) -> {PF ++ [Elem], LF}; + (Elem, {PF, LF}) -> {PF, LF ++ [Elem]} + end, {[], []}, Format), + case {PrefixFormat0, LineFormat0} of + {_, []} -> {[], PrefixFormat0}; + _ -> {PrefixFormat0, LineFormat0} + end. + +-spec translate_colors_conf(string(), cuttlefish_conf:conf()) -> + {boolean(), map()}. +%% @doc +%% Computes the color configuration. +%% +%% The function uses the following two variables: +%% `log.console.use_colors' +%% `log.console.color_esc_seqs' +%% +%% It does not verify what escape sequences are actually configured. It is +%% entirely possible to play with the cursor position or other control +%% characters. +%% +%% This is only valid for the console output. + +translate_colors_conf("log.console.formatter", Conf) -> + { + cuttlefish:conf_get("log.console.use_colors", Conf), + lists:foldl( + fun(Lvl, Acc) -> + LvlS = atom_to_list(Lvl), + Key = "log.console.color_esc_seqs." ++ LvlS, + RawVal = cuttlefish:conf_get(Key, Conf), + %% The ESC character will be escaped if the user entered the + %% string "\033" for instance. We need to convert it back to an + %% actual ESC character. + Val = re:replace( + RawVal, + "\\\\(e|033)", + "\033", + [global, {return, list}]), + Acc#{Lvl => Val} + end, + #{}, + levels()) + }; +translate_colors_conf(_, _) -> + {false, #{}}. + +-type json_field_map() :: [{atom(), atom()} | {atom() | '$REST', false}]. +-type json_verbosity_map() :: #{logger:level() => non_neg_integer(), + '$REST' => non_neg_integer()}. +-type formatter_json_conf() :: #{time_format := time_format(), + level_format := level_format(), + single_line := boolean(), + field_map := json_field_map(), + verbosity_map := json_verbosity_map()}. + +-spec translate_json_formatter_conf( + string(), cuttlefish_conf:conf(), map()) -> + {rabbit_logger_json_fmt, formatter_json_conf()}. +%% @doc +%% Handles variables specific to the JSON formatter. + +translate_json_formatter_conf(Var, Conf, GenericConfig) -> + %% log.*.formatter.json.field_map + %% It indicates several things: + %% - the order of fields; non-mentionned fields go unordered at the end + %% of the JSON object + %% - if fields should be renamed + %% - if fields should be removed from the final object + RawFieldMapping = cuttlefish:conf_get(Var ++ ".json.field_map", Conf), + FieldMapping = parse_json_field_mapping(RawFieldMapping), + + %% log.*.formatter.json.verbosity_map + %% It indicates if a `verbosity' field should be added and how its value + %% should be derived from `level'. + RawVerbMapping = cuttlefish:conf_get( + Var ++ ".json.verbosity_map", Conf), + VerbMapping = parse_json_verbosity_mapping(RawVerbMapping), + + Mod = rabbit_logger_json_fmt, + Config = GenericConfig#{field_map => FieldMapping, + verbosity_map => VerbMapping}, + {Mod, Config}. + +-spec parse_json_field_mapping(string()) -> json_field_map(). +%% @doc +%% Parses the field_map pattern. +%% +%% The pattern is of the form: `time:ts level msg *:-'. +%% +%% `time:ts' means the `time' field should be renamed to `ts'. +%% +%% `level' means that field should be kept as-is. +%% +%% `gl:-' means the `gl' field should be dropped. +%% +%% `*:-' means all non-mentionned fields should be dropped. +%% +%% The order of fields in the pattern is important: it tells the order of +%% fields in the final JSON object. + +parse_json_field_mapping(RawMapping) -> + parse_json_field_mapping(string:split(RawMapping, " ", all), []). + +parse_json_field_mapping([Entry | Rest], Mapping) -> + Mapping1 = case string:split(Entry, ":", leading) of + ["*", "-"] -> + [{'$REST', false} | Mapping]; + [OldS, "-"] -> + Old = list_to_atom(OldS), + [{Old, false} | Mapping]; + ["*", _] -> + throw({bad_json_mapping, Entry}); + [OldS, NewS] -> + Old = list_to_atom(OldS), + New = list_to_atom(NewS), + [{Old, New} | Mapping]; + [KeepS] -> + Keep = list_to_atom(KeepS), + [{Keep, Keep} | Mapping] + end, + parse_json_field_mapping(Rest, Mapping1); +parse_json_field_mapping([], Mapping) -> + %% We parsed everything. Now we want to organize fields a bit: + %% - All `{atom(), atom()}' (kept or renamed fields) go at the + %% beginning, preserving their order + %% - All `{_, false}' (removed fields) go at the end + {Renames0, Removes0} = lists:partition( + fun + ({_, false}) -> false; + (_) -> true + end, + Mapping), + Renames = lists:reverse(Renames0), + %% If all non-mentionned fields are to be removed, only the `{$REST, + %% false}' entry is useful. + Removes = case lists:member({'$REST', false}, Removes0) of + true -> [{'$REST', false}]; + false -> Removes0 + end, + Renames ++ Removes. + +-spec parse_json_verbosity_mapping(string()) -> json_verbosity_map(). +%% @doc +%% Parses the verbosity_map pattern. +%% +%% The pattern is of the form: `debug=2 info=1 *=0'. +%% +%% `debug=2' means that the verbosity of the debug level is 2. +%% +%% `*=0' means that the verbosity of all non-mentionned levels is 0. + +parse_json_verbosity_mapping("") -> + #{}; +parse_json_verbosity_mapping(RawMapping) -> + parse_json_verbosity_mapping(string:split(RawMapping, " ", all), #{}). + +parse_json_verbosity_mapping([Entry | Rest], Mapping) -> + Mapping1 = case string:split(Entry, "=", leading) of + ["*", VerbS] -> + Verb = list_to_integer(VerbS), + Mapping#{'$REST' => Verb}; + [LvlS, VerbS] -> + Lvl = list_to_atom(LvlS), + Verb = list_to_integer(VerbS), + Mapping#{Lvl => Verb} + end, + parse_json_verbosity_mapping(Rest, Mapping1); +parse_json_verbosity_mapping([], #{'$REST' := Default} = Mapping) -> + DefaultMapping = lists:foldl( + fun(Lvl, Acc) -> Acc#{Lvl => Default} end, + #{}, levels()), + maps:merge( + DefaultMapping, + maps:remove('$REST', Mapping)); +parse_json_verbosity_mapping([], Mapping) -> + Mapping. + +levels() -> + [debug, info, notice, warning, error, critical, alert, emergency]. diff --git a/deps/rabbit/priv/schema/rabbit.schema b/deps/rabbit/priv/schema/rabbit.schema index 62368486e6..a32157b370 100644 --- a/deps/rabbit/priv/schema/rabbit.schema +++ b/deps/rabbit/priv/schema/rabbit.schema @@ -1192,6 +1192,78 @@ end}. {mapping, "log.console.level", "rabbit.log.console.level", [ {datatype, {enum, [debug, info, notice, warning, error, critical, alert, emergency, none]}} ]}. +{mapping, "log.console.stdio", "rabbit.log.console.stdio", [ + {default, stdout}, + {datatype, {enum, [stdout, stderr]}} +]}. +{mapping, "log.console.use_colors", "rabbit.log.console.formatter", [ + {default, on}, + {datatype, flag} +]}. +{mapping, "log.console.color_esc_seqs.debug", "rabbit.log.console.formatter", [ + {default, "\033[38;5;246m"}, + {datatype, string} +]}. +{mapping, "log.console.color_esc_seqs.info", "rabbit.log.console.formatter", [ + {default, ""}, + {datatype, string} +]}. +{mapping, "log.console.color_esc_seqs.notice", "rabbit.log.console.formatter", [ + {default, "\033[38;5;87m"}, + {datatype, string} +]}. +{mapping, "log.console.color_esc_seqs.warning", "rabbit.log.console.formatter", [ + {default, "\033[38;5;214m"}, + {datatype, string} +]}. +{mapping, "log.console.color_esc_seqs.error", "rabbit.log.console.formatter", [ + {default, "\033[38;5;160m"}, + {datatype, string} +]}. +{mapping, "log.console.color_esc_seqs.critical", "rabbit.log.console.formatter", [ + {default, "\033[1;37m\033[48;5;20m"}, + {datatype, string} +]}. +{mapping, "log.console.color_esc_seqs.alert", "rabbit.log.console.formatter", [ + {default, "\033[1;37m\033[48;5;93m"}, + {datatype, string} +]}. +{mapping, "log.console.color_esc_seqs.emergency", "rabbit.log.console.formatter", [ + {default, "\033[1;37m\033[48;5;196m"}, + {datatype, string} +]}. +{mapping, "log.console.formatter", "rabbit.log.console.formatter", [ + {default, plaintext}, + {datatype, {enum, [plaintext, json]}} +]}. +{mapping, "log.console.formatter.time_format", "rabbit.log.console.formatter", [ + {default, rfc3339_space}, + {datatype, {enum, [rfc3339_space, rfc3339_T, epoch_usecs, epoch_secs, lager_default]}} +]}. +{mapping, "log.console.formatter.level_format", "rabbit.log.console.formatter", [ + {default, lc}, + {datatype, {enum, [lc, uc, lc3, uc3, lc4, uc4]}} +]}. +{mapping, "log.console.formatter.single_line", "rabbit.log.file.formatter", [ + {default, off}, + {datatype, flag} +]}. +{mapping, "log.console.formatter.plaintext.format", "rabbit.log.console.formatter", [ + {default, "$time [$level] $pid $msg"}, + {datatype, string} +]}. +{mapping, "log.console.formatter.json.field_map", "rabbit.log.console.formatter", [ + {default, "time level msg gl:- logger_formatter:- report_cb:- error_logger:-"}, + {datatype, string} +]}. +{mapping, "log.console.formatter.json.verbosity_map", "rabbit.log.console.formatter", [ + {default, ""}, + {datatype, string} +]}. +{translation, "rabbit.log.console.formatter", + fun(Conf) -> + rabbit_prelaunch_early_logging:translate_formatter_conf("log.console.formatter", Conf) + end}. {mapping, "log.exchange", "rabbit.log.exchange.enabled", [ {datatype, {enum, [true, false]}} @@ -1199,6 +1271,38 @@ end}. {mapping, "log.exchange.level", "rabbit.log.exchange.level", [ {datatype, {enum, [debug, info, notice, warning, error, critical, alert, emergency, none]}} ]}. +{mapping, "log.exchange.formatter", "rabbit.log.exchange.formatter", [ + {default, plaintext}, + {datatype, {enum, [plaintext, json]}} +]}. +{mapping, "log.exchange.formatter.time_format", "rabbit.log.console.formatter", [ + {default, rfc3339_space}, + {datatype, [{enum, [rfc3339_space, rfc3339_T, epoch_usecs, epoch_secs, lager_default]}, string]} +]}. +{mapping, "log.exchange.formatter.level_format", "rabbit.log.exchange.formatter", [ + {default, lc}, + {datatype, {enum, [lc, uc, lc3, uc3, lc4, uc4]}} +]}. +{mapping, "log.exchange.formatter.single_line", "rabbit.log.file.formatter", [ + {default, off}, + {datatype, flag} +]}. +{mapping, "log.exchange.formatter.plaintext.format", "rabbit.log.exchange.formatter", [ + {default, "$time [$level] $pid $msg"}, + {datatype, string} +]}. +{mapping, "log.exchange.formatter.json.field_map", "rabbit.log.exchange.formatter", [ + {default, "time level msg gl:- logger_formatter:- report_cb:- error_logger:-"}, + {datatype, string} +]}. +{mapping, "log.exchange.formatter.json.verbosity_map", "rabbit.log.exchange.formatter", [ + {default, ""}, + {datatype, string} +]}. +{translation, "rabbit.log.exchange.formatter", + fun(Conf) -> + rabbit_prelaunch_early_logging:translate_formatter_conf("log.exchange.formatter", Conf) + end}. {mapping, "log.syslog", "rabbit.log.syslog.enabled", [ {datatype, {enum, [true, false]}} @@ -1207,6 +1311,38 @@ end}. {mapping, "log.syslog.level", "rabbit.log.syslog.level", [ {datatype, {enum, [debug, info, notice, warning, error, critical, alert, emergency, none]}} ]}. +{mapping, "log.syslog.formatter", "rabbit.log.syslog.formatter", [ + {default, plaintext}, + {datatype, {enum, [plaintext, json]}} +]}. +{mapping, "log.syslog.formatter.time_format", "rabbit.log.console.formatter", [ + {default, rfc3339_space}, + {datatype, [{enum, [rfc3339_space, rfc3339_T, epoch_usecs, epoch_secs, lager_default]}, string]} +]}. +{mapping, "log.syslog.formatter.level_format", "rabbit.log.syslog.formatter", [ + {default, lc}, + {datatype, {enum, [lc, uc, lc3, uc3, lc4, uc4]}} +]}. +{mapping, "log.syslog.formatter.single_line", "rabbit.log.file.formatter", [ + {default, off}, + {datatype, flag} +]}. +{mapping, "log.syslog.formatter.plaintext.format", "rabbit.log.syslog.formatter", [ + {default, "$msg"}, + {datatype, string} +]}. +{mapping, "log.syslog.formatter.json.field_map", "rabbit.log.syslog.formatter", [ + {default, "time level msg gl:- logger_formatter:- report_cb:- error_logger:-"}, + {datatype, string} +]}. +{mapping, "log.syslog.formatter.json.verbosity_map", "rabbit.log.syslog.formatter", [ + {default, ""}, + {datatype, string} +]}. +{translation, "rabbit.log.syslog.formatter", + fun(Conf) -> + rabbit_prelaunch_early_logging:translate_formatter_conf("log.syslog.formatter", Conf) + end}. {mapping, "log.syslog.identity", "syslog.app_name", [ {datatype, string} @@ -1413,6 +1549,38 @@ end}. {mapping, "log.file.rotation.count", "rabbit.log.file.count", [ {datatype, integer} ]}. +{mapping, "log.file.formatter", "rabbit.log.file.formatter", [ + {default, plaintext}, + {datatype, {enum, [plaintext, json]}} +]}. +{mapping, "log.file.formatter.time_format", "rabbit.log.console.formatter", [ + {default, rfc3339_space}, + {datatype, [{enum, [rfc3339_space, rfc3339_T, epoch_usecs, epoch_secs, lager_default]}, string]} +]}. +{mapping, "log.file.formatter.level_format", "rabbit.log.file.formatter", [ + {default, lc}, + {datatype, {enum, [lc, uc, lc3, uc3, lc4, uc4]}} +]}. +{mapping, "log.file.formatter.single_line", "rabbit.log.file.formatter", [ + {default, off}, + {datatype, flag} +]}. +{mapping, "log.file.formatter.plaintext.format", "rabbit.log.file.formatter", [ + {default, "$time [$level] $pid $msg"}, + {datatype, string} +]}. +{mapping, "log.file.formatter.json.field_map", "rabbit.log.file.formatter", [ + {default, "time level msg gl:- logger_formatter:- report_cb:- error_logger:-"}, + {datatype, string} +]}. +{mapping, "log.file.formatter.json.verbosity_map", "rabbit.log.file.formatter", [ + {default, ""}, + {datatype, string} +]}. +{translation, "rabbit.log.file.formatter", + fun(Conf) -> + rabbit_prelaunch_early_logging:translate_formatter_conf("log.file.formatter", Conf) + end}. %% Log categories diff --git a/deps/rabbit/src/rabbit_prelaunch_logging.erl b/deps/rabbit/src/rabbit_prelaunch_logging.erl index b70c881582..8195bfed4b 100644 --- a/deps/rabbit/src/rabbit_prelaunch_logging.erl +++ b/deps/rabbit/src/rabbit_prelaunch_logging.erl @@ -98,7 +98,8 @@ log_locations/0]). -ifdef(TEST). --export([clear_config_run_number/0, get_less_severe_level/2]). +-export([clear_config_run_number/0, + get_less_severe_level/2]). -endif. -export_type([log_location/0]). @@ -125,11 +126,15 @@ %% domain. -type console_props() :: [{level, logger:level()} | - {enabled, boolean()}]. + {enabled, boolean()} | + {stdio, stdout | stderr} | + {formatter, {atom(), term()}}]. %% Console properties are the parameters in the configuration file for a %% console-based handler. --type exchange_props() :: console_props(). +-type exchange_props() :: [{level, logger:level()} | + {enabled, boolean()} | + {formatter, {atom(), term()}}]. %% Exchange properties are the parameters in the configuration file for an %% exchange-based handler. @@ -137,11 +142,14 @@ {file, file:filename() | false} | {date, string()} | {size, non_neg_integer()} | - {count, non_neg_integer()}]. + {count, non_neg_integer()} | + {formatter, {atom(), term()}}]. %% File properties are the parameters in the configuration file for a %% file-based handler. --type syslog_props() :: console_props(). +-type syslog_props() :: [{level, logger:level()} | + {enabled, boolean()} | + {formatter, {atom(), term()}}]. %% Syslog properties are the parameters in the configuration file for a %% syslog-based handler. @@ -522,7 +530,58 @@ normalize_main_log_config(Props, DefaultProps) -> Level -> #{outputs => [], level => Level} end, - normalize_main_log_config1(Props, Outputs). + Props1 = compute_implicitly_enabled_output(Props), + normalize_main_log_config1(Props1, Outputs). + +compute_implicitly_enabled_output(Props) -> + {ConsoleEnabled, Props1} = compute_implicitly_enabled_output( + console, Props), + {ExchangeEnabled, Props2} = compute_implicitly_enabled_output( + exchange, Props1), + {SyslogEnabled, Props3} = compute_implicitly_enabled_output( + syslog, Props2), + FileDisabledByDefault = + ConsoleEnabled orelse ExchangeEnabled orelse SyslogEnabled, + + FileProps = proplists:get_value(file, Props3, []), + case is_output_explicitely_enabled(FileProps) of + true -> + Props3; + false -> + case FileDisabledByDefault of + true -> + FileProps1 = lists:keystore( + file, 1, FileProps, {file, false}), + lists:keystore( + file, 1, Props3, {file, FileProps1}); + false -> + Props3 + end + end. + +compute_implicitly_enabled_output(PropName, Props) -> + SubProps = proplists:get_value(PropName, Props, []), + {Enabled, SubProps1} = compute_implicitly_enabled_output1(SubProps), + {Enabled, + lists:keystore(PropName, 1, Props, {PropName, SubProps1})}. + +compute_implicitly_enabled_output1(SubProps) -> + %% We consider the output enabled or disabled if: + %% * it is explicitely marked as such, or + %% * the level is set to a log level (enabled) or `none' (disabled) + Enabled = proplists:get_value( + enabled, SubProps, + proplists:get_value(level, SubProps, none) =/= none), + {Enabled, + lists:keystore(enabled, 1, SubProps, {enabled, Enabled})}. + +is_output_explicitely_enabled(FileProps) -> + %% We consider the output enabled or disabled if: + %% * the file is explicitely set, or + %% * the level is set to a log level (enabled) or `none' (disabled) + File = proplists:get_value(file, FileProps), + Level = proplists:get_value(level, FileProps), + is_list(File) orelse (Level =/= undefined andalso Level =/= none). normalize_main_log_config1([{Type, Props} | Rest], #{outputs := Outputs} = LogConfig) -> @@ -555,13 +614,13 @@ normalize_main_output(console, Props, Outputs) -> config => #{type => standard_io}}, Outputs); normalize_main_output(syslog, Props, Outputs) -> - normalize_main_console_output( + normalize_main_syslog_output( Props, #{module => syslog_logger_h, config => #{}}, Outputs); normalize_main_output(exchange, Props, Outputs) -> - normalize_main_console_output( + normalize_main_exchange_output( Props, #{module => rabbit_logger_exchange_h, config => #{}}, @@ -571,42 +630,106 @@ normalize_main_output(exchange, Props, Outputs) -> [logger:handler_config()]) -> [logger:handler_config()]. -normalize_main_file_output([{file, false} | _], _, Outputs) -> - lists:filter( - fun - (#{module := rabbit_logger_std_h, - config := #{type := file}}) -> false; - (_) -> true - end, Outputs); -normalize_main_file_output([{file, Filename} | Rest], - #{config := Config} = Output, Outputs) -> +normalize_main_file_output(Props, Output, Outputs) -> + Enabled = case proplists:get_value(file, Props) of + false -> false; + _ -> true + end, + case Enabled of + true -> normalize_main_file_output1(Props, Output, Outputs); + false -> remove_main_file_output(Outputs) + end. + +normalize_main_file_output1( + [{file, Filename} | Rest], + #{config := Config} = Output, Outputs) -> Output1 = Output#{config => Config#{file => Filename}}, - normalize_main_file_output(Rest, Output1, Outputs); -normalize_main_file_output([{level, Level} | Rest], - Output, Outputs) -> + normalize_main_file_output1(Rest, Output1, Outputs); +normalize_main_file_output1( + [{level, Level} | Rest], + Output, Outputs) -> Output1 = Output#{level => Level}, - normalize_main_file_output(Rest, Output1, Outputs); -normalize_main_file_output([{date, DateSpec} | Rest], - #{config := Config} = Output, Outputs) -> + normalize_main_file_output1(Rest, Output1, Outputs); +normalize_main_file_output1( + [{date, DateSpec} | Rest], + #{config := Config} = Output, Outputs) -> Output1 = Output#{config => Config#{rotate_on_date => DateSpec}}, - normalize_main_file_output(Rest, Output1, Outputs); -normalize_main_file_output([{size, Size} | Rest], - #{config := Config} = Output, Outputs) -> + normalize_main_file_output1(Rest, Output1, Outputs); +normalize_main_file_output1( + [{size, Size} | Rest], + #{config := Config} = Output, Outputs) -> Output1 = Output#{config => Config#{max_no_bytes => Size}}, - normalize_main_file_output(Rest, Output1, Outputs); -normalize_main_file_output([{count, Count} | Rest], - #{config := Config} = Output, Outputs) -> + normalize_main_file_output1(Rest, Output1, Outputs); +normalize_main_file_output1( + [{count, Count} | Rest], + #{config := Config} = Output, Outputs) -> Output1 = Output#{config => Config#{max_no_files => Count}}, - normalize_main_file_output(Rest, Output1, Outputs); -normalize_main_file_output([], Output, Outputs) -> + normalize_main_file_output1(Rest, Output1, Outputs); +normalize_main_file_output1( + [{formatter, undefined} | Rest], + Output, Outputs) -> + normalize_main_file_output1(Rest, Output, Outputs); +normalize_main_file_output1( + [{formatter, Formatter} | Rest], + Output, Outputs) -> + Output1 = Output#{formatter => Formatter}, + normalize_main_file_output1(Rest, Output1, Outputs); +normalize_main_file_output1([], Output, Outputs) -> [Output | Outputs]. +remove_main_file_output(Outputs) -> + lists:filter( + fun + (#{module := rabbit_logger_std_h, + config := #{type := file}}) -> false; + (_) -> true + end, Outputs). + -spec normalize_main_console_output(console_props(), logger:handler_config(), [logger:handler_config()]) -> [logger:handler_config()]. -normalize_main_console_output( - [{enabled, false} | _], +normalize_main_console_output(Props, Output, Outputs) -> + Enabled = proplists:get_value(enabled, Props), + case Enabled of + true -> normalize_main_console_output1(Props, Output, Outputs); + false -> remove_main_console_output(Output, Outputs) + end. + +normalize_main_console_output1( + [{enabled, true} | Rest], + Output, Outputs) -> + normalize_main_console_output1(Rest, Output, Outputs); +normalize_main_console_output1( + [{level, Level} | Rest], + Output, Outputs) -> + Output1 = Output#{level => Level}, + normalize_main_console_output1(Rest, Output1, Outputs); +normalize_main_console_output1( + [{stdio, stdout} | Rest], + #{config := Config} = Output, Outputs) -> + Config1 = Config#{type => standard_io}, + Output1 = Output#{config => Config1}, + normalize_main_console_output1(Rest, Output1, Outputs); +normalize_main_console_output1( + [{stdio, stderr} | Rest], + #{config := Config} = Output, Outputs) -> + Config1 = Config#{type => standard_error}, + Output1 = Output#{config => Config1}, + normalize_main_console_output1(Rest, Output1, Outputs); +normalize_main_console_output1( + [{formatter, undefined} | Rest], + Output, Outputs) -> + normalize_main_console_output1(Rest, Output, Outputs); +normalize_main_console_output1( + [{formatter, Formatter} | Rest], + Output, Outputs) -> + Output1 = Output#{formatter => Formatter}, + normalize_main_console_output1(Rest, Output1, Outputs); +normalize_main_console_output1([], Output, Outputs) -> + [Output | Outputs]. + +remove_main_console_output( #{module := Mod1, config := #{type := Stddev}}, Outputs) when ?IS_STD_H_COMPAT(Mod1) andalso @@ -623,23 +746,90 @@ normalize_main_console_output( false; (_) -> true - end, Outputs); -normalize_main_console_output( - [{enabled, false} | _], - #{module := Mod}, - Outputs) - when Mod =:= syslog_logger_h orelse - Mod =:= rabbit_logger_exchange_h -> - lists:filter(fun(#{module := M}) -> M =/= Mod end, Outputs); -normalize_main_console_output([{enabled, true} | Rest], Output, Outputs) -> - normalize_main_console_output(Rest, Output, Outputs); -normalize_main_console_output([{level, Level} | Rest], - Output, Outputs) -> + end, Outputs). + +-spec normalize_main_exchange_output( + exchange_props(), logger:handler_config(), + [logger:handler_config()]) -> + [logger:handler_config()]. + +normalize_main_exchange_output(Props, Output, Outputs) -> + Enabled = proplists:get_value(enabled, Props), + case Enabled of + true -> normalize_main_exchange_output1(Props, Output, Outputs); + false -> remove_main_exchange_output(Output, Outputs) + end. + +normalize_main_exchange_output1( + [{enabled, true} | Rest], + Output, Outputs) -> + normalize_main_exchange_output1(Rest, Output, Outputs); +normalize_main_exchange_output1( + [{level, Level} | Rest], + Output, Outputs) -> Output1 = Output#{level => Level}, - normalize_main_console_output(Rest, Output1, Outputs); -normalize_main_console_output([], Output, Outputs) -> + normalize_main_exchange_output1(Rest, Output1, Outputs); +normalize_main_exchange_output1( + [{formatter, undefined} | Rest], + Output, Outputs) -> + normalize_main_exchange_output1(Rest, Output, Outputs); +normalize_main_exchange_output1( + [{formatter, Formatter} | Rest], + Output, Outputs) -> + Output1 = Output#{formatter => Formatter}, + normalize_main_exchange_output1(Rest, Output1, Outputs); +normalize_main_exchange_output1([], Output, Outputs) -> [Output | Outputs]. +remove_main_exchange_output( + #{module := rabbit_logger_exchange_h}, Outputs) -> + lists:filter( + fun + (#{module := rabbit_logger_exchange_h}) -> false; + (_) -> true + end, Outputs). + +-spec normalize_main_syslog_output( + syslog_props(), logger:handler_config(), + [logger:handler_config()]) -> + [logger:handler_config()]. + +normalize_main_syslog_output(Props, Output, Outputs) -> + Enabled = proplists:get_value(enabled, Props), + case Enabled of + true -> normalize_main_syslog_output1(Props, Output, Outputs); + false -> remove_main_syslog_output(Output, Outputs) + end. + +normalize_main_syslog_output1( + [{enabled, true} | Rest], + Output, Outputs) -> + normalize_main_syslog_output1(Rest, Output, Outputs); +normalize_main_syslog_output1( + [{level, Level} | Rest], + Output, Outputs) -> + Output1 = Output#{level => Level}, + normalize_main_syslog_output1(Rest, Output1, Outputs); +normalize_main_syslog_output1( + [{formatter, undefined} | Rest], + Output, Outputs) -> + normalize_main_syslog_output1(Rest, Output, Outputs); +normalize_main_syslog_output1( + [{formatter, Formatter} | Rest], + Output, Outputs) -> + Output1 = Output#{formatter => Formatter}, + normalize_main_syslog_output1(Rest, Output1, Outputs); +normalize_main_syslog_output1([], Output, Outputs) -> + [Output | Outputs]. + +remove_main_syslog_output( + #{module := syslog_logger_h}, Outputs) -> + lists:filter( + fun + (#{module := syslog_logger_h}) -> false; + (_) -> true + end, Outputs). + -spec normalize_per_cat_log_config(per_cat_env()) -> per_cat_log_config(). normalize_per_cat_log_config(Props) -> @@ -1292,6 +1482,7 @@ adjust_running_dependencies1([]) -> do_install_handlers([#{id := Id, module := Module} = Handler | Rest]) -> case logger:add_handler(Id, Module, Handler) of ok -> + ok = remove_syslog_logger_h_hardcoded_filters(Handler), do_install_handlers(Rest); {error, {handler_not_added, {open_failed, Filename, Reason}}} -> throw({error, {cannot_log_to_file, Filename, Reason}}); @@ -1301,6 +1492,14 @@ do_install_handlers([#{id := Id, module := Module} = Handler | Rest]) -> do_install_handlers([]) -> ok. +remove_syslog_logger_h_hardcoded_filters( + #{id := Id, module := syslog_logger_h}) -> + _ = logger:remove_handler_filter(Id, progress), + _ = logger:remove_handler_filter(Id, remote_gl), + ok; +remove_syslog_logger_h_hardcoded_filters(_) -> + ok. + -spec remove_old_handlers() -> ok. remove_old_handlers() -> diff --git a/deps/rabbit/test/logging_SUITE.erl b/deps/rabbit/test/logging_SUITE.erl index e5c865bed8..eb0d907385 100644 --- a/deps/rabbit/test/logging_SUITE.erl +++ b/deps/rabbit/test/logging_SUITE.erl @@ -14,7 +14,9 @@ -include_lib("rabbit_common/include/logging.hrl"). -include_lib("amqp_client/include/amqp_client.hrl"). --export([all/0, +-export([suite/0, + all/0, + groups/0, init_per_suite/1, end_per_suite/1, init_per_group/2, @@ -23,25 +25,76 @@ end_per_testcase/2, logging_with_default_config_works/1, + setting_log_levels_in_env_works/1, + setting_log_levels_in_config_works/1, + setting_log_levels_in_config_with_output_overridden_in_env_works/1, + setting_message_format_works/1, + setting_level_format_works/1, + setting_time_format_works/1, + logging_as_single_line_works/1, + logging_as_multi_line_works/1, + formatting_as_json_configured_in_env_works/1, + formatting_as_json_configured_in_config_works/1, + renaming_json_fields_works/1, + removing_specific_json_fields_works/1, + removing_non_mentionned_json_fields_works/1, + configuring_verbosity_works/1, + logging_to_stdout_configured_in_env_works/1, logging_to_stdout_configured_in_config_works/1, logging_to_stderr_configured_in_env_works/1, + logging_to_stderr_configured_in_config_works/1, + formatting_with_colors_works/1, + formatting_without_colors_works/1, + logging_to_exchange_works/1, - setting_log_levels_in_env_works/1, - setting_log_levels_in_config_works/1, - setting_log_levels_in_config_with_output_overridden_in_env_works/1, - format_messages_as_json_works/1]). + + logging_to_syslog_works/1]). + +suite() -> + [{timetrap, {minutes, 1}}]. all() -> - [logging_with_default_config_works, - logging_to_stdout_configured_in_env_works, - logging_to_stdout_configured_in_config_works, - logging_to_stderr_configured_in_env_works, - logging_to_exchange_works, - setting_log_levels_in_env_works, - setting_log_levels_in_config_works, - setting_log_levels_in_config_with_output_overridden_in_env_works, - format_messages_as_json_works]. + [ + {group, file_output}, + {group, console_output}, + {group, exchange_output}, + {group, syslog_output} + ]. + +groups() -> + [ + {file_output, [], + [logging_with_default_config_works, + setting_log_levels_in_env_works, + setting_log_levels_in_config_works, + setting_log_levels_in_config_with_output_overridden_in_env_works, + setting_message_format_works, + setting_level_format_works, + setting_time_format_works, + logging_as_single_line_works, + logging_as_multi_line_works, + formatting_as_json_configured_in_env_works, + formatting_as_json_configured_in_config_works, + renaming_json_fields_works, + removing_specific_json_fields_works, + removing_non_mentionned_json_fields_works, + configuring_verbosity_works]}, + + {console_output, [], + [logging_to_stdout_configured_in_env_works, + logging_to_stdout_configured_in_config_works, + logging_to_stderr_configured_in_env_works, + logging_to_stderr_configured_in_config_works, + formatting_with_colors_works, + formatting_without_colors_works]}, + + {exchange_output, [], + [logging_to_exchange_works]}, + + {syslog_output, [], + [logging_to_syslog_works]} + ]. init_per_suite(Config) -> rabbit_ct_helpers:log_environment(), @@ -50,50 +103,91 @@ init_per_suite(Config) -> end_per_suite(Config) -> Config. +init_per_group(syslog_output, Config) -> + Config1 = start_fake_syslogd(Config), + TcpPort = ?config(syslogd_tcp_port, Config1), + ok = application:set_env( + syslog, logger, [], + [{persistent, true}]), + ok = application:set_env( + syslog, syslog_error_logger, false, + [{persistent, true}]), + ok = application:set_env( + syslog, protocol, {rfc3164, tcp}, + [{persistent, true}]), + ok = application:set_env( + syslog, dest_port, TcpPort, + [{persistent, true}]), + {ok, _} = application:ensure_all_started(syslog), + Config1; init_per_group(_, Config) -> Config. +end_per_group(syslog_output, Config) -> + ok = application:stop(syslog), + stop_fake_syslogd(Config); end_per_group(_, Config) -> Config. -init_per_testcase(logging_to_exchange_works = Testcase, Config) -> - rabbit_ct_helpers:testcase_started(Config, Testcase), - Config1 = rabbit_ct_helpers:set_config( - Config, - [{rmq_nodes_count, 1}, - {rmq_nodename_suffix, Testcase}]), - Config2 = rabbit_ct_helpers:merge_app_env( - Config1, - {rabbit, [{log, [{exchange, [{enabled, true}, - {level, info}]}, - {file, [{level, info}]}]}]}), - rabbit_ct_helpers:run_steps( - Config2, - rabbit_ct_broker_helpers:setup_steps() ++ - rabbit_ct_client_helpers:setup_steps()); init_per_testcase(Testcase, Config) -> - remove_all_handlers(), - application:unset_env(rabbit, log), - LogBaseDir = filename:join( - ?config(priv_dir, Config), - atom_to_list(Testcase)), - Config1 = rabbit_ct_helpers:set_config( - Config, {log_base_dir, LogBaseDir}), + rabbit_ct_helpers:testcase_started(Config, Testcase), + GroupProps = ?config(tc_group_properties, Config), + Group = proplists:get_value(name, GroupProps), + case Group of + %% The exchange output requires RabbitMQ to run. All testcases in this + %% group will run in the context of that RabbitMQ node. + exchange_output -> + ExchProps = case Testcase of + logging_to_exchange_works -> + [{enabled, true}, + {level, info}] + end, + Config1 = rabbit_ct_helpers:set_config( + Config, + [{rmq_nodes_count, 1}, + {rmq_nodename_suffix, Testcase}]), + Config2 = rabbit_ct_helpers:merge_app_env( + Config1, + {rabbit, [{log, [{exchange, ExchProps}, + {file, [{level, info}]}]}]}), + rabbit_ct_helpers:run_steps( + Config2, + rabbit_ct_broker_helpers:setup_steps() ++ + rabbit_ct_client_helpers:setup_steps()); + + %% Other groups and testcases runs the tested code directly without a + %% RabbitMQ node running. + _ -> + remove_all_handlers(), + application:unset_env(rabbit, log), + LogBaseDir = filename:join( + ?config(priv_dir, Config), + atom_to_list(Testcase)), + rabbit_ct_helpers:set_config( + Config, {log_base_dir, LogBaseDir}) + end. + +end_per_testcase(Testcase, Config) -> + Config1 = case rabbit_ct_helpers:get_config(Config, rmq_nodes_count) of + undefined -> + application:unset_env(rabbit, log), + Config; + _ -> + rabbit_ct_helpers:run_steps( + Config, + rabbit_ct_client_helpers:teardown_steps() ++ + rabbit_ct_broker_helpers:teardown_steps()) + end, rabbit_ct_helpers:testcase_finished(Config1, Testcase). -end_per_testcase(logging_to_exchange_works, Config) -> - rabbit_ct_helpers:run_steps( - Config, - rabbit_ct_client_helpers:teardown_steps() ++ - rabbit_ct_broker_helpers:teardown_steps()); -end_per_testcase(_, Config) -> - application:unset_env(rabbit, log), - Config. - remove_all_handlers() -> _ = [logger:remove_handler(Id) || #{id := Id} <- logger:get_handler_config()]. +%% ------------------------------------------------------------------- +%% Testcases. +%% ------------------------------------------------------------------- + logging_with_default_config_works(Config) -> Context = default_context(Config), rabbit_prelaunch_logging:clear_config_run_number(), @@ -143,156 +237,6 @@ logging_with_default_config_works(Config) -> #{domain => ?RMQLOG_DOMAIN_GLOBAL})), ok. -logging_to_stdout_configured_in_env_works(Config) -> - #{var_origins := Origins0} = Context0 = default_context(Config), - Context = Context0#{main_log_file => "-", - var_origins => Origins0#{ - main_log_file => environment}}, - logging_to_stddev_works(standard_io, rmq_1_stdout, Config, Context). - -logging_to_stdout_configured_in_config_works(Config) -> - Context = default_context(Config), - ok = application:set_env( - rabbit, log, - [{console, [{enabled, true}]}], - [{persistent, true}]), - logging_to_stddev_works(standard_io, rmq_1_stdout, Config, Context). - -logging_to_stderr_configured_in_env_works(Config) -> - #{var_origins := Origins0} = Context0 = default_context(Config), - Context = Context0#{main_log_file => "-stderr", - var_origins => Origins0#{ - main_log_file => environment}}, - logging_to_stddev_works(standard_error, rmq_1_stderr, Config, Context). - -logging_to_stddev_works(Stddev, Id, Config, Context) -> - rabbit_prelaunch_logging:clear_config_run_number(), - rabbit_prelaunch_logging:setup(Context), - - Handlers = logger:get_handler_config(), - - StddevHandler = get_handler_by_id(Handlers, Id), - ?assertNotEqual(undefined, StddevHandler), - ?assertMatch( - #{level := info, - module := rabbit_logger_std_h, - filter_default := log, - filters := [{progress_reports, {_, stop}}, - {rmqlog_filter, {_, #{global := info, - upgrade := none}}}], - formatter := {rabbit_logger_text_fmt, _}, - config := #{type := Stddev}}, - StddevHandler), - - UpgradeFileHandler = get_handler_by_id(Handlers, rmq_1_file_1), - UpgradeFile = upgrade_log_file_in_context(Context), - ?assertNotEqual(undefined, UpgradeFileHandler), - ?assertMatch( - #{level := info, - module := rabbit_logger_std_h, - filter_default := stop, - filters := [{rmqlog_filter, {_, #{upgrade := info}}}], - formatter := {rabbit_logger_text_fmt, _}, - config := #{type := file, - file := UpgradeFile}}, - UpgradeFileHandler), - - ?assert(ping_log(Id, info, Config)), - ?assert(ping_log(Id, info, - #{domain => ?RMQLOG_DOMAIN_GLOBAL}, Config)), - ?assert(ping_log(Id, info, - #{domain => ['3rd_party']}, Config)), - ?assertNot(ping_log(Id, info, - #{domain => ?RMQLOG_DOMAIN_UPGRADE}, Config)), - - ?assert(ping_log(rmq_1_file_1, info, - #{domain => ?RMQLOG_DOMAIN_UPGRADE})), - ?assertNot(ping_log(rmq_1_file_1, info, - #{domain => ?RMQLOG_DOMAIN_GLOBAL})), - ok. - -logging_to_exchange_works(Config) -> - Context = rabbit_ct_broker_helpers:rpc( - Config, 0, - rabbit_prelaunch, get_context, []), - Handlers = rabbit_ct_broker_helpers:rpc( - Config, 0, - logger, get_handler_config, []), - - ExchangeHandler = get_handler_by_id(Handlers, rmq_1_exchange), - ?assertNotEqual(undefined, ExchangeHandler), - ?assertMatch( - #{level := info, - module := rabbit_logger_exchange_h, - filter_default := log, - filters := [{progress_reports, {_, stop}}, - {rmqlog_filter, {_, #{global := info, - upgrade := none}}}], - formatter := {rabbit_logger_text_fmt, _}, - config := #{exchange := _}}, - ExchangeHandler), - #{config := - #{exchange := #resource{name = XName} = Exchange}} = ExchangeHandler, - - UpgradeFileHandler = get_handler_by_id(Handlers, rmq_1_file_2), - UpgradeFile = upgrade_log_file_in_context(Context), - ?assertNotEqual(undefined, UpgradeFileHandler), - ?assertMatch( - #{level := info, - module := rabbit_logger_std_h, - filter_default := stop, - filters := [{rmqlog_filter, {_, #{upgrade := info}}}], - formatter := {rabbit_logger_text_fmt, _}, - config := #{type := file, - file := UpgradeFile}}, - UpgradeFileHandler), - - %% Wait for the expected exchange to be automatically declared. - lists:any( - fun(_) -> - Ret = rabbit_ct_broker_helpers:rpc( - Config, 0, - rabbit_exchange, lookup, [Exchange]), - case Ret of - {ok, _} -> true; - _ -> timer:sleep(500), - false - end - end, lists:seq(1, 20)), - - %% Declare a queue to collect all logged messages. - {Conn, Chan} = rabbit_ct_client_helpers:open_connection_and_channel( - Config), - QName = <<"log-messages">>, - ?assertMatch( - #'queue.declare_ok'{}, - amqp_channel:call(Chan, #'queue.declare'{queue = QName, - durable = false})), - ?assertMatch( - #'queue.bind_ok'{}, - amqp_channel:call(Chan, #'queue.bind'{queue = QName, - exchange = XName, - routing_key = <<"#">>})), - Config1 = rabbit_ct_helpers:set_config( - Config, {test_channel_and_queue, {Chan, QName}}), - - ?assert(ping_log(rmq_1_exchange, info, Config1)), - ?assert(ping_log(rmq_1_exchange, info, - #{domain => ?RMQLOG_DOMAIN_GLOBAL}, Config1)), - ?assert(ping_log(rmq_1_exchange, info, - #{domain => ['3rd_party']}, Config1)), - ?assertNot(ping_log(rmq_1_exchange, info, - #{domain => ?RMQLOG_DOMAIN_UPGRADE}, Config1)), - - ?assert(ping_log(rmq_1_file_2, info, - #{domain => ?RMQLOG_DOMAIN_UPGRADE}, Config)), - ?assertNot(ping_log(rmq_1_file_2, info, - #{domain => ?RMQLOG_DOMAIN_GLOBAL}, Config)), - - amqp_channel:call(Chan, #'queue.delete'{queue = QName}), - rabbit_ct_client_helpers:close_connection_and_channel(Conn, Chan), - ok. - setting_log_levels_in_env_works(Config) -> GlobalLevel = warning, PrelaunchLevel = error, @@ -443,8 +387,7 @@ setting_log_levels_in_config_with_output_overridden_in_env_works(Config) -> var_origins => Origins0#{ main_log_file => environment}}, ok = application:set_env( - rabbit, log, - [{console, [{level, debug}]}], + rabbit, log, [{console, [{level, debug}]}], [{persistent, true}]), rabbit_prelaunch_logging:clear_config_run_number(), rabbit_prelaunch_logging:setup(Context), @@ -486,10 +429,177 @@ setting_log_levels_in_config_with_output_overridden_in_env_works(Config) -> #{domain => ?RMQLOG_DOMAIN_UPGRADE}, Config)), ok. -format_messages_as_json_works(Config) -> +setting_message_format_works(Config) -> + Context = default_context(Config), + Format = ["level=", level, " ", + "md_key=", md_key, " ", + "unknown_field=", unknown_field, " ", + "msg=", msg], + {PrefixFormat, LineFormat} = + rabbit_prelaunch_early_logging:determine_prefix(Format), + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_text_fmt, + #{prefix_format => PrefixFormat, + line_format => LineFormat}}}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + Metadata = #{md_key => "md_value"}, + {RandomMsg, Line} = log_and_return_line(Context, Metadata), + + RandomMsgBin = list_to_binary(RandomMsg), + ?assertEqual( + <<"level=warn ", + "md_key=md_value ", + "unknown_field=<unknown unknown_field> " + "msg=", RandomMsgBin/binary>>, + Line). + +setting_level_format_works(Config) -> + LevelFormats = #{lc => "warning", + uc => "WARNING", + lc3 => "wrn", + uc3 => "WRN", + lc4 => "warn", + uc4 => "WARN"}, + maps:fold( + fun(LevelFormat, LevelName, Acc) -> + remove_all_handlers(), + setting_level_format_works( + LevelFormat, list_to_binary(LevelName), Config), + Acc + end, ok, LevelFormats). + +setting_level_format_works(LevelFormat, LevelName, Config) -> + Context = default_context(Config), + Format = [level, " ", msg], + {PrefixFormat, LineFormat} = + rabbit_prelaunch_early_logging:determine_prefix(Format), + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_text_fmt, + #{level_format => LevelFormat, + prefix_format => PrefixFormat, + line_format => LineFormat}}}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + {RandomMsg, Line} = log_and_return_line(Context, #{}), + + RandomMsgBin = list_to_binary(RandomMsg), + ?assertEqual( + <<LevelName/binary, " ", RandomMsgBin/binary>>, + Line). + +setting_time_format_works(Config) -> + DateTime = "2018-02-01T16:17:58.123456+01:00", + Timestamp = calendar:rfc3339_to_system_time( + DateTime, [{unit, microsecond}]), + TimeFormats = + #{{rfc3339, $T} => DateTime, + {rfc3339, $\s} => "2018-02-01 16:17:58.123456+01:00", + {epoch, usecs, binary} => integer_to_list(Timestamp), + {epoch, secs, binary} => io_lib:format("~.6.0f", [Timestamp / 1000000]), + {"~4..0b-~2..0b-~2..0b " + "~2..0b:~2..0b:~2..0b.~3..0b", + [year, month, day, + hour, minute, second, + {second_fractional, 3}]} => "2018-02-01 16:17:58.123"}, + maps:fold( + fun(TimeFormat, TimeValue, Acc) -> + remove_all_handlers(), + setting_time_format_works( + Timestamp, TimeFormat, list_to_binary(TimeValue), Config), + Acc + end, ok, TimeFormats). + +setting_time_format_works(Timestamp, TimeFormat, TimeValue, Config) -> + Context = default_context(Config), + Format = [time, " ", msg], + {PrefixFormat, LineFormat} = + rabbit_prelaunch_early_logging:determine_prefix(Format), + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_text_fmt, + #{time_format => TimeFormat, + prefix_format => PrefixFormat, + line_format => LineFormat}}}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + Metadata = #{time => Timestamp}, + {RandomMsg, Line} = log_and_return_line(Context, Metadata), + + RandomMsgBin = list_to_binary(RandomMsg), + ?assertEqual( + <<TimeValue/binary, " ", RandomMsgBin/binary>>, + Line). + +logging_as_single_line_works(Config) -> + logging_as_single_or_multi_line_works(false, Config). + +logging_as_multi_line_works(Config) -> + logging_as_single_or_multi_line_works(true, Config). + +logging_as_single_or_multi_line_works(AsMultiline, Config) -> + Context = default_context(Config), + Format = [time, " ", msg], + {PrefixFormat, LineFormat} = + rabbit_prelaunch_early_logging:determine_prefix(Format), + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_text_fmt, + #{single_line => not AsMultiline, + prefix_format => PrefixFormat, + line_format => LineFormat}}}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + RandomMsg1 = get_random_string( + 32, + "abcdefghijklmnopqrstuvwxyz" + "ABCDEFGHIJKLMNOPQRSTUVWXYZ"), + RandomMsg2 = get_random_string( + 32, + "abcdefghijklmnopqrstuvwxyz" + "ABCDEFGHIJKLMNOPQRSTUVWXYZ"), + ?LOG_WARNING(RandomMsg1 ++ "\n" ++ RandomMsg2, #{}), + + rabbit_logger_std_h:filesync(rmq_1_file_1), + MainFile = main_log_file_in_context(Context), + {ok, Content} = file:read_file(MainFile), + ReOpts = [{capture, none}, multiline], + case AsMultiline of + true -> + match = re:run(Content, RandomMsg1 ++ "$", ReOpts), + match = re:run(Content, RandomMsg2 ++ "$", ReOpts); + false -> + match = re:run( + Content, + RandomMsg1 ++ ", " ++ RandomMsg2 ++ "$", + ReOpts) + end. + +formatting_as_json_configured_in_env_works(Config) -> #{var_origins := Origins0} = Context0 = default_context(Config), Context = Context0#{log_levels => #{json => true}, var_origins => Origins0#{log_levels => environment}}, + formatting_as_json_works(Config, Context). + +formatting_as_json_configured_in_config_works(Config) -> + Context = default_context(Config), + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_json_fmt, #{}}}]}], + [{persistent, true}]), + formatting_as_json_works(Config, Context). + +formatting_as_json_works(_, Context) -> rabbit_prelaunch_logging:clear_config_run_number(), rabbit_prelaunch_logging:setup(Context), @@ -512,10 +622,6 @@ format_messages_as_json_works(Config) -> ?assertNot(ping_log(rmq_1_file_1, info)), - RandomMsg = get_random_string( - 32, - "abcdefghijklmnopqrstuvwxyz" - "ABCDEFGHIJKLMNOPQRSTUVWXYZ"), Metadata = #{atom => rabbit, integer => 1, float => 1.42, @@ -526,37 +632,383 @@ format_messages_as_json_works(Config) -> pid => self(), port => hd(erlang:ports()), ref => erlang:make_ref()}, - ?LOG_INFO(RandomMsg, Metadata), - - rabbit_logger_std_h:filesync(rmq_1_file_1), - {ok, Content} = file:read_file(MainFile), - ReOpts = [{capture, first, binary}, multiline], - {match, [Line]} = re:run( - Content, - "^.+\"" ++ RandomMsg ++ "\".+$", - ReOpts), - Term = jsx:decode(Line, [return_maps, {labels, attempt_atom}]), + {RandomMsg, Term} = log_and_return_json_object( + Context, Metadata, [return_maps]), RandomMsgBin = list_to_binary(RandomMsg), ?assertMatch(#{time := _}, Term), ?assertMatch(#{level := <<"info">>}, Term), ?assertMatch(#{msg := RandomMsgBin}, Term), - Meta = maps:get(meta, Term), FunBin = list_to_binary(erlang:fun_to_list(maps:get(function, Metadata))), PidBin = list_to_binary(erlang:pid_to_list(maps:get(pid, Metadata))), PortBin = list_to_binary(erlang:port_to_list(maps:get(port, Metadata))), RefBin = list_to_binary(erlang:ref_to_list(maps:get(ref, Metadata))), - ?assertMatch(#{atom := <<"rabbit">>}, Meta), - ?assertMatch(#{integer := 1}, Meta), - ?assertMatch(#{float := 1.42}, Meta), - ?assertMatch(#{string := <<"string">>}, Meta), - ?assertMatch(#{list := [<<"s">>, <<"a">>, 3]}, Meta), - ?assertMatch(#{map := #{key := <<"value">>}}, Meta), - ?assertMatch(#{function := FunBin}, Meta), - ?assertMatch(#{pid := PidBin}, Meta), - ?assertMatch(#{port := PortBin}, Meta), - ?assertMatch(#{ref := RefBin}, Meta). + ?assertMatch(#{atom := <<"rabbit">>}, Term), + ?assertMatch(#{integer := 1}, Term), + ?assertMatch(#{float := 1.42}, Term), + ?assertMatch(#{string := <<"string">>}, Term), + ?assertMatch(#{list := [<<"s">>, <<"a">>, 3]}, Term), + ?assertMatch(#{map := #{key := <<"value">>}}, Term), + ?assertMatch(#{function := FunBin}, Term), + ?assertMatch(#{pid := PidBin}, Term), + ?assertMatch(#{port := PortBin}, Term), + ?assertMatch(#{ref := RefBin}, Term). + +renaming_json_fields_works(Config) -> + Context = default_context(Config), + FieldMap = [{integer, int}, + {msg, m}, + {unknown_field, still_unknown_field}, + {'$REST', false}], + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_json_fmt, + #{field_map => FieldMap}}}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + Metadata = #{atom => rabbit, + integer => 1, + string => "string", + list => ["s", a, 3]}, + {RandomMsg, Term} = log_and_return_json_object(Context, Metadata, []), + + RandomMsgBin = list_to_binary(RandomMsg), + ?assertEqual( + [{int, 1}, + {m, RandomMsgBin}], + Term). + +removing_specific_json_fields_works(Config) -> + Context = default_context(Config), + FieldMap = [{integer, integer}, + {msg, msg}, + {list, false}], + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_json_fmt, + #{field_map => FieldMap}}}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + Metadata = #{atom => rabbit, + integer => 1, + string => "string", + list => ["s", a, 3]}, + {RandomMsg, Term} = log_and_return_json_object(Context, Metadata, []), + + RandomMsgBin = list_to_binary(RandomMsg), + ?assertMatch( + [{integer, 1}, + {msg, RandomMsgBin} | _], + Term), + ?assertMatch(<<"string">>, proplists:get_value(string, Term)). + +removing_non_mentionned_json_fields_works(Config) -> + Context = default_context(Config), + FieldMap = [{integer, integer}, + {msg, msg}, + {'$REST', false}], + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_json_fmt, + #{field_map => FieldMap}}}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + Metadata = #{atom => rabbit, + integer => 1, + string => "string", + list => ["s", a, 3]}, + {RandomMsg, Term} = log_and_return_json_object(Context, Metadata, []), + + RandomMsgBin = list_to_binary(RandomMsg), + ?assertEqual( + [{integer, 1}, + {msg, RandomMsgBin}], + Term). + +configuring_verbosity_works(Config) -> + Context = default_context(Config), + FieldMap = [{verbosity, v}, + {msg, msg}, + {'$REST', false}], + VerbMap = #{debug => 2, + info => 1, + '$REST' => 0}, + ok = application:set_env( + rabbit, log, + [{file, [{formatter, {rabbit_logger_json_fmt, + #{field_map => FieldMap, + verbosity_map => VerbMap}}}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + {RandomMsg, Term} = log_and_return_json_object(Context, #{}, []), + + RandomMsgBin = list_to_binary(RandomMsg), + ?assertEqual( + [{v, 1}, + {msg, RandomMsgBin}], + Term). + +logging_to_stdout_configured_in_env_works(Config) -> + #{var_origins := Origins0} = Context0 = default_context(Config), + Context = Context0#{main_log_file => "-", + var_origins => Origins0#{ + main_log_file => environment}}, + logging_to_stddev_works(standard_io, rmq_1_stdout, Config, Context). + +logging_to_stdout_configured_in_config_works(Config) -> + Context = default_context(Config), + ok = application:set_env( + rabbit, log, [{console, [{enabled, true}]}], + [{persistent, true}]), + logging_to_stddev_works(standard_io, rmq_1_stdout, Config, Context). + +logging_to_stderr_configured_in_env_works(Config) -> + #{var_origins := Origins0} = Context0 = default_context(Config), + Context = Context0#{main_log_file => "-stderr", + var_origins => Origins0#{ + main_log_file => environment}}, + logging_to_stddev_works(standard_error, rmq_1_stderr, Config, Context). + +logging_to_stderr_configured_in_config_works(Config) -> + Context = default_context(Config), + ok = application:set_env( + rabbit, log, [{console, [{enabled, true}, + {stdio, stderr}]}], + [{persistent, true}]), + logging_to_stddev_works(standard_error, rmq_1_stderr, Config, Context). + +logging_to_stddev_works(Stddev, Id, Config, Context) -> + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + Handlers = logger:get_handler_config(), + + StddevHandler = get_handler_by_id(Handlers, Id), + ?assertNotEqual(undefined, StddevHandler), + ?assertMatch( + #{level := info, + module := rabbit_logger_std_h, + filter_default := log, + filters := [{progress_reports, {_, stop}}, + {rmqlog_filter, {_, #{global := info, + upgrade := none}}}], + formatter := {rabbit_logger_text_fmt, _}, + config := #{type := Stddev}}, + StddevHandler), + + UpgradeFileHandler = get_handler_by_id(Handlers, rmq_1_file_1), + UpgradeFile = upgrade_log_file_in_context(Context), + ?assertNotEqual(undefined, UpgradeFileHandler), + ?assertMatch( + #{level := info, + module := rabbit_logger_std_h, + filter_default := stop, + filters := [{rmqlog_filter, {_, #{upgrade := info}}}], + formatter := {rabbit_logger_text_fmt, _}, + config := #{type := file, + file := UpgradeFile}}, + UpgradeFileHandler), + + ?assert(ping_log(Id, info, Config)), + ?assert(ping_log(Id, info, + #{domain => ?RMQLOG_DOMAIN_GLOBAL}, Config)), + ?assert(ping_log(Id, info, + #{domain => ['3rd_party']}, Config)), + ?assertNot(ping_log(Id, info, + #{domain => ?RMQLOG_DOMAIN_UPGRADE}, Config)), + + ?assert(ping_log(rmq_1_file_1, info, + #{domain => ?RMQLOG_DOMAIN_UPGRADE})), + ?assertNot(ping_log(rmq_1_file_1, info, + #{domain => ?RMQLOG_DOMAIN_GLOBAL})), + ok. + +formatting_with_colors_works(Config) -> + EscSeqs = make_color_esc_seqs_map(), + Context = default_context(Config), + ok = application:set_env( + rabbit, log, [{console, [{level, debug}, + {formatter, + {rabbit_logger_text_fmt, + #{use_colors => true, + color_esc_seqs => EscSeqs}}}]}], + [{persistent, true}]), + formatting_maybe_with_colors_works(Config, Context, EscSeqs). + +formatting_without_colors_works(Config) -> + EscSeqs = make_color_esc_seqs_map(), + Context = default_context(Config), + ok = application:set_env( + rabbit, log, [{console, [{level, debug}, + {formatter, + {rabbit_logger_text_fmt, + #{use_colors => false, + color_esc_seqs => EscSeqs}}}]}], + [{persistent, true}]), + formatting_maybe_with_colors_works(Config, Context, EscSeqs). + +make_color_esc_seqs_map() -> + lists:foldl( + fun(Lvl, Acc) -> + EscSeq = "[" ++ atom_to_list(Lvl) ++ " color]", + Acc#{Lvl => EscSeq} + end, #{}, rabbit_prelaunch_early_logging:levels()). + +formatting_maybe_with_colors_works(Config, Context, _EscSeqs) -> + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + + ?assert(ping_log(rmq_1_stdout, debug, Config)), + ?assert(ping_log(rmq_1_stdout, info, Config)), + ?assert(ping_log(rmq_1_stdout, notice, Config)), + ?assert(ping_log(rmq_1_stdout, warning, Config)), + ?assert(ping_log(rmq_1_stdout, error, Config)), + ?assert(ping_log(rmq_1_stdout, critical, Config)), + ?assert(ping_log(rmq_1_stdout, alert, Config)), + ?assert(ping_log(rmq_1_stdout, emergency, Config)), + ok. + +logging_to_exchange_works(Config) -> + Context = rabbit_ct_broker_helpers:rpc( + Config, 0, + rabbit_prelaunch, get_context, []), + Handlers = rabbit_ct_broker_helpers:rpc( + Config, 0, + logger, get_handler_config, []), + + ExchangeHandler = get_handler_by_id(Handlers, rmq_1_exchange), + ?assertNotEqual(undefined, ExchangeHandler), + ?assertMatch( + #{level := info, + module := rabbit_logger_exchange_h, + filter_default := log, + filters := [{progress_reports, {_, stop}}, + {rmqlog_filter, {_, #{global := info, + upgrade := none}}}], + formatter := {rabbit_logger_text_fmt, _}, + config := #{exchange := _}}, + ExchangeHandler), + #{config := + #{exchange := #resource{name = XName} = Exchange}} = ExchangeHandler, + + UpgradeFileHandler = get_handler_by_id(Handlers, rmq_1_file_2), + UpgradeFile = upgrade_log_file_in_context(Context), + ?assertNotEqual(undefined, UpgradeFileHandler), + ?assertMatch( + #{level := info, + module := rabbit_logger_std_h, + filter_default := stop, + filters := [{rmqlog_filter, {_, #{upgrade := info}}}], + formatter := {rabbit_logger_text_fmt, _}, + config := #{type := file, + file := UpgradeFile}}, + UpgradeFileHandler), + + %% Wait for the expected exchange to be automatically declared. + lists:any( + fun(_) -> + Ret = rabbit_ct_broker_helpers:rpc( + Config, 0, + rabbit_exchange, lookup, [Exchange]), + case Ret of + {ok, _} -> true; + _ -> timer:sleep(500), + false + end + end, lists:seq(1, 20)), + + %% Declare a queue to collect all logged messages. + {Conn, Chan} = rabbit_ct_client_helpers:open_connection_and_channel( + Config), + QName = <<"log-messages">>, + ?assertMatch( + #'queue.declare_ok'{}, + amqp_channel:call(Chan, #'queue.declare'{queue = QName, + durable = false})), + ?assertMatch( + #'queue.bind_ok'{}, + amqp_channel:call(Chan, #'queue.bind'{queue = QName, + exchange = XName, + routing_key = <<"#">>})), + Config1 = rabbit_ct_helpers:set_config( + Config, {test_channel_and_queue, {Chan, QName}}), + + ?assert(ping_log(rmq_1_exchange, info, Config1)), + ?assert(ping_log(rmq_1_exchange, info, + #{domain => ?RMQLOG_DOMAIN_GLOBAL}, Config1)), + ?assert(ping_log(rmq_1_exchange, info, + #{domain => ['3rd_party']}, Config1)), + ?assertNot(ping_log(rmq_1_exchange, info, + #{domain => ?RMQLOG_DOMAIN_UPGRADE}, Config1)), + + ?assert(ping_log(rmq_1_file_2, info, + #{domain => ?RMQLOG_DOMAIN_UPGRADE}, Config)), + ?assertNot(ping_log(rmq_1_file_2, info, + #{domain => ?RMQLOG_DOMAIN_GLOBAL}, Config)), + + amqp_channel:call(Chan, #'queue.delete'{queue = QName}), + rabbit_ct_client_helpers:close_connection_and_channel(Conn, Chan), + ok. + +logging_to_syslog_works(Config) -> + Context = default_context(Config), + ok = application:set_env( + rabbit, log, [{syslog, [{enabled, true}]}], + [{persistent, true}]), + rabbit_prelaunch_logging:clear_config_run_number(), + rabbit_prelaunch_logging:setup(Context), + clear_syslogd_messages(Config), + + Handlers = logger:get_handler_config(), + + SyslogHandler = get_handler_by_id(Handlers, rmq_1_syslog), + ?assertNotEqual(undefined, SyslogHandler), + ?assertMatch( + #{level := info, + module := syslog_logger_h, + filter_default := log, + filters := [{progress_reports, {_, stop}}, + {rmqlog_filter, {_, #{global := info, + upgrade := none}}}], + formatter := {rabbit_logger_text_fmt, _}, + config := #{}}, + SyslogHandler), + + UpgradeFileHandler = get_handler_by_id(Handlers, rmq_1_file_1), + UpgradeFile = upgrade_log_file_in_context(Context), + ?assertNotEqual(undefined, UpgradeFileHandler), + ?assertMatch( + #{level := info, + module := rabbit_logger_std_h, + filter_default := stop, + filters := [{rmqlog_filter, {_, #{upgrade := info}}}], + formatter := {rabbit_logger_text_fmt, _}, + config := #{type := file, + file := UpgradeFile}}, + UpgradeFileHandler), + + ?assert(ping_log(rmq_1_syslog, info, Config)), + ?assert(ping_log(rmq_1_syslog, info, + #{domain => ?RMQLOG_DOMAIN_GLOBAL}, Config)), + ?assert(ping_log(rmq_1_syslog, info, + #{domain => ['3rd_party']}, Config)), + ?assertNot(ping_log(rmq_1_syslog, info, + #{domain => ?RMQLOG_DOMAIN_UPGRADE}, Config)), + + ?assert(ping_log(rmq_1_file_1, info, + #{domain => ?RMQLOG_DOMAIN_UPGRADE})), + ?assertNot(ping_log(rmq_1_file_1, info, + #{domain => ?RMQLOG_DOMAIN_GLOBAL})), + ok. %% ------------------------------------------------------------------- %% Internal functions. @@ -610,25 +1062,26 @@ ping_log(Id, Level, Metadata, Config) -> Config, 0, logger, log, [Level, RandomMsg, Metadata]) end, - check_log(Id, RandomMsg, Config). + check_log(Id, Level, RandomMsg, Config). need_rpc(Config) -> rabbit_ct_helpers:get_config( Config, rmq_nodes_count) =/= undefined. -check_log(Id, RandomMsg, Config) -> +check_log(Id, Level, RandomMsg, Config) -> {ok, Handler} = case need_rpc(Config) of false -> logger:get_handler_config(Id); true -> rabbit_ct_broker_helpers:rpc( Config, 0, logger, get_handler_config, [Id]) end, - check_log1(Handler, RandomMsg, Config). + check_log1(Handler, Level, RandomMsg, Config). check_log1(#{id := Id, module := rabbit_logger_std_h, config := #{type := file, file := Filename}}, + _Level, RandomMsg, Config) -> ok = case need_rpc(Config) of @@ -641,22 +1094,27 @@ check_log1(#{id := Id, ReOpts = [{capture, none}, multiline], match =:= re:run(Content, RandomMsg ++ "$", ReOpts); check_log1(#{module := Mod, - config := #{type := Stddev}}, + config := #{type := Stddev}} = Handler, + Level, RandomMsg, Config) when ?IS_STD_H_COMPAT(Mod) andalso ?IS_STDDEV(Stddev) -> Filename = html_report_filename(Config), + {ColorStart, ColorEnd} = get_color_config(Handler, Level), ReOpts = [{capture, none}, multiline], lists:any( fun(_) -> {ok, Content} = file:read_file(Filename), - case re:run(Content, RandomMsg ++ "$", ReOpts) of + Regex = + "^" ++ ColorStart ++ ".+" ++ RandomMsg ++ ColorEnd ++ "$", + case re:run(Content, Regex, ReOpts) of match -> true; _ -> timer:sleep(500), false end end, lists:seq(1, 10)); check_log1(#{module := rabbit_logger_exchange_h}, + _Level, RandomMsg, Config) -> {Chan, QName} = ?config(test_channel_and_queue, Config), @@ -680,6 +1138,20 @@ check_log1(#{module := rabbit_logger_exchange_h}, timer:sleep(500), false end + end, lists:seq(1, 10)); +check_log1(#{module := syslog_logger_h}, + _Level, + RandomMsg, + Config) -> + ReOpts = [{capture, none}, multiline], + lists:any( + fun(_) -> + Buffer = get_syslogd_messages(Config), + case re:run(Buffer, RandomMsg ++ "$", ReOpts) of + match -> true; + _ -> timer:sleep(500), + false + end end, lists:seq(1, 10)). get_random_string(Length, AllowedChars) -> @@ -691,3 +1163,155 @@ get_random_string(Length, AllowedChars) -> html_report_filename(Config) -> ?config(tc_logfile, Config). + +get_color_config( + #{formatter := {rabbit_logger_text_fmt, + #{use_colors := true, + color_esc_seqs := EscSeqs}}}, Level) -> + ColorStart = maps:get(Level, EscSeqs), + ColorEnd = "\033[0m", + {escape_for_re(ColorStart), escape_for_re(ColorEnd)}; +get_color_config(_, _) -> + {"", ""}. + +escape_for_re(String) -> + String1 = string:replace(String, "[", "\\[", all), + string:replace(String1, "]", "\\]", all). + +log_and_return_line(Context, Metadata) -> + RandomMsg = get_random_string( + 32, + "abcdefghijklmnopqrstuvwxyz" + "ABCDEFGHIJKLMNOPQRSTUVWXYZ"), + logger:warning(RandomMsg, Metadata), + + rabbit_logger_std_h:filesync(rmq_1_file_1), + MainFile = main_log_file_in_context(Context), + {ok, Content} = file:read_file(MainFile), + ReOpts = [{capture, first, binary}, multiline], + {match, [Line]} = re:run( + Content, + "^.+" ++ RandomMsg ++ ".*$", + ReOpts), + {RandomMsg, Line}. + +log_and_return_json_object(Context, Metadata, DecodeOpts) -> + RandomMsg = get_random_string( + 32, + "abcdefghijklmnopqrstuvwxyz" + "ABCDEFGHIJKLMNOPQRSTUVWXYZ"), + ?LOG_INFO(RandomMsg, Metadata), + + rabbit_logger_std_h:filesync(rmq_1_file_1), + MainFile = main_log_file_in_context(Context), + {ok, Content} = file:read_file(MainFile), + ReOpts = [{capture, first, binary}, multiline], + {match, [Line]} = re:run( + Content, + "^.+\"" ++ RandomMsg ++ "\".+$", + ReOpts), + Term = jsx:decode(Line, [{labels, attempt_atom} | DecodeOpts]), + + {RandomMsg, Term}. + +%% ------------------------------------------------------------------- +%% Fake syslog server. +%% ------------------------------------------------------------------- + +start_fake_syslogd(Config) -> + Self = self(), + Pid = spawn(fun() -> syslogd_init(Self) end), + TcpPort = receive {syslogd_ready, P} -> P end, + + rabbit_ct_helpers:set_config( + Config, [{syslogd_pid, Pid}, + {syslogd_tcp_port, TcpPort}]). + +stop_fake_syslogd(Config) -> + Pid = ?config(syslogd_pid, Config), + Pid ! stop, + Config1 = rabbit_ct_helpers:delete_config(Config, syslogd_pid), + rabbit_ct_helpers:delete_config(Config1, syslogd_tcp_port). + +get_syslogd_messages(Config) -> + Pid = ?config(syslogd_pid, Config), + Pid ! {get_messages, self()}, + receive {syslogd_messages, Buffer} -> Buffer end. + +clear_syslogd_messages(Config) -> + Pid = ?config(syslogd_pid, Config), + Pid ! clear_messages. + +syslogd_init(Parent) -> + {ok, TcpPort, LSock} = open_tcp_listening_sock(22000), + ct:pal( + "Fake syslogd ready (~p), listening on TCP port ~p", + [self(), TcpPort]), + Parent ! {syslogd_ready, TcpPort}, + syslogd_start_loop(LSock). + +open_tcp_listening_sock(TcpPort) -> + Options = [binary, + {active, true}], + case gen_tcp:listen(TcpPort, Options) of + {ok, LSock} -> {ok, TcpPort, LSock}; + {error, eaddrinuse} -> open_tcp_listening_sock(TcpPort + 1) + end. + +syslogd_start_loop(LSock) -> + ct:pal("Fake syslogd: accepting new connection", []), + {ok, Sock} = gen_tcp:accept(LSock), + ct:pal("Fake syslogd: accepted new connection!", []), + syslogd_loop(LSock, Sock, [], <<>>). + +syslogd_loop(LSock, Sock, Messages, Buffer) -> + try + receive + {tcp, Sock, NewData} -> + Buffer1 = <<Buffer/binary, NewData/binary>>, + {NewMessages, Buffer2} = parse_messages(Buffer1), + syslogd_loop(LSock, Sock, Messages ++ NewMessages, Buffer2); + {get_messages, From} -> + ct:pal( + "Fake syslogd: sending messages to ~p:~n~p", + [From, Messages]), + From ! {syslogd_messages, Messages}, + syslogd_loop(LSock, Sock, Messages, Buffer); + clear_messages -> + ct:pal("Fake syslogd: clearing buffer", []), + syslogd_loop(LSock, Sock, [], Buffer); + {tcp_closed, Sock} -> + ct:pal("Fake syslogd: socket closed, restarting loop", []), + syslogd_start_loop(LSock); + stop -> + ct:pal("Fake syslogd: exiting", []), + _ = gen_tcp:close(Sock), + _ = gen_tcp:close(LSock); + Other -> + ct:pal("Fake syslogd: unhandled message: ~p", [Other]), + syslogd_loop(LSock, Sock, Messages, Buffer) + end + catch + C:R:S -> + ct:pal("~p ~p ~p", [C, R, S]), + throw(R) + end. + +parse_messages(Buffer) -> + parse_messages(Buffer, []). + +parse_messages(Buffer, Messages) -> + ReOpts = [{capture, all_but_first, binary}], + case re:run(Buffer, "^([0-9]+) (.*)", ReOpts) of + {match, [Length0, Buffer1]} -> + Length = list_to_integer(binary_to_list(Length0)), + case Buffer1 of + <<Message:Length/binary, Buffer2/binary>> -> + parse_messages( + Buffer2, [<<Message/binary, $\n>> | Messages]); + _ -> + {lists:reverse(Messages), Buffer} + end; + _ -> + {lists:reverse(Messages), Buffer} + end. |