diff --git a/CHANGES.rst b/CHANGES.rst index 2275993d71f84cfb806e030658adfd05096aa76d..1eb252ddc96ff78d4e63331f8181a69b0f83e5c6 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 6455ad0f8511d3c2b151c8cf59456f98e5062b6c..5a4274d7d3cb83c0634976cc8f356740759ab4e6 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 083a5a0b816813bdef4e0cc08201e5cf547c9bb4..1c919df00ce4f35df0334a9d2b6341ff13a18a4c 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 874cf37c17bfa46806ec9f5cb4c86744a5fc630a..8330b5f9e3f202002f581dffcca9d784f848c50b 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 e5dbc62274e7a8d0241861a496755397ce81df0a..532eb3117f2c1f1c37d8bc1168a6b4199ce96e98 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 ed11ca7e06bd6f93f759e0f2bd7468d065ec164a..e34b578d80c3eb88defb9438b0cfe8513401cf7b 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 3278e373114d021b3c4112c0826fd773fbf43d47..2dbd2305990a7e7900abc1229cc6270777dccca7 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 78c1af04151b80cfd8adc283a28164a97d481092..ca02a51c1e67cf1ec9c5907150802ba3b3508bba 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 7be9e32616dff678f68c4d6aae732aba3c25f5c1..27fd21cd3acd6ef5f5176ac28e6ab1d98c7a03dd 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 4f4799c36b6b46ba9e2886b40bbefd82762b71fa..31223e6b603ef2a588b09c06e43a263a162b02c6 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 3cf4cdc6d086e9213d4fca351b89925977708c2b..09ee915340d5f56f18aa4585ff4236b0660a4f51 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.