Merge pull request #230 from samuelmanzanera/feat/500_error_page

feat: Display 500 error by tracing steps of execution

Author: samcamwilliams

src/dev_meta.erl

@@ -199,6 +199,7 @@ adopt_node_message(Request, NodeMsg) ->
 %% After execution, we run the node's `postprocessor' message on the result of
 %% the request before returning the result it grants back to the user.
 handle_resolve(Req, Msgs, NodeMsg) ->
+	TracePID = maps:get(trace, NodeMsg),
     % Apply the pre-processor to the request.
     case resolve_processor(<<"preprocess">>, preprocessor, Req, Msgs, NodeMsg) of
         {ok, PreProcessedMsg} ->
@@ -216,7 +217,7 @@ handle_resolve(Req, Msgs, NodeMsg) ->
                 try
                     hb_ao:resolve_many(
                         PreProcessedMsg,
-                        HTTPOpts#{ force_message => true }
+                        HTTPOpts#{ force_message => true, trace => TracePID }
                     )
                 catch
                     throw:{necessary_message_not_found, MsgID} ->

src/hb_ao.erl

@@ -189,7 +189,8 @@ do_resolve_many([Msg1, Msg2 | MsgList], Opts) ->
                     resolved_message_of_many,
                     {msg3, Msg3},
                     {opts, Opts}
-                }
+                },
+				Opts
             ),
             do_resolve_many([Msg3 | MsgList], Opts);
         Res ->
@@ -272,7 +273,7 @@ resolve_stage(2, Msg1, Msg2, Opts) ->
     % only return a result if it is already in the cache).
     case hb_cache_control:maybe_lookup(Msg1, Msg2, Opts) of
         {ok, Msg3} ->
-            ?event(ao_core, {stage, 2, cache_hit, {msg3, Msg3}, {opts, Opts}}),
+            ?event(ao_core, {stage, 2, cache_hit, {msg3, Msg3}, {opts, Opts}}, Opts),
             {ok, Msg3};
         {continue, NewMsg1, NewMsg2} ->
             resolve_stage(3, NewMsg1, NewMsg2, Opts);
@@ -357,7 +358,7 @@ resolve_stage(4, Msg1, Msg2, Opts) ->
             end
     end.
 resolve_stage(5, Msg1, Msg2, ExecName, Opts) ->
-    ?event(ao_core, {stage, 5, device_lookup}),
+    ?event(ao_core, {stage, 5, device_lookup}, Opts),
     % Device lookup: Find the Erlang function that should be utilized to 
     % execute Msg2 on Msg1.
 	{ResolvedFunc, NewOpts} =
@@ -409,7 +410,8 @@ resolve_stage(5, Msg1, Msg2, ExecName, Opts) ->
                         {exec_exception, Exception},
                         {exec_stacktrace, Stacktrace},
                         {opts, Opts}
-                    }
+                    },
+					Opts
                 ),
                 % If the device cannot be loaded, we alert the caller.
 				error_execution(
@@ -426,7 +428,7 @@ resolve_stage(6, Func, Msg1, Msg2, ExecName, Opts) ->
 	% Execution.
 	% First, determine the arguments to pass to the function.
 	% While calculating the arguments we unset the add_key option.
-	UserOpts1 = maps:without(?TEMP_OPTS, Opts),
+	UserOpts1 = maps:remove(trace, maps:without(?TEMP_OPTS, Opts)),
     % Unless the user has explicitly requested recursive spawning, we
     % unset the spawn_worker option so that we do not spawn a new worker
     % for every resulting execution.
@@ -479,7 +481,8 @@ resolve_stage(6, Func, Msg1, Msg2, ExecName, Opts) ->
                         {exec_exception, ExecException},
                         {exec_stacktrace, erlang:process_info(self(), backtrace)},
                         {opts, Opts}
-                    }
+                    },
+					Opts
                 ),
                 % If the function call fails, we raise an error in the manner
                 % indicated by caller's `#Opts'.
@@ -691,7 +694,7 @@ error_invalid_intermediate_status(Msg1, Msg2, Msg3, RemainingPath, Opts) ->
 error_execution(ExecGroup, Msg2, Whence, {Class, Exception, Stacktrace}, Opts) ->
     Error = {error, Whence, {Class, Exception, Stacktrace}},
     hb_persistent:unregister_notify(ExecGroup, Msg2, Error, Opts),
-    ?event(ao_core, {handle_error, Error, {opts, Opts}}),
+    ?event(ao_core, {handle_error, Error, {opts, Opts}}, Opts),
     case hb_opts:get(error_strategy, throw, Opts) of
         throw -> erlang:raise(Class, Exception, Stacktrace);
         _ -> Error
@@ -954,7 +957,8 @@ message_to_fun(Msg, Key, Opts) ->
             {key, Key},
             {is_exported, Exported},
             {opts, Opts}
-        }
+        },
+		Opts
     ),
     % Does the device have an explicit handler function?
     case {maps:find(handler, Info), Exported} of

src/hb_event.erl

@@ -39,7 +39,34 @@ log(Topic, X, ModStr, Func, Line, Opts) ->
             end;
         true -> hb_util:debug_print(X, ModStr, Func, Line);
         false -> X
-    end.
+    end,
+	handle_tracer(Topic, X, Opts).
+
+handle_tracer(Topic, X, Opts) ->
+	AllowedTopics = [http, ao_core, ao_result],
+	case lists:member(Topic, AllowedTopics) of
+		true -> 
+			case maps:get(trace, Opts, undefined) of
+				undefined -> 
+					case tuple_to_list(X) of
+						[_ | Rest] -> 
+							try
+								Map = maps:from_list(Rest),
+								TopicOpts = maps:get(opts, Map, #{}),
+								case maps:get(trace, TopicOpts, undefined) of
+									undefined ->  ok;
+									TracePID -> hb_tracer:record_step(TracePID, {Topic, X})
+								end
+							catch
+								_:_ -> ok
+							end;
+						_ -> 
+							ok
+					end;
+				TracePID -> hb_tracer:record_step(TracePID, {Topic, X})
+			end;
+		_ -> ok
+	end.
 
 %% @doc Increment the counter for the given topic and message. Registers the
 %% counter if it doesn't exist. If the topic is `global', the message is ignored.

src/hb_http_server.erl

@@ -305,17 +305,35 @@ handle_request(RawReq, Body, ServerID) ->
             % The request is of normal AO-Core form, so we parse it and invoke
             % the meta@1.0 device to handle it.
             ?event(http, {http_inbound, {cowboy_req, Req}, {body, {string, Body}}}),
+
+			TracePID = hb_tracer:start_trace(),
+
             % Parse the HTTP request into HyerBEAM's message format.
-            ReqSingleton = hb_http:req_to_tabm_singleton(Req, Body, NodeMsg),
-            CommitmentCodec = hb_http:accept_to_codec(ReqSingleton, NodeMsg),
-            ?event(http, {parsed_singleton, ReqSingleton, {accept_codec, CommitmentCodec}}),
-            {ok, Res} =
-                dev_meta:handle(
-                    NodeMsg#{ commitment_device => CommitmentCodec },
-                    ReqSingleton
-                ),
-            hb_http:reply(Req, ReqSingleton, Res, NodeMsg)
-    end.
+			try 
+				ReqSingleton = hb_http:req_to_tabm_singleton(Req, Body, NodeMsg),
+				CommitmentCodec = hb_http:accept_to_codec(ReqSingleton, NodeMsg),
+				?event(http, {parsed_singleton, ReqSingleton, {accept_codec, CommitmentCodec}}, #{trace => TracePID}),
+
+				% hb_tracer:record_step(TracePID, request_parsing),
+				% Invoke the meta@1.0 device to handle the request.
+				{ok, Res} =
+					dev_meta:handle(
+						NodeMsg#{ commitment_device => CommitmentCodec, trace => TracePID },
+						ReqSingleton
+					),
+				hb_http:reply(Req, ReqSingleton, Res, NodeMsg)
+			catch
+				throw:_ ->
+					Trace = hb_tracer:get_trace(TracePID),
+					TraceString = hb_tracer:format_error_trace(Trace),
+					hb_http:reply(Req, #{}, #{ <<"status">> => 500, <<"body">> => list_to_binary(TraceString)}, NodeMsg);
+
+				error:_ ->
+					Trace = hb_tracer:get_trace(TracePID),
+					TraceString = hb_tracer:format_error_trace(Trace),
+					hb_http:reply(Req, #{}, #{ <<"status">> => 500, <<"body">> => list_to_binary(TraceString)}, NodeMsg)
+			end
+end.
 
 %% @doc Return the list of allowed methods for the HTTP server.
 allowed_methods(Req, State) ->

src/hb_tracer.erl

@@ -0,0 +1,103 @@
+%%% @doc A module for tracing the flow of requests through the system.
+%%% This allows for tracking the lifecycle of a request from HTTP receipt through processing and response.
+
+-module(hb_tracer).
+-export([start_trace/0, record_step/2, get_trace/1, format_error_trace/1]).
+
+-include("include/hb.hrl").
+
+start_trace() ->
+	Trace = #{ steps => queue:new() },
+	TracePID = spawn(fun() -> trace_loop(Trace) end),
+	?event(trace, {trace_started, TracePID}),
+	TracePID.
+
+trace_loop(Trace) ->
+	receive
+		{record_step, Step} ->
+			Steps = maps:get(steps, Trace),
+			NewTrace = Trace#{steps => queue:in(Step, Steps)},
+			?event(trace, {step_recorded, Step}),
+			trace_loop(NewTrace);
+		{get_trace, From} ->
+			% Convert queue to list for the response
+			TraceWithList = Trace#{steps => queue:to_list(maps:get(steps, Trace))},
+			From ! {trace, TraceWithList},
+			trace_loop(Trace)
+	end.
+
+record_step(TracePID, Step) ->
+	TracePID! {record_step, Step}.
+
+get_trace(TracePID) ->
+	TracePID! {get_trace, self()},
+	receive
+		{trace, Trace} ->
+			Trace
+		after 5000 ->
+			?event(trace, {trace_timeout, TracePID}),
+			{trace, #{}}
+	end.
+
+format_error_trace(Trace) ->
+	Steps = maps:get(steps, Trace, []),
+
+	TraceMap = lists:foldl(fun (TraceItem, Acc) ->
+		case TraceItem of
+			{http, {parsed_singleton, _ReqSingleton, _}} -> 
+				maps:put(request_parsing, true, Acc);
+			{ao_core, {stage, Stage, _Task}} -> 
+				maps:put(resolve_stage, Stage, Acc);
+			{ao_result, {load_device_failed, _, _, _, _, {exec_exception, Exception}, _, _}} ->
+				maps:put(error, Exception, Acc);
+			{ao_result, {exec_failed, _, _, _, {func, Fun}, _, {exec_exception, Error}, _, _}} ->
+				maps:put(error, {Fun, Error}, Acc);
+			_ -> Acc
+		end
+	end, #{}, Steps),
+
+	% Build the trace message
+	TraceStrings = ["Oops! Something went wrong. Here's the rundown:"],
+
+	% Add parsing status
+	ParsingTrace = case maps:get(request_parsing, TraceMap, false) of
+		false ->
+			TraceStrings ++ [[failure_emoji(), "Parsing your request"]];
+		true ->
+			TraceStrings ++ [[checkmark_emoji(), "Parsing your request"]]
+	end,
+
+	% Add stage information
+	StageTrace = case maps:get(resolve_stage, TraceMap, undefined) of
+		undefined ->
+			ParsingTrace;
+		Stage ->
+			ParsingTrace ++ [[stage_to_emoji(Stage), " Resolved steps of your execution"]]
+	end,
+
+	% Add error information
+	ErrorTrace = case maps:get(error, TraceMap, undefined) of
+		undefined ->
+			StageTrace;
+		{Fun, Reason} ->
+			StageTrace ++ [[failure_emoji(), io_lib:format("Error: ~p -> ~p", [Fun, Reason])]];
+		Error ->
+			StageTrace ++ [[failure_emoji(), io_lib:format("Error: ~p", [Error])]]
+	end,
+	string:join(ErrorTrace, "\n").
+
+
+checkmark_emoji() ->
+	% Unicode for checkmark
+	"\xE2\x9C\x85". % \xE2\x9C\x85 is the checkmark emoji in UTF-8
+
+failure_emoji() ->
+	% Unicode for failure emoji
+	"\xE2\x9D\x8C". % \xE2\x9D\x8C is the failure emoji in UTF-8
+
+% Helper function to convert stage number to emoji
+stage_to_emoji(Stage) when Stage >= 1, Stage =< 9 ->
+	% Unicode for circled numbers 1-9
+	[Stage + 48, 16#E2, 16#83, 16#A3];
+stage_to_emoji(_) ->
+	"".

src/include/hb.hrl

@@ -26,7 +26,7 @@
 %%% underlying function.
 -define(event(X), hb_event:log(global, X, ?MODULE, ?FUNCTION_NAME, ?LINE)).
 -define(event(Topic, X), hb_event:log(Topic, X, ?MODULE, ?FUNCTION_NAME, ?LINE)).
--define(event(Topic, X, Opts), hb_event:log(maps:get(topic, Opts, Topic), X, ?MODULE, ?FUNCTION_NAME, ?LINE), Opts).
+-define(event(Topic, X, Opts), hb_event:log(maps:get(topic, Opts, Topic), X, ?MODULE, ?FUNCTION_NAME, ?LINE, Opts)).
 -define(debug_wait(T), hb:debug_wait(T, ?MODULE, ?FUNCTION_NAME, ?LINE)).
 -define(debug_print(X), hb_util:debug_print(X, ?MODULE, ?FUNCTION_NAME, ?LINE)).
 -define(no_prod(X), hb:no_prod(X, ?MODULE, ?LINE)).