diff options
| -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. |