Ability to return extra measurements from :telemetry.span (#130)

It's useful to be able to return extra measurements from span, based on values
that cannot be determined from the outside, such as the number of bytes in an
HTTP request.

src/telemetry.erl

@@ -29,7 +29,7 @@
 -type handler_config() :: term().
 -type handler_function() :: fun((event_name(), event_measurements(), event_metadata(), handler_config()) -> any()).
 -type span_result() :: term().
--type span_function() :: fun(() -> {span_result(), event_metadata()}).
+-type span_function() :: fun(() -> {span_result(), event_metadata()}) | {span_result(), event_measurements(), event_metadata()}.
 -type handler() :: #{id := handler_id(),
                      event_name := event_name(),
                      function := handler_function(),
@@ -178,7 +178,7 @@ execute([_ | _] = EventName, Measurements, Metadata) when is_map(Measurements) a
 
 %% @doc Runs the provided `SpanFunction', emitting start and stop/exception events, invoking the handlers attached to each.
 %%
-%% The `SpanFunction' must return a `{result, stop_metadata}' tuple.
+%% The `SpanFunction' must return a `{result, stop_metadata}' or a `{result, extra_measurements, stop_metadata}` tuple.
 %%
 %% When this function is called, 2 events will be emitted via {@link execute/3}. Those events will be one of the following
 %% pairs:
@@ -203,6 +203,10 @@ execute([_ | _] = EventName, Measurements, Metadata) when is_map(Measurements) a
 %% should be available to both `start' and `stop' events need to supplied separately for `StartMetadata' and
 %% `StopMetadata'.
 %%
+%% If `SpanFunction` returns `{result, extra_measurements, stop_metadata}`, then a map of extra measurements
+%% will be merged with the measurements automatically provided. This is useful if you want to return, for example, 
+%% bytes from an HTTP request. The standard measurements `duration` and `monotonic_time` cannot be overridden.
+%%
 %% For `telemetry' events denoting the <strong>start</strong> of a larger event, the following data is provided:
 %%
 %% <p>
@@ -253,7 +257,8 @@ execute([_ | _] = EventName, Measurements, Metadata) when is_map(Measurements) a
 %%   % The current monotonic time minus the start monotonic time in native units
 %%   % by calling: erlang:monotonic_time() - start_monotonic_time
 %%   duration => integer(),
-%%   monotonic_time => integer()
+%%   monotonic_time => integer(),
+%%   % User defined measurements when returning `SpanFunction` as a 3 element tuple
 %% }
 %% '''
 %% </li>
@@ -318,15 +323,25 @@ span(EventPrefix, StartMetadata, SpanFunction) ->
         merge_ctx(StartMetadata, DefaultCtx)
     ),
 
-    try {_, #{}} = SpanFunction() of
+    try SpanFunction() of
       {Result, StopMetadata} ->
           StopTime = erlang:monotonic_time(),
           execute(
               EventPrefix ++ [stop],
               #{duration => StopTime - StartTime, monotonic_time => StopTime},
               merge_ctx(StopMetadata, DefaultCtx)
           ),
+          Result;
+      {Result, ExtraMeasurements, StopMetadata} ->
+          StopTime = erlang:monotonic_time(),
+          Measurements = maps:merge(ExtraMeasurements, #{duration => StopTime - StartTime, monotonic_time => StopTime}),
+          execute(
+              EventPrefix ++ [stop],
+              Measurements,
+              merge_ctx(StopMetadata, DefaultCtx)
+          ),
           Result
+
     catch
         ?WITH_STACKTRACE(Class, Reason, Stacktrace)
             StopTime = erlang:monotonic_time(),

test/telemetry_SUITE.erl

@@ -336,14 +336,43 @@ invoke_successful_span_handlers(Config) ->
 
     receive
         {event, StartEvent, StartMeasurements, StartMetadata, HandlerConfig} ->
-          ?assertEqual([monotonic_time, system_time], maps:keys(StartMeasurements))
+          ?assertEqual([monotonic_time, system_time], lists:sort(maps:keys(StartMeasurements)))
     after
         1000 -> ct:fail(timeout_receive_echo)
     end,
 
     receive
         {event, StopEvent, StopMeasurements, StopMetadata, HandlerConfig} ->
-          ?assertEqual([duration, monotonic_time], maps:keys(StopMeasurements))
+          ?assertEqual([duration, monotonic_time], lists:sort(maps:keys(StopMeasurements)))
+    after
+        1000 -> ct:fail(timeout_receive_echo)
+    end.
+
+% Ensure that stop event includes custom measurements if provided
+invoke_successful_span_handlers_with_measurements(Config) ->
+    HandlerId = ?config(id, Config),
+    EventPrefix = [some, action],
+    StartEvent = EventPrefix ++ [start],
+    StopEvent = EventPrefix ++ [stop],
+    HandlerConfig = #{send_to => self()},
+    StartMetadata = #{some => start_metadata, telemetry_span_context => ctx},
+    StopMetadata = #{other => stop_metadata, telemetry_span_context => ctx},
+    ExtraMeasurements = #{other_thing => 100},
+    ErrorSpanFunction = fun() -> {ok, ExtraMeasurements, StopMetadata} end,
+
+    telemetry:attach_many(HandlerId, [StartEvent, StopEvent], fun ?MODULE:echo_event/4, HandlerConfig),
+    telemetry:span(EventPrefix, StartMetadata, ErrorSpanFunction),
+
+    receive
+        {event, StartEvent, StartMeasurements, StartMetadata, HandlerConfig} ->
+          ?assertEqual([monotonic_time, system_time], lists:sort(maps:keys(StartMeasurements)))
+    after
+        1000 -> ct:fail(timeout_receive_echo)
+    end,
+
+    receive
+        {event, StopEvent, StopMeasurements, StopMetadata, HandlerConfig} ->
+          ?assertEqual([duration, monotonic_time, other_thing], lists:sort(maps:keys(StopMeasurements)))
     after
         1000 -> ct:fail(timeout_receive_echo)
     end.
@@ -372,14 +401,14 @@ invoke_exception_span_handlers(Config) ->
 
     receive
         {event, StartEvent, StartMeasurements, StartMetadata, HandlerConfig} ->
-          ?assertEqual([monotonic_time, system_time], maps:keys(StartMeasurements))
+          ?assertEqual([monotonic_time, system_time], lists:sort(maps:keys(StartMeasurements)))
     after
         1000 -> ct:fail(timeout_receive_echo)
     end,
 
     receive
         {event, ExceptionEvent, StopMeasurements, ExceptionMetadata, HandlerConfig} ->
-          ?assertEqual([duration, monotonic_time], maps:keys(StopMeasurements)),
+          ?assertEqual([duration, monotonic_time], lists:sort(maps:keys(StopMeasurements))),
           ?assertEqual([kind, reason, some, stacktrace, telemetry_span_context], lists:sort(maps:keys(ExceptionMetadata)))
     after
         1000 -> ct:fail(timeout_receive_echo)