From 6d0160b49796be6ffcfa7049bb924f2b130a59a6 Mon Sep 17 00:00:00 2001 From: Thomas Letan Date: Mon, 13 Jan 2025 07:19:28 +0100 Subject: [PATCH] Logging: Introduce `advertise-levels` for displaying event level MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit We propose to add a new opt-in feature for logging which makes explicit the level of events, instead of forcing consumer to know about them. - For the `one-per-line` and `netstring` format, it adds the field `level` along with the existing `hostname`, `time_stamp`, `section` and `event`. - For the `pp-short` format, it changes the string prepends to the event to include the level in addition to the timestamp. - For the `pp_rfc5424` format, it adds the priority value at the very beginning of the log line—reusing the suggested severity number. We believe this new feature will provide more flexibility to logs consumers. For instance, with this, you can easily setup an alert in your system for any `Error` or `Fatal` log emitted by your service. This is not something possible to do today without the developer to adopt a strict naming convention or similar workaround. It can also simplify debugging by allowing to `grep` errors and warnings. This is implemented by adding a new query parameter `advertise-levels` for defining sinks, defaulting to `false` (the current behavior if it is not set explicitly). This means that it is an opt-in change, that users need to enabled themselves. Here are examples of the new format with a project I am currently working on. For `pp-short`: Jan 11 17:42:00.374 INFO │ worker started Jan 11 17:42:00.375 NOTICE │ Tx queue is ready Jan 11 17:42:00.449 NOTICE │ Floodgate is ready to spam network 0x1f47b Jan 11 17:42:00.449 NOTICE │ (base_fee_per_gas: 0.000000001) Jan 11 17:42:00.529 INFO │ Received blueprint 16790339 Jan 11 17:42:00.700 INFO │ Injecting 1 transactions Jan 11 17:42:00.860 INFO │ Received blueprint 16790340 For the JSON constructed for `one-per-line` and `netstring` (pretty-printed for readability): { "fd-sink-item.v0": { "level": "notice", "hostname": "vanellope", "time_stamp": 1736610520.317238, "section": ["floodgate"], "event": { "is_ready.v0": { "chain_id": "0x1f47b", "base_fee_per_gas":"1000000000" } } } } Finally, for the `pp_rfc5424` log line: <005> 2025-01-12T14:22:43.632-00:00 [evm_node.dev.shutting_down_tx_pool] Stopping the tx-pool --- CHANGES.rst | 4 + docs/user/logging.rst | 3 + src/lib_base/internal_event_config.ml | 5 +- src/lib_base/internal_event_config.mli | 1 + src/lib_base/unix/file_descriptor_sink.ml | 133 ++++++++++++++++++---- src/lib_base/unix/internal_event_unix.ml | 15 ++- src/lib_base/unix/internal_event_unix.mli | 4 +- src/lib_base/unix/logs_simple_config.ml | 25 ++-- src/lib_base/unix/logs_simple_config.mli | 2 + src/lib_stdlib/pretty_printing.ml | 4 + src/lib_stdlib/pretty_printing.mli | 2 + 11 files changed, 162 insertions(+), 36 deletions(-) diff --git a/CHANGES.rst b/CHANGES.rst index 2275993d71f8..1eb252ddc96f 100644 --- a/CHANGES.rst +++ b/CHANGES.rst @@ -27,6 +27,10 @@ General - Logging output on TTYs now adapt to the terminal width. (MR :gl:`!12348`) +- Logging output can now advertise the level associated to each events, by + enabling the ``advertise-levels`` option in the file-descriptor sink URI. (MR + :gl:`!16190`) + Node ---- diff --git a/docs/user/logging.rst b/docs/user/logging.rst index 6455ad0f8511..5a4274d7d3cb 100644 --- a/docs/user/logging.rst +++ b/docs/user/logging.rst @@ -98,6 +98,9 @@ Common options: - ``color=true`` enables logs coloring. It only works on ttys, in conjunction with ``format=pp-short``. +- ``advertise-levels=true`` enables the advertisement of the log-level of each + events outputted in the sink. + Options available only for the ``file-descriptor-path://`` case: - ``with-pid=`` when ``true`` adds the current process-id to the diff --git a/src/lib_base/internal_event_config.ml b/src/lib_base/internal_event_config.ml index 083a5a0b8168..1c919df00ce4 100644 --- a/src/lib_base/internal_event_config.ml +++ b/src/lib_base/internal_event_config.ml @@ -31,7 +31,7 @@ let make_section_prefix ~pattern level = Format.sprintf "%s:%s" pattern (Internal_event.Level.opt_to_string level) let make_config_uri ?level ?daily_logs ?create_dirs ?format ?chmod ?with_pid - ?colors ?fresh ?(section_prefixes = []) kind = + ?colors ?fresh ?(section_prefixes = []) ?advertise_levels kind = let scheme, path = match kind with | `Stdout -> ("file-descriptor-stdout", None) @@ -59,7 +59,8 @@ let make_config_uri ?level ?daily_logs ?create_dirs ?format ?chmod ?with_pid |> add "daily-logs" string_of_int daily_logs |> add "fresh" bool fresh |> add "colors" bool colors |> add "chmod" string_of_int chmod - |> add "with_pid" bool with_pid) + |> add "with_pid" bool with_pid + |> add "advertise-levels" bool advertise_levels) () let short_stdout_uri = make_config_uri ~format:"pp-short" ~level:Notice `Stdout diff --git a/src/lib_base/internal_event_config.mli b/src/lib_base/internal_event_config.mli index 874cf37c17bf..8330b5f9e3f2 100644 --- a/src/lib_base/internal_event_config.mli +++ b/src/lib_base/internal_event_config.mli @@ -54,6 +54,7 @@ val make_config_uri : ?colors:bool -> ?fresh:bool -> ?section_prefixes:(string * Internal_event.level option) list -> + ?advertise_levels:bool -> [`Stdout | `Stderr | `Path of string | `Null | `Syslog of string] -> Uri.t diff --git a/src/lib_base/unix/file_descriptor_sink.ml b/src/lib_base/unix/file_descriptor_sink.ml index e5dbc62274e7..532eb3117f2c 100644 --- a/src/lib_base/unix/file_descriptor_sink.ml +++ b/src/lib_base/unix/file_descriptor_sink.ml @@ -52,6 +52,7 @@ type t = { [ `Level_at_least of Internal_event.Level.t | `Per_section_prefix of (Internal_event.Section.t * Internal_event.Level.t option) list ]; + advertise_levels : bool; } let hostname = @@ -99,7 +100,7 @@ module Color = struct end end -let wrapped_encoding event_encoding = +let wrapped_encoding ~advertise_levels event_encoding = let open Data_encoding in let ptime_encoding = conv @@ -112,10 +113,17 @@ let wrapped_encoding event_encoding = in let v0 = conv - (fun {time_stamp; section; event} -> - (hostname, time_stamp, section, event)) - (fun (_, time_stamp, section, event) -> {time_stamp; section; event}) - (obj4 + (fun (level, {time_stamp; section; event}) -> + ( (if advertise_levels then Some level else None), + hostname, + time_stamp, + section, + event )) + (fun (level, _, time_stamp, section, event) -> + ( Option.value ~default:Internal_event.Debug level, + {time_stamp; section; event} )) + (obj5 + (opt "level" Internal_event.Level.encoding) (req "hostname" string) (req "time_stamp" ptime_encoding) (req "section" Internal_event.Section.encoding) @@ -123,10 +131,25 @@ let wrapped_encoding event_encoding = in With_version.(encoding ~name:"fd-sink-item" (first_version v0)) -let make_with_pp_rfc5424 pp wrapped_event name = +let make_with_pp_rfc5424 ~advertise_levels ~level pp wrapped_event name = (* See https://tools.ietf.org/html/rfc5424#section-6 *) + let priority_str = + if advertise_levels then + (* See https://datatracker.ietf.org/doc/html/rfc5424#section-6.2.1 *) + Format.sprintf + "<00%d> " + (match level with + | Internal_event.Debug -> 7 + | Info -> 6 + | Notice -> 5 + | Warning -> 4 + | Error -> 3 + | Fatal -> 0) + else "" + in Format.asprintf - "%a [%a.%s] %a\n" + "%s%a [%a.%s] %a\n" + priority_str (Ptime.pp_rfc3339 ~frac_s:3 ()) wrapped_event.time_stamp Internal_event.Section.pp @@ -137,7 +160,15 @@ let make_with_pp_rfc5424 pp wrapped_event name = type color_setting = Enabled of string option | Disabled -let make_with_pp_short ?cols ~color pp wrapped_event = +let make_with_pp_short ?cols ~color ~advertise_levels ~level pp wrapped_event = + let string_of_level = function + | Internal_event.Fatal -> "FATAL" + | Debug -> "DEBUG" + | Info -> "INFO" + | Notice -> "NOTICE" + | Warning -> "WARN" + | Error -> "ERROR" + in let pp_date fmt time = let time = Ptime.to_float_s time in let tm = Unix.localtime time in @@ -158,18 +189,31 @@ let make_with_pp_short ?cols ~color pp wrapped_event = | _ -> assert false (* `tm` is built locally, so it should contain invalid month code *) in + let level_string = + if advertise_levels then + Format.asprintf + "%a" + Pretty_printing.(pp_right_aligned 7) (* NOTICE + 1 space *) + (string_of_level level) + else "" + in let ms = mod_float (time *. 1000.) 1000. in Format.fprintf fmt - "%s %02d %02d:%02d:%02d.%03.0f" + "%s %02d %02d:%02d:%02d.%03.0f%s" month_string tm.Unix.tm_mday tm.Unix.tm_hour tm.Unix.tm_min tm.Unix.tm_sec ms + level_string + in + let timestamp = + if advertise_levels then + Format.asprintf "%a │ " pp_date wrapped_event.time_stamp + else Format.asprintf "%a: " pp_date wrapped_event.time_stamp in - let timestamp = Format.asprintf "%a: " pp_date wrapped_event.time_stamp in let timestamp_size = String.length timestamp in let line_size = Option.map (fun cols -> max 1 (cols - timestamp_size)) cols in let lines = @@ -246,26 +290,54 @@ let%expect_test _ = section = Internal_event.Section.make_sanitized ["my"; "section"]; } in - print_endline (make_with_pp_short ~color:Disabled pp_string ev) ; + print_endline + (make_with_pp_short + ~color:Disabled + ~advertise_levels:false + ~level:Debug + pp_string + ev) ; [%expect {| Apr 27 08:29:09.000: toto |}] ; let ev_line_cut = {ev with event = "totototototototototototototototo before_cut after_cut"} in print_endline (String.escaped - @@ make_with_pp_short ~color:(Enabled None) pp_string ev_line_cut) ; + @@ make_with_pp_short + ~color:(Enabled None) + ~advertise_levels:false + ~level:Debug + pp_string + ev_line_cut) ; [%expect {| \027[1mApr 27 08:29:09.000: \027[0mtotototototototototototototototo before_cut\nApr 27 08:29:09.000: after_cut\n|}] ; print_endline - (String.escaped @@ make_with_pp_short ~color:(Enabled None) pp_string ev) ; + (String.escaped + @@ make_with_pp_short + ~color:(Enabled None) + ~advertise_levels:false + ~level:Debug + pp_string + ev) ; [%expect {| \027[1mApr 27 08:29:09.000: \027[0mtoto\n|}] ; print_endline (String.escaped - @@ make_with_pp_short ~color:(Enabled (Some Color.FG.red)) pp_string ev) ; + @@ make_with_pp_short + ~color:(Enabled (Some Color.FG.red)) + ~advertise_levels:false + ~level:Debug + pp_string + ev) ; [%expect {| \027[1mApr 27 08:29:09.000: \027[0m\027[31mtoto\027[0m\n|}] ; let ev = {ev with time_stamp = make_timestamp ts} in - print_endline (make_with_pp_rfc5424 pp_string ev "my-event") ; + print_endline + (make_with_pp_rfc5424 + ~advertise_levels:false + ~level:Debug + pp_string + ev + "my-event") ; [%expect {| 2023-04-27T08:29:09.777-00:00 [my.section.my-event] toto |}] ; () @@ -424,6 +496,12 @@ end) : Internal_event.SINK with type t = t = struct return (`Per_section_prefix sections) with Failure s -> fail_parsing uri "%s" s) in + let* advertise_levels = + match Uri.get_query_param uri "advertise-levels" with + | Some "false" | None -> return false + | Some "true" -> return true + | Some other -> fail_parsing uri "Expected bool, got %S" other + in let* format = match Uri.get_query_param uri "format" with | Some "netstring" -> return `Netstring @@ -526,7 +604,7 @@ end) : Internal_event.SINK with type t = t = struct | `Stdout -> return (Static Lwt_unix.stdout) | `Stderr -> return (Static Lwt_unix.stderr) in - let t = {output; filter; format; colors} in + let t = {output; filter; format; colors; advertise_levels} in return t let write_mutex = Lwt_mutex.create () @@ -661,7 +739,7 @@ end) : Internal_event.SINK with type t = t = struct if is_a_tty then return (Terminal.Size.get_columns ()) else return_none | Syslog _ | Rotating _ -> return_none - let handle (type a) {output; format; colors; _} m + let handle (type a) {output; format; colors; advertise_levels; _} m ?(section = Internal_event.Section.empty) (event : a) = let open Lwt_result_syntax in let module M = (val m : Internal_event.EVENT_DEFINITION with type t = a) in @@ -672,12 +750,18 @@ end) : Internal_event.SINK with type t = t = struct else let json () = Data_encoding.Json.construct - (wrapped_encoding M.encoding) - wrapped_event + (wrapped_encoding ~advertise_levels M.encoding) + (M.level, wrapped_event) in match format with | `Pp_RFC5424 -> - Lwt.return @@ make_with_pp_rfc5424 M.pp wrapped_event M.name + Lwt.return + @@ make_with_pp_rfc5424 + ~advertise_levels + ~level:M.level + M.pp + wrapped_event + M.name | `Pp_short -> let*! color = if colors then @@ -690,7 +774,14 @@ end) : Internal_event.SINK with type t = t = struct else Lwt.return Disabled in let*! cols = output_columns output in - Lwt.return @@ make_with_pp_short ?cols ~color M.pp wrapped_event + Lwt.return + @@ make_with_pp_short + ?cols + ~color + ~advertise_levels + ~level:M.level + M.pp + wrapped_event | `One_per_line -> Lwt.return @@ Ezjsonm.value_to_string ~minify:true (json ()) ^ "\n" | `Netstring -> diff --git a/src/lib_base/unix/internal_event_unix.ml b/src/lib_base/unix/internal_event_unix.ml index ed11ca7e06bd..e34b578d80c3 100644 --- a/src/lib_base/unix/internal_event_unix.ml +++ b/src/lib_base/unix/internal_event_unix.ml @@ -117,18 +117,19 @@ let close () = open Filename.Infix -let default_daily_logs_at ~daily_logs_path ~section_prefixes = +let default_daily_logs_at ~daily_logs_path ~section_prefixes ~advertise_levels = Internal_event_config.make_config_uri ~create_dirs:true ~daily_logs:7 ~level:Info ~format:"pp-rfc5424" ~section_prefixes + ~advertise_levels (`Path (daily_logs_path // "daily.log")) let make_default_internal_events ~rules ~verbosity ~colors ~(log_output : Logs_simple_config.Output.t) ~daily_logs_path - ~daily_logs_section_prefixes = + ~daily_logs_section_prefixes ~advertise_levels = (* By default the node has two logs output: - on the configured [log_output] using the configured [verbosity] and a short pretty printing @@ -160,6 +161,7 @@ let make_default_internal_events ~rules ~verbosity ~colors ~section_prefixes ~colors ~format:"pp-short" + ~advertise_levels kind in let sinks = [user_events] in @@ -170,6 +172,7 @@ let make_default_internal_events ~rules ~verbosity ~colors default_daily_logs_at ~section_prefixes:daily_logs_section_prefixes ~daily_logs_path + ~advertise_levels in internal_logs_events :: sinks | None -> sinks @@ -186,6 +189,7 @@ let make_with_defaults ?verbosity ?enable_default_daily_logs_at ~log_output:log_cfg.output ~daily_logs_path:enable_default_daily_logs_at ~daily_logs_section_prefixes + ~advertise_levels:log_cfg.advertise_levels let init ?config:(internal_events = make_with_defaults ()) () = let open Lwt_syntax in @@ -193,5 +197,10 @@ let init ?config:(internal_events = make_with_defaults ()) () = return_unit let enable_default_daily_logs_at ~daily_logs_path = - let uri = default_daily_logs_at ~section_prefixes:[] ~daily_logs_path in + let uri = + default_daily_logs_at + ~section_prefixes:[] + ~daily_logs_path + ~advertise_levels:false + in Internal_event.All_sinks.activate uri diff --git a/src/lib_base/unix/internal_event_unix.mli b/src/lib_base/unix/internal_event_unix.mli index 3278e373114d..2dbd2305990a 100644 --- a/src/lib_base/unix/internal_event_unix.mli +++ b/src/lib_base/unix/internal_event_unix.mli @@ -60,7 +60,7 @@ val close : unit -> unit Lwt.t - [enable_default_daily_logs_at] adds daily rotating sink at the given path with the following value: ["file-descriptor-path:////daily.log - ?create-dirs=true&daily-logs=7§ion-prefix=info&format=pp"] + ?create-dirs=true&daily-logs=7§ion-prefix=info&format=pp&advertise-levels=false"] This function handles [TEZOS_LOG] environment variables and rules provided through it. It also optionally accepts [?daily_logs_section_prefixes]. @@ -91,5 +91,5 @@ val init : ?config:Internal_event_config.t -> unit -> unit Lwt.t (** Adds a daily rotating sink at the given path with the following value: ["file-descriptor-path:////daily.log - ?create-dirs=true&daily-logs=7§ion-prefix=info&format=pp"] *) + ?create-dirs=true&daily-logs=7§ion-prefix=info&format=pp&advertise-levels=false"] *) val enable_default_daily_logs_at : daily_logs_path:string -> unit tzresult Lwt.t diff --git a/src/lib_base/unix/logs_simple_config.ml b/src/lib_base/unix/logs_simple_config.ml index 78c1af04151b..ca02a51c1e67 100644 --- a/src/lib_base/unix/logs_simple_config.ml +++ b/src/lib_base/unix/logs_simple_config.ml @@ -109,22 +109,24 @@ type cfg = { default_level : Internal_event.level; rules : string option; colors : bool; + advertise_levels : bool; } let create_cfg ?(output = Output.Stderr) - ?(default_level = Internal_event.Notice) ?(colors = true) ?rules () = - {output; default_level; rules; colors} + ?(default_level = Internal_event.Notice) ?(colors = true) + ?(advertise_levels = false) ?rules () = + {output; default_level; rules; colors; advertise_levels} let default_cfg = create_cfg () let cfg_encoding = let open Data_encoding in conv - (fun {output; default_level; rules; colors} -> - (output, default_level, colors, rules)) - (fun (output, default_level, colors, rules) -> - {output; default_level; rules; colors}) - (obj4 + (fun {output; default_level; rules; colors; advertise_levels} -> + (output, default_level, colors, rules, advertise_levels)) + (fun (output, default_level, colors, rules, advertise_levels) -> + {output; default_level; rules; colors; advertise_levels}) + (obj5 (dft "output" ~description: @@ -152,4 +154,11 @@ let cfg_encoding = sections 'p2p' and all sections starting by 'client' will have \ their messages logged up to the debug level, whereas the rest of \ log sections will be logged up to the notice level." - string)) + string) + (dft + "advertises_level" + ~description: + "When `true`, advertises the level of an event in addition to its \ + contents." + bool + default_cfg.advertise_levels)) diff --git a/src/lib_base/unix/logs_simple_config.mli b/src/lib_base/unix/logs_simple_config.mli index 7be9e32616df..27fd21cd3acd 100644 --- a/src/lib_base/unix/logs_simple_config.mli +++ b/src/lib_base/unix/logs_simple_config.mli @@ -41,6 +41,7 @@ type cfg = { default_level : Internal_event.level; rules : string option; colors : bool; + advertise_levels : bool; } val default_cfg : cfg @@ -49,6 +50,7 @@ val create_cfg : ?output:Output.t -> ?default_level:Internal_event.level -> ?colors:bool -> + ?advertise_levels:bool -> ?rules:string -> unit -> cfg diff --git a/src/lib_stdlib/pretty_printing.ml b/src/lib_stdlib/pretty_printing.ml index 4f4799c36b6b..31223e6b603e 100644 --- a/src/lib_stdlib/pretty_printing.ml +++ b/src/lib_stdlib/pretty_printing.ml @@ -250,3 +250,7 @@ include Semantic_tag let pp_centered width ppf s = let start = (width / 2) + (String.length s / 2) in Format.fprintf ppf "%*s%*s" start s (width - start) "" + +let pp_right_aligned width ppf s = + let left_margin = width - String.length s in + Format.fprintf ppf "%*s%s" left_margin "" s diff --git a/src/lib_stdlib/pretty_printing.mli b/src/lib_stdlib/pretty_printing.mli index 3cf4cdc6d086..09ee915340d5 100644 --- a/src/lib_stdlib/pretty_printing.mli +++ b/src/lib_stdlib/pretty_printing.mli @@ -39,6 +39,8 @@ val add_ansi_marking : Format.formatter -> unit -> unit val pp_centered : int -> Format.formatter -> string -> unit +val pp_right_aligned : int -> Format.formatter -> string -> unit + module Handled_tags : Set.S with type elt = string (** [handles tag] returns [true] if [tag] is handled by this module. -- GitLab