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