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 0f2fe82..dae5e92 100644 --- a/src/nova_jsonlogger.erl +++ b/src/nova_jsonlogger.erl @@ -1,36 +1,109 @@ %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% -%%% This module is copied 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 +%%% Originally derived from https://github.com/kivra/jsonformat. %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% - -module(nova_jsonlogger). -%%%_* Exports ========================================================== --export([format/2, - system_time_to_iso8601/1, - system_time_to_iso8601_nano/1]). +-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 +} +``` + +## 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 + +`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([ + format/2, + system_time_to_iso8601/1, + 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()]. -%%%_* Types ============================================================ -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). - -%%%_* Code ============================================================= -%%%_ * API ------------------------------------------------------------- +-define(DEFAULT_MAX_TERM_SIZE, 8192). +-define(DEFAULT_MAX_STRING_LENGTH, 8192). +-define(REDACTED, <<"[REDACTED]">>). +-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 @@ -39,9 +112,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,11 +126,12 @@ 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. +-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). @@ -63,26 +140,293 @@ 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) -> + M0 = error_info(lists:keyfind(error_info, 1, Proc)), + M1 = take_into(registered_name, Proc, M0), + take_into(pid, Proc, M1); +normalise_crash_report(_) -> + #{}. + +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) -> + #{}. + +take_into(Key, Proplist, Acc) -> + case lists:keyfind(Key, 1, Proplist) of + {Key, V} -> Acc#{Key => V}; + false -> Acc + 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. +%%% 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 + 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 +436,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 @@ -157,255 +523,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(Epoch) -> Epoch + 1 end, - level => fun(alert) -> info end - } - }, - ?assertJSONEqual( - <<"{\"level\":\"info\",\"text\":\"derp\",\"time\":2}">>, - 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) - ). - -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) - ), - - 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}, - msg => {report, #{report => [{hej, "hopp"}]}} - }, - ?assertJSONEqual( - <<"{\"level\":\"error\",\"report\":\"[{hej,\\\"hopp\\\"}]\",\"time\":1}">>, - format(ErrorReport, #{}) - ). - -meta_without_test() -> - Error = #{ - level => info, - msg => {report, #{answer => 42}}, - meta => #{secret => xyz} - }, - ?assertEqual( - {ok, #{ - <<"answer">> => 42, - <<"level">> => <<"info">>, - <<"secret">> => <<"xyz">> - }}, - thoas:decode(format(Error, #{})) - ), - Config2 = #{meta_without => [secret]}, - ?assertEqual( - {ok, #{ - <<"answer">> => 42, - <<"level">> => <<"info">> - }}, - thoas:decode(format(Error, Config2)) - ), - ok. - -meta_with_test() -> - Error = #{ - level => info, - 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. - -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) - ). - -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() -> - Base = #{level => alert, msg => {string, "x"}, meta => #{}}, - Result = format(Base, #{}), - ?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()))). - -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() -> - %% Ports are jsonified as binaries - Port = hd(erlang:ports()), - Result = jsonify(Port), - ?assert(is_binary(Result)). - --endif. \ No newline at end of file diff --git a/test/nova_jsonlogger_tests.erl b/test/nova_jsonlogger_tests.erl new file mode 100644 index 0000000..c8c285a --- /dev/null +++ b/test/nova_jsonlogger_tests.erl @@ -0,0 +1,442 @@ +-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), + ?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). + +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} = (json_lib()):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} = (json_lib()):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} = (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} = (json_lib()):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} = (json_lib()):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 => #{}}, + {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} = (json_lib()):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} = (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} = (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} = (json_lib()):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}}, + {ok, Decoded} = (json_lib()):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} = (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)), + ?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} = (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)), + ?assertEqual(<<"abc">>, maps:get(<<"TraceId">>, D)), + ?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, + msg => {report, #{text => <<"bad">>}}, + meta => #{trace_id => <<"abc">>, span_id => <<"def">>} + }, + {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)), + ?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} = (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)), + ?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} = (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)). + +gcp_source_location_test() -> + Event = #{ + level => info, + msg => {report, #{text => <<"hi">>}}, + meta => #{file => "foo.erl", line => 42, mfa => {mod, fun_, 1}} + }, + {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)). + +%%%--- 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}]}] + } + }, + {ok, D} = (json_lib()):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)). + +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, + msg => {report, #{}}, + meta => #{ + class => error, + reason => badarg, + stacktrace => [{mymod, myfun, 2, [{file, "mymod.erl"}, {line, 17}]}] + } + }, + {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))). + +extract_error_otel_test() -> + Event = #{ + level => error, + msg => {report, #{}}, + meta => #{ + class => exit, + reason => normal, + stacktrace => [{m, f, 0, []}] + } + }, + {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))). + +%%%--- Redaction tests ------------------------------------------------- +redact_top_level_test() -> + Event = #{ + level => info, + msg => {report, #{user => <<"alice">>, password => <<"secret">>}}, + meta => #{} + }, + Config = #{redact => [[password]]}, + {ok, D} = (json_lib()):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} = (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)). + +redact_missing_path_test() -> + Event = #{level => info, msg => {report, #{a => 1}}, meta => #{}}, + Config = #{redact => [[nope, nothing]]}, + {ok, D} = (json_lib()):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}, + {ok, D} = (json_lib()):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} = (json_lib()):decode(format(Event, Config)), + S = maps:get(<<"s">>, D), + ?assert(byte_size(S) < 200).