1%% This Source Code Form is subject to the terms of the Mozilla Public
2%% License, v. 2.0. If a copy of the MPL was not distributed with this
3%% file, You can obtain one at https://mozilla.org/MPL/2.0/.
4%%
5%% Copyright (c) 2019-2021 VMware, Inc. or its affiliates.  All rights reserved.
6%%
7
8-module(rabbit_prelaunch_early_logging).
9
10-include_lib("kernel/include/logger.hrl").
11
12-include_lib("rabbit_common/include/logging.hrl").
13
14-export([setup_early_logging/1,
15         default_formatter/1,
16         default_console_formatter/1,
17         default_file_formatter/1,
18         default_journald_formatter/1,
19         default_syslog_formatter/1,
20         enable_quick_dbg/1,
21         use_colored_logging/0,
22         use_colored_logging/1,
23         translate_formatter_conf/2,
24         translate_journald_fields_conf/2]).
25-export([filter_log_event/2]).
26
27-ifdef(TEST).
28-export([levels/0,
29         determine_prefix/1]).
30-endif.
31
32-define(CONFIGURED_KEY, {?MODULE, configured}).
33
34setup_early_logging(#{log_levels := undefined} = Context) ->
35    setup_early_logging(Context#{log_levels => get_default_log_level()});
36setup_early_logging(Context) ->
37    case is_configured() of
38        true  -> ok;
39        false -> do_setup_early_logging(Context)
40    end.
41
42get_default_log_level() ->
43    #{"prelaunch" => notice}.
44
45do_setup_early_logging(#{log_levels := LogLevels} = Context) ->
46    add_rmqlog_filter(LogLevels),
47    ok = logger:update_handler_config(
48           default, main_handler_config(Context)).
49
50is_configured() ->
51    persistent_term:get(?CONFIGURED_KEY, false).
52
53add_rmqlog_filter(LogLevels) ->
54    add_erlang_specific_filters(LogLevels),
55    FilterConfig0 = lists:foldl(
56                      fun
57                          ({_, V}, FC) when is_boolean(V) -> FC;
58                          ({K, V}, FC) when is_atom(K) -> FC#{K => V};
59                          ({K, V}, FC) -> FC#{list_to_atom(K) => V}
60                      end, #{}, maps:to_list(LogLevels)),
61    FilterConfig1 = case maps:is_key(global, FilterConfig0) of
62                        true  -> FilterConfig0;
63                        false -> FilterConfig0#{global => ?DEFAULT_LOG_LEVEL}
64                    end,
65    ok = logger:add_handler_filter(
66           default, ?FILTER_NAME, {fun filter_log_event/2, FilterConfig1}),
67    ok = logger:set_primary_config(level, all),
68    ok = persistent_term:put(?CONFIGURED_KEY, true).
69
70add_erlang_specific_filters(_) ->
71    _ = logger:add_handler_filter(
72          default, progress_reports, {fun logger_filters:progress/2, stop}),
73    ok.
74
75filter_log_event(
76  #{meta := #{domain := ?RMQLOG_DOMAIN_GLOBAL}} = LogEvent,
77  FilterConfig) ->
78    MinLevel = get_min_level(global, FilterConfig),
79    do_filter_log_event(LogEvent, MinLevel);
80filter_log_event(
81  #{meta := #{domain := [?RMQLOG_SUPER_DOMAIN_NAME, CatName | _]}} = LogEvent,
82  FilterConfig) ->
83    MinLevel = get_min_level(CatName, FilterConfig),
84    do_filter_log_event(LogEvent, MinLevel);
85filter_log_event(
86  #{meta := #{domain := [CatName | _]}} = LogEvent,
87  FilterConfig) ->
88    MinLevel = get_min_level(CatName, FilterConfig),
89    do_filter_log_event(LogEvent, MinLevel);
90filter_log_event(LogEvent, FilterConfig) ->
91    MinLevel = get_min_level(global, FilterConfig),
92    do_filter_log_event(LogEvent, MinLevel).
93
94get_min_level(global, FilterConfig) ->
95    maps:get(global, FilterConfig, none);
96get_min_level(CatName, FilterConfig) ->
97    case maps:is_key(CatName, FilterConfig) of
98        true  -> maps:get(CatName, FilterConfig);
99        false -> get_min_level(global, FilterConfig)
100    end.
101
102do_filter_log_event(_, none) ->
103    stop;
104do_filter_log_event(#{level := Level} = LogEvent, MinLevel) ->
105    case logger:compare_levels(Level, MinLevel) of
106        lt -> stop;
107        _  -> LogEvent
108    end.
109
110main_handler_config(Context) ->
111    #{filter_default => log,
112      formatter => default_formatter(Context)}.
113
114default_formatter(#{log_levels := #{json := true}}) ->
115    {rabbit_logger_json_fmt, #{}};
116default_formatter(Context) ->
117    Color = use_colored_logging(Context),
118    {rabbit_logger_text_fmt, #{use_colors => Color}}.
119
120default_console_formatter(Context) ->
121    default_formatter(Context).
122
123default_file_formatter(Context) ->
124    default_formatter(Context#{output_supports_colors => false}).
125
126default_journald_formatter(_Context) ->
127    {rabbit_logger_text_fmt, #{prefix_format => [],
128                               use_colors => false}}.
129
130default_syslog_formatter(Context) ->
131    {Module, Config} = default_file_formatter(Context),
132    case Module of
133        rabbit_logger_text_fmt -> {Module, Config#{prefix_format => []}};
134        rabbit_logger_json_fmt -> {Module, Config}
135    end.
136
137use_colored_logging() ->
138    use_colored_logging(rabbit_prelaunch:get_context()).
139
140use_colored_logging(#{log_levels := #{color := true},
141                      output_supports_colors := true}) ->
142    true;
143use_colored_logging(_) ->
144    false.
145
146enable_quick_dbg(#{dbg_output := Output, dbg_mods := Mods}) ->
147    case Output of
148        stdout -> {ok, _} = dbg:tracer(),
149                  ok;
150        _      -> {ok, _} = dbg:tracer(port, dbg:trace_port(file, Output)),
151                  ok
152    end,
153    {ok, _} = dbg:p(all, c),
154    lists:foreach(fun(M) -> {ok, _} = dbg:tp(M, cx) end, Mods).
155
156%% -------------------------------------------------------------------
157%% Internal function used by our Cuttlefish schema.
158%% -------------------------------------------------------------------
159
160-spec translate_formatter_conf(string(), cuttlefish_conf:conf()) ->
161    {rabbit_logger_text_fmt, formatter_plaintext_conf()} |
162    {rabbit_logger_json_fmt, formatter_json_conf()}.
163%% @doc
164%% Called from the Cuttlefish schema to derive the actual formatter
165%% configuration from several Cuttlefish variables.
166
167translate_formatter_conf(Var, Conf) when is_list(Var) ->
168    try
169        %% Part of the formatter configuration is common to all the
170        %% formatters, the rest is formatter-specific.
171        GenericConfig = translate_generic_conf(Var, Conf),
172        case cuttlefish:conf_get(Var, Conf) of
173            plaintext ->
174                translate_plaintext_formatter_conf(Var, Conf, GenericConfig);
175            json ->
176                translate_json_formatter_conf(Var, Conf, GenericConfig)
177        end
178    catch
179        Class:Reason:Stacktrace ->
180            ?LOG_ERROR(
181               rabbit_prelaunch_errors:format_exception(
182                 Class, Reason, Stacktrace),
183               #{domain => ?RMQLOG_DOMAIN_PRELAUNCH}),
184            throw({configuration_translation_failure, Reason})
185    end.
186
187-type time_format_string_arg() :: year | month | day |
188                                  hour | minute | second |
189                                  {second_fractional, non_neg_integer()}.
190-type time_format() :: {rfc3339, char(), string() | integer()} |
191                       {epoch, secs | usecs, binary | int} |
192                       {local | universal,
193                        string(),
194                        [time_format_string_arg()]}.
195-type level_format() :: lc | uc | lc3 | uc3 | lc4 | uc4.
196-type formatter_generic_conf() :: #{time_format := time_format(),
197                                    level_format := level_format(),
198                                    single_line := boolean()}.
199
200-spec translate_generic_conf(string(), cuttlefish_conf:conf()) ->
201    formatter_generic_conf().
202%% @doc
203%% Handles variables common to all formatters.
204
205translate_generic_conf(Var, Conf) ->
206    %% log.*.formatter.time_format
207    %% It accepts either a "named pattern" like `rfc3339_T' or a custom
208    %% pattern.
209    Formatter = cuttlefish:conf_get(Var, Conf),
210    TimeFormat = case cuttlefish:conf_get(Var ++ ".time_format", Conf) of
211                     rfc3339_T ->
212                         {rfc3339, $T, ""};
213                     rfc3339_space ->
214                         {rfc3339, $\s, ""};
215                     epoch_secs when Formatter =:= json ->
216                         {epoch, secs, int};
217                     epoch_usecs when Formatter =:= json ->
218                         {epoch, usecs, int};
219                     epoch_secs ->
220                         {epoch, secs, binary};
221                     epoch_usecs ->
222                         {epoch, usecs, binary};
223                     lager_default ->
224                         {local,
225                          "~4..0b-~2..0b-~2..0b "
226                          "~2..0b:~2..0b:~2..0b.~3..0b",
227                          [year, month, day,
228                           hour, minute, second,
229                           {second_fractional, 3}]}
230                 end,
231
232    %% log.*.formatter.level_format
233    %% It determines basically if the level should be printed in lowercase or
234    %% uppercase, and fully or truncated (to align messages horizontally).
235    LevelFormat = cuttlefish:conf_get(Var ++ ".level_format", Conf),
236
237    %% log.*.formatter.single_line
238    %% It tells if multi-line messages should be kept as-is or reformatted to
239    %% stay on a single line.
240    SingleLine = cuttlefish:conf_get(Var ++ ".single_line", Conf),
241
242    #{time_format => TimeFormat,
243      level_format => LevelFormat,
244      single_line => SingleLine}.
245
246-type line_format() :: [atom() | string()].
247-type color_esc_seqs() :: #{logger:level() => string()}.
248-type formatter_plaintext_conf() :: #{time_format := time_format(),
249                                      level_format := level_format(),
250                                      single_line := boolean(),
251                                      prefix_format := line_format(),
252                                      line_format := line_format(),
253                                      use_colors := boolean(),
254                                      color_esc_seqs := color_esc_seqs()}.
255
256-spec translate_plaintext_formatter_conf(
257        string(), cuttlefish_conf:conf(), formatter_generic_conf()) ->
258    {rabbit_logger_text_fmt, formatter_plaintext_conf()}.
259%% @doc
260%% Handles variables specific to the plaintext formatter.
261
262translate_plaintext_formatter_conf(Var, Conf, GenericConfig) ->
263    %% log.*.formatter.plaintext.format
264    %% This is a variable-based string used to indicate the message format.
265    %% Here, we parse that pattern to make it easier and more efficient for
266    %% the formatter to format the final message.
267    Format0 = cuttlefish:conf_get(Var ++ ".plaintext.format", Conf),
268    Format = prepare_fmt_format(Format0),
269    {PrefixFormat, LineFormat} = determine_prefix(Format),
270
271    %% log.console.use_colors
272    %% log.console.color_esc_seqs
273    %% Those variables indicates if colors should be used and which one. They
274    %% are specific to the console handler.
275    {UseColors, ColorEscSeqs} = translate_colors_conf(Var, Conf),
276
277    Mod = rabbit_logger_text_fmt,
278    Config = GenericConfig#{prefix_format => PrefixFormat,
279                            line_format => LineFormat,
280                            use_colors => UseColors,
281                            color_esc_seqs => ColorEscSeqs},
282    {Mod, Config}.
283
284-spec prepare_fmt_format(string()) -> [atom() | string()].
285%% @doc
286%% Parse the pattern and prepare a list which makes it easy for the formatter
287%% to format the final message.
288%%
289%% The initial pattern will use variables; for example:
290%% `$time [$level] $pid - $msg'
291%%
292%% Once parsed, the pattern will look like:
293%% `[time, " [", level, "] ", pid, " - ", msg]'
294%%
295%% Variables are taken from the log event structure: `msg' and `level' are
296%% taken from the top-level, other variables come from the `meta' map.
297
298prepare_fmt_format(Format) ->
299    prepare_fmt_format(Format, []).
300
301prepare_fmt_format([$$ | Rest], Parsed) ->
302    {match, [Var, Rest1]} = re:run(Rest, "^([a-zA_Z0-9_]+)(.*)",
303                                   [{capture, all_but_first, list}]),
304    Var1 = list_to_atom(Var),
305    prepare_fmt_format(Rest1, [Var1 | Parsed]);
306prepare_fmt_format(Rest, Parsed) when Rest =/= "" ->
307    %% We made sure in the guard expression that `Rest' contains at least
308    %% onecharacter. The following regex "eats" at least that character. This
309    %% avoids an infinite loop which would happen if the returned `String' was
310    %% empty and `Rest1' would be the same as `Rest'.
311    {match, [String, Rest1]} = re:run(Rest, "^(.[^$]*)(.*)",
312                                      [{capture, all_but_first, list}]),
313    prepare_fmt_format(Rest1, [String | Parsed]);
314prepare_fmt_format("", Parsed) ->
315    lists:reverse(Parsed).
316
317determine_prefix(Format) ->
318    %% Based on where the `msg' variable is, we determine the prefix of the
319    %% message. This is later used by the formatter to repeat the prefix for
320    %% each line making a multi-line message.
321    %%
322    %% If `msg' is not logged at all, we consider the line has no prefix.
323    {PrefixFormat0, LineFormat0} =
324    lists:foldl(
325      fun
326          (msg, {PF, LF})       -> {PF, LF ++ [msg]};
327          (Elem, {PF, [] = LF}) -> {PF ++ [Elem], LF};
328          (Elem, {PF, LF})      -> {PF, LF ++ [Elem]}
329      end, {[], []}, Format),
330    case {PrefixFormat0, LineFormat0} of
331        {_, []} -> {[], PrefixFormat0};
332        _       -> {PrefixFormat0, LineFormat0}
333    end.
334
335-spec translate_colors_conf(string(), cuttlefish_conf:conf()) ->
336    {boolean(), map()}.
337%% @doc
338%% Computes the color configuration.
339%%
340%% The function uses the following two variables:
341%% `log.console.use_colors'
342%% `log.console.color_esc_seqs'
343%%
344%% It does not verify what escape sequences are actually configured. It is
345%% entirely possible to play with the cursor position or other control
346%% characters.
347%%
348%% This is only valid for the console output.
349
350translate_colors_conf("log.console.formatter", Conf) ->
351    {
352     cuttlefish:conf_get("log.console.use_colors", Conf),
353     lists:foldl(
354       fun(Lvl, Acc) ->
355               LvlS = atom_to_list(Lvl),
356               Key = "log.console.color_esc_seqs." ++ LvlS,
357               RawVal = cuttlefish:conf_get(Key, Conf),
358               %% The ESC character will be escaped if the user entered the
359               %% string "\033" for instance. We need to convert it back to an
360               %% actual ESC character.
361               Val = re:replace(
362                       RawVal,
363                       "\\\\(e|033)",
364                       "\033",
365                       [global, {return, list}]),
366               Acc#{Lvl => Val}
367       end,
368       #{},
369       levels())
370    };
371translate_colors_conf(_, _) ->
372    {false, #{}}.
373
374-type json_field_map() :: [{atom(), atom()} | {atom() | '$REST', false}].
375-type json_verbosity_map() :: #{logger:level() => non_neg_integer(),
376                                '$REST' => non_neg_integer()}.
377-type formatter_json_conf() :: #{time_format := time_format(),
378                                 level_format := level_format(),
379                                 single_line := boolean(),
380                                 field_map := json_field_map(),
381                                 verbosity_map := json_verbosity_map()}.
382
383-spec translate_json_formatter_conf(
384        string(), cuttlefish_conf:conf(), map()) ->
385    {rabbit_logger_json_fmt, formatter_json_conf()}.
386%% @doc
387%% Handles variables specific to the JSON formatter.
388
389translate_json_formatter_conf(Var, Conf, GenericConfig) ->
390    %% log.*.formatter.json.field_map
391    %% It indicates several things:
392    %%   - the order of fields; non-mentionned fields go unordered at the end
393    %%     of the JSON object
394    %%   - if fields should be renamed
395    %%   - if fields should be removed from the final object
396    RawFieldMapping = cuttlefish:conf_get(Var ++ ".json.field_map", Conf),
397    FieldMapping = parse_json_field_mapping(RawFieldMapping),
398
399    %% log.*.formatter.json.verbosity_map
400    %% It indicates if a `verbosity' field should be added and how its value
401    %% should be derived from `level'.
402    RawVerbMapping = cuttlefish:conf_get(
403                       Var ++ ".json.verbosity_map", Conf),
404    VerbMapping = parse_json_verbosity_mapping(RawVerbMapping),
405
406    Mod = rabbit_logger_json_fmt,
407    Config = GenericConfig#{field_map => FieldMapping,
408                            verbosity_map => VerbMapping},
409    {Mod, Config}.
410
411-spec parse_json_field_mapping(string()) -> json_field_map().
412%% @doc
413%% Parses the JSON formatter field_map pattern.
414%%
415%% The pattern is of the form: `time:ts level msg *:-'.
416%%
417%% `time:ts' means the `time' field should be renamed to `ts'.
418%%
419%% `level' means that field should be kept as-is.
420%%
421%% `gl:-' means the `gl' field should be dropped.
422%%
423%% `*:-' means all non-mentionned fields should be dropped.
424%%
425%% The order of fields in the pattern is important: it tells the order of
426%% fields in the final JSON object.
427
428parse_json_field_mapping(RawMapping) ->
429    parse_json_field_mapping(string:split(RawMapping, " ", all), []).
430
431parse_json_field_mapping([Entry | Rest], Mapping) ->
432    Mapping1 = case string:split(Entry, ":", leading) of
433                   ["*", "-"] ->
434                       [{'$REST', false} | Mapping];
435                   [OldS, "-"] ->
436                       Old = list_to_atom(OldS),
437                       [{Old, false} | Mapping];
438                   ["*", _] ->
439                       throw({bad_json_mapping, Entry});
440                   [OldS, NewS] ->
441                       Old = list_to_atom(OldS),
442                       New = list_to_atom(NewS),
443                       [{Old, New} | Mapping];
444                   [KeepS] ->
445                       Keep = list_to_atom(KeepS),
446                       [{Keep, Keep} | Mapping]
447               end,
448    parse_json_field_mapping(Rest, Mapping1);
449parse_json_field_mapping([], Mapping) ->
450    %% We parsed everything. Now we want to organize fields a bit:
451    %%   - All `{atom(), atom()}' (kept or renamed fields) go at the
452    %%     beginning, preserving their order
453    %%   - All `{_, false}' (removed fields) go at the end
454    {Renames0, Removes0} = lists:partition(
455                             fun
456                                 ({_, false}) -> false;
457                                 (_)          -> true
458                             end,
459                             Mapping),
460    Renames = lists:reverse(Renames0),
461    %% If all non-mentionned fields are to be removed, only the `{$REST,
462    %% false}' entry is useful.
463    Removes = case lists:member({'$REST', false}, Removes0) of
464                  true  -> [{'$REST', false}];
465                  false -> Removes0
466              end,
467    Renames ++ Removes.
468
469-spec parse_json_verbosity_mapping(string()) -> json_verbosity_map().
470%% @doc
471%% Parses the verbosity_map pattern.
472%%
473%% The pattern is of the form: `debug:2 info:1 *:0'.
474%%
475%% `debug:2' means that the verbosity of the debug level is 2.
476%%
477%% `*:0' means that the verbosity of all non-mentionned levels is 0.
478
479parse_json_verbosity_mapping("") ->
480    #{};
481parse_json_verbosity_mapping(RawMapping) ->
482    parse_json_verbosity_mapping(string:split(RawMapping, " ", all), #{}).
483
484parse_json_verbosity_mapping([Entry | Rest], Mapping) ->
485    Mapping1 = case string:split(Entry, ":", leading) of
486                   ["*", VerbS] ->
487                       Verb = list_to_integer(VerbS),
488                       Mapping#{'$REST' => Verb};
489                   [LvlS, VerbS] ->
490                       Lvl = list_to_atom(LvlS),
491                       Verb = list_to_integer(VerbS),
492                       Mapping#{Lvl => Verb}
493               end,
494    parse_json_verbosity_mapping(Rest, Mapping1);
495parse_json_verbosity_mapping([], #{'$REST' := Default} = Mapping) ->
496    DefaultMapping = lists:foldl(
497                       fun(Lvl, Acc) -> Acc#{Lvl => Default} end,
498                       #{}, levels()),
499    maps:merge(
500      DefaultMapping,
501      maps:remove('$REST', Mapping));
502parse_json_verbosity_mapping([], Mapping) ->
503    Mapping.
504
505-spec translate_journald_fields_conf(string(), cuttlefish_conf:conf()) ->
506    proplists:proplist().
507%% @doc
508%% Called from the Cuttlefish schema to create the actual journald handler
509%% configuration.
510
511translate_journald_fields_conf(Var, Conf) when is_list(Var) ->
512    try
513        RawFieldMapping = cuttlefish:conf_get(Var, Conf),
514        parse_journald_field_mapping(RawFieldMapping)
515    catch
516        Class:Reason:Stacktrace ->
517            ?LOG_ERROR(
518               rabbit_prelaunch_errors:format_exception(
519                 Class, Reason, Stacktrace),
520               #{domain => ?RMQLOG_DOMAIN_PRELAUNCH}),
521            throw({configuration_translation_failure, Reason})
522    end.
523
524-spec parse_journald_field_mapping(string()) ->
525    [atom() | {atom(), atom()}].
526%% @doc
527%% Parses the journald fields pattern.
528%%
529%% The pattern is of the form: `SYSLOG_IDENTIFIER="rabbitmq-server" pid
530%% CODE_FILE=file'.
531%%
532%% `SYSLOG_IDENTIFIER="rabbitmq"' means the `SYSLOG_IDENTIFIER' field should
533%% be set to the string `rabbitmq-server'.
534%%
535%% `pid' means that field should be kept as-is.
536%%
537%% `CODE_FILE=file' means the `CODE_FILE' field should be set to the value of
538%% the `pid' field.
539
540parse_journald_field_mapping(RawMapping) ->
541    parse_journald_field_mapping(string:split(RawMapping, " ", all), []).
542
543parse_journald_field_mapping([Entry | Rest], Mapping) ->
544    Mapping1 = case string:split(Entry, "=", leading) of
545                   [[$_ | _], _] ->
546                       throw({bad_journald_mapping,
547                              leading_underscore_forbidden,
548                              Entry});
549                   [Name, Value] ->
550                       case re:run(Name, "^[A-Z0-9_]+$", [{capture, none}]) of
551                           match ->
552                               ReOpts = [{capture, all_but_first, list}],
553                               case re:run(Value, "^\"(.+)\"$", ReOpts) of
554                                   {match, [Data]} ->
555                                       [{Name, Data} | Mapping];
556                                   nomatch ->
557                                       Field = list_to_atom(Value),
558                                       [{Name, Field} | Mapping]
559                               end;
560                           nomatch ->
561                               throw({bad_journald_mapping,
562                                      name_with_invalid_characters,
563                                      Entry})
564                       end;
565                   [FieldS] ->
566                       Field = list_to_atom(FieldS),
567                       [Field | Mapping]
568               end,
569    parse_journald_field_mapping(Rest, Mapping1);
570parse_journald_field_mapping([], Mapping) ->
571    lists:reverse(Mapping).
572
573levels() ->
574    [debug, info, notice, warning, error, critical, alert, emergency].
575