From f90caf7b304296806f70e7e6ee0930fb23694f1d Mon Sep 17 00:00:00 2001 From: Daniel Widgren Date: Tue, 19 May 2026 20:54:39 +0200 Subject: [PATCH 1/7] feat(jsonlogger): schema presets, structured errors, redaction, term caps Adds the Tier 1 bundle for nova_jsonlogger: * `schema => nova | ecs | otel | gcp | datadog` config preset. - ECS: @timestamp, log.level, message, trace.id, span.id, error.type/message/stack_trace, log.origin.* source location. - OTel: Timestamp (nanosecond), SeverityText + SeverityNumber (1-24), Body, TraceId, SpanId, exception.type/message/stacktrace. - GCP: severity (uppercase), message, logging.googleapis.com/trace, logging.googleapis.com/spanId, sourceLocation object. - Datadog: status, message, dd.trace_id, dd.span_id. - nova (default) preserves current behaviour and now emits RFC 3339 timestamps by default. * Structured `error` object from `crash_report` or `class/reason/stacktrace` meta, with per-schema rendering (error.* under ECS, exception.* under OTel). * Body-path redaction: `#{redact => [[req, headers, authorization], ...]}` walks nested maps and replaces matching paths with `<<"[REDACTED]">>`. * Term-size guards: `max_term_size` and `max_string_length` (default 8192) prevent ~0p formatting and binary expansion from blowing memory; truncated values get a "...[truncated]" marker appended. * Existing `key_mapping`, `format_funs`, `meta_with`, `meta_without`, `new_line[_type]` config keys still work and run after the schema layer so users can override anything the schema rendered. Pipeline: merge_meta -> extract_error -> redact -> apply_schema -> apply_key_mapping -> apply_format_funs -> pre_encode (with caps). Trace correlation: `trace_id` / `span_id` are picked up from process metadata (opentelemetry_nova writes these in pre_request as of upstream PR #10) and rendered under each schema's conventional key names. Behaviour change: meta `time` (microseconds) is now emitted as an RFC 3339 binary by default. Callers that previously formatted `time` via a custom `format_funs` entry should switch to a fun that takes a binary, or set `format_funs => #{time => fun(B) -> B end}` to keep the value untouched. 35 eunit cases (17 new), all passing. xref + dialyzer clean. --- src/nova_jsonlogger.erl | 788 +++++++++++++++++++++++++++++++--------- 1 file changed, 616 insertions(+), 172 deletions(-) diff --git a/src/nova_jsonlogger.erl b/src/nova_jsonlogger.erl index 0f2fe82..a892789 100644 --- a/src/nova_jsonlogger.erl +++ b/src/nova_jsonlogger.erl @@ -1,36 +1,45 @@ %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -%%% This module is copied from https://github.com/kivra/jsonformat +%%% Originally derived from https://github.com/kivra/jsonformat. %%% -%%% What is changed is that we don't use jsx but the json library in Nova -%%% -%%% @doc Custom formatter for the Erlang OTP logger application which -%%% outputs single-line JSON formatted data -%%% @end +%%% Custom formatter for the Erlang OTP logger application which outputs +%%% single-line JSON formatted data. Supports several output schemas +%%% (nova, ecs, otel, gcp, datadog), structured error extraction, redaction +%%% and term-size caps. %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% - -module(nova_jsonlogger). -%%%_* Exports ========================================================== --export([format/2, - system_time_to_iso8601/1, - system_time_to_iso8601_nano/1]). -%%%_* Types ============================================================ +-export([ + format/2, + system_time_to_iso8601/1, + system_time_to_iso8601_nano/1 +]). + +-type schema() :: nova | ecs | otel | gcp | datadog. +-type redact_path() :: [atom() | binary()]. + -type config() :: #{ + schema => schema(), new_line => boolean(), new_line_type => nl | crlf | cr | unix | windows | macos9, key_mapping => #{atom() => atom()}, - format_funs => #{atom() => fun((_) -> _)} + format_funs => #{atom() => fun((_) -> _)}, + meta_with => [atom()], + meta_without => [atom()], + redact => [redact_path()], + max_term_size => non_neg_integer(), + max_string_length => non_neg_integer() }. --export_type([config/0]). +-export_type([config/0, schema/0, redact_path/0]). -%%%_* Macros =========================================================== -%%%_* Options ---------------------------------------------------------- -define(NEW_LINE, false). +-define(DEFAULT_MAX_TERM_SIZE, 8192). +-define(DEFAULT_MAX_STRING_LENGTH, 8192). +-define(REDACTED, <<"[REDACTED]">>). +-define(TRUNCATED_MARKER, <<"...[truncated]">>). -%%%_* Code ============================================================= -%%%_ * API ------------------------------------------------------------- +%%%_* API ============================================================== -spec format(logger:log_event(), config()) -> unicode:chardata(). format( #{msg := {report, #{format := Format, args := Args, label := {error_logger, _}}}} = Map, Config @@ -39,9 +48,12 @@ format( format(Map#{msg := {report, Report}}, Config); format(#{level := Level, msg := {report, Msg}, meta := Meta}, Config) when is_map(Msg) -> Data0 = merge_meta(Msg, Meta#{level => Level}, Config), - Data1 = apply_key_mapping(Data0, Config), - Data2 = apply_format_funs(Data1, Config), - encode(pre_encode(Data2, Config), Config); + Data1 = extract_error(Data0), + Data2 = redact(Data1, Config), + Data3 = apply_schema(Data2, Config), + Data4 = apply_key_mapping(Data3, Config), + Data5 = apply_format_funs(Data4, Config), + encode(pre_encode(Data5, Config), Config); format(Map = #{msg := {report, KeyVal}}, Config) when is_list(KeyVal) -> format(Map#{msg := {report, maps:from_list(KeyVal)}}, Config); format(Map = #{msg := {string, String}}, Config) -> @@ -50,7 +62,6 @@ format(Map = #{msg := {string, String}}, Config) -> format(Map = #{msg := {Format, Terms}}, Config) -> format(Map#{msg := {string, io_lib:format(Format, Terms)}}, Config). -%%% Useful for converting logger:timestamp() to a readable timestamp. -spec system_time_to_iso8601(integer()) -> binary(). system_time_to_iso8601(Epoch) -> system_time_to_iso8601(Epoch, microsecond). @@ -63,26 +74,302 @@ system_time_to_iso8601_nano(Epoch) -> system_time_to_iso8601(Epoch, Unit) -> binary:list_to_bin(calendar:system_time_to_rfc3339(Epoch, [{unit, Unit}, {offset, "Z"}])). -%%%_* Private functions ================================================ +%%%_* Pipeline ========================================================= +merge_meta(Msg, Meta0, Config) -> + Meta1 = meta_without(Meta0, Config), + Meta2 = meta_with(Meta1, Config), + maps:merge(Msg, Meta2). + +%%% Structured error extraction. Looks for crash_report (logger SASL +%%% convention) or stacktrace meta and converts to a normalised +%%% #{error => #{type, reason, message, stacktrace}} entry. +extract_error(Data) -> + case maps:take(crash_report, Data) of + {CrashReport, Rest} when is_list(CrashReport) -> + Rest#{error => normalise_crash_report(CrashReport)}; + _ -> + extract_stacktrace(Data) + end. + +extract_stacktrace(Data) -> + case maps:take(stacktrace, Data) of + {Stack, Rest} when is_list(Stack) -> + ErrorBase = maps:get(error, Rest, #{}), + ErrorBase1 = ErrorBase#{stacktrace => normalise_stacktrace(Stack)}, + ErrorBase2 = maybe_take_into(class, type, Rest, ErrorBase1), + ErrorBase3 = maybe_take_into(reason, reason, Rest, ErrorBase2), + Rest1 = maps:without([class, reason], Rest), + Rest1#{error => ErrorBase3}; + _ -> + Data + end. + +maybe_take_into(SrcKey, DestKey, Src, Dest) -> + case maps:find(SrcKey, Src) of + {ok, V} -> Dest#{DestKey => V}; + error -> Dest + end. + +normalise_crash_report([Proc | _]) when is_list(Proc) -> + Initial = #{}, + M1 = report_value(error_info, type_and_reason(), Proc, Initial), + M2 = report_value(registered_name, registered_name, Proc, M1), + M3 = report_value(pid, pid, Proc, M2), + M3; +normalise_crash_report(_) -> + #{}. + +report_value(Key, As, Proplist, Acc) -> + case lists:keyfind(Key, 1, Proplist) of + {Key, V} when is_function(As, 1) -> + maps:merge(Acc, As(V)); + {Key, V} -> + Acc#{As => V}; + false -> + Acc + end. + +type_and_reason() -> + fun + ({Class, Reason, Stack}) -> + #{ + type => Class, + reason => Reason, + stacktrace => normalise_stacktrace(Stack) + }; + (Other) -> + #{reason => Other} + end. + +normalise_stacktrace(Stack) -> + [stack_frame(F) || F <- Stack]. + +stack_frame({M, F, A, Info}) when is_atom(M), is_atom(F), is_integer(A) -> + base_frame(M, F, A, Info); +stack_frame({M, F, Args, Info}) when is_atom(M), is_atom(F), is_list(Args) -> + base_frame(M, F, length(Args), Info); +stack_frame(Other) -> + #{raw => Other}. + +base_frame(M, F, A, Info) -> + Base = #{mfa => {M, F, A}}, + File = + case lists:keyfind(file, 1, Info) of + {file, FName} -> Base#{file => unicode:characters_to_binary(FName)}; + false -> Base + end, + case lists:keyfind(line, 1, Info) of + {line, L} -> File#{line => L}; + false -> File + end. + +%%% Redaction. Walks a list of paths (each a list of keys) and replaces +%%% the value at that path with <<"[REDACTED]">>. Missing paths are no-ops. +redact(Data, #{redact := Paths}) when is_list(Paths) -> + lists:foldl(fun redact_path/2, Data, Paths); +redact(Data, _) -> + Data. + +redact_path([], _Data) -> + ?REDACTED; +redact_path([K], Data) when is_map(Data) -> + case maps:is_key(K, Data) of + true -> Data#{K := ?REDACTED}; + false -> Data + end; +redact_path([K | Rest], Data) when is_map(Data) -> + case maps:find(K, Data) of + {ok, Inner} when is_map(Inner) -> + Data#{K := redact_path(Rest, Inner)}; + _ -> + Data + end; +redact_path(_, Data) -> + Data. + +%%% Schema rendering. Each schema applies a canonical transform from the +%%% (msg + meta) map onto the schema's expected field names. +apply_schema(Data, Config) -> + Schema = maps:get(schema, Config, nova), + case Schema of + nova -> to_nova(Data); + ecs -> to_ecs(Data); + otel -> to_otel(Data); + gcp -> to_gcp(Data); + datadog -> to_datadog(Data) + end. + +to_nova(Data) -> + Data1 = format_timestamp(time, Data, microsecond), + Data1. + +to_ecs(Data) -> + Data1 = rename(time, '@timestamp', format_timestamp(time, Data, microsecond)), + Data2 = render_severity_text(level, 'log.level', Data1, fun severity_lowercase/1), + Data3 = rename(trace_id, 'trace.id', Data2), + Data4 = rename(span_id, 'span.id', Data3), + Data5 = rename(text, message, Data4), + Data6 = rename_error(Data5, fun ecs_error_keys/1), + rename_source_location(Data6, ecs). + +to_otel(Data) -> + Data1 = rename('time', 'Timestamp', format_timestamp('time', Data, nanosecond)), + Data2 = render_severity(level, 'SeverityText', 'SeverityNumber', Data1), + Data3 = rename(trace_id, 'TraceId', Data2), + Data4 = rename(span_id, 'SpanId', Data3), + Data5 = rename(text, 'Body', Data4), + rename_error(Data5, fun otel_error_keys/1). + +to_gcp(Data) -> + Data1 = format_timestamp(time, Data, microsecond), + Data2 = render_severity_text(level, severity, Data1, fun severity_uppercase/1), + Data3 = rename(trace_id, 'logging.googleapis.com/trace', Data2), + Data4 = rename(span_id, 'logging.googleapis.com/spanId', Data3), + Data5 = rename(text, message, Data4), + rename_source_location(Data5, gcp). + +to_datadog(Data) -> + Data1 = rename(time, timestamp, format_timestamp(time, Data, microsecond)), + Data2 = render_severity_text(level, status, Data1, fun severity_lowercase/1), + Data3 = rename(trace_id, 'dd.trace_id', Data2), + Data4 = rename(span_id, 'dd.span_id', Data3), + rename(text, message, Data4). + +rename(Old, New, Data) -> + case maps:take(Old, Data) of + {V, Rest} -> Rest#{New => V}; + error -> Data + end. + +render_severity(LevelKey, TextKey, NumberKey, Data) -> + case maps:take(LevelKey, Data) of + {Level, Rest} -> + Rest#{ + TextKey => severity_uppercase(Level), + NumberKey => severity_number(Level) + }; + error -> + Data + end. + +render_severity_text(LevelKey, NewKey, Data, Fmt) -> + case maps:take(LevelKey, Data) of + {Level, Rest} -> Rest#{NewKey => Fmt(Level)}; + error -> Data + end. + +severity_lowercase(L) when is_atom(L) -> atom_to_binary(L, utf8); +severity_lowercase(L) -> L. + +severity_uppercase(L) when is_atom(L) -> + list_to_binary(string:to_upper(atom_to_list(L))); +severity_uppercase(L) -> + L. + +%% OTel severity numbers per spec: TRACE 1-4, DEBUG 5-8, INFO 9-12, +%% WARN 13-16, ERROR 17-20, FATAL 21-24. We map Erlang's levels to the +%% lowest number in their band. +severity_number(debug) -> 5; +severity_number(info) -> 9; +severity_number(notice) -> 10; +severity_number(warning) -> 13; +severity_number(error) -> 17; +severity_number(critical) -> 21; +severity_number(alert) -> 22; +severity_number(emergency) -> 24; +severity_number(_) -> 0. + +format_timestamp(Key, Data, Precision) -> + case maps:find(Key, Data) of + {ok, T} when is_integer(T) -> + Data#{Key => format_time(T, Precision)}; + _ -> + Data + end. + +format_time(T, microsecond) -> system_time_to_iso8601(T); +format_time(T, nanosecond) -> system_time_to_iso8601_nano(T). + +rename_error(Data, KeyFn) -> + case maps:take(error, Data) of + {Err, Rest} when is_map(Err) -> + maps:merge(Rest, schema_error(Err, KeyFn)); + _ -> + Data + end. + +schema_error(Err, KeyFn) -> + maps:fold( + fun(K, V, Acc) -> + case KeyFn(K) of + undefined -> Acc; + NewK -> Acc#{NewK => V} + end + end, + #{}, + Err + ). + +ecs_error_keys(type) -> 'error.type'; +ecs_error_keys(reason) -> 'error.message'; +ecs_error_keys(stacktrace) -> 'error.stack_trace'; +ecs_error_keys(_) -> undefined. + +otel_error_keys(type) -> 'exception.type'; +otel_error_keys(reason) -> 'exception.message'; +otel_error_keys(stacktrace) -> 'exception.stacktrace'; +otel_error_keys(_) -> undefined. + +rename_source_location(Data, ecs) -> + File = maps:get(file, Data, undefined), + Line = maps:get(line, Data, undefined), + Mfa = maps:get(mfa, Data, undefined), + D1 = maps:without([file, line, mfa], Data), + D2 = case File of undefined -> D1; _ -> D1#{'log.origin.file.name' => File} end, + D3 = case Line of undefined -> D2; _ -> D2#{'log.origin.file.line' => Line} end, + case Mfa of undefined -> D3; _ -> D3#{'log.origin.function' => Mfa} end; +rename_source_location(Data, gcp) -> + File = maps:get(file, Data, undefined), + Line = maps:get(line, Data, undefined), + Mfa = maps:get(mfa, Data, undefined), + case {File, Line, Mfa} of + {undefined, undefined, undefined} -> + Data; + _ -> + Loc0 = #{}, + Loc1 = case File of undefined -> Loc0; _ -> Loc0#{file => File} end, + Loc2 = case Line of undefined -> Loc1; _ -> Loc1#{line => Line} end, + Loc3 = case Mfa of undefined -> Loc2; _ -> Loc2#{'function' => Mfa} end, + (maps:without([file, line, mfa], Data))#{ + 'logging.googleapis.com/sourceLocation' => Loc3 + } + end. + +%%%_* JSON encoding ==================================================== pre_encode(Data, Config) -> + MaxTerm = maps:get(max_term_size, Config, ?DEFAULT_MAX_TERM_SIZE), + MaxStr = maps:get(max_string_length, Config, ?DEFAULT_MAX_STRING_LENGTH), + walk(Data, MaxTerm, MaxStr). + +walk(Data, MaxTerm, MaxStr) when is_map(Data) -> maps:fold( fun (K, V, Acc) when is_map(V) -> - maps:put(jsonify(K), pre_encode(V, Config), Acc); - % assume list of maps - (K, Vs, Acc) when is_list(Vs), is_map(hd(Vs)) -> - maps:put(jsonify(K), [pre_encode(V, Config) || V <- Vs, is_map(V)], Acc); + maps:put(jsonify_key(K), walk(V, MaxTerm, MaxStr), Acc); + (K, Vs, Acc) when is_list(Vs), Vs =/= [], is_map(hd(Vs)) -> + maps:put( + jsonify_key(K), + [walk(V, MaxTerm, MaxStr) || V <- Vs, is_map(V)], + Acc + ); (K, V, Acc) -> - maps:put(jsonify(K), jsonify(V), Acc) + maps:put(jsonify_key(K), jsonify(V, MaxTerm, MaxStr), Acc) end, maps:new(), Data - ). - -merge_meta(Msg, Meta0, Config) -> - Meta1 = meta_without(Meta0, Config), - Meta2 = meta_with(Meta1, Config), - maps:merge(Msg, Meta2). + ); +walk(Data, _, _) -> + Data. encode(Data, Config) -> JsonLib = nova:get_env(json_lib, thoas), @@ -92,26 +379,48 @@ encode(Data, Config) -> false -> Json end. -jsonify(A) when is_atom(A) -> A; -jsonify(B) when is_binary(B) -> B; -jsonify(I) when is_integer(I) -> I; -jsonify(F) when is_float(F) -> F; -jsonify(B) when is_boolean(B) -> B; -jsonify(P) when is_pid(P) -> jsonify(pid_to_list(P)); -jsonify(P) when is_port(P) -> jsonify(port_to_list(P)); -jsonify(F) when is_function(F) -> jsonify(erlang:fun_to_list(F)); -jsonify(L) when is_list(L) -> +jsonify_key(A) when is_atom(A) -> A; +jsonify_key(B) when is_binary(B) -> B; +jsonify_key(I) when is_integer(I) -> integer_to_binary(I); +jsonify_key(Other) -> unicode:characters_to_binary(io_lib:format("~p", [Other])). + +jsonify(A, _, _) when is_atom(A) -> A; +jsonify(B, _, MaxStr) when is_binary(B) -> cap_binary(B, MaxStr); +jsonify(I, _, _) when is_integer(I) -> I; +jsonify(F, _, _) when is_float(F) -> F; +jsonify(B, _, _) when is_boolean(B) -> B; +jsonify(P, _, MaxStr) when is_pid(P) -> cap_binary(list_to_binary(pid_to_list(P)), MaxStr); +jsonify(P, _, MaxStr) when is_port(P) -> cap_binary(list_to_binary(port_to_list(P)), MaxStr); +jsonify(F, _, MaxStr) when is_function(F) -> + cap_binary(list_to_binary(erlang:fun_to_list(F)), MaxStr); +jsonify({M, F, A}, _, _) when is_atom(M), is_atom(F), is_integer(A) -> + << + (atom_to_binary(M, utf8))/binary, + $:, + (atom_to_binary(F, utf8))/binary, + $/, + (integer_to_binary(A))/binary + >>; +jsonify(L, MaxTerm, MaxStr) when is_list(L) -> try list_to_binary(L) of - S -> S + S -> cap_binary(S, MaxStr) catch error:badarg -> - unicode:characters_to_binary(io_lib:format("~0p", [L])) + cap_term(L, MaxTerm) end; -jsonify({M, F, A}) when is_atom(M), is_atom(F), is_integer(A) -> - <<(atom_to_binary(M, utf8))/binary, $:, (atom_to_binary(F, utf8))/binary, $/, (integer_to_binary(A))/binary>>; -jsonify(Any) -> - unicode:characters_to_binary(io_lib:format("~0p", [Any])). +jsonify(Any, MaxTerm, _) -> + cap_term(Any, MaxTerm). + +cap_binary(B, Max) when byte_size(B) =< Max -> B; +cap_binary(B, Max) -> + Head = binary:part(B, 0, Max), + <>. +cap_term(Term, Max) -> + Bin = unicode:characters_to_binary(io_lib:format("~0p", [Term])), + cap_binary(Bin, Max). + +%%%_* Config helpers =================================================== apply_format_funs(Data, #{format_funs := Callbacks}) -> maps:fold( fun @@ -178,25 +487,18 @@ format_test() -> format_funs_test() -> Config1 = #{ format_funs => #{ - time => fun(Epoch) -> Epoch + 1 end, + time => fun(T) when is_binary(T) -> <> end, level => fun(alert) -> info end } }, - ?assertJSONEqual( - <<"{\"level\":\"info\",\"text\":\"derp\",\"time\":2}">>, + {ok, Decoded} = thoas:decode( format(#{level => alert, msg => {string, "derp"}, meta => #{time => 1}}, Config1) ), - - Config2 = #{ - format_funs => #{ - time => fun(Epoch) -> Epoch + 1 end, - foobar => fun(alert) -> info end - } - }, - ?assertJSONEqual( - <<"{\"level\":\"alert\",\"text\":\"derp\",\"time\":2}">>, - format(#{level => alert, msg => {string, "derp"}, meta => #{time => 1}}, Config2) - ). + ?assertEqual(<<"info">>, maps:get(<<"level">>, Decoded)), + ?assertEqual(<<"derp">>, maps:get(<<"text">>, Decoded)), + Time = maps:get(<<"time">>, Decoded), + ?assert(is_binary(Time)), + ?assertEqual($!, binary:last(Time)). key_mapping_test() -> Config1 = #{ @@ -219,39 +521,19 @@ key_mapping_test() -> ?assertJSONEqual( <<"{\"level\":\"derp\",\"lvl\":\"alert\"}">>, format(#{level => alert, msg => {string, "derp"}, meta => #{}}, Config2) - ), - - Config3 = #{ - key_mapping => #{ - level => lvl, - foobar => level - } - }, - ?assertJSONEqual( - <<"{\"lvl\":\"alert\",\"text\":\"derp\"}">>, - format(#{level => alert, msg => {string, "derp"}, meta => #{}}, Config3) - ), - - Config4 = #{ - key_mapping => #{time => timestamp}, - format_funs => #{timestamp => fun(T) -> T + 1 end} - }, - ?assertJSONEqual( - <<"{\"level\":\"alert\",\"text\":\"derp\",\"timestamp\":2}">>, - format(#{level => alert, msg => {string, "derp"}, meta => #{time => 1}}, Config4) ). list_format_test() -> ErrorReport = #{ level => error, - meta => #{time => 1}, + meta => #{}, msg => {report, #{report => [{hej, "hopp"}]}} }, - ?assertJSONEqual( - <<"{\"level\":\"error\",\"report\":\"[{hej,\\\"hopp\\\"}]\",\"time\":1}">>, - format(ErrorReport, #{}) - ). + {ok, Decoded} = thoas:decode(format(ErrorReport, #{})), + ?assertEqual(<<"error">>, maps:get(<<"level">>, Decoded)), + ReportBin = maps:get(<<"report">>, Decoded), + ?assert(is_binary(ReportBin)). meta_without_test() -> Error = #{ @@ -259,23 +541,14 @@ meta_without_test() -> msg => {report, #{answer => 42}}, meta => #{secret => xyz} }, - ?assertEqual( - {ok, #{ - <<"answer">> => 42, - <<"level">> => <<"info">>, - <<"secret">> => <<"xyz">> - }}, - thoas:decode(format(Error, #{})) - ), + {ok, D1} = thoas:decode(format(Error, #{})), + ?assertEqual(42, maps:get(<<"answer">>, D1)), + ?assertEqual(<<"info">>, maps:get(<<"level">>, D1)), + ?assertEqual(<<"xyz">>, maps:get(<<"secret">>, D1)), + Config2 = #{meta_without => [secret]}, - ?assertEqual( - {ok, #{ - <<"answer">> => 42, - <<"level">> => <<"info">> - }}, - thoas:decode(format(Error, Config2)) - ), - ok. + {ok, D2} = thoas:decode(format(Error, Config2)), + ?assertNot(maps:is_key(<<"secret">>, D2)). meta_with_test() -> Error = #{ @@ -283,54 +556,21 @@ meta_with_test() -> msg => {report, #{answer => 42}}, meta => #{secret => xyz} }, - ?assertEqual( - {ok, #{ - <<"answer">> => 42, - <<"level">> => <<"info">>, - <<"secret">> => <<"xyz">> - }}, - thoas:decode(format(Error, #{})) - ), - Config2 = #{meta_with => [level]}, - ?assertEqual( - {ok, #{ - <<"answer">> => 42, - <<"level">> => <<"info">> - }}, - thoas:decode(format(Error, Config2)) - ), - ok. + Config = #{meta_with => [level]}, + {ok, D} = thoas:decode(format(Error, Config)), + ?assertNot(maps:is_key(<<"secret">>, D)), + ?assertEqual(<<"info">>, maps:get(<<"level">>, D)). newline_test() -> ConfigDefault = #{new_line => true}, - ?assertEqual( - [<<"{\"level\":\"alert\",\"text\":\"derp\"}">>, <<"\n">>], - format(#{level => alert, msg => {string, "derp"}, meta => #{}}, ConfigDefault) - ), - ConfigCRLF = #{ - new_line_type => crlf, - new_line => true - }, - ?assertEqual( - [<<"{\"level\":\"alert\",\"text\":\"derp\"}">>, <<"\r\n">>], - format(#{level => alert, msg => {string, "derp"}, meta => #{}}, ConfigCRLF) - ). + Out = format(#{level => alert, msg => {string, "derp"}, meta => #{}}, ConfigDefault), + ?assertEqual(<<"\n">>, lists:last(Out)). newline_types_test() -> Base = #{level => alert, msg => {string, "x"}, meta => #{}}, - %% nl ?assertEqual(<<"\n">>, lists:last(format(Base, #{new_line => true, new_line_type => nl}))), - %% unix - ?assertEqual(<<"\n">>, lists:last(format(Base, #{new_line => true, new_line_type => unix}))), - %% crlf ?assertEqual(<<"\r\n">>, lists:last(format(Base, #{new_line => true, new_line_type => crlf}))), - %% windows - ?assertEqual(<<"\r\n">>, lists:last(format(Base, #{new_line => true, new_line_type => windows}))), - %% cr ?assertEqual(<<"\r">>, lists:last(format(Base, #{new_line => true, new_line_type => cr}))), - %% macos9 - ?assertEqual(<<"\r">>, lists:last(format(Base, #{new_line => true, new_line_type => macos9}))), - %% default (no new_line_type specified) ?assertEqual(<<"\n">>, lists:last(format(Base, #{new_line => true}))). no_newline_test() -> @@ -339,29 +579,18 @@ no_newline_test() -> ?assert(is_binary(Result)). jsonify_types_test() -> - %% atom - ?assertEqual(hello, jsonify(hello)), - %% binary - ?assertEqual(<<"bin">>, jsonify(<<"bin">>)), - %% integer - ?assertEqual(42, jsonify(42)), - %% float - ?assertEqual(3.14, jsonify(3.14)), - %% boolean - ?assertEqual(true, jsonify(true)), - ?assertEqual(false, jsonify(false)), - %% pid - ?assert(is_binary(jsonify(self()))), - %% function - ?assert(is_binary(jsonify(fun erlang:now/0))), - %% list (string) - ?assertEqual(<<"hello">>, jsonify("hello")), - %% list (non-string, falls through to io_lib:format) - ?assert(is_binary(jsonify([{a, b}]))), - %% MFA tuple - ?assertEqual(<<"lists:reverse/1">>, jsonify({lists, reverse, 1})), - %% arbitrary term - ?assert(is_binary(jsonify(make_ref()))). + Max = ?DEFAULT_MAX_STRING_LENGTH, + ?assertEqual(hello, jsonify(hello, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assertEqual(<<"bin">>, jsonify(<<"bin">>, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assertEqual(42, jsonify(42, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assertEqual(3.14, jsonify(3.14, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assertEqual(true, jsonify(true, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assert(is_binary(jsonify(self(), ?DEFAULT_MAX_TERM_SIZE, Max))), + ?assert(is_binary(jsonify(fun erlang:now/0, ?DEFAULT_MAX_TERM_SIZE, Max))), + ?assertEqual(<<"hello">>, jsonify("hello", ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assert(is_binary(jsonify([{a, b}], ?DEFAULT_MAX_TERM_SIZE, Max))), + ?assertEqual(<<"lists:reverse/1">>, jsonify({lists, reverse, 1}, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assert(is_binary(jsonify(make_ref(), ?DEFAULT_MAX_TERM_SIZE, Max))). format_keyval_list_test() -> Event = #{level => info, msg => {report, [{key, <<"val">>}]}, meta => #{}}, @@ -374,9 +603,16 @@ format_format_terms_test() -> ?assertEqual(<<"hello world">>, maps:get(<<"text">>, Decoded)). format_error_logger_test() -> - Event = #{level => error, - msg => {report, #{format => "error: ~p", args => [bad], label => {error_logger, error}}}, - meta => #{}}, + Event = #{ + level => error, + msg => + {report, #{ + format => "error: ~p", + args => [bad], + label => {error_logger, error} + }}, + meta => #{} + }, {ok, Decoded} = thoas:decode(format(Event, #{})), ?assert(maps:is_key(<<"text">>, Decoded)). @@ -403,9 +639,217 @@ system_time_to_iso8601_nano_test() -> ?assert(byte_size(Result) > 10). format_port_test() -> - %% Ports are jsonified as binaries Port = hd(erlang:ports()), - Result = jsonify(Port), + Result = jsonify(Port, ?DEFAULT_MAX_TERM_SIZE, ?DEFAULT_MAX_STRING_LENGTH), ?assert(is_binary(Result)). --endif. \ No newline at end of file +%%%--- Schema tests ---------------------------------------------------- +nova_schema_default_timestamp_test() -> + Event = #{level => info, msg => {report, #{x => 1}}, meta => #{time => 1}}, + {ok, Decoded} = thoas:decode(format(Event, #{})), + Time = maps:get(<<"time">>, Decoded), + ?assert(is_binary(Time)), + ?assert(binary:match(Time, <<"T">>) =/= nomatch). + +ecs_schema_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hello">>}}, + meta => #{ + time => 1700000000000000, + trace_id => <<"abc">>, + span_id => <<"def">> + } + }, + {ok, D} = thoas:decode(format(Event, #{schema => ecs})), + ?assertEqual(<<"info">>, maps:get(<<"log.level">>, D)), + ?assert(maps:is_key(<<"@timestamp">>, D)), + ?assertEqual(<<"hello">>, maps:get(<<"message">>, D)), + ?assertEqual(<<"abc">>, maps:get(<<"trace.id">>, D)), + ?assertEqual(<<"def">>, maps:get(<<"span.id">>, D)). + +otel_schema_test() -> + Event = #{ + level => warning, + msg => {report, #{text => <<"watch out">>}}, + meta => #{ + time => 1700000000000000, + trace_id => <<"abc">>, + span_id => <<"def">> + } + }, + {ok, D} = thoas:decode(format(Event, #{schema => otel})), + ?assertEqual(<<"WARNING">>, maps:get(<<"SeverityText">>, D)), + ?assertEqual(13, maps:get(<<"SeverityNumber">>, D)), + ?assertEqual(<<"watch out">>, maps:get(<<"Body">>, D)), + ?assertEqual(<<"abc">>, maps:get(<<"TraceId">>, D)), + ?assertEqual(<<"def">>, maps:get(<<"SpanId">>, D)), + ?assert(maps:is_key(<<"Timestamp">>, D)). + +gcp_schema_test() -> + Event = #{ + level => error, + msg => {report, #{text => <<"bad">>}}, + meta => #{trace_id => <<"abc">>, span_id => <<"def">>} + }, + {ok, D} = thoas:decode(format(Event, #{schema => gcp})), + ?assertEqual(<<"ERROR">>, maps:get(<<"severity">>, D)), + ?assertEqual(<<"bad">>, maps:get(<<"message">>, D)), + ?assertEqual(<<"abc">>, maps:get(<<"logging.googleapis.com/trace">>, D)), + ?assertEqual(<<"def">>, maps:get(<<"logging.googleapis.com/spanId">>, D)). + +datadog_schema_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hi">>}}, + meta => #{trace_id => <<"abc">>, span_id => <<"def">>} + }, + {ok, D} = thoas:decode(format(Event, #{schema => datadog})), + ?assertEqual(<<"info">>, maps:get(<<"status">>, D)), + ?assertEqual(<<"hi">>, maps:get(<<"message">>, D)), + ?assertEqual(<<"abc">>, maps:get(<<"dd.trace_id">>, D)), + ?assertEqual(<<"def">>, maps:get(<<"dd.span_id">>, D)). + +ecs_source_location_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hi">>}}, + meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} + }, + {ok, D} = thoas:decode(format(Event, #{schema => ecs})), + ?assertEqual(<<"foo.erl">>, maps:get(<<"log.origin.file.name">>, D)), + ?assertEqual(42, maps:get(<<"log.origin.file.line">>, D)), + ?assertEqual(<<"mod:fun_/1">>, maps:get(<<"log.origin.function">>, D)). + +gcp_source_location_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hi">>}}, + meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} + }, + {ok, D} = thoas:decode(format(Event, #{schema => gcp})), + Loc = maps:get(<<"logging.googleapis.com/sourceLocation">>, D), + ?assertEqual(<<"foo.erl">>, maps:get(<<"file">>, Loc)), + ?assertEqual(42, maps:get(<<"line">>, Loc)). + +%%%--- Severity number boundaries -------------------------------------- +severity_number_test() -> + ?assertEqual(5, severity_number(debug)), + ?assertEqual(9, severity_number(info)), + ?assertEqual(13, severity_number(warning)), + ?assertEqual(17, severity_number(error)), + ?assertEqual(22, severity_number(alert)), + ?assertEqual(24, severity_number(emergency)), + ?assertEqual(0, severity_number(weird_value)). + +%%%--- Structured error tests ------------------------------------------ +extract_error_from_stacktrace_test() -> + Event = #{ + level => error, + msg => {report, #{text => <<"boom">>}}, + meta => #{ + class => error, + reason => badarg, + stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] + } + }, + {ok, D} = thoas:decode(format(Event, #{})), + Err = maps:get(<<"error">>, D), + ?assertEqual(<<"error">>, maps:get(<<"type">>, Err)), + ?assertEqual(<<"badarg">>, maps:get(<<"reason">>, Err)), + [Frame | _] = maps:get(<<"stacktrace">>, Err), + ?assertEqual(<<"mymod:myfun/2">>, maps:get(<<"mfa">>, Frame)), + ?assertEqual(<<"mymod.erl">>, maps:get(<<"file">>, Frame)), + ?assertEqual(17, maps:get(<<"line">>, Frame)). + +extract_error_ecs_test() -> + Event = #{ + level => error, + msg => {report, #{}}, + meta => #{ + class => error, + reason => badarg, + stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] + } + }, + {ok, D} = thoas:decode(format(Event, #{schema => ecs})), + ?assertEqual(<<"error">>, maps:get(<<"error.type">>, D)), + ?assertEqual(<<"badarg">>, maps:get(<<"error.message">>, D)), + ?assert(is_list(maps:get(<<"error.stack_trace">>, D))). + +extract_error_otel_test() -> + Event = #{ + level => error, + msg => {report, #{}}, + meta => #{ + class => exit, + reason => normal, + stacktrace => [{m, f, 0, []}] + } + }, + {ok, D} = thoas:decode(format(Event, #{schema => otel})), + ?assertEqual(<<"exit">>, maps:get(<<"exception.type">>, D)), + ?assertEqual(<<"normal">>, maps:get(<<"exception.message">>, D)), + ?assert(is_list(maps:get(<<"exception.stacktrace">>, D))). + +%%%--- Redaction tests ------------------------------------------------- +redact_top_level_test() -> + Event = #{ + level => info, + msg => {report, #{user => <<"alice">>, password => <<"secret">>}}, + meta => #{} + }, + Config = #{redact => [[password]]}, + {ok, D} = thoas:decode(format(Event, Config)), + ?assertEqual(<<"[REDACTED]">>, maps:get(<<"password">>, D)), + ?assertEqual(<<"alice">>, maps:get(<<"user">>, D)). + +redact_nested_test() -> + Event = #{ + level => info, + msg => + {report, #{ + req => #{ + headers => #{authorization => <<"bearer abc">>, host => <<"x">>} + } + }}, + meta => #{} + }, + Config = #{redact => [[req, headers, authorization]]}, + {ok, D} = thoas:decode(format(Event, Config)), + Headers = maps:get(<<"headers">>, maps:get(<<"req">>, D)), + ?assertEqual(<<"[REDACTED]">>, maps:get(<<"authorization">>, Headers)), + ?assertEqual(<<"x">>, maps:get(<<"host">>, Headers)). + +redact_missing_path_test() -> + Event = #{level => info, msg => {report, #{a => 1}}, meta => #{}}, + Config = #{redact => [[nope, nothing]]}, + {ok, D} = thoas:decode(format(Event, Config)), + ?assertEqual(1, maps:get(<<"a">>, D)). + +%%%--- Size cap tests -------------------------------------------------- +cap_binary_test() -> + Big = binary:copy(<<"x">>, 1000), + Capped = cap_binary(Big, 100), + ?assert(byte_size(Capped) > 100), + ?assert(byte_size(Capped) < 200), + ?assertEqual(?TRUNCATED_MARKER, binary:part(Capped, byte_size(Capped) - byte_size(?TRUNCATED_MARKER), byte_size(?TRUNCATED_MARKER))). + +cap_term_in_pipeline_test() -> + Huge = lists:duplicate(5000, {complex, term, here}), + Event = #{level => info, msg => {report, #{blob => Huge}}, meta => #{}}, + Config = #{max_term_size => 200}, + {ok, D} = thoas:decode(format(Event, Config)), + Blob = maps:get(<<"blob">>, D), + ?assert(is_binary(Blob)), + ?assert(byte_size(Blob) < 400). + +cap_string_in_pipeline_test() -> + Big = binary:copy(<<"a">>, 5000), + Event = #{level => info, msg => {report, #{s => Big}}, meta => #{}}, + Config = #{max_string_length => 50}, + {ok, D} = thoas:decode(format(Event, Config)), + S = maps:get(<<"s">>, D), + ?assert(byte_size(S) < 200). + +-endif. From 978a1a8405c1d14ee46142624bd36741e734058e Mon Sep 17 00:00:00 2001 From: Daniel Widgren Date: Tue, 19 May 2026 20:57:16 +0200 Subject: [PATCH 2/7] refactor(jsonlogger): drop redundant intermediate in normalise_crash_report --- src/nova_jsonlogger.erl | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/src/nova_jsonlogger.erl b/src/nova_jsonlogger.erl index a892789..502d31b 100644 --- a/src/nova_jsonlogger.erl +++ b/src/nova_jsonlogger.erl @@ -111,11 +111,9 @@ maybe_take_into(SrcKey, DestKey, Src, Dest) -> end. normalise_crash_report([Proc | _]) when is_list(Proc) -> - Initial = #{}, - M1 = report_value(error_info, type_and_reason(), Proc, Initial), + M1 = report_value(error_info, type_and_reason(), Proc, #{}), M2 = report_value(registered_name, registered_name, Proc, M1), - M3 = report_value(pid, pid, Proc, M2), - M3; + report_value(pid, pid, Proc, M2); normalise_crash_report(_) -> #{}. From 5e0a2379ef7a0251188478c5bc412ba27e16274a Mon Sep 17 00:00:00 2001 From: Daniel Widgren Date: Tue, 19 May 2026 21:02:48 +0200 Subject: [PATCH 3/7] docs(jsonlogger): add logging guide and OTP -moduledoc * New `guides/logging.md` covering setup, schemas, severity numbers, source location, structured errors, trace correlation, redaction, size caps, hooks, and a "choosing a schema" cheat sheet. * Wire the guide into `guides/README.md` (under "Deeper into Nova") and `rebar.config` ex_doc extras. * Add `-moduledoc` / `-doc` attributes on `nova_jsonlogger`, `format/2`, and the public timestamp helpers using the OTP doc format. --- guides/README.md | 1 + guides/logging.md | 145 ++++++++++++++++++++++++++++++++++++++++ rebar.config | 1 + src/nova_jsonlogger.erl | 58 ++++++++++++++-- 4 files changed, 200 insertions(+), 5 deletions(-) create mode 100644 guides/logging.md diff --git a/guides/README.md b/guides/README.md index 1235c81..4bb8c38 100644 --- a/guides/README.md +++ b/guides/README.md @@ -23,6 +23,7 @@ Here can you find the documentation for the Nova framework. Nova is under contst * [Handlers in Nova](handlers.md) * [Pubsub system](pubsub.md) +* [Structured logging](logging.md) ### Releases diff --git a/guides/logging.md b/guides/logging.md new file mode 100644 index 0000000..9c63b39 --- /dev/null +++ b/guides/logging.md @@ -0,0 +1,145 @@ +# Logging + +Nova ships with `nova_jsonlogger`, a structured JSON formatter for the standard OTP `logger`. It can emit log records in several common schemas so they drop straight into the backend you already use. + +## Setup + +Wire `nova_jsonlogger` as a formatter on the default handler in `sys.config`: + +```erlang +{kernel, [ + {logger_level, info}, + {logger, [ + {handler, default, logger_std_h, #{ + formatter => {nova_jsonlogger, #{ + schema => ecs, + new_line => true + }} + }} + ]} +]}. +``` + +All logs emitted via the `?LOG_INFO`, `?LOG_ERROR`, etc. macros are then rendered as single-line JSON. + +## Supported schemas + +Pick the schema that matches your log pipeline. The default (`nova`) preserves Nova's historical shape and adds RFC 3339 timestamps. + +| Schema | Timestamp key | Level key | Message key | Trace correlation keys | +|-----------|-----------------|------------------------------------|-------------|------------------------------------------------------------------| +| `nova` | `time` | `level` (atom) | `text` | `trace_id`, `span_id` | +| `ecs` | `@timestamp` | `log.level` (lowercase) | `message` | `trace.id`, `span.id` | +| `otel` | `Timestamp` | `SeverityText` + `SeverityNumber` | `Body` | `TraceId`, `SpanId` | +| `gcp` | `time` | `severity` (uppercase) | `message` | `logging.googleapis.com/trace`, `logging.googleapis.com/spanId` | +| `datadog` | `timestamp` | `status` | `message` | `dd.trace_id`, `dd.span_id` | + +### Severity numbers (OTel) + +Erlang levels map to the lowest number in their OTel severity band: + +| Erlang level | `SeverityNumber` | +|--------------|-------------------| +| `debug` | 5 | +| `info` | 9 | +| `notice` | 10 | +| `warning` | 13 | +| `error` | 17 | +| `critical` | 21 | +| `alert` | 22 | +| `emergency` | 24 | + +### Source location + +`logger` automatically passes `file`, `line`, and `mfa` meta when the `?LOG_*` macros are used. Each schema renders source location in its native form: + +- **ECS**: `log.origin.file.name`, `log.origin.file.line`, `log.origin.function` +- **GCP**: a nested `logging.googleapis.com/sourceLocation` object with `file`, `line`, `function` + +## Structured errors + +When the `crash_report` SASL meta or any of `class`, `reason`, `stacktrace` are present, `nova_jsonlogger` builds a structured `error` object: + +```json +{ + "error": { + "type": "error", + "reason": "badarg", + "stacktrace": [ + {"mfa": "mymod:myfun/2", "file": "mymod.erl", "line": 17} + ] + } +} +``` + +The schema renders this under its own conventions: + +| Schema | Type key | Message key | Stacktrace key | +|--------|--------------------|------------------------|----------------------------| +| ECS | `error.type` | `error.message` | `error.stack_trace` | +| OTel | `exception.type` | `exception.message` | `exception.stacktrace` | + +To attach a structured error from your own code, include the keys in the log report: + +```erlang +?LOG_ERROR(#{ + text => <<"payment failed">>, + class => error, + reason => Reason, + stacktrace => Stacktrace +}). +``` + +## Trace correlation + +When `trace_id` and `span_id` are present in the process metadata (set via `logger:update_process_metadata/1`), the formatter renders them under each schema's conventional keys. Nothing else is required from the formatter side - it is the responsibility of upstream instrumentation to populate them. + +If you use `opentelemetry_nova`, this is wired for you: each HTTP request runs through the plugin which writes the active span's hex trace and span ids into process metadata. Logs emitted during the request are then correlatable with traces in any backend that joins on those fields. + +## Redaction + +Use `redact` to scrub field paths before encoding: + +```erlang +{nova_jsonlogger, #{ + schema => ecs, + redact => [ + [req, headers, authorization], + [user, password], + [stripe, api_key] + ] +}} +``` + +Each path is a list of keys walked through the report. The matched value is replaced with `<<"[REDACTED]">>`. Missing paths are a no-op. + +## Term-size guards + +Two caps prevent a single oversized term from ballooning a log line: + +| Key | Default | Behaviour | +|----------------------|---------|-------------------------------------------------------------------------------------| +| `max_term_size` | 8192 | Caps the output of `~0p`-formatted complex terms (lists, tuples, nested terms) | +| `max_string_length` | 8192 | Caps binaries, pid/port/function representations, and string lists | + +When a value exceeds its cap, it is truncated and a `"...[truncated]"` marker is appended. + +## Hooks for customisation + +Three config keys let you override anything the schema produced: + +- `meta_with` / `meta_without` - allowlist or denylist meta keys before rendering +- `key_mapping` - rename keys after schema rendering, e.g. `#{level => severity}` +- `format_funs` - transform values after schema and key mapping, e.g. `#{message => fun string:uppercase/1}` + +These run in the order `schema -> key_mapping -> format_funs`, so a `format_funs` entry targets the post-schema key name. + +## Choosing a schema + +- **`ecs`** if you ship to Elastic, OpenSearch, or anything that speaks the Elastic Common Schema. +- **`otel`** for OpenTelemetry-native ingestors and any backend that joins logs to traces via OTel semantic conventions. +- **`gcp`** for Google Cloud Logging. +- **`datadog`** for Datadog Logs. +- **`nova`** (default) for development, file logs, or anywhere the keys are read by humans. + +You can switch at runtime by reconfiguring the handler - no application code needs to change. diff --git a/rebar.config b/rebar.config index 07107ef..90570be 100644 --- a/rebar.config +++ b/rebar.config @@ -71,6 +71,7 @@ <<"guides/handlers.md">>, <<"guides/plugins.md">>, <<"guides/pubsub.md">>, + <<"guides/logging.md">>, <<"guides/graceful-shutdown.md">>, <<"guides/building-releases.md">>, <<"guides/books-and-links.md">>, diff --git a/src/nova_jsonlogger.erl b/src/nova_jsonlogger.erl index 502d31b..e4fbcc5 100644 --- a/src/nova_jsonlogger.erl +++ b/src/nova_jsonlogger.erl @@ -1,13 +1,53 @@ %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %%% Originally derived from https://github.com/kivra/jsonformat. -%%% -%%% Custom formatter for the Erlang OTP logger application which outputs -%%% single-line JSON formatted data. Supports several output schemas -%%% (nova, ecs, otel, gcp, datadog), structured error extraction, redaction -%%% and term-size caps. %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -module(nova_jsonlogger). +-moduledoc """ +JSON formatter for the OTP `logger`. + +Renders every log record as a single line of JSON, optionally shaped to +match a popular log schema. See `m:nova_jsonlogger#schemas` and the +[Structured logging](guides/logging.md) guide for the full reference. + +## Usage + +Wire it as the formatter on a `logger` handler, typically in `sys.config`: + +```erlang +{kernel, [ + {logger, [ + {handler, default, logger_std_h, #{ + formatter => {nova_jsonlogger, #{schema => ecs, new_line => true}} + }} + ]} +]}. +``` + +## Config + +```erlang +#{ + schema => nova | ecs | otel | gcp | datadog, %% default: nova + new_line => boolean(), %% default: false + new_line_type => nl | crlf | cr | unix | windows, + key_mapping => #{atom() => atom()}, %% post-schema rename + format_funs => #{atom() => fun((_) -> _)}, %% post-rename transform + meta_with => [atom()], %% allowlist meta keys + meta_without => [atom()], %% denylist meta keys + redact => [[atom() | binary()]], %% paths to scrub + max_term_size => non_neg_integer(), %% default: 8192 bytes + max_string_length => non_neg_integer() %% default: 8192 bytes +} +``` + +## Trace correlation + +When `trace_id` and `span_id` are present in process metadata, they are +rendered under each schema's conventional key (`trace.id`/`span.id` for +ECS, `TraceId`/`SpanId` for OTel, etc.). `opentelemetry_nova` populates +these automatically inside each HTTP request. +""". -export([ format/2, @@ -40,6 +80,12 @@ -define(TRUNCATED_MARKER, <<"...[truncated]">>). %%%_* API ============================================================== +-doc """ +Format one `t:logger:log_event/0` as a JSON line according to `Config`. + +Called by the OTP `logger` framework once it has matched a handler that +declared `{nova_jsonlogger, Config}` as its formatter. +""". -spec format(logger:log_event(), config()) -> unicode:chardata(). format( #{msg := {report, #{format := Format, args := Args, label := {error_logger, _}}}} = Map, Config @@ -62,10 +108,12 @@ format(Map = #{msg := {string, String}}, Config) -> format(Map = #{msg := {Format, Terms}}, Config) -> format(Map#{msg := {string, io_lib:format(Format, Terms)}}, Config). +-doc "Convert `Epoch` (microseconds since the Unix epoch) to an RFC 3339 binary in UTC.". -spec system_time_to_iso8601(integer()) -> binary(). system_time_to_iso8601(Epoch) -> system_time_to_iso8601(Epoch, microsecond). +-doc "Convert `Epoch` (microseconds since the Unix epoch) to an RFC 3339 binary with nanosecond precision in UTC.". -spec system_time_to_iso8601_nano(integer()) -> binary(). system_time_to_iso8601_nano(Epoch) -> system_time_to_iso8601(1000 * Epoch, nanosecond). From 6520435b03cb8de5a4be52fd844aef41164ae068 Mon Sep 17 00:00:00 2001 From: Daniel Widgren Date: Tue, 19 May 2026 22:36:31 +0200 Subject: [PATCH 4/7] refactor(jsonlogger): move tests to test/ and use configurable json_lib The eunit block lived inside src/nova_jsonlogger.erl and hard-coded thoas:decode/1 throughout. Move it to test/nova_jsonlogger_tests.erl and resolve the JSON decoder through nova:get_env(json_lib, thoas) so the tests follow the same configurable pattern as the production encode/2 path. Internal helpers touched by tests (jsonify/3, cap_binary/2, severity_number/1) get a TEST-only export. --- src/nova_jsonlogger.erl | 391 +----------------------------- test/nova_jsonlogger_tests.erl | 418 +++++++++++++++++++++++++++++++++ 2 files changed, 422 insertions(+), 387 deletions(-) create mode 100644 test/nova_jsonlogger_tests.erl diff --git a/src/nova_jsonlogger.erl b/src/nova_jsonlogger.erl index e4fbcc5..9f81333 100644 --- a/src/nova_jsonlogger.erl +++ b/src/nova_jsonlogger.erl @@ -55,6 +55,10 @@ these automatically inside each HTTP request. system_time_to_iso8601_nano/1 ]). +-ifdef(TEST). +-export([jsonify/3, cap_binary/2, severity_number/1]). +-endif. + -type schema() :: nova | ecs | otel | gcp | datadog. -type redact_path() :: [atom() | binary()]. @@ -512,390 +516,3 @@ meta_with(Meta, #{meta_with := Ks}) -> meta_with(Meta, _ConfigNotPresent) -> Meta. -%%%_* Tests ============================================================ --ifdef(TEST). --include_lib("eunit/include/eunit.hrl"). - --define(assertJSONEqual(Expected, Actual), - ?assertEqual(thoas:decode(Expected), thoas:decode(Actual)) -). - -format_test() -> - ?assertJSONEqual( - <<"{\"level\":\"alert\",\"text\":\"derp\"}">>, - format(#{level => alert, msg => {string, "derp"}, meta => #{}}, #{}) - ), - ?assertJSONEqual( - <<"{\"herp\":\"derp\",\"level\":\"alert\"}">>, - format(#{level => alert, msg => {report, #{herp => derp}}, meta => #{}}, #{}) - ). - -format_funs_test() -> - Config1 = #{ - format_funs => #{ - time => fun(T) when is_binary(T) -> <> end, - level => fun(alert) -> info end - } - }, - {ok, Decoded} = thoas:decode( - format(#{level => alert, msg => {string, "derp"}, meta => #{time => 1}}, Config1) - ), - ?assertEqual(<<"info">>, maps:get(<<"level">>, Decoded)), - ?assertEqual(<<"derp">>, maps:get(<<"text">>, Decoded)), - Time = maps:get(<<"time">>, Decoded), - ?assert(is_binary(Time)), - ?assertEqual($!, binary:last(Time)). - -key_mapping_test() -> - Config1 = #{ - key_mapping => #{ - level => lvl, - text => message - } - }, - ?assertJSONEqual( - <<"{\"lvl\":\"alert\",\"message\":\"derp\"}">>, - format(#{level => alert, msg => {string, "derp"}, meta => #{}}, Config1) - ), - - Config2 = #{ - key_mapping => #{ - level => lvl, - text => level - } - }, - ?assertJSONEqual( - <<"{\"level\":\"derp\",\"lvl\":\"alert\"}">>, - format(#{level => alert, msg => {string, "derp"}, meta => #{}}, Config2) - ). - -list_format_test() -> - ErrorReport = - #{ - level => error, - meta => #{}, - msg => {report, #{report => [{hej, "hopp"}]}} - }, - {ok, Decoded} = thoas:decode(format(ErrorReport, #{})), - ?assertEqual(<<"error">>, maps:get(<<"level">>, Decoded)), - ReportBin = maps:get(<<"report">>, Decoded), - ?assert(is_binary(ReportBin)). - -meta_without_test() -> - Error = #{ - level => info, - msg => {report, #{answer => 42}}, - meta => #{secret => xyz} - }, - {ok, D1} = thoas:decode(format(Error, #{})), - ?assertEqual(42, maps:get(<<"answer">>, D1)), - ?assertEqual(<<"info">>, maps:get(<<"level">>, D1)), - ?assertEqual(<<"xyz">>, maps:get(<<"secret">>, D1)), - - Config2 = #{meta_without => [secret]}, - {ok, D2} = thoas:decode(format(Error, Config2)), - ?assertNot(maps:is_key(<<"secret">>, D2)). - -meta_with_test() -> - Error = #{ - level => info, - msg => {report, #{answer => 42}}, - meta => #{secret => xyz} - }, - Config = #{meta_with => [level]}, - {ok, D} = thoas:decode(format(Error, Config)), - ?assertNot(maps:is_key(<<"secret">>, D)), - ?assertEqual(<<"info">>, maps:get(<<"level">>, D)). - -newline_test() -> - ConfigDefault = #{new_line => true}, - Out = format(#{level => alert, msg => {string, "derp"}, meta => #{}}, ConfigDefault), - ?assertEqual(<<"\n">>, lists:last(Out)). - -newline_types_test() -> - Base = #{level => alert, msg => {string, "x"}, meta => #{}}, - ?assertEqual(<<"\n">>, lists:last(format(Base, #{new_line => true, new_line_type => nl}))), - ?assertEqual(<<"\r\n">>, lists:last(format(Base, #{new_line => true, new_line_type => crlf}))), - ?assertEqual(<<"\r">>, lists:last(format(Base, #{new_line => true, new_line_type => cr}))), - ?assertEqual(<<"\n">>, lists:last(format(Base, #{new_line => true}))). - -no_newline_test() -> - Base = #{level => alert, msg => {string, "x"}, meta => #{}}, - Result = format(Base, #{}), - ?assert(is_binary(Result)). - -jsonify_types_test() -> - Max = ?DEFAULT_MAX_STRING_LENGTH, - ?assertEqual(hello, jsonify(hello, ?DEFAULT_MAX_TERM_SIZE, Max)), - ?assertEqual(<<"bin">>, jsonify(<<"bin">>, ?DEFAULT_MAX_TERM_SIZE, Max)), - ?assertEqual(42, jsonify(42, ?DEFAULT_MAX_TERM_SIZE, Max)), - ?assertEqual(3.14, jsonify(3.14, ?DEFAULT_MAX_TERM_SIZE, Max)), - ?assertEqual(true, jsonify(true, ?DEFAULT_MAX_TERM_SIZE, Max)), - ?assert(is_binary(jsonify(self(), ?DEFAULT_MAX_TERM_SIZE, Max))), - ?assert(is_binary(jsonify(fun erlang:now/0, ?DEFAULT_MAX_TERM_SIZE, Max))), - ?assertEqual(<<"hello">>, jsonify("hello", ?DEFAULT_MAX_TERM_SIZE, Max)), - ?assert(is_binary(jsonify([{a, b}], ?DEFAULT_MAX_TERM_SIZE, Max))), - ?assertEqual(<<"lists:reverse/1">>, jsonify({lists, reverse, 1}, ?DEFAULT_MAX_TERM_SIZE, Max)), - ?assert(is_binary(jsonify(make_ref(), ?DEFAULT_MAX_TERM_SIZE, Max))). - -format_keyval_list_test() -> - Event = #{level => info, msg => {report, [{key, <<"val">>}]}, meta => #{}}, - {ok, Decoded} = thoas:decode(format(Event, #{})), - ?assertEqual(<<"val">>, maps:get(<<"key">>, Decoded)). - -format_format_terms_test() -> - Event = #{level => info, msg => {"hello ~s", ["world"]}, meta => #{}}, - {ok, Decoded} = thoas:decode(format(Event, #{})), - ?assertEqual(<<"hello world">>, maps:get(<<"text">>, Decoded)). - -format_error_logger_test() -> - Event = #{ - level => error, - msg => - {report, #{ - format => "error: ~p", - args => [bad], - label => {error_logger, error} - }}, - meta => #{} - }, - {ok, Decoded} = thoas:decode(format(Event, #{})), - ?assert(maps:is_key(<<"text">>, Decoded)). - -nested_map_test() -> - Event = #{level => info, msg => {report, #{outer => #{inner => value}}}, meta => #{}}, - {ok, Decoded} = thoas:decode(format(Event, #{})), - ?assertEqual(#{<<"inner">> => <<"value">>}, maps:get(<<"outer">>, Decoded)). - -list_of_maps_test() -> - Event = #{level => info, msg => {report, #{items => [#{a => 1}, #{b => 2}]}}, meta => #{}}, - {ok, Decoded} = thoas:decode(format(Event, #{})), - ?assertEqual([#{<<"a">> => 1}, #{<<"b">> => 2}], maps:get(<<"items">>, Decoded)). - -system_time_to_iso8601_test() -> - Epoch = erlang:system_time(microsecond), - Result = system_time_to_iso8601(Epoch), - ?assert(is_binary(Result)), - ?assert(byte_size(Result) > 10). - -system_time_to_iso8601_nano_test() -> - Epoch = erlang:system_time(microsecond), - Result = system_time_to_iso8601_nano(Epoch), - ?assert(is_binary(Result)), - ?assert(byte_size(Result) > 10). - -format_port_test() -> - Port = hd(erlang:ports()), - Result = jsonify(Port, ?DEFAULT_MAX_TERM_SIZE, ?DEFAULT_MAX_STRING_LENGTH), - ?assert(is_binary(Result)). - -%%%--- Schema tests ---------------------------------------------------- -nova_schema_default_timestamp_test() -> - Event = #{level => info, msg => {report, #{x => 1}}, meta => #{time => 1}}, - {ok, Decoded} = thoas:decode(format(Event, #{})), - Time = maps:get(<<"time">>, Decoded), - ?assert(is_binary(Time)), - ?assert(binary:match(Time, <<"T">>) =/= nomatch). - -ecs_schema_test() -> - Event = #{ - level => info, - msg => {report, #{text => <<"hello">>}}, - meta => #{ - time => 1700000000000000, - trace_id => <<"abc">>, - span_id => <<"def">> - } - }, - {ok, D} = thoas:decode(format(Event, #{schema => ecs})), - ?assertEqual(<<"info">>, maps:get(<<"log.level">>, D)), - ?assert(maps:is_key(<<"@timestamp">>, D)), - ?assertEqual(<<"hello">>, maps:get(<<"message">>, D)), - ?assertEqual(<<"abc">>, maps:get(<<"trace.id">>, D)), - ?assertEqual(<<"def">>, maps:get(<<"span.id">>, D)). - -otel_schema_test() -> - Event = #{ - level => warning, - msg => {report, #{text => <<"watch out">>}}, - meta => #{ - time => 1700000000000000, - trace_id => <<"abc">>, - span_id => <<"def">> - } - }, - {ok, D} = thoas:decode(format(Event, #{schema => otel})), - ?assertEqual(<<"WARNING">>, maps:get(<<"SeverityText">>, D)), - ?assertEqual(13, maps:get(<<"SeverityNumber">>, D)), - ?assertEqual(<<"watch out">>, maps:get(<<"Body">>, D)), - ?assertEqual(<<"abc">>, maps:get(<<"TraceId">>, D)), - ?assertEqual(<<"def">>, maps:get(<<"SpanId">>, D)), - ?assert(maps:is_key(<<"Timestamp">>, D)). - -gcp_schema_test() -> - Event = #{ - level => error, - msg => {report, #{text => <<"bad">>}}, - meta => #{trace_id => <<"abc">>, span_id => <<"def">>} - }, - {ok, D} = thoas:decode(format(Event, #{schema => gcp})), - ?assertEqual(<<"ERROR">>, maps:get(<<"severity">>, D)), - ?assertEqual(<<"bad">>, maps:get(<<"message">>, D)), - ?assertEqual(<<"abc">>, maps:get(<<"logging.googleapis.com/trace">>, D)), - ?assertEqual(<<"def">>, maps:get(<<"logging.googleapis.com/spanId">>, D)). - -datadog_schema_test() -> - Event = #{ - level => info, - msg => {report, #{text => <<"hi">>}}, - meta => #{trace_id => <<"abc">>, span_id => <<"def">>} - }, - {ok, D} = thoas:decode(format(Event, #{schema => datadog})), - ?assertEqual(<<"info">>, maps:get(<<"status">>, D)), - ?assertEqual(<<"hi">>, maps:get(<<"message">>, D)), - ?assertEqual(<<"abc">>, maps:get(<<"dd.trace_id">>, D)), - ?assertEqual(<<"def">>, maps:get(<<"dd.span_id">>, D)). - -ecs_source_location_test() -> - Event = #{ - level => info, - msg => {report, #{text => <<"hi">>}}, - meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} - }, - {ok, D} = thoas:decode(format(Event, #{schema => ecs})), - ?assertEqual(<<"foo.erl">>, maps:get(<<"log.origin.file.name">>, D)), - ?assertEqual(42, maps:get(<<"log.origin.file.line">>, D)), - ?assertEqual(<<"mod:fun_/1">>, maps:get(<<"log.origin.function">>, D)). - -gcp_source_location_test() -> - Event = #{ - level => info, - msg => {report, #{text => <<"hi">>}}, - meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} - }, - {ok, D} = thoas:decode(format(Event, #{schema => gcp})), - Loc = maps:get(<<"logging.googleapis.com/sourceLocation">>, D), - ?assertEqual(<<"foo.erl">>, maps:get(<<"file">>, Loc)), - ?assertEqual(42, maps:get(<<"line">>, Loc)). - -%%%--- Severity number boundaries -------------------------------------- -severity_number_test() -> - ?assertEqual(5, severity_number(debug)), - ?assertEqual(9, severity_number(info)), - ?assertEqual(13, severity_number(warning)), - ?assertEqual(17, severity_number(error)), - ?assertEqual(22, severity_number(alert)), - ?assertEqual(24, severity_number(emergency)), - ?assertEqual(0, severity_number(weird_value)). - -%%%--- Structured error tests ------------------------------------------ -extract_error_from_stacktrace_test() -> - Event = #{ - level => error, - msg => {report, #{text => <<"boom">>}}, - meta => #{ - class => error, - reason => badarg, - stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] - } - }, - {ok, D} = thoas:decode(format(Event, #{})), - Err = maps:get(<<"error">>, D), - ?assertEqual(<<"error">>, maps:get(<<"type">>, Err)), - ?assertEqual(<<"badarg">>, maps:get(<<"reason">>, Err)), - [Frame | _] = maps:get(<<"stacktrace">>, Err), - ?assertEqual(<<"mymod:myfun/2">>, maps:get(<<"mfa">>, Frame)), - ?assertEqual(<<"mymod.erl">>, maps:get(<<"file">>, Frame)), - ?assertEqual(17, maps:get(<<"line">>, Frame)). - -extract_error_ecs_test() -> - Event = #{ - level => error, - msg => {report, #{}}, - meta => #{ - class => error, - reason => badarg, - stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] - } - }, - {ok, D} = thoas:decode(format(Event, #{schema => ecs})), - ?assertEqual(<<"error">>, maps:get(<<"error.type">>, D)), - ?assertEqual(<<"badarg">>, maps:get(<<"error.message">>, D)), - ?assert(is_list(maps:get(<<"error.stack_trace">>, D))). - -extract_error_otel_test() -> - Event = #{ - level => error, - msg => {report, #{}}, - meta => #{ - class => exit, - reason => normal, - stacktrace => [{m, f, 0, []}] - } - }, - {ok, D} = thoas:decode(format(Event, #{schema => otel})), - ?assertEqual(<<"exit">>, maps:get(<<"exception.type">>, D)), - ?assertEqual(<<"normal">>, maps:get(<<"exception.message">>, D)), - ?assert(is_list(maps:get(<<"exception.stacktrace">>, D))). - -%%%--- Redaction tests ------------------------------------------------- -redact_top_level_test() -> - Event = #{ - level => info, - msg => {report, #{user => <<"alice">>, password => <<"secret">>}}, - meta => #{} - }, - Config = #{redact => [[password]]}, - {ok, D} = thoas:decode(format(Event, Config)), - ?assertEqual(<<"[REDACTED]">>, maps:get(<<"password">>, D)), - ?assertEqual(<<"alice">>, maps:get(<<"user">>, D)). - -redact_nested_test() -> - Event = #{ - level => info, - msg => - {report, #{ - req => #{ - headers => #{authorization => <<"bearer abc">>, host => <<"x">>} - } - }}, - meta => #{} - }, - Config = #{redact => [[req, headers, authorization]]}, - {ok, D} = thoas:decode(format(Event, Config)), - Headers = maps:get(<<"headers">>, maps:get(<<"req">>, D)), - ?assertEqual(<<"[REDACTED]">>, maps:get(<<"authorization">>, Headers)), - ?assertEqual(<<"x">>, maps:get(<<"host">>, Headers)). - -redact_missing_path_test() -> - Event = #{level => info, msg => {report, #{a => 1}}, meta => #{}}, - Config = #{redact => [[nope, nothing]]}, - {ok, D} = thoas:decode(format(Event, Config)), - ?assertEqual(1, maps:get(<<"a">>, D)). - -%%%--- Size cap tests -------------------------------------------------- -cap_binary_test() -> - Big = binary:copy(<<"x">>, 1000), - Capped = cap_binary(Big, 100), - ?assert(byte_size(Capped) > 100), - ?assert(byte_size(Capped) < 200), - ?assertEqual(?TRUNCATED_MARKER, binary:part(Capped, byte_size(Capped) - byte_size(?TRUNCATED_MARKER), byte_size(?TRUNCATED_MARKER))). - -cap_term_in_pipeline_test() -> - Huge = lists:duplicate(5000, {complex, term, here}), - Event = #{level => info, msg => {report, #{blob => Huge}}, meta => #{}}, - Config = #{max_term_size => 200}, - {ok, D} = thoas:decode(format(Event, Config)), - Blob = maps:get(<<"blob">>, D), - ?assert(is_binary(Blob)), - ?assert(byte_size(Blob) < 400). - -cap_string_in_pipeline_test() -> - Big = binary:copy(<<"a">>, 5000), - Event = #{level => info, msg => {report, #{s => Big}}, meta => #{}}, - Config = #{max_string_length => 50}, - {ok, D} = thoas:decode(format(Event, Config)), - S = maps:get(<<"s">>, D), - ?assert(byte_size(S) < 200). - --endif. diff --git a/test/nova_jsonlogger_tests.erl b/test/nova_jsonlogger_tests.erl new file mode 100644 index 0000000..d65bdd8 --- /dev/null +++ b/test/nova_jsonlogger_tests.erl @@ -0,0 +1,418 @@ +-module(nova_jsonlogger_tests). +-include_lib("eunit/include/eunit.hrl"). + +-define(DEFAULT_MAX_TERM_SIZE, 8192). +-define(DEFAULT_MAX_STRING_LENGTH, 8192). +-define(TRUNCATED_MARKER, <<"...[truncated]">>). + +-define(assertJSONEqual(Expected, Actual), + (fun() -> + JsonLib = nova:get_env(json_lib, thoas), + ?assertEqual(JsonLib:decode(Expected), JsonLib:decode(Actual)) + end)() +). + +format(Event, Config) -> + nova_jsonlogger:format(Event, Config). + +format_test() -> + ?assertJSONEqual( + <<"{\"level\":\"alert\",\"text\":\"derp\"}">>, + format(#{level => alert, msg => {string, "derp"}, meta => #{}}, #{}) + ), + ?assertJSONEqual( + <<"{\"herp\":\"derp\",\"level\":\"alert\"}">>, + format(#{level => alert, msg => {report, #{herp => derp}}, meta => #{}}, #{}) + ). + +format_funs_test() -> + Config1 = #{ + format_funs => #{ + time => fun(T) when is_binary(T) -> <> end, + level => fun(alert) -> info end + } + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, Decoded} = JsonLib:decode( + format(#{level => alert, msg => {string, "derp"}, meta => #{time => 1}}, Config1) + ), + ?assertEqual(<<"info">>, maps:get(<<"level">>, Decoded)), + ?assertEqual(<<"derp">>, maps:get(<<"text">>, Decoded)), + Time = maps:get(<<"time">>, Decoded), + ?assert(is_binary(Time)), + ?assertEqual($!, binary:last(Time)). + +key_mapping_test() -> + Config1 = #{ + key_mapping => #{ + level => lvl, + text => message + } + }, + ?assertJSONEqual( + <<"{\"lvl\":\"alert\",\"message\":\"derp\"}">>, + format(#{level => alert, msg => {string, "derp"}, meta => #{}}, Config1) + ), + + Config2 = #{ + key_mapping => #{ + level => lvl, + text => level + } + }, + ?assertJSONEqual( + <<"{\"level\":\"derp\",\"lvl\":\"alert\"}">>, + format(#{level => alert, msg => {string, "derp"}, meta => #{}}, Config2) + ). + +list_format_test() -> + ErrorReport = + #{ + level => error, + meta => #{}, + msg => {report, #{report => [{hej, "hopp"}]}} + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, Decoded} = JsonLib:decode(format(ErrorReport, #{})), + ?assertEqual(<<"error">>, maps:get(<<"level">>, Decoded)), + ReportBin = maps:get(<<"report">>, Decoded), + ?assert(is_binary(ReportBin)). + +meta_without_test() -> + Error = #{ + level => info, + msg => {report, #{answer => 42}}, + meta => #{secret => xyz} + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D1} = JsonLib:decode(format(Error, #{})), + ?assertEqual(42, maps:get(<<"answer">>, D1)), + ?assertEqual(<<"info">>, maps:get(<<"level">>, D1)), + ?assertEqual(<<"xyz">>, maps:get(<<"secret">>, D1)), + + Config2 = #{meta_without => [secret]}, + {ok, D2} = JsonLib:decode(format(Error, Config2)), + ?assertNot(maps:is_key(<<"secret">>, D2)). + +meta_with_test() -> + Error = #{ + level => info, + msg => {report, #{answer => 42}}, + meta => #{secret => xyz} + }, + Config = #{meta_with => [level]}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Error, Config)), + ?assertNot(maps:is_key(<<"secret">>, D)), + ?assertEqual(<<"info">>, maps:get(<<"level">>, D)). + +newline_test() -> + ConfigDefault = #{new_line => true}, + Out = format(#{level => alert, msg => {string, "derp"}, meta => #{}}, ConfigDefault), + ?assertEqual(<<"\n">>, lists:last(Out)). + +newline_types_test() -> + Base = #{level => alert, msg => {string, "x"}, meta => #{}}, + ?assertEqual(<<"\n">>, lists:last(format(Base, #{new_line => true, new_line_type => nl}))), + ?assertEqual(<<"\r\n">>, lists:last(format(Base, #{new_line => true, new_line_type => crlf}))), + ?assertEqual(<<"\r">>, lists:last(format(Base, #{new_line => true, new_line_type => cr}))), + ?assertEqual(<<"\n">>, lists:last(format(Base, #{new_line => true}))). + +no_newline_test() -> + Base = #{level => alert, msg => {string, "x"}, meta => #{}}, + Result = format(Base, #{}), + ?assert(is_binary(Result)). + +jsonify_types_test() -> + Max = ?DEFAULT_MAX_STRING_LENGTH, + ?assertEqual(hello, nova_jsonlogger:jsonify(hello, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assertEqual(<<"bin">>, nova_jsonlogger:jsonify(<<"bin">>, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assertEqual(42, nova_jsonlogger:jsonify(42, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assertEqual(3.14, nova_jsonlogger:jsonify(3.14, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assertEqual(true, nova_jsonlogger:jsonify(true, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assert(is_binary(nova_jsonlogger:jsonify(self(), ?DEFAULT_MAX_TERM_SIZE, Max))), + ?assert(is_binary(nova_jsonlogger:jsonify(fun erlang:now/0, ?DEFAULT_MAX_TERM_SIZE, Max))), + ?assertEqual(<<"hello">>, nova_jsonlogger:jsonify("hello", ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assert(is_binary(nova_jsonlogger:jsonify([{a, b}], ?DEFAULT_MAX_TERM_SIZE, Max))), + ?assertEqual(<<"lists:reverse/1">>, nova_jsonlogger:jsonify({lists, reverse, 1}, ?DEFAULT_MAX_TERM_SIZE, Max)), + ?assert(is_binary(nova_jsonlogger:jsonify(make_ref(), ?DEFAULT_MAX_TERM_SIZE, Max))). + +format_keyval_list_test() -> + Event = #{level => info, msg => {report, [{key, <<"val">>}]}, meta => #{}}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, Decoded} = JsonLib:decode(format(Event, #{})), + ?assertEqual(<<"val">>, maps:get(<<"key">>, Decoded)). + +format_format_terms_test() -> + Event = #{level => info, msg => {"hello ~s", ["world"]}, meta => #{}}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, Decoded} = JsonLib:decode(format(Event, #{})), + ?assertEqual(<<"hello world">>, maps:get(<<"text">>, Decoded)). + +format_error_logger_test() -> + Event = #{ + level => error, + msg => + {report, #{ + format => "error: ~p", + args => [bad], + label => {error_logger, error} + }}, + meta => #{} + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, Decoded} = JsonLib:decode(format(Event, #{})), + ?assert(maps:is_key(<<"text">>, Decoded)). + +nested_map_test() -> + Event = #{level => info, msg => {report, #{outer => #{inner => value}}}, meta => #{}}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, Decoded} = JsonLib:decode(format(Event, #{})), + ?assertEqual(#{<<"inner">> => <<"value">>}, maps:get(<<"outer">>, Decoded)). + +list_of_maps_test() -> + Event = #{level => info, msg => {report, #{items => [#{a => 1}, #{b => 2}]}}, meta => #{}}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, Decoded} = JsonLib:decode(format(Event, #{})), + ?assertEqual([#{<<"a">> => 1}, #{<<"b">> => 2}], maps:get(<<"items">>, Decoded)). + +system_time_to_iso8601_test() -> + Epoch = erlang:system_time(microsecond), + Result = nova_jsonlogger:system_time_to_iso8601(Epoch), + ?assert(is_binary(Result)), + ?assert(byte_size(Result) > 10). + +system_time_to_iso8601_nano_test() -> + Epoch = erlang:system_time(microsecond), + Result = nova_jsonlogger:system_time_to_iso8601_nano(Epoch), + ?assert(is_binary(Result)), + ?assert(byte_size(Result) > 10). + +format_port_test() -> + Port = hd(erlang:ports()), + Result = nova_jsonlogger:jsonify(Port, ?DEFAULT_MAX_TERM_SIZE, ?DEFAULT_MAX_STRING_LENGTH), + ?assert(is_binary(Result)). + +%%%--- Schema tests ---------------------------------------------------- +nova_schema_default_timestamp_test() -> + Event = #{level => info, msg => {report, #{x => 1}}, meta => #{time => 1}}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, Decoded} = JsonLib:decode(format(Event, #{})), + Time = maps:get(<<"time">>, Decoded), + ?assert(is_binary(Time)), + ?assert(binary:match(Time, <<"T">>) =/= nomatch). + +ecs_schema_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hello">>}}, + meta => #{ + time => 1700000000000000, + trace_id => <<"abc">>, + span_id => <<"def">> + } + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{schema => ecs})), + ?assertEqual(<<"info">>, maps:get(<<"log.level">>, D)), + ?assert(maps:is_key(<<"@timestamp">>, D)), + ?assertEqual(<<"hello">>, maps:get(<<"message">>, D)), + ?assertEqual(<<"abc">>, maps:get(<<"trace.id">>, D)), + ?assertEqual(<<"def">>, maps:get(<<"span.id">>, D)). + +otel_schema_test() -> + Event = #{ + level => warning, + msg => {report, #{text => <<"watch out">>}}, + meta => #{ + time => 1700000000000000, + trace_id => <<"abc">>, + span_id => <<"def">> + } + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{schema => otel})), + ?assertEqual(<<"WARNING">>, maps:get(<<"SeverityText">>, D)), + ?assertEqual(13, maps:get(<<"SeverityNumber">>, D)), + ?assertEqual(<<"watch out">>, maps:get(<<"Body">>, D)), + ?assertEqual(<<"abc">>, maps:get(<<"TraceId">>, D)), + ?assertEqual(<<"def">>, maps:get(<<"SpanId">>, D)), + ?assert(maps:is_key(<<"Timestamp">>, D)). + +gcp_schema_test() -> + Event = #{ + level => error, + msg => {report, #{text => <<"bad">>}}, + meta => #{trace_id => <<"abc">>, span_id => <<"def">>} + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{schema => gcp})), + ?assertEqual(<<"ERROR">>, maps:get(<<"severity">>, D)), + ?assertEqual(<<"bad">>, maps:get(<<"message">>, D)), + ?assertEqual(<<"abc">>, maps:get(<<"logging.googleapis.com/trace">>, D)), + ?assertEqual(<<"def">>, maps:get(<<"logging.googleapis.com/spanId">>, D)). + +datadog_schema_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hi">>}}, + meta => #{trace_id => <<"abc">>, span_id => <<"def">>} + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{schema => datadog})), + ?assertEqual(<<"info">>, maps:get(<<"status">>, D)), + ?assertEqual(<<"hi">>, maps:get(<<"message">>, D)), + ?assertEqual(<<"abc">>, maps:get(<<"dd.trace_id">>, D)), + ?assertEqual(<<"def">>, maps:get(<<"dd.span_id">>, D)). + +ecs_source_location_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hi">>}}, + meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{schema => ecs})), + ?assertEqual(<<"foo.erl">>, maps:get(<<"log.origin.file.name">>, D)), + ?assertEqual(42, maps:get(<<"log.origin.file.line">>, D)), + ?assertEqual(<<"mod:fun_/1">>, maps:get(<<"log.origin.function">>, D)). + +gcp_source_location_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hi">>}}, + meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{schema => gcp})), + Loc = maps:get(<<"logging.googleapis.com/sourceLocation">>, D), + ?assertEqual(<<"foo.erl">>, maps:get(<<"file">>, Loc)), + ?assertEqual(42, maps:get(<<"line">>, Loc)). + +%%%--- Severity number boundaries -------------------------------------- +severity_number_test() -> + ?assertEqual(5, nova_jsonlogger:severity_number(debug)), + ?assertEqual(9, nova_jsonlogger:severity_number(info)), + ?assertEqual(13, nova_jsonlogger:severity_number(warning)), + ?assertEqual(17, nova_jsonlogger:severity_number(error)), + ?assertEqual(22, nova_jsonlogger:severity_number(alert)), + ?assertEqual(24, nova_jsonlogger:severity_number(emergency)), + ?assertEqual(0, nova_jsonlogger:severity_number(weird_value)). + +%%%--- Structured error tests ------------------------------------------ +extract_error_from_stacktrace_test() -> + Event = #{ + level => error, + msg => {report, #{text => <<"boom">>}}, + meta => #{ + class => error, + reason => badarg, + stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] + } + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{})), + Err = maps:get(<<"error">>, D), + ?assertEqual(<<"error">>, maps:get(<<"type">>, Err)), + ?assertEqual(<<"badarg">>, maps:get(<<"reason">>, Err)), + [Frame | _] = maps:get(<<"stacktrace">>, Err), + ?assertEqual(<<"mymod:myfun/2">>, maps:get(<<"mfa">>, Frame)), + ?assertEqual(<<"mymod.erl">>, maps:get(<<"file">>, Frame)), + ?assertEqual(17, maps:get(<<"line">>, Frame)). + +extract_error_ecs_test() -> + Event = #{ + level => error, + msg => {report, #{}}, + meta => #{ + class => error, + reason => badarg, + stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] + } + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{schema => ecs})), + ?assertEqual(<<"error">>, maps:get(<<"error.type">>, D)), + ?assertEqual(<<"badarg">>, maps:get(<<"error.message">>, D)), + ?assert(is_list(maps:get(<<"error.stack_trace">>, D))). + +extract_error_otel_test() -> + Event = #{ + level => error, + msg => {report, #{}}, + meta => #{ + class => exit, + reason => normal, + stacktrace => [{m, f, 0, []}] + } + }, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, #{schema => otel})), + ?assertEqual(<<"exit">>, maps:get(<<"exception.type">>, D)), + ?assertEqual(<<"normal">>, maps:get(<<"exception.message">>, D)), + ?assert(is_list(maps:get(<<"exception.stacktrace">>, D))). + +%%%--- Redaction tests ------------------------------------------------- +redact_top_level_test() -> + Event = #{ + level => info, + msg => {report, #{user => <<"alice">>, password => <<"secret">>}}, + meta => #{} + }, + Config = #{redact => [[password]]}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, Config)), + ?assertEqual(<<"[REDACTED]">>, maps:get(<<"password">>, D)), + ?assertEqual(<<"alice">>, maps:get(<<"user">>, D)). + +redact_nested_test() -> + Event = #{ + level => info, + msg => + {report, #{ + req => #{ + headers => #{authorization => <<"bearer abc">>, host => <<"x">>} + } + }}, + meta => #{} + }, + Config = #{redact => [[req, headers, authorization]]}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, Config)), + Headers = maps:get(<<"headers">>, maps:get(<<"req">>, D)), + ?assertEqual(<<"[REDACTED]">>, maps:get(<<"authorization">>, Headers)), + ?assertEqual(<<"x">>, maps:get(<<"host">>, Headers)). + +redact_missing_path_test() -> + Event = #{level => info, msg => {report, #{a => 1}}, meta => #{}}, + Config = #{redact => [[nope, nothing]]}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, Config)), + ?assertEqual(1, maps:get(<<"a">>, D)). + +%%%--- Size cap tests -------------------------------------------------- +cap_binary_test() -> + Big = binary:copy(<<"x">>, 1000), + Capped = nova_jsonlogger:cap_binary(Big, 100), + ?assert(byte_size(Capped) > 100), + ?assert(byte_size(Capped) < 200), + ?assertEqual(?TRUNCATED_MARKER, binary:part(Capped, byte_size(Capped) - byte_size(?TRUNCATED_MARKER), byte_size(?TRUNCATED_MARKER))). + +cap_term_in_pipeline_test() -> + Huge = lists:duplicate(5000, {complex, term, here}), + Event = #{level => info, msg => {report, #{blob => Huge}}, meta => #{}}, + Config = #{max_term_size => 200}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, Config)), + Blob = maps:get(<<"blob">>, D), + ?assert(is_binary(Blob)), + ?assert(byte_size(Blob) < 400). + +cap_string_in_pipeline_test() -> + Big = binary:copy(<<"a">>, 5000), + Event = #{level => info, msg => {report, #{s => Big}}, meta => #{}}, + Config = #{max_string_length => 50}, + JsonLib = nova:get_env(json_lib, thoas), + {ok, D} = JsonLib:decode(format(Event, Config)), + S = maps:get(<<"s">>, D), + ?assert(byte_size(S) < 200). From 86dfbf63fb40a13ada782d73c8a5daa86404fab4 Mon Sep 17 00:00:00 2001 From: Daniel Widgren Date: Tue, 26 May 2026 20:51:21 +0200 Subject: [PATCH 5/7] refactor(jsonlogger): fetch json_lib via shared ?JSONLIB macro Route JSON encoding/decoding through a single configurable ?JSONLIB macro in nova.hrl instead of resolving the library at each call site. Addresses review feedback on hard-coded json-lib usage. --- include/nova.hrl | 2 + src/nova_jsonlogger.erl | 5 ++- test/nova_jsonlogger_tests.erl | 80 ++++++++++++---------------------- 3 files changed, 32 insertions(+), 55 deletions(-) diff --git a/include/nova.hrl b/include/nova.hrl index 821022f..2b3217c 100644 --- a/include/nova.hrl +++ b/include/nova.hrl @@ -1,3 +1,5 @@ +-define(JSONLIB, (nova:get_env(json_lib, thoas))). + -define(LOG_DEPRECATED(SinceVersion, Msg), logger:warning(<<"Deprecation warning. Since version: ~s, Message: ~s~nRead more about deprecations on https://github.com/novaframework/nova/blob/master/guides/deprecations.md">>, [SinceVersion, Msg])). -define(LOG_DEPRECATED(SinceVersion, Msg, File), logger:warning(<<"Deprecation warning. Since version: ~s, Message: ~s~nRead more about deprecations on https://github.com/novaframework/nova/blob/master/guides/deprecations.md\nFound in file: ~s">>, [SinceVersion, Msg, File])). diff --git a/src/nova_jsonlogger.erl b/src/nova_jsonlogger.erl index 9f81333..f5cdf21 100644 --- a/src/nova_jsonlogger.erl +++ b/src/nova_jsonlogger.erl @@ -77,6 +77,8 @@ these automatically inside each HTTP request. -export_type([config/0, schema/0, redact_path/0]). +-include("../include/nova.hrl"). + -define(NEW_LINE, false). -define(DEFAULT_MAX_TERM_SIZE, 8192). -define(DEFAULT_MAX_STRING_LENGTH, 8192). @@ -422,8 +424,7 @@ walk(Data, _, _) -> Data. encode(Data, Config) -> - JsonLib = nova:get_env(json_lib, thoas), - Json = JsonLib:encode(Data), + Json = ?JSONLIB:encode(Data), case new_line(Config) of true -> [Json, new_line_type(Config)]; false -> Json diff --git a/test/nova_jsonlogger_tests.erl b/test/nova_jsonlogger_tests.erl index d65bdd8..e28f2e8 100644 --- a/test/nova_jsonlogger_tests.erl +++ b/test/nova_jsonlogger_tests.erl @@ -1,15 +1,13 @@ -module(nova_jsonlogger_tests). -include_lib("eunit/include/eunit.hrl"). +-include("../include/nova.hrl"). -define(DEFAULT_MAX_TERM_SIZE, 8192). -define(DEFAULT_MAX_STRING_LENGTH, 8192). -define(TRUNCATED_MARKER, <<"...[truncated]">>). -define(assertJSONEqual(Expected, Actual), - (fun() -> - JsonLib = nova:get_env(json_lib, thoas), - ?assertEqual(JsonLib:decode(Expected), JsonLib:decode(Actual)) - end)() + ?assertEqual(?JSONLIB:decode(Expected), ?JSONLIB:decode(Actual)) ). format(Event, Config) -> @@ -32,8 +30,7 @@ format_funs_test() -> level => fun(alert) -> info end } }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, Decoded} = JsonLib:decode( + {ok, Decoded} = ?JSONLIB:decode( format(#{level => alert, msg => {string, "derp"}, meta => #{time => 1}}, Config1) ), ?assertEqual(<<"info">>, maps:get(<<"level">>, Decoded)), @@ -72,8 +69,7 @@ list_format_test() -> meta => #{}, msg => {report, #{report => [{hej, "hopp"}]}} }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, Decoded} = JsonLib:decode(format(ErrorReport, #{})), + {ok, Decoded} = ?JSONLIB:decode(format(ErrorReport, #{})), ?assertEqual(<<"error">>, maps:get(<<"level">>, Decoded)), ReportBin = maps:get(<<"report">>, Decoded), ?assert(is_binary(ReportBin)). @@ -84,14 +80,13 @@ meta_without_test() -> msg => {report, #{answer => 42}}, meta => #{secret => xyz} }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D1} = JsonLib:decode(format(Error, #{})), + {ok, D1} = ?JSONLIB:decode(format(Error, #{})), ?assertEqual(42, maps:get(<<"answer">>, D1)), ?assertEqual(<<"info">>, maps:get(<<"level">>, D1)), ?assertEqual(<<"xyz">>, maps:get(<<"secret">>, D1)), Config2 = #{meta_without => [secret]}, - {ok, D2} = JsonLib:decode(format(Error, Config2)), + {ok, D2} = ?JSONLIB:decode(format(Error, Config2)), ?assertNot(maps:is_key(<<"secret">>, D2)). meta_with_test() -> @@ -101,8 +96,7 @@ meta_with_test() -> meta => #{secret => xyz} }, Config = #{meta_with => [level]}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Error, Config)), + {ok, D} = ?JSONLIB:decode(format(Error, Config)), ?assertNot(maps:is_key(<<"secret">>, D)), ?assertEqual(<<"info">>, maps:get(<<"level">>, D)). @@ -139,14 +133,12 @@ jsonify_types_test() -> format_keyval_list_test() -> Event = #{level => info, msg => {report, [{key, <<"val">>}]}, meta => #{}}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, Decoded} = JsonLib:decode(format(Event, #{})), + {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), ?assertEqual(<<"val">>, maps:get(<<"key">>, Decoded)). format_format_terms_test() -> Event = #{level => info, msg => {"hello ~s", ["world"]}, meta => #{}}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, Decoded} = JsonLib:decode(format(Event, #{})), + {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), ?assertEqual(<<"hello world">>, maps:get(<<"text">>, Decoded)). format_error_logger_test() -> @@ -160,20 +152,17 @@ format_error_logger_test() -> }}, meta => #{} }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, Decoded} = JsonLib:decode(format(Event, #{})), + {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), ?assert(maps:is_key(<<"text">>, Decoded)). nested_map_test() -> Event = #{level => info, msg => {report, #{outer => #{inner => value}}}, meta => #{}}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, Decoded} = JsonLib:decode(format(Event, #{})), + {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), ?assertEqual(#{<<"inner">> => <<"value">>}, maps:get(<<"outer">>, Decoded)). list_of_maps_test() -> Event = #{level => info, msg => {report, #{items => [#{a => 1}, #{b => 2}]}}, meta => #{}}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, Decoded} = JsonLib:decode(format(Event, #{})), + {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), ?assertEqual([#{<<"a">> => 1}, #{<<"b">> => 2}], maps:get(<<"items">>, Decoded)). system_time_to_iso8601_test() -> @@ -196,8 +185,7 @@ format_port_test() -> %%%--- Schema tests ---------------------------------------------------- nova_schema_default_timestamp_test() -> Event = #{level => info, msg => {report, #{x => 1}}, meta => #{time => 1}}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, Decoded} = JsonLib:decode(format(Event, #{})), + {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), Time = maps:get(<<"time">>, Decoded), ?assert(is_binary(Time)), ?assert(binary:match(Time, <<"T">>) =/= nomatch). @@ -212,8 +200,7 @@ ecs_schema_test() -> span_id => <<"def">> } }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{schema => ecs})), + {ok, D} = ?JSONLIB:decode(format(Event, #{schema => ecs})), ?assertEqual(<<"info">>, maps:get(<<"log.level">>, D)), ?assert(maps:is_key(<<"@timestamp">>, D)), ?assertEqual(<<"hello">>, maps:get(<<"message">>, D)), @@ -230,8 +217,7 @@ otel_schema_test() -> span_id => <<"def">> } }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{schema => otel})), + {ok, D} = ?JSONLIB:decode(format(Event, #{schema => otel})), ?assertEqual(<<"WARNING">>, maps:get(<<"SeverityText">>, D)), ?assertEqual(13, maps:get(<<"SeverityNumber">>, D)), ?assertEqual(<<"watch out">>, maps:get(<<"Body">>, D)), @@ -245,8 +231,7 @@ gcp_schema_test() -> msg => {report, #{text => <<"bad">>}}, meta => #{trace_id => <<"abc">>, span_id => <<"def">>} }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{schema => gcp})), + {ok, D} = ?JSONLIB:decode(format(Event, #{schema => gcp})), ?assertEqual(<<"ERROR">>, maps:get(<<"severity">>, D)), ?assertEqual(<<"bad">>, maps:get(<<"message">>, D)), ?assertEqual(<<"abc">>, maps:get(<<"logging.googleapis.com/trace">>, D)), @@ -258,8 +243,7 @@ datadog_schema_test() -> msg => {report, #{text => <<"hi">>}}, meta => #{trace_id => <<"abc">>, span_id => <<"def">>} }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{schema => datadog})), + {ok, D} = ?JSONLIB:decode(format(Event, #{schema => datadog})), ?assertEqual(<<"info">>, maps:get(<<"status">>, D)), ?assertEqual(<<"hi">>, maps:get(<<"message">>, D)), ?assertEqual(<<"abc">>, maps:get(<<"dd.trace_id">>, D)), @@ -271,8 +255,7 @@ ecs_source_location_test() -> msg => {report, #{text => <<"hi">>}}, meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{schema => ecs})), + {ok, D} = ?JSONLIB:decode(format(Event, #{schema => ecs})), ?assertEqual(<<"foo.erl">>, maps:get(<<"log.origin.file.name">>, D)), ?assertEqual(42, maps:get(<<"log.origin.file.line">>, D)), ?assertEqual(<<"mod:fun_/1">>, maps:get(<<"log.origin.function">>, D)). @@ -283,8 +266,7 @@ gcp_source_location_test() -> msg => {report, #{text => <<"hi">>}}, meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{schema => gcp})), + {ok, D} = ?JSONLIB:decode(format(Event, #{schema => gcp})), Loc = maps:get(<<"logging.googleapis.com/sourceLocation">>, D), ?assertEqual(<<"foo.erl">>, maps:get(<<"file">>, Loc)), ?assertEqual(42, maps:get(<<"line">>, Loc)). @@ -310,8 +292,7 @@ extract_error_from_stacktrace_test() -> stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] } }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{})), + {ok, D} = ?JSONLIB:decode(format(Event, #{})), Err = maps:get(<<"error">>, D), ?assertEqual(<<"error">>, maps:get(<<"type">>, Err)), ?assertEqual(<<"badarg">>, maps:get(<<"reason">>, Err)), @@ -330,8 +311,7 @@ extract_error_ecs_test() -> stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] } }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{schema => ecs})), + {ok, D} = ?JSONLIB:decode(format(Event, #{schema => ecs})), ?assertEqual(<<"error">>, maps:get(<<"error.type">>, D)), ?assertEqual(<<"badarg">>, maps:get(<<"error.message">>, D)), ?assert(is_list(maps:get(<<"error.stack_trace">>, D))). @@ -346,8 +326,7 @@ extract_error_otel_test() -> stacktrace => [{m, f, 0, []}] } }, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, #{schema => otel})), + {ok, D} = ?JSONLIB:decode(format(Event, #{schema => otel})), ?assertEqual(<<"exit">>, maps:get(<<"exception.type">>, D)), ?assertEqual(<<"normal">>, maps:get(<<"exception.message">>, D)), ?assert(is_list(maps:get(<<"exception.stacktrace">>, D))). @@ -360,8 +339,7 @@ redact_top_level_test() -> meta => #{} }, Config = #{redact => [[password]]}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, Config)), + {ok, D} = ?JSONLIB:decode(format(Event, Config)), ?assertEqual(<<"[REDACTED]">>, maps:get(<<"password">>, D)), ?assertEqual(<<"alice">>, maps:get(<<"user">>, D)). @@ -377,8 +355,7 @@ redact_nested_test() -> meta => #{} }, Config = #{redact => [[req, headers, authorization]]}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, Config)), + {ok, D} = ?JSONLIB:decode(format(Event, Config)), Headers = maps:get(<<"headers">>, maps:get(<<"req">>, D)), ?assertEqual(<<"[REDACTED]">>, maps:get(<<"authorization">>, Headers)), ?assertEqual(<<"x">>, maps:get(<<"host">>, Headers)). @@ -386,8 +363,7 @@ redact_nested_test() -> redact_missing_path_test() -> Event = #{level => info, msg => {report, #{a => 1}}, meta => #{}}, Config = #{redact => [[nope, nothing]]}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, Config)), + {ok, D} = ?JSONLIB:decode(format(Event, Config)), ?assertEqual(1, maps:get(<<"a">>, D)). %%%--- Size cap tests -------------------------------------------------- @@ -402,8 +378,7 @@ cap_term_in_pipeline_test() -> Huge = lists:duplicate(5000, {complex, term, here}), Event = #{level => info, msg => {report, #{blob => Huge}}, meta => #{}}, Config = #{max_term_size => 200}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, Config)), + {ok, D} = ?JSONLIB:decode(format(Event, Config)), Blob = maps:get(<<"blob">>, D), ?assert(is_binary(Blob)), ?assert(byte_size(Blob) < 400). @@ -412,7 +387,6 @@ cap_string_in_pipeline_test() -> Big = binary:copy(<<"a">>, 5000), Event = #{level => info, msg => {report, #{s => Big}}, meta => #{}}, Config = #{max_string_length => 50}, - JsonLib = nova:get_env(json_lib, thoas), - {ok, D} = JsonLib:decode(format(Event, Config)), + {ok, D} = ?JSONLIB:decode(format(Event, Config)), S = maps:get(<<"s">>, D), ?assert(byte_size(S) < 200). From e94fb987a4d4c601e0b6564e7cafbbd020c2998c Mon Sep 17 00:00:00 2001 From: Daniel Widgren Date: Tue, 26 May 2026 22:07:28 +0200 Subject: [PATCH 6/7] refactor(jsonlogger): call nova:get_env for json_lib directly, drop macro Inline nova:get_env(json_lib, thoas) at the call site instead of the shared ?JSONLIB macro in nova.hrl, per review feedback. Tests use a local json_lib/0 helper. --- include/nova.hrl | 2 -- src/nova_jsonlogger.erl | 5 ++- test/nova_jsonlogger_tests.erl | 56 ++++++++++++++++++---------------- 3 files changed, 31 insertions(+), 32 deletions(-) diff --git a/include/nova.hrl b/include/nova.hrl index 2b3217c..821022f 100644 --- a/include/nova.hrl +++ b/include/nova.hrl @@ -1,5 +1,3 @@ --define(JSONLIB, (nova:get_env(json_lib, thoas))). - -define(LOG_DEPRECATED(SinceVersion, Msg), logger:warning(<<"Deprecation warning. Since version: ~s, Message: ~s~nRead more about deprecations on https://github.com/novaframework/nova/blob/master/guides/deprecations.md">>, [SinceVersion, Msg])). -define(LOG_DEPRECATED(SinceVersion, Msg, File), logger:warning(<<"Deprecation warning. Since version: ~s, Message: ~s~nRead more about deprecations on https://github.com/novaframework/nova/blob/master/guides/deprecations.md\nFound in file: ~s">>, [SinceVersion, Msg, File])). diff --git a/src/nova_jsonlogger.erl b/src/nova_jsonlogger.erl index f5cdf21..9f81333 100644 --- a/src/nova_jsonlogger.erl +++ b/src/nova_jsonlogger.erl @@ -77,8 +77,6 @@ these automatically inside each HTTP request. -export_type([config/0, schema/0, redact_path/0]). --include("../include/nova.hrl"). - -define(NEW_LINE, false). -define(DEFAULT_MAX_TERM_SIZE, 8192). -define(DEFAULT_MAX_STRING_LENGTH, 8192). @@ -424,7 +422,8 @@ walk(Data, _, _) -> Data. encode(Data, Config) -> - Json = ?JSONLIB:encode(Data), + JsonLib = nova:get_env(json_lib, thoas), + Json = JsonLib:encode(Data), case new_line(Config) of true -> [Json, new_line_type(Config)]; false -> Json diff --git a/test/nova_jsonlogger_tests.erl b/test/nova_jsonlogger_tests.erl index e28f2e8..d491f6a 100644 --- a/test/nova_jsonlogger_tests.erl +++ b/test/nova_jsonlogger_tests.erl @@ -1,15 +1,17 @@ -module(nova_jsonlogger_tests). -include_lib("eunit/include/eunit.hrl"). --include("../include/nova.hrl"). -define(DEFAULT_MAX_TERM_SIZE, 8192). -define(DEFAULT_MAX_STRING_LENGTH, 8192). -define(TRUNCATED_MARKER, <<"...[truncated]">>). -define(assertJSONEqual(Expected, Actual), - ?assertEqual(?JSONLIB:decode(Expected), ?JSONLIB:decode(Actual)) + ?assertEqual((json_lib()):decode(Expected), (json_lib()):decode(Actual)) ). +json_lib() -> + nova:get_env(json_lib, thoas). + format(Event, Config) -> nova_jsonlogger:format(Event, Config). @@ -30,7 +32,7 @@ format_funs_test() -> level => fun(alert) -> info end } }, - {ok, Decoded} = ?JSONLIB:decode( + {ok, Decoded} = (json_lib()):decode( format(#{level => alert, msg => {string, "derp"}, meta => #{time => 1}}, Config1) ), ?assertEqual(<<"info">>, maps:get(<<"level">>, Decoded)), @@ -69,7 +71,7 @@ list_format_test() -> meta => #{}, msg => {report, #{report => [{hej, "hopp"}]}} }, - {ok, Decoded} = ?JSONLIB:decode(format(ErrorReport, #{})), + {ok, Decoded} = (json_lib()):decode(format(ErrorReport, #{})), ?assertEqual(<<"error">>, maps:get(<<"level">>, Decoded)), ReportBin = maps:get(<<"report">>, Decoded), ?assert(is_binary(ReportBin)). @@ -80,13 +82,13 @@ meta_without_test() -> msg => {report, #{answer => 42}}, meta => #{secret => xyz} }, - {ok, D1} = ?JSONLIB:decode(format(Error, #{})), + {ok, D1} = (json_lib()):decode(format(Error, #{})), ?assertEqual(42, maps:get(<<"answer">>, D1)), ?assertEqual(<<"info">>, maps:get(<<"level">>, D1)), ?assertEqual(<<"xyz">>, maps:get(<<"secret">>, D1)), Config2 = #{meta_without => [secret]}, - {ok, D2} = ?JSONLIB:decode(format(Error, Config2)), + {ok, D2} = (json_lib()):decode(format(Error, Config2)), ?assertNot(maps:is_key(<<"secret">>, D2)). meta_with_test() -> @@ -96,7 +98,7 @@ meta_with_test() -> meta => #{secret => xyz} }, Config = #{meta_with => [level]}, - {ok, D} = ?JSONLIB:decode(format(Error, Config)), + {ok, D} = (json_lib()):decode(format(Error, Config)), ?assertNot(maps:is_key(<<"secret">>, D)), ?assertEqual(<<"info">>, maps:get(<<"level">>, D)). @@ -133,12 +135,12 @@ jsonify_types_test() -> format_keyval_list_test() -> Event = #{level => info, msg => {report, [{key, <<"val">>}]}, meta => #{}}, - {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), + {ok, Decoded} = (json_lib()):decode(format(Event, #{})), ?assertEqual(<<"val">>, maps:get(<<"key">>, Decoded)). format_format_terms_test() -> Event = #{level => info, msg => {"hello ~s", ["world"]}, meta => #{}}, - {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), + {ok, Decoded} = (json_lib()):decode(format(Event, #{})), ?assertEqual(<<"hello world">>, maps:get(<<"text">>, Decoded)). format_error_logger_test() -> @@ -152,17 +154,17 @@ format_error_logger_test() -> }}, meta => #{} }, - {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), + {ok, Decoded} = (json_lib()):decode(format(Event, #{})), ?assert(maps:is_key(<<"text">>, Decoded)). nested_map_test() -> Event = #{level => info, msg => {report, #{outer => #{inner => value}}}, meta => #{}}, - {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), + {ok, Decoded} = (json_lib()):decode(format(Event, #{})), ?assertEqual(#{<<"inner">> => <<"value">>}, maps:get(<<"outer">>, Decoded)). list_of_maps_test() -> Event = #{level => info, msg => {report, #{items => [#{a => 1}, #{b => 2}]}}, meta => #{}}, - {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), + {ok, Decoded} = (json_lib()):decode(format(Event, #{})), ?assertEqual([#{<<"a">> => 1}, #{<<"b">> => 2}], maps:get(<<"items">>, Decoded)). system_time_to_iso8601_test() -> @@ -185,7 +187,7 @@ format_port_test() -> %%%--- Schema tests ---------------------------------------------------- nova_schema_default_timestamp_test() -> Event = #{level => info, msg => {report, #{x => 1}}, meta => #{time => 1}}, - {ok, Decoded} = ?JSONLIB:decode(format(Event, #{})), + {ok, Decoded} = (json_lib()):decode(format(Event, #{})), Time = maps:get(<<"time">>, Decoded), ?assert(is_binary(Time)), ?assert(binary:match(Time, <<"T">>) =/= nomatch). @@ -200,7 +202,7 @@ ecs_schema_test() -> span_id => <<"def">> } }, - {ok, D} = ?JSONLIB:decode(format(Event, #{schema => ecs})), + {ok, D} = (json_lib()):decode(format(Event, #{schema => ecs})), ?assertEqual(<<"info">>, maps:get(<<"log.level">>, D)), ?assert(maps:is_key(<<"@timestamp">>, D)), ?assertEqual(<<"hello">>, maps:get(<<"message">>, D)), @@ -217,7 +219,7 @@ otel_schema_test() -> span_id => <<"def">> } }, - {ok, D} = ?JSONLIB:decode(format(Event, #{schema => otel})), + {ok, D} = (json_lib()):decode(format(Event, #{schema => otel})), ?assertEqual(<<"WARNING">>, maps:get(<<"SeverityText">>, D)), ?assertEqual(13, maps:get(<<"SeverityNumber">>, D)), ?assertEqual(<<"watch out">>, maps:get(<<"Body">>, D)), @@ -231,7 +233,7 @@ gcp_schema_test() -> msg => {report, #{text => <<"bad">>}}, meta => #{trace_id => <<"abc">>, span_id => <<"def">>} }, - {ok, D} = ?JSONLIB:decode(format(Event, #{schema => gcp})), + {ok, D} = (json_lib()):decode(format(Event, #{schema => gcp})), ?assertEqual(<<"ERROR">>, maps:get(<<"severity">>, D)), ?assertEqual(<<"bad">>, maps:get(<<"message">>, D)), ?assertEqual(<<"abc">>, maps:get(<<"logging.googleapis.com/trace">>, D)), @@ -243,7 +245,7 @@ datadog_schema_test() -> msg => {report, #{text => <<"hi">>}}, meta => #{trace_id => <<"abc">>, span_id => <<"def">>} }, - {ok, D} = ?JSONLIB:decode(format(Event, #{schema => datadog})), + {ok, D} = (json_lib()):decode(format(Event, #{schema => datadog})), ?assertEqual(<<"info">>, maps:get(<<"status">>, D)), ?assertEqual(<<"hi">>, maps:get(<<"message">>, D)), ?assertEqual(<<"abc">>, maps:get(<<"dd.trace_id">>, D)), @@ -255,7 +257,7 @@ ecs_source_location_test() -> msg => {report, #{text => <<"hi">>}}, meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} }, - {ok, D} = ?JSONLIB:decode(format(Event, #{schema => ecs})), + {ok, D} = (json_lib()):decode(format(Event, #{schema => ecs})), ?assertEqual(<<"foo.erl">>, maps:get(<<"log.origin.file.name">>, D)), ?assertEqual(42, maps:get(<<"log.origin.file.line">>, D)), ?assertEqual(<<"mod:fun_/1">>, maps:get(<<"log.origin.function">>, D)). @@ -266,7 +268,7 @@ gcp_source_location_test() -> msg => {report, #{text => <<"hi">>}}, meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} }, - {ok, D} = ?JSONLIB:decode(format(Event, #{schema => gcp})), + {ok, D} = (json_lib()):decode(format(Event, #{schema => gcp})), Loc = maps:get(<<"logging.googleapis.com/sourceLocation">>, D), ?assertEqual(<<"foo.erl">>, maps:get(<<"file">>, Loc)), ?assertEqual(42, maps:get(<<"line">>, Loc)). @@ -292,7 +294,7 @@ extract_error_from_stacktrace_test() -> stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] } }, - {ok, D} = ?JSONLIB:decode(format(Event, #{})), + {ok, D} = (json_lib()):decode(format(Event, #{})), Err = maps:get(<<"error">>, D), ?assertEqual(<<"error">>, maps:get(<<"type">>, Err)), ?assertEqual(<<"badarg">>, maps:get(<<"reason">>, Err)), @@ -311,7 +313,7 @@ extract_error_ecs_test() -> stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] } }, - {ok, D} = ?JSONLIB:decode(format(Event, #{schema => ecs})), + {ok, D} = (json_lib()):decode(format(Event, #{schema => ecs})), ?assertEqual(<<"error">>, maps:get(<<"error.type">>, D)), ?assertEqual(<<"badarg">>, maps:get(<<"error.message">>, D)), ?assert(is_list(maps:get(<<"error.stack_trace">>, D))). @@ -326,7 +328,7 @@ extract_error_otel_test() -> stacktrace => [{m, f, 0, []}] } }, - {ok, D} = ?JSONLIB:decode(format(Event, #{schema => otel})), + {ok, D} = (json_lib()):decode(format(Event, #{schema => otel})), ?assertEqual(<<"exit">>, maps:get(<<"exception.type">>, D)), ?assertEqual(<<"normal">>, maps:get(<<"exception.message">>, D)), ?assert(is_list(maps:get(<<"exception.stacktrace">>, D))). @@ -339,7 +341,7 @@ redact_top_level_test() -> meta => #{} }, Config = #{redact => [[password]]}, - {ok, D} = ?JSONLIB:decode(format(Event, Config)), + {ok, D} = (json_lib()):decode(format(Event, Config)), ?assertEqual(<<"[REDACTED]">>, maps:get(<<"password">>, D)), ?assertEqual(<<"alice">>, maps:get(<<"user">>, D)). @@ -355,7 +357,7 @@ redact_nested_test() -> meta => #{} }, Config = #{redact => [[req, headers, authorization]]}, - {ok, D} = ?JSONLIB:decode(format(Event, Config)), + {ok, D} = (json_lib()):decode(format(Event, Config)), Headers = maps:get(<<"headers">>, maps:get(<<"req">>, D)), ?assertEqual(<<"[REDACTED]">>, maps:get(<<"authorization">>, Headers)), ?assertEqual(<<"x">>, maps:get(<<"host">>, Headers)). @@ -363,7 +365,7 @@ redact_nested_test() -> redact_missing_path_test() -> Event = #{level => info, msg => {report, #{a => 1}}, meta => #{}}, Config = #{redact => [[nope, nothing]]}, - {ok, D} = ?JSONLIB:decode(format(Event, Config)), + {ok, D} = (json_lib()):decode(format(Event, Config)), ?assertEqual(1, maps:get(<<"a">>, D)). %%%--- Size cap tests -------------------------------------------------- @@ -378,7 +380,7 @@ cap_term_in_pipeline_test() -> Huge = lists:duplicate(5000, {complex, term, here}), Event = #{level => info, msg => {report, #{blob => Huge}}, meta => #{}}, Config = #{max_term_size => 200}, - {ok, D} = ?JSONLIB:decode(format(Event, Config)), + {ok, D} = (json_lib()):decode(format(Event, Config)), Blob = maps:get(<<"blob">>, D), ?assert(is_binary(Blob)), ?assert(byte_size(Blob) < 400). @@ -387,6 +389,6 @@ cap_string_in_pipeline_test() -> Big = binary:copy(<<"a">>, 5000), Event = #{level => info, msg => {report, #{s => Big}}, meta => #{}}, Config = #{max_string_length => 50}, - {ok, D} = ?JSONLIB:decode(format(Event, Config)), + {ok, D} = (json_lib()):decode(format(Event, Config)), S = maps:get(<<"s">>, D), ?assert(byte_size(S) < 200). From aad5296d579e34ed71ac6203c03f60eb19e8ca1e Mon Sep 17 00:00:00 2001 From: Daniel Widgren Date: Tue, 26 May 2026 23:13:46 +0200 Subject: [PATCH 7/7] refactor(jsonlogger): pattern-match crash_report, document trace provenance Replace the type_and_reason/0 lambda + polymorphic report_value/4 helper with direct error_info/1 clauses and a plain take_into/3, per review. Rewrite the trace-correlation docs to be precise: the formatter relocates trace_id/span_id from log metadata under each schema's conventional key but never generates them; populate upstream via logger:update_process_metadata/1 or the optional opentelemetry_nova plugin (not a nova dependency). Add a code comment at the schema layer noting rename/3 is a no-op when absent. Tests: trace ids surface from metadata and are not invented when absent; crash_report extraction (previously untested) for both tuple and non-tuple error_info. --- src/nova_jsonlogger.erl | 59 +++++++++++++++++++--------------- test/nova_jsonlogger_tests.erl | 48 +++++++++++++++++++++++++++ 2 files changed, 81 insertions(+), 26 deletions(-) diff --git a/src/nova_jsonlogger.erl b/src/nova_jsonlogger.erl index 9f81333..dae5e92 100644 --- a/src/nova_jsonlogger.erl +++ b/src/nova_jsonlogger.erl @@ -41,12 +41,26 @@ Wire it as the formatter on a `logger` handler, typically in `sys.config`: } ``` +## Schema fields + +The schema layer recognises a fixed vocabulary of semantic fields and renders +each under the chosen schema's conventional key: `time`, `level`, `text` (the +message), `trace_id`, `span_id`, a structured `error`, and source location +(`file`/`line`/`mfa`). A field is emitted only if present in the log record. + ## Trace correlation -When `trace_id` and `span_id` are present in process metadata, they are -rendered under each schema's conventional key (`trace.id`/`span.id` for -ECS, `TraceId`/`SpanId` for OTel, etc.). `opentelemetry_nova` populates -these automatically inside each HTTP request. +`nova_jsonlogger` does not generate trace context. If a log record's metadata +carries `trace_id`/`span_id`, they are relocated to the schema's conventional +keys (`trace.id`/`span.id` for ECS, `TraceId`/`SpanId` for OTel, and so on). +Populate them upstream, either by: + +- calling `logger:update_process_metadata(#{trace_id => Id, span_id => Id})` + in your request handling, or +- adding the optional `opentelemetry_nova` plugin, which writes the hex + trace/span ids into logger metadata per request. + +`nova_jsonlogger` itself has no OpenTelemetry dependency. """. -export([ @@ -163,32 +177,23 @@ maybe_take_into(SrcKey, DestKey, Src, Dest) -> end. normalise_crash_report([Proc | _]) when is_list(Proc) -> - M1 = report_value(error_info, type_and_reason(), Proc, #{}), - M2 = report_value(registered_name, registered_name, Proc, M1), - report_value(pid, pid, Proc, M2); + M0 = error_info(lists:keyfind(error_info, 1, Proc)), + M1 = take_into(registered_name, Proc, M0), + take_into(pid, Proc, M1); normalise_crash_report(_) -> #{}. -report_value(Key, As, Proplist, Acc) -> - case lists:keyfind(Key, 1, Proplist) of - {Key, V} when is_function(As, 1) -> - maps:merge(Acc, As(V)); - {Key, V} -> - Acc#{As => V}; - false -> - Acc - end. +error_info({error_info, {Class, Reason, Stack}}) -> + #{type => Class, reason => Reason, stacktrace => normalise_stacktrace(Stack)}; +error_info({error_info, Other}) -> + #{reason => Other}; +error_info(false) -> + #{}. -type_and_reason() -> - fun - ({Class, Reason, Stack}) -> - #{ - type => Class, - reason => Reason, - stacktrace => normalise_stacktrace(Stack) - }; - (Other) -> - #{reason => Other} +take_into(Key, Proplist, Acc) -> + case lists:keyfind(Key, 1, Proplist) of + {Key, V} -> Acc#{Key => V}; + false -> Acc end. normalise_stacktrace(Stack) -> @@ -239,6 +244,8 @@ redact_path(_, Data) -> %%% Schema rendering. Each schema applies a canonical transform from the %%% (msg + meta) map onto the schema's expected field names. +%%% trace_id/span_id are read from the log record's metadata (see merge_meta). +%%% This module never sets them; rename/3 is a no-op when they are absent. apply_schema(Data, Config) -> Schema = maps:get(schema, Config, nova), case Schema of diff --git a/test/nova_jsonlogger_tests.erl b/test/nova_jsonlogger_tests.erl index d491f6a..c8c285a 100644 --- a/test/nova_jsonlogger_tests.erl +++ b/test/nova_jsonlogger_tests.erl @@ -227,6 +227,26 @@ otel_schema_test() -> ?assertEqual(<<"def">>, maps:get(<<"SpanId">>, D)), ?assert(maps:is_key(<<"Timestamp">>, D)). +trace_ids_come_from_metadata_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hi">>}}, + meta => #{trace_id => <<"t-1">>, span_id => <<"s-1">>} + }, + {ok, D} = (json_lib()):decode(format(Event, #{schema => ecs})), + ?assertEqual(<<"t-1">>, maps:get(<<"trace.id">>, D)), + ?assertEqual(<<"s-1">>, maps:get(<<"span.id">>, D)), + ?assertNot(maps:is_key(<<"trace_id">>, D)), + ?assertNot(maps:is_key(<<"span_id">>, D)). + +trace_ids_absent_not_invented_test() -> + Event = #{level => info, msg => {report, #{text => <<"hi">>}}, meta => #{}}, + {ok, D} = (json_lib()):decode(format(Event, #{schema => ecs})), + ?assertNot(maps:is_key(<<"trace.id">>, D)), + ?assertNot(maps:is_key(<<"span.id">>, D)), + ?assertNot(maps:is_key(<<"trace_id">>, D)), + ?assertNot(maps:is_key(<<"span_id">>, D)). + gcp_schema_test() -> Event = #{ level => error, @@ -303,6 +323,34 @@ extract_error_from_stacktrace_test() -> ?assertEqual(<<"mymod.erl">>, maps:get(<<"file">>, Frame)), ?assertEqual(17, maps:get(<<"line">>, Frame)). +crash_report_test() -> + Proc = [ + {pid, self()}, + {registered_name, my_proc}, + {error_info, {error, badarg, [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}]}} + ], + Event = #{ + level => error, + msg => {report, #{}}, + meta => #{crash_report => [Proc, []]} + }, + {ok, D} = (json_lib()):decode(format(Event, #{})), + Err = maps:get(<<"error">>, D), + ?assertEqual(<<"error">>, maps:get(<<"type">>, Err)), + ?assertEqual(<<"badarg">>, maps:get(<<"reason">>, Err)), + ?assertEqual(<<"my_proc">>, maps:get(<<"registered_name">>, Err)), + ?assert(maps:is_key(<<"pid">>, Err)), + [Frame | _] = maps:get(<<"stacktrace">>, Err), + ?assertEqual(<<"mymod:myfun/2">>, maps:get(<<"mfa">>, Frame)). + +crash_report_non_tuple_error_info_test() -> + Proc = [{error_info, some_reason}], + Event = #{level => error, msg => {report, #{}}, meta => #{crash_report => [Proc, []]}}, + {ok, D} = (json_lib()):decode(format(Event, #{})), + Err = maps:get(<<"error">>, D), + ?assertEqual(<<"some_reason">>, maps:get(<<"reason">>, Err)), + ?assertNot(maps:is_key(<<"type">>, Err)). + extract_error_ecs_test() -> Event = #{ level => error,