diff --git a/apps/opentelemetry/src/otel_tracer_default.erl b/apps/opentelemetry/src/otel_tracer_default.erl index c983e30b..d39e5945 100644 --- a/apps/opentelemetry/src/otel_tracer_default.erl +++ b/apps/opentelemetry/src/otel_tracer_default.erl @@ -38,13 +38,33 @@ start_span(Ctx, {_, #tracer{on_start_processors=Processors, SpanCtx#span_ctx{span_sdk={otel_span_ets, OnEndProcessors}}. -spec with_span(otel_ctx:t(), opentelemetry:tracer(), opentelemetry:span_name(), - otel_span:start_opts(), otel_tracer:traced_fun(T)) -> T. + otel_span:with_opts(), otel_tracer:traced_fun(T)) -> T. with_span(Ctx, Tracer, SpanName, Opts, Fun) -> + RecordException = maps:get(record_exception, Opts, false), + SetStatusOnException = maps:get(set_status_on_exception, Opts, false), SpanCtx = start_span(Ctx, Tracer, SpanName, Opts), Ctx1 = otel_tracer:set_current_span(Ctx, SpanCtx), Token = otel_ctx:attach(Ctx1), try Fun(SpanCtx) + catch + Class:Term:Stacktrace -> + if + RecordException -> + otel_span:record_exception(SpanCtx, Class, Term, Stacktrace, #{}); + true -> + ok + end, + + if + SetStatusOnException -> + Status = opentelemetry:status(?OTEL_STATUS_ERROR, <<"exception">>), + otel_span:set_status(SpanCtx, Status); + true -> + ok + end, + + erlang:raise(Class, Term, Stacktrace) after %% passing SpanCtx directly ensures that this `end_span' ends the span started %% in this function. If spans in `Fun()' were started and not finished properly diff --git a/apps/opentelemetry/test/opentelemetry_SUITE.erl b/apps/opentelemetry/test/opentelemetry_SUITE.erl index c41db277..c8f96e2b 100644 --- a/apps/opentelemetry/test/opentelemetry_SUITE.erl +++ b/apps/opentelemetry/test/opentelemetry_SUITE.erl @@ -33,7 +33,7 @@ all() -> {group, otel_batch_processor}]. all_cases() -> - [with_span, macros, child_spans, disabled_sdk, + [with_span, record_exception, macros, child_spans, disabled_sdk, update_span_data, tracer_instrumentation_scope, tracer_previous_ctx, stop_temporary_app, reset_after, attach_ctx, default_sampler, non_recording_ets_table, root_span_sampling_always_on, root_span_sampling_always_off, @@ -122,7 +122,7 @@ init_per_testcase(tracer_instrumentation_scope, Config) -> Config1 = set_batch_tab_processor(Config), {ok, _} = application:ensure_all_started(opentelemetry), Config1; -init_per_testcase(multiple_tracer_providers, Config) -> +init_per_testcase(Test, Config) when Test =:= record_exception; Test =:= multiple_tracer_providers-> application:set_env(opentelemetry, processors, [{otel_batch_processor, #{exporter => {otel_exporter_pid, self()}, scheduled_delay_ms => 1}}]), {ok, _} = application:ensure_all_started(opentelemetry), @@ -465,6 +465,84 @@ with_span(Config) -> ok. +record_exception(_Config) -> + Tracer = opentelemetry:get_tracer(), + + %% ERROR + ?assertException(error, badarg, otel_tracer:with_span(Tracer, <<"span-error">>, #{record_exception => true}, + fun(_SpanCtx) -> + erlang:error(badarg) + end)), + + receive + {span, SpanError} -> + ?assertEqual(<<"span-error">>, SpanError#span.name), + ?assertEqual(undefined, SpanError#span.status), + [#event{name=exception, attributes=A}] = otel_events:list(SpanError#span.events), + ?assertMatch(#{'exception.type' := <<"error:badarg">>, 'exception.stacktrace' := _}, otel_attributes:map(A)) + + after + 1000 -> + ct:fail(timeout) + end, + + %% THROW + ?assertException(throw, value, otel_tracer:with_span(Tracer, <<"span-throw">>, #{record_exception => true, set_status_on_exception => true}, + fun(_SpanCtx) -> + erlang:throw(value) + end)), + + receive + {span, SpanThrow} -> + ?assertEqual(<<"span-throw">>, SpanThrow#span.name), + ?assertMatch(#status{code=?OTEL_STATUS_ERROR}, SpanThrow#span.status), + [#event{name=exception, attributes=A1}] = otel_events:list(SpanThrow#span.events), + ?assertMatch(#{'exception.type' := <<"throw:value">>, 'exception.stacktrace' := _}, otel_attributes:map(A1)) + + after + 1000 -> + ct:fail(timeout) + end, + + %% EXIT + ?assertException(exit, shutdown, otel_tracer:with_span(Tracer, <<"span-exit">>, #{record_exception => true}, + fun(_SpanCtx) -> + erlang:exit(shutdown) + end)), + + receive + {span, SpanExit} -> + ?assertEqual(<<"span-exit">>, SpanExit#span.name), + ?assertEqual(undefined, SpanExit#span.status), + [#event{name=exception, attributes=A2}] = otel_events:list(SpanExit#span.events), + ?assertMatch(#{'exception.type' := <<"exit:shutdown">>, 'exception.stacktrace' := _}, otel_attributes:map(A2)) + + after + 1000 -> + ct:fail(timeout) + end, + + %% broken elixir exception + Exception = #{'__exception__' => true, '__struct__' => invalid}, + ?assertException(exit, Exception, otel_tracer:with_span(Tracer, <<"span-elixir">>, #{record_exception => true}, + fun(_SpanCtx) -> + erlang:exit(Exception) + end)), + + receive + {span, SpanElixir} -> + ?assertEqual(<<"span-elixir">>, SpanElixir#span.name), + ?assertEqual(undefined, SpanElixir#span.status), + [#event{name=exception, attributes=A3}] = otel_events:list(SpanElixir#span.events), + ?assertMatch(#{'exception.type' := <<"exit:#{'__exception__' => true,'__struct__' => invalid}">>, 'exception.stacktrace' := _}, otel_attributes:map(A3)) + + after + 1000 -> + ct:fail(timeout) + end, + + ok. + child_spans(Config) -> Tid = ?config(tid, Config), diff --git a/apps/opentelemetry_api/lib/open_telemetry/span.ex b/apps/opentelemetry_api/lib/open_telemetry/span.ex index 75adda9f..b0fe2536 100644 --- a/apps/opentelemetry_api/lib/open_telemetry/span.ex +++ b/apps/opentelemetry_api/lib/open_telemetry/span.ex @@ -136,16 +136,15 @@ defmodule OpenTelemetry.Span do def record_exception(span_ctx, exception, trace \\ nil, attributes \\ []) def record_exception(span_ctx, exception, trace, attributes) when is_exception?(exception) do - exception_type = to_string(exception.__struct__) - - exception_attributes = [ - {OpenTelemetry.SemanticConventions.Trace.exception_type(), exception_type}, - {OpenTelemetry.SemanticConventions.Trace.exception_message(), Exception.message(exception)}, - {OpenTelemetry.SemanticConventions.Trace.exception_stacktrace(), - Exception.format_stacktrace(trace)} - ] - - add_event(span_ctx, "exception", exception_attributes ++ attributes) + trace = + if trace do + trace + else + {:current_stacktrace, t} = Process.info(self(), :current_stacktrace) + Enum.drop(t, 3) + end + + :otel_span.record_exception(span_ctx, :error, exception, trace, attributes) end def record_exception(_, _, _, _), do: false diff --git a/apps/opentelemetry_api/src/otel_span.erl b/apps/opentelemetry_api/src/otel_span.erl index 5b3a3c4a..f73d939c 100644 --- a/apps/opentelemetry_api/src/otel_span.erl +++ b/apps/opentelemetry_api/src/otel_span.erl @@ -28,6 +28,7 @@ is_valid/1, is_valid_name/1, validate_start_opts/1, + validate_with_opts/1, set_attribute/3, set_attributes/2, add_event/3, @@ -51,7 +52,15 @@ start_time := opentelemetry:timestamp(), kind := opentelemetry:span_kind()}. --export_type([start_opts/0]). +-type with_opts() :: #{attributes => opentelemetry:attributes_map(), + links => [opentelemetry:link()], + is_recording => boolean(), + start_time => opentelemetry:timestamp(), + kind => opentelemetry:span_kind(), + record_exception => boolean(), + set_status_on_exception => boolean()}. + +-export_type([start_opts/0, with_opts/0]). -spec validate_start_opts(start_opts()) -> start_opts(). validate_start_opts(Opts) when is_map(Opts) -> @@ -68,6 +77,17 @@ validate_start_opts(Opts) when is_map(Opts) -> is_recording => IsRecording }. +-spec validate_with_opts(with_opts()) -> with_opts(). +validate_with_opts(Opts) when is_map(Opts) -> + StartOpts = validate_start_opts(Opts), + RecordException = maps:get(record_exception, Opts, false), + SetStatusOnException = maps:get(set_status_on_exception, Opts, false), + maps:merge(StartOpts, #{ + record_exception => RecordException, + set_status_on_exception => SetStatusOnException + }). + + -spec is_recording(SpanCtx) -> boolean() when SpanCtx :: opentelemetry:span_ctx(). is_recording(SpanCtx) -> @@ -201,11 +221,7 @@ add_events(_, _) -> record_exception(SpanCtx, Class, Term, Stacktrace, Attributes) when is_list(Attributes) -> record_exception(SpanCtx, Class, Term, Stacktrace, maps:from_list(Attributes)); record_exception(SpanCtx, Class, Term, Stacktrace, Attributes) when is_map(Attributes) -> - {ok, ExceptionType} = otel_utils:format_binary_string("~0tP:~0tP", [Class, 10, Term, 10], [{chars_limit, 50}]), - {ok, StacktraceString} = otel_utils:format_binary_string("~0tP", [Stacktrace, 10], [{chars_limit, 50}]), - ExceptionAttributes = #{?EXCEPTION_TYPE => ExceptionType, - ?EXCEPTION_STACKTRACE => StacktraceString}, - add_event(SpanCtx, 'exception', maps:merge(ExceptionAttributes, Attributes)); + do_record_exception(SpanCtx, Class, Term, undefined, Stacktrace, Attributes); record_exception(_, _, _, _, _) -> false. @@ -219,15 +235,57 @@ record_exception(_, _, _, _, _) -> record_exception(SpanCtx, Class, Term, Message, Stacktrace, Attributes) when is_list(Attributes) -> record_exception(SpanCtx, Class, Term, Message, Stacktrace, maps:from_list(Attributes)); record_exception(SpanCtx, Class, Term, Message, Stacktrace, Attributes) when is_map(Attributes) -> - {ok, ExceptionType} = otel_utils:format_binary_string("~0tP:~0tP", [Class, 10, Term, 10], [{chars_limit, 50}]), - {ok, StacktraceString} = otel_utils:format_binary_string("~0tP", [Stacktrace, 10], [{chars_limit, 50}]), - ExceptionAttributes = #{?EXCEPTION_TYPE => ExceptionType, - ?EXCEPTION_STACKTRACE => StacktraceString, - ?EXCEPTION_MESSAGE => Message}, - add_event(SpanCtx, 'exception', maps:merge(ExceptionAttributes, Attributes)); + do_record_exception(SpanCtx, Class, Term, Message, Stacktrace, Attributes); record_exception(_, _, _, _, _, _) -> false. +do_record_exception(SpanCtx, Class, Term, Message, Stacktrace, Attributes) -> + ExceptionFromElixir = exception_from_elixir(Stacktrace), + Term1 = normalize_exception(Class, Term, Stacktrace, ExceptionFromElixir), + ExceptionType = exception_type(Class, Term1), + StacktraceString = format_stacktrace(Stacktrace, ExceptionFromElixir), + ExceptionAttributes = #{?EXCEPTION_TYPE => ExceptionType, + ?EXCEPTION_STACKTRACE => StacktraceString}, + ExceptionAttributes1 = add_message(ExceptionAttributes, Message, Term1), + add_event(SpanCtx, exception, maps:merge(ExceptionAttributes1, Attributes)). +exception_from_elixir([{Module, _, _, _} | _]) -> + ModuleStr = atom_to_list(Module), + string:find(ModuleStr, "Elixir.") =:= ModuleStr; +exception_from_elixir(_) -> + false. +format_stacktrace(Stacktrace, false) -> + {ok, StacktraceString} = otel_utils:format_binary_string("~0tP", [Stacktrace, 10], [{chars_limit, 50}]), + StacktraceString; +format_stacktrace(Stacktrace, true) -> + 'Elixir.Exception':format_stacktrace(Stacktrace). +normalize_exception(Class, Term, Stacktrace, true) -> + 'Elixir.Exception':normalize(Class, Term, Stacktrace); +normalize_exception(_Class, Term, _ExceptionStacktrace, false) -> + Term. +exception_type(error, #{'__exception__' := true, '__struct__' := ElixirErrorStruct} = Term) -> + case atom_to_binary(ElixirErrorStruct) of + <<"Elixir.", ExceptionType/binary>> -> ExceptionType; + _ -> exception_type_erl(error, Term) + end; +exception_type(Class, Term) -> + exception_type_erl(Class, Term). +exception_type_erl(Class, Term) -> + {ok, ExceptionType} = otel_utils:format_binary_string("~0tP:~0tP", [Class, 10, Term, 10], [{chars_limit, 50}]), + ExceptionType. + +add_message(Attributes, Message, _Exception) when Message /= undefined -> + maps:put(?EXCEPTION_MESSAGE, Message, Attributes); +add_message(Attributes, undefined, #{'__exception__' := true} = Exception) -> + try + Message = 'Elixir.Exception':message(Exception), + maps:put(?EXCEPTION_MESSAGE, Message, Attributes) + catch + _Class:_Exception -> + Attributes + end; +add_message(Attributes, _, _) -> + Attributes. + -spec set_status(SpanCtx, StatusOrCode) -> boolean() when StatusOrCode :: opentelemetry:status() | undefined | opentelemetry:status_code(), SpanCtx :: opentelemetry:span_ctx(). diff --git a/apps/opentelemetry_api/src/otel_tracer.erl b/apps/opentelemetry_api/src/otel_tracer.erl index eccd2b08..f146a787 100644 --- a/apps/opentelemetry_api/src/otel_tracer.erl +++ b/apps/opentelemetry_api/src/otel_tracer.erl @@ -66,20 +66,20 @@ start_span(Ctx, Tracer={Module, _}, SpanName, Opts) -> otel_tracer_noop:noop_span_ctx() end. --spec with_span(opentelemetry:tracer(), opentelemetry:span_name(), otel_span:start_opts(), traced_fun(T)) -> T. +-spec with_span(opentelemetry:tracer(), opentelemetry:span_name(), otel_span:with_opts(), traced_fun(T)) -> T. with_span(Tracer={Module, _}, SpanName, Opts, Fun) when is_atom(Module) -> case otel_span:is_valid_name(SpanName) of true -> - Module:with_span(otel_ctx:get_current(), Tracer, SpanName, otel_span:validate_start_opts(Opts), Fun); + Module:with_span(otel_ctx:get_current(), Tracer, SpanName, otel_span:validate_with_opts(Opts), Fun); false -> Fun(otel_tracer_noop:noop_span_ctx()) end. --spec with_span(otel_ctx:t(), opentelemetry:tracer(), opentelemetry:span_name(), otel_span:start_opts(), traced_fun(T)) -> T. +-spec with_span(otel_ctx:t(), opentelemetry:tracer(), opentelemetry:span_name(), otel_span:with_opts(), traced_fun(T)) -> T. with_span(Ctx, Tracer={Module, _}, SpanName, Opts, Fun) when is_atom(Module) -> case otel_span:is_valid_name(SpanName) of true -> - Module:with_span(Ctx, Tracer, SpanName, otel_span:validate_start_opts(Opts), Fun); + Module:with_span(Ctx, Tracer, SpanName, otel_span:validate_with_opts(Opts), Fun); false -> Fun(otel_tracer_noop:noop_span_ctx()) end. diff --git a/rebar.config b/rebar.config index dc4f2f51..98139dc6 100644 --- a/rebar.config +++ b/rebar.config @@ -58,8 +58,9 @@ opentelemetry_exporter_trace_service_pb, opentelemetry_exporter_metrics_service_pb, opentelemetry_exporter_logs_service_pb, - opentelemetry_zipkin_pb]}. - + opentelemetry_zipkin_pb, + + 'Elixir.Exception']}. {dialyzer, [{warnings, [no_unknown]}]}. diff --git a/test/otel_tests.exs b/test/otel_tests.exs index 786e0f65..231eb75b 100644 --- a/test/otel_tests.exs +++ b/test/otel_tests.exs @@ -9,12 +9,18 @@ defmodule OtelTests do @fields Record.extract(:span, from_lib: "opentelemetry/include/otel_span.hrl") Record.defrecordp(:span, @fields) + @fields Record.extract(:event, from_lib: "opentelemetry/include/otel_span.hrl") + Record.defrecordp(:event, @fields) + @fields Record.extract(:tracer, from_lib: "opentelemetry/src/otel_tracer.hrl") Record.defrecordp(:tracer, @fields) @fields Record.extract(:span_ctx, from_lib: "opentelemetry_api/include/opentelemetry.hrl") Record.defrecordp(:span_ctx, @fields) + @fields Record.extract(:status, from_lib: "opentelemetry_api/include/opentelemetry.hrl") + Record.defrecordp(:status, @fields) + setup do Application.load(:opentelemetry) @@ -241,7 +247,7 @@ defmodule OtelTests do attributes = :otel_attributes.new( [ - {:"exception.type", "Elixir.RuntimeError"}, + {:"exception.type", "RuntimeError"}, {:"exception.message", "my error message"}, {:"exception.stacktrace", stacktrace} ], @@ -259,7 +265,7 @@ defmodule OtelTests do :infinity, 0, [ - {:event, _, "exception", ^attributes} + {:event, _, :exception, ^attributes} ] } )} @@ -308,4 +314,101 @@ defmodule OtelTests do opts ) end + + describe "Tracer.with_span record exception" do + test "raise" do + assert_raise RuntimeError, "my error message", fn -> + Tracer.with_span "span-1", record_exception: true, set_status_on_exception: true do + raise RuntimeError, "my error message" + end + end + + assert_receive {:span, + span( + name: "span-1", + events: {:events, _, _, _, _, [event]}, + status: status(code: :error) + )} + + assert event(name: :exception, attributes: {:attributes, _, _, _, received_attirbutes}) = + event + + assert %{ + "exception.type": "RuntimeError", + "exception.message": "my error message", + "exception.stacktrace": _ + } = received_attirbutes + end + + test ":erlang.error()" do + assert_raise ArgumentError, fn -> + Tracer.with_span "span-1", record_exception: true do + :erlang.error(:badarg) + end + end + + assert_receive {:span, + span( + name: "span-1", + events: {:events, _, _, _, _, [event]}, + status: :undefined + )} + + assert event(name: :exception, attributes: {:attributes, _, _, _, received_attirbutes}) = + event + + assert %{ + "exception.type": "ArgumentError", + "exception.stacktrace": _ + } = received_attirbutes + end + + test "exit" do + assert :shutdown == + catch_exit( + Tracer.with_span "span-1", record_exception: true, set_status_on_exception: true do + exit(:shutdown) + end + ) + + assert_receive {:span, + span( + name: "span-1", + events: {:events, _, _, _, _, [event]}, + status: status(code: :error) + )} + + assert event(name: :exception, attributes: {:attributes, _, _, _, received_attirbutes}) = + event + + assert %{ + "exception.type": "exit:shutdown", + "exception.stacktrace": _ + } = received_attirbutes + end + + test "throw" do + assert :value == + catch_throw( + Tracer.with_span "span-1", record_exception: true do + throw(:value) + end + ) + + assert_receive {:span, + span( + name: "span-1", + events: {:events, _, _, _, _, [event]}, + status: :undefined + )} + + assert event(name: :exception, attributes: {:attributes, _, _, _, received_attirbutes}) = + event + + assert %{ + "exception.type": "throw:value", + "exception.stacktrace": _ + } = received_attirbutes + end + end end