diff options
| -rw-r--r-- | doc/src/manual/cowboy_stream.asciidoc | 5 | ||||
| -rw-r--r-- | src/cowboy.erl | 31 | ||||
| -rw-r--r-- | src/cowboy_http.erl | 55 | ||||
| -rw-r--r-- | src/cowboy_http2.erl | 71 | ||||
| -rw-r--r-- | src/cowboy_stream.erl | 43 | ||||
| -rw-r--r-- | src/cowboy_stream_h.erl | 37 | ||||
| -rw-r--r-- | src/cowboy_tracer_h.erl | 28 |
7 files changed, 152 insertions, 118 deletions
diff --git a/doc/src/manual/cowboy_stream.asciidoc b/doc/src/manual/cowboy_stream.asciidoc index 0207ad8..763cbd5 100644 --- a/doc/src/manual/cowboy_stream.asciidoc +++ b/doc/src/manual/cowboy_stream.asciidoc @@ -81,9 +81,8 @@ Stream handlers can return a list of commands to be executed from the `init/3`, `data/4` and `info/3` callbacks. In addition, the `early_error/5` callback must return a response command. -// @todo We need a 'log' command that would call error_logger. -// It's better than doing in the handlers directly because -// then we can have other stream handlers manipulate those logs. +// @todo The logger option and the {log, Level, Format, Args} +// options need to be documented and tested. The following commands are defined: diff --git a/src/cowboy.erl b/src/cowboy.erl index 99615de..0230f07 100644 --- a/src/cowboy.erl +++ b/src/cowboy.erl @@ -19,6 +19,10 @@ -export([stop_listener/1]). -export([set_env/3]). +%% Internal. +-export([log/2]). +-export([log/4]). + %% @todo Detailed opts. -type opts() :: map(). -export_type([opts/0]). @@ -71,3 +75,30 @@ set_env(Ref, Name, Value) -> Env = maps:get(env, Opts, #{}), Opts2 = maps:put(env, maps:put(Name, Value, Env), Opts), ok = ranch:set_protocol_options(Ref, Opts2). + +%% Internal. + +-spec log({log, logger:level(), io:format(), list()}, opts()) -> ok. +log({log, Level, Format, Args}, Opts) -> + log(Level, Format, Args, Opts). + +-spec log(logger:level(), io:format(), list(), opts()) -> ok. +log(Level, Format, Args, #{logger := Logger}) + when Logger =/= error_logger -> + _ = Logger:Level(Format, Args), + ok; +%% We use error_logger by default. Because error_logger does +%% not have all the levels we accept we have to do some +%% mapping to error_logger functions. +log(Level, Format, Args, _) -> + Function = case Level of + emergency -> error_msg; + alert -> error_msg; + critical -> error_msg; + error -> error_msg; + warning -> warning_msg; + notice -> warning_msg; + info -> info_msg; + debug -> info_msg + end, + error_logger:Function(Format, Args). diff --git a/src/cowboy_http.erl b/src/cowboy_http.erl index 818a88a..e1af0e9 100644 --- a/src/cowboy_http.erl +++ b/src/cowboy_http.erl @@ -30,6 +30,7 @@ idle_timeout => timeout(), inactivity_timeout => timeout(), linger_timeout => timeout(), + logger => module(), max_authority_length => non_neg_integer(), max_empty_lines => non_neg_integer(), max_header_name_length => non_neg_integer(), @@ -224,7 +225,7 @@ loop(State=#state{parent=Parent, socket=Socket, transport=Transport, opts=Opts, loop(State, Buffer); %% Unknown messages. Msg -> - error_logger:error_msg("Received stray message ~p.~n", [Msg]), + cowboy:log(warning, "Received stray message ~p.~n", [Msg], Opts), loop(State, Buffer) after InactivityTimeout -> terminate(State, {internal_error, timeout, 'No message or data received before timeout.'}) @@ -300,16 +301,16 @@ after_parse({request, Req=#{streamid := StreamID, method := Method, State = set_timeout(State1), parse(Buffer, commands(State, StreamID, Commands)) catch Class:Exception -> - cowboy_stream:report_error(init, + cowboy:log(cowboy_stream:make_error_log(init, [StreamID, Req, Opts], - Class, Exception, erlang:get_stacktrace()), + Class, Exception, erlang:get_stacktrace()), Opts), early_error(500, State0, {internal_error, {Class, Exception}, 'Unhandled exception in cowboy_stream:init/3.'}, Req), parse(Buffer, State0) end; %% Streams are sequential so the body is always about the last stream created %% unless that stream has terminated. -after_parse({data, StreamID, IsFin, Data, State=#state{ +after_parse({data, StreamID, IsFin, Data, State=#state{opts=Opts, streams=Streams0=[Stream=#stream{id=StreamID, state=StreamState0}|_]}, Buffer}) -> try cowboy_stream:data(StreamID, IsFin, Data, StreamState0) of {Commands, StreamState} -> @@ -317,9 +318,9 @@ after_parse({data, StreamID, IsFin, Data, State=#state{ Stream#stream{state=StreamState}), parse(Buffer, commands(State#state{streams=Streams}, StreamID, Commands)) catch Class:Exception -> - cowboy_stream:report_error(data, + cowboy:log(cowboy_stream:make_error_log(data, [StreamID, IsFin, Data, StreamState0], - Class, Exception, erlang:get_stacktrace()), + Class, Exception, erlang:get_stacktrace()), Opts), stream_reset(State, StreamID, {internal_error, {Class, Exception}, 'Unhandled exception in cowboy_stream:data/4.'}) end; @@ -821,7 +822,7 @@ parse_body(Buffer, State=#state{in_streamid=StreamID, in_state= %% Message handling. -down(State=#state{children=Children0}, Pid, Msg) -> +down(State=#state{opts=Opts, children=Children0}, Pid, Msg) -> case cowboy_children:down(Children0, Pid) of %% The stream was terminated already. {ok, undefined, Children} -> @@ -831,11 +832,12 @@ down(State=#state{children=Children0}, Pid, Msg) -> info(State#state{children=Children}, StreamID, Msg); %% The process was unknown. error -> - error_logger:error_msg("Received EXIT signal ~p for unknown process ~p.~n", [Msg, Pid]), + cowboy:log(warning, "Received EXIT signal ~p for unknown process ~p.~n", + [Msg, Pid], Opts), State end. -info(State=#state{streams=Streams0}, StreamID, Msg) -> +info(State=#state{opts=Opts, streams=Streams0}, StreamID, Msg) -> case lists:keyfind(StreamID, #stream.id, Streams0) of Stream = #stream{state=StreamState0} -> try cowboy_stream:info(StreamID, Msg, StreamState0) of @@ -844,14 +846,15 @@ info(State=#state{streams=Streams0}, StreamID, Msg) -> Stream#stream{state=StreamState}), commands(State#state{streams=Streams}, StreamID, Commands) catch Class:Exception -> - cowboy_stream:report_error(info, + cowboy:log(cowboy_stream:make_error_log(info, [StreamID, Msg, StreamState0], - Class, Exception, erlang:get_stacktrace()), + Class, Exception, erlang:get_stacktrace()), Opts), stream_reset(State, StreamID, {internal_error, {Class, Exception}, 'Unhandled exception in cowboy_stream:info/3.'}) end; false -> - error_logger:error_msg("Received message ~p for unknown stream ~p.~n", [Msg, StreamID]), + cowboy:log(warning, "Received message ~p for unknown stream ~p.~n", + [Msg, StreamID], Opts), State end. @@ -1077,7 +1080,7 @@ commands(State0=#state{ref=Ref, parent=Parent, socket=Socket, transport=Transpor #state{streams=Streams} = info(State, StreamID, {inform, 101, Headers}), #stream{state=StreamState} = lists:keyfind(StreamID, #stream.id, Streams), %% @todo We need to shutdown processes here first. - stream_call_terminate(StreamID, switch_protocol, StreamState), + stream_call_terminate(StreamID, switch_protocol, StreamState, State), %% Terminate children processes and flush any remaining messages from the mailbox. cowboy_children:terminate(Children), flush(Parent), @@ -1095,6 +1098,10 @@ commands(State, StreamID, [stop|Tail]) -> %% the next request concurrently. This can be done as a %% future optimization. maybe_terminate(State, StreamID, Tail); +%% Log event. +commands(State=#state{opts=Opts}, StreamID, [Log={log, _, _, _}|Tail]) -> + cowboy:log(Log, Opts), + commands(State, StreamID, Tail); %% HTTP/1.1 does not support push; ignore. commands(State, StreamID, [{push, _, _, _, _, _, _, _}|Tail]) -> commands(State, StreamID, Tail). @@ -1160,7 +1167,7 @@ stream_terminate(State0=#state{opts=Opts, in_streamid=InStreamID, in_state=InSta = lists:keytake(StreamID, #stream.id, Streams1), State2 = State1#state{streams=Streams}, %% Stop the stream. - stream_call_terminate(StreamID, Reason, StreamState), + stream_call_terminate(StreamID, Reason, StreamState, State2), Children = cowboy_children:shutdown(Children0, StreamID), %% We reset the timeout if there are no active streams anymore. State = case Streams of @@ -1195,13 +1202,13 @@ stream_terminate(State0=#state{opts=Opts, in_streamid=InStreamID, in_state=InSta end end. -stream_call_terminate(StreamID, Reason, StreamState) -> +stream_call_terminate(StreamID, Reason, StreamState, #state{opts=Opts}) -> try cowboy_stream:terminate(StreamID, Reason, StreamState) catch Class:Exception -> - cowboy_stream:report_error(terminate, + cowboy:log(cowboy_stream:make_error_log(terminate, [StreamID, Reason, StreamState], - Class, Exception, erlang:get_stacktrace()) + Class, Exception, erlang:get_stacktrace()), Opts) end. %% @todo max_reqs also @@ -1298,9 +1305,9 @@ early_error(StatusCode0, #state{socket=Socket, transport=Transport, RespBody ]) catch Class:Exception -> - cowboy_stream:report_error(early_error, + cowboy:log(cowboy_stream:make_error_log(early_error, [StreamID, Reason, PartialReq, Resp, Opts], - Class, Exception, erlang:get_stacktrace()), + Class, Exception, erlang:get_stacktrace()), Opts), %% We still need to send an error response, so send what we initially %% wanted to send. It's better than nothing. Transport:send(Socket, cow_http:response(StatusCode0, @@ -1312,16 +1319,16 @@ early_error(StatusCode0, #state{socket=Socket, transport=Transport, terminate(undefined, Reason) -> exit({shutdown, Reason}); terminate(State=#state{streams=Streams, children=Children}, Reason) -> - terminate_all_streams(Streams, Reason), + terminate_all_streams(State, Streams, Reason), cowboy_children:terminate(Children), terminate_linger(State), exit({shutdown, Reason}). -terminate_all_streams([], _) -> +terminate_all_streams(_, [], _) -> ok; -terminate_all_streams([#stream{id=StreamID, state=StreamState}|Tail], Reason) -> - stream_call_terminate(StreamID, Reason, StreamState), - terminate_all_streams(Tail, Reason). +terminate_all_streams(State, [#stream{id=StreamID, state=StreamState}|Tail], Reason) -> + stream_call_terminate(StreamID, Reason, StreamState, State), + terminate_all_streams(State, Tail, Reason). terminate_linger(State=#state{socket=Socket, transport=Transport, opts=Opts}) -> case Transport:shutdown(Socket, write) of diff --git a/src/cowboy_http2.erl b/src/cowboy_http2.erl index 70a5e46..c2686aa 100644 --- a/src/cowboy_http2.erl +++ b/src/cowboy_http2.erl @@ -311,7 +311,7 @@ loop(State=#state{parent=Parent, socket=Socket, transport=Transport, cowboy_children:handle_supervisor_call(Call, From, Children, ?MODULE), loop(State, Buffer); Msg -> - error_logger:error_msg("Received stray message ~p.", [Msg]), + cowboy:log(warning, "Received stray message ~p.", [Msg], Opts), loop(State, Buffer) after InactivityTimeout -> terminate(State, {internal_error, timeout, 'No message or data received before timeout.'}) @@ -567,14 +567,15 @@ data_frame(State, Stream0=#stream{id=StreamID, remote_window=StreamWindow, %% We ignore DATA frames for streams that are flushing out data. data_frame(State, Stream=#stream{state=flush}, _, _) -> after_commands(State, Stream); -data_frame(State, Stream=#stream{id=StreamID, state=StreamState0}, IsFin, Data) -> +data_frame(State=#state{opts=Opts}, Stream=#stream{id=StreamID, state=StreamState0}, + IsFin, Data) -> try cowboy_stream:data(StreamID, IsFin, Data, StreamState0) of {Commands, StreamState} -> commands(State, Stream#stream{state=StreamState}, Commands) catch Class:Exception -> - cowboy_stream:report_error(data, + cowboy:log(cowboy_stream:make_error_log(data, [StreamID, IsFin, Data, StreamState0], - Class, Exception, erlang:get_stacktrace()), + Class, Exception, erlang:get_stacktrace()), Opts), stream_reset(State, StreamID, {internal_error, {Class, Exception}, 'Unhandled exception in cowboy_stream:data/4.'}) end. @@ -614,7 +615,7 @@ continuation_frame(State, _) -> terminate(State, {connection_error, protocol_error, 'An invalid frame was received in the middle of a header block. (RFC7540 6.2)'}). -down(State=#state{children=Children0}, Pid, Msg) -> +down(State=#state{opts=Opts, children=Children0}, Pid, Msg) -> case cowboy_children:down(Children0, Pid) of %% The stream was terminated already. {ok, undefined, Children} -> @@ -624,23 +625,25 @@ down(State=#state{children=Children0}, Pid, Msg) -> info(State#state{children=Children}, StreamID, Msg); %% The process was unknown. error -> - error_logger:error_msg("Received EXIT signal ~p for unknown process ~p.~n", [Msg, Pid]), + cowboy:log(warning, "Received EXIT signal ~p for unknown process ~p.~n", + [Msg, Pid], Opts), State end. -info(State=#state{client_streamid=LastStreamID, streams=Streams}, StreamID, Msg) -> +info(State=#state{opts=Opts, client_streamid=LastStreamID, streams=Streams}, StreamID, Msg) -> case lists:keyfind(StreamID, #stream.id, Streams) of #stream{state=flush} -> - error_logger:error_msg("Received message ~p for terminated stream ~p.", [Msg, StreamID]), + cowboy:log(warning, "Received message ~p for terminated stream ~p.", + [Msg, StreamID], Opts), State; Stream = #stream{state=StreamState0} -> try cowboy_stream:info(StreamID, Msg, StreamState0) of {Commands, StreamState} -> commands(State, Stream#stream{state=StreamState}, Commands) catch Class:Exception -> - cowboy_stream:report_error(info, + cowboy:log(cowboy_stream:make_error_log(info, [StreamID, Msg, StreamState0], - Class, Exception, erlang:get_stacktrace()), + Class, Exception, erlang:get_stacktrace()), Opts), stream_reset(State, StreamID, {internal_error, {Class, Exception}, 'Unhandled exception in cowboy_stream:info/3.'}) end; @@ -650,8 +653,8 @@ info(State=#state{client_streamid=LastStreamID, streams=Streams}, StreamID, Msg) %% around. In these cases we do not want to log anything. State; false -> - error_logger:error_msg("Received message ~p for unknown stream ~p.", - [Msg, StreamID]), + cowboy:log(warning, "Received message ~p for unknown stream ~p.", + [Msg, StreamID], Opts), State end. @@ -782,7 +785,11 @@ commands(State0, #stream{id=StreamID}, [{switch_protocol, Headers, _Mod, _ModSta commands(State, Stream=#stream{id=StreamID}, [stop|_Tail]) -> %% @todo Do we want to run the commands after a stop? %% @todo Do we even allow commands after? - stream_terminate(after_commands(State, Stream), StreamID, normal). + stream_terminate(after_commands(State, Stream), StreamID, normal); +%% Log event. +commands(State=#state{opts=Opts}, StreamID, [Log={log, _, _, _}|Tail]) -> + cowboy:log(Log, Opts), + commands(State, StreamID, Tail). after_commands(State=#state{streams=Streams0}, Stream=#stream{id=StreamID}) -> Streams = lists:keystore(StreamID, #stream.id, Streams0, Stream), @@ -952,12 +959,12 @@ terminate(undefined, Reason) -> terminate(#state{socket=Socket, transport=Transport, parse_state={preface, _, _}}, Reason) -> Transport:close(Socket), exit({shutdown, Reason}); -terminate(#state{socket=Socket, transport=Transport, client_streamid=LastStreamID, +terminate(State=#state{socket=Socket, transport=Transport, client_streamid=LastStreamID, streams=Streams, children=Children}, Reason) -> %% @todo We might want to optionally send the Reason value %% as debug data in the GOAWAY frame here. Perhaps more. Transport:send(Socket, cow_http2:goaway(LastStreamID, terminate_reason(Reason), <<>>)), - terminate_all_streams(Streams, Reason), + terminate_all_streams(State, Streams, Reason), cowboy_children:terminate(Children), Transport:close(Socket), exit({shutdown, Reason}). @@ -967,14 +974,14 @@ terminate_reason({stop, _, _}) -> no_error; terminate_reason({socket_error, _, _}) -> internal_error; terminate_reason({internal_error, _, _}) -> internal_error. -terminate_all_streams([], _) -> +terminate_all_streams(_, [], _) -> ok; %% This stream was already terminated and is now just flushing the data out. Skip it. -terminate_all_streams([#stream{state=flush}|Tail], Reason) -> - terminate_all_streams(Tail, Reason); -terminate_all_streams([#stream{id=StreamID, state=StreamState}|Tail], Reason) -> - stream_call_terminate(StreamID, Reason, StreamState), - terminate_all_streams(Tail, Reason). +terminate_all_streams(State, [#stream{state=flush}|Tail], Reason) -> + terminate_all_streams(State, Tail, Reason); +terminate_all_streams(State, [#stream{id=StreamID, state=StreamState}|Tail], Reason) -> + stream_call_terminate(StreamID, Reason, StreamState, State), + terminate_all_streams(State, Tail, Reason). %% Stream functions. @@ -1214,9 +1221,9 @@ stream_early_error(State0=#state{ref=Ref, opts=Opts, peer=Peer, State#state{streams=[Stream|Streams]} end catch Class:Exception -> - cowboy_stream:report_error(early_error, + cowboy:log(cowboy_stream:make_error_log(early_error, [StreamID, Reason, PartialReq, Resp, Opts], - Class, Exception, erlang:get_stacktrace()), + Class, Exception, erlang:get_stacktrace()), Opts), %% We still need to send an error response, so send what we initially %% wanted to send. It's better than nothing. send_headers(State0, Stream0, StatusCode0, RespHeaders0, fin) @@ -1237,9 +1244,9 @@ stream_handler_init(State=#state{opts=Opts, te=maps:get(<<"te">>, Headers, undefined)}, Commands) catch Class:Exception -> - cowboy_stream:report_error(init, + cowboy:log(cowboy_stream:make_error_log(init, [StreamID, Req, Opts], - Class, Exception, erlang:get_stacktrace()), + Class, Exception, erlang:get_stacktrace()), Opts), stream_reset(State, StreamID, {internal_error, {Class, Exception}, 'Unhandled exception in cowboy_stream:init/3.'}) end. @@ -1308,7 +1315,7 @@ stream_terminate(State0=#state{streams=Streams0, children=Children0}, StreamID, State1 = #state{streams=Streams1} = info(State0, StreamID, {response, 204, #{}, <<>>}), State = maybe_skip_body(State1, Stream, Reason), #stream{state=StreamState} = lists:keyfind(StreamID, #stream.id, Streams1), - stream_call_terminate(StreamID, Reason, StreamState), + stream_call_terminate(StreamID, Reason, StreamState, State), Children = cowboy_children:shutdown(Children0, StreamID), State#state{streams=Streams, children=Children}; %% When a response was sent but not terminated, we need to close the stream. @@ -1317,7 +1324,7 @@ stream_terminate(State0=#state{streams=Streams0, children=Children0}, StreamID, State1 = #state{streams=Streams1} = info(State0, StreamID, {data, fin, <<>>}), State = maybe_skip_body(State1, Stream, Reason), #stream{state=StreamState} = lists:keyfind(StreamID, #stream.id, Streams1), - stream_call_terminate(StreamID, Reason, StreamState), + stream_call_terminate(StreamID, Reason, StreamState, State), Children = cowboy_children:shutdown(Children0, StreamID), State#state{streams=Streams, children=Children}; %% Unless there is still data in the buffer. We can however reset @@ -1327,14 +1334,14 @@ stream_terminate(State0=#state{streams=Streams0, children=Children0}, StreamID, %% because we are still sending data via the buffer. We will %% reset the stream if necessary once the buffer is empty. {value, Stream=#stream{state=StreamState, local=nofin}, Streams} -> - stream_call_terminate(StreamID, Reason, StreamState), + stream_call_terminate(StreamID, Reason, StreamState, State0), Children = cowboy_children:shutdown(Children0, StreamID), State0#state{streams=[Stream#stream{state=flush, local=flush}|Streams], children=Children}; %% Otherwise we sent or received an RST_STREAM and/or the stream is already closed. {value, Stream=#stream{state=StreamState}, Streams} -> State = maybe_skip_body(State0, Stream, Reason), - stream_call_terminate(StreamID, Reason, StreamState), + stream_call_terminate(StreamID, Reason, StreamState, State), Children = cowboy_children:shutdown(Children0, StreamID), State#state{streams=Streams, children=Children}; %% The stream doesn't exist. This can occur for various reasons. @@ -1355,13 +1362,13 @@ maybe_skip_body(State=#state{socket=Socket, transport=Transport}, maybe_skip_body(State, _, _) -> State. -stream_call_terminate(StreamID, Reason, StreamState) -> +stream_call_terminate(StreamID, Reason, StreamState, #state{opts=Opts}) -> try cowboy_stream:terminate(StreamID, Reason, StreamState) catch Class:Exception -> - cowboy_stream:report_error(terminate, + cowboy:log(cowboy_stream:make_error_log(terminate, [StreamID, Reason, StreamState], - Class, Exception, erlang:get_stacktrace()) + Class, Exception, erlang:get_stacktrace()), Opts) end. %% System callbacks. diff --git a/src/cowboy_stream.erl b/src/cowboy_stream.erl index 1a1031e..6776863 100644 --- a/src/cowboy_stream.erl +++ b/src/cowboy_stream.erl @@ -78,7 +78,7 @@ -export([info/3]). -export([terminate/3]). -export([early_error/5]). --export([report_error/5]). +-export([make_error_log/5]). %% Note that this and other functions in this module do NOT catch %% exceptions. We want the exception to go all the way down to the @@ -148,47 +148,44 @@ early_error(StreamID, Reason, PartialReq, Resp, Opts) -> PartialReq, Resp, Opts#{stream_handlers => Tail}) end. --spec report_error(atom(), list(), error | exit | throw, any(), list()) -> ok. -report_error(init, [StreamID, Req, Opts], Class, Exception, Stacktrace) -> - error_logger:error_msg( +-spec make_error_log(init | data | info | terminate | early_error, + list(), error | exit | throw, any(), list()) + -> {log, error, string(), list()}. +make_error_log(init, [StreamID, Req, Opts], Class, Exception, Stacktrace) -> + {log, error, "Unhandled exception ~p:~p in cowboy_stream:init(~p, Req, Opts)~n" "Stacktrace: ~p~n" "Req: ~p~n" "Opts: ~p~n", - [Class, Exception, StreamID, Stacktrace, Req, Opts]); -report_error(data, [StreamID, IsFin, Data, State], Class, Exception, Stacktrace) -> - error_logger:error_msg( + [Class, Exception, StreamID, Stacktrace, Req, Opts]}; +make_error_log(data, [StreamID, IsFin, Data, State], Class, Exception, Stacktrace) -> + {log, error, "Unhandled exception ~p:~p in cowboy_stream:data(~p, ~p, Data, State)~n" "Stacktrace: ~p~n" "Data: ~p~n" "State: ~p~n", - [Class, Exception, StreamID, IsFin, Stacktrace, Data, State]); -report_error(info, [StreamID, Msg, State], Class, Exception, Stacktrace) -> - error_logger:error_msg( + [Class, Exception, StreamID, IsFin, Stacktrace, Data, State]}; +make_error_log(info, [StreamID, Msg, State], Class, Exception, Stacktrace) -> + {log, error, "Unhandled exception ~p:~p in cowboy_stream:info(~p, Msg, State)~n" "Stacktrace: ~p~n" "Msg: ~p~n" "State: ~p~n", - [Class, Exception, StreamID, Stacktrace, Msg, State]); -report_error(terminate, [StreamID, Reason, State], Class, Exception, Stacktrace) -> - error_logger:error_msg( + [Class, Exception, StreamID, Stacktrace, Msg, State]}; +make_error_log(terminate, [StreamID, Reason, State], Class, Exception, Stacktrace) -> + {log, error, "Unhandled exception ~p:~p in cowboy_stream:terminate(~p, Reason, State)~n" "Stacktrace: ~p~n" "Reason: ~p~n" "State: ~p~n", - [Class, Exception, StreamID, Stacktrace, Reason, State]); -report_error(early_error, [StreamID, Reason, PartialReq, Resp, Opts], Class, Exception, Stacktrace) -> - error_logger:error_msg( + [Class, Exception, StreamID, Stacktrace, Reason, State]}; +make_error_log(early_error, [StreamID, Reason, PartialReq, Resp, Opts], + Class, Exception, Stacktrace) -> + {log, error, "Unhandled exception ~p:~p in cowboy_stream:early_error(~p, Reason, PartialReq, Resp, Opts)~n" "Stacktrace: ~p~n" "Reason: ~p~n" "PartialReq: ~p~n" "Resp: ~p~n" "Opts: ~p~n", - [Class, Exception, StreamID, Stacktrace, Reason, PartialReq, Resp, Opts]); -report_error(Callback, _, Class, Reason, Stacktrace) -> - error_logger:error_msg( - "Exception occurred in unknown callback ~p~n" - "Reason: ~p:~p~n" - "Stacktrace: ~p~n", - [Callback, Class, Reason, Stacktrace]). + [Class, Exception, StreamID, Stacktrace, Reason, PartialReq, Resp, Opts]}. diff --git a/src/cowboy_stream_h.erl b/src/cowboy_stream_h.erl index 21651f7..55a1ca2 100644 --- a/src/cowboy_stream_h.erl +++ b/src/cowboy_stream_h.erl @@ -134,24 +134,32 @@ info(StreamID, Info={'EXIT', Pid, normal}, State=#state{pid=Pid}) -> do_info(StreamID, Info, [stop], State); info(StreamID, Info={'EXIT', Pid, {{request_error, Reason, _HumanReadable}, _}}, State=#state{pid=Pid}) -> - %% @todo Optionally report the crash to help debugging. - %%report_crash(Ref, StreamID, Pid, Reason, Stacktrace), Status = case Reason of timeout -> 408; payload_too_large -> 413; _ -> 400 end, - %% @todo Headers? Details in body? More stuff in debug only? + %% @todo Headers? Details in body? Log the crash? More stuff in debug only? do_info(StreamID, Info, [ {error_response, Status, #{<<"content-length">> => <<"0">>}, <<>>}, stop ], State); info(StreamID, Exit={'EXIT', Pid, {Reason, Stacktrace}}, State=#state{ref=Ref, pid=Pid}) -> - report_crash(Ref, StreamID, Pid, Reason, Stacktrace), + Commands0 = [{internal_error, Exit, 'Stream process crashed.'}], + Commands = case Reason of + normal -> Commands0; + shutdown -> Commands0; + {shutdown, _} -> Commands0; + _ -> [{log, error, + "Ranch listener ~p, connection process ~p, stream ~p " + "had its request process ~p exit with reason " + "~999999p and stacktrace ~999999p~n", + [Ref, self(), StreamID, Pid, Reason, Stacktrace]} + |Commands0] + end, do_info(StreamID, Exit, [ - {error_response, 500, #{<<"content-length">> => <<"0">>}, <<>>}, - {internal_error, Exit, 'Stream process crashed.'} - ], State); + {error_response, 500, #{<<"content-length">> => <<"0">>}, <<>>} + |Commands], State); %% Request body, auto mode, no body buffered. info(StreamID, Info={read_body, Ref, auto, infinity}, State=#state{read_body_buffer= <<>>}) -> do_info(StreamID, Info, [], State#state{ @@ -244,21 +252,6 @@ send_request_body(Pid, Ref, fin, BodyLen, Data) -> Pid ! {request_body, Ref, fin, BodyLen, Data}, ok. -%% We use ~999999p here instead of ~w because the latter doesn't -%% support printable strings. -report_crash(_, _, _, normal, _) -> - ok; -report_crash(_, _, _, shutdown, _) -> - ok; -report_crash(_, _, _, {shutdown, _}, _) -> - ok; -report_crash(Ref, StreamID, Pid, Reason, Stacktrace) -> - error_logger:error_msg( - "Ranch listener ~p, connection process ~p, stream ~p " - "had its request process ~p exit with reason " - "~999999p and stacktrace ~999999p~n", - [Ref, self(), StreamID, Pid, Reason, Stacktrace]). - %% Request process. %% We catch all exceptions in order to add the stacktrace to diff --git a/src/cowboy_tracer_h.erl b/src/cowboy_tracer_h.erl index 932653b..bbe10a1 100644 --- a/src/cowboy_tracer_h.erl +++ b/src/cowboy_tracer_h.erl @@ -152,37 +152,37 @@ tracer_process(StreamID, Req=#{pid := Parent}, Opts=#{tracer_callback := Fun}) - %% before it has finished processing the events in its queue. process_flag(trap_exit, true), State = Fun(init, {StreamID, Req, Opts}), - tracer_loop(Parent, Fun, State). + tracer_loop(Parent, Opts, State). -tracer_loop(Parent, Fun, State0) -> +tracer_loop(Parent, Opts=#{tracer_callback := Fun}, State0) -> receive Msg when element(1, Msg) =:= trace_ts -> State = Fun(Msg, State0), - tracer_loop(Parent, Fun, State); + tracer_loop(Parent, Opts, State); {'EXIT', Parent, Reason} -> - tracer_terminate(Reason, Fun, State0); + tracer_terminate(Reason, Opts, State0); {system, From, Request} -> - sys:handle_system_msg(Request, From, Parent, ?MODULE, [], {Fun, State0}); + sys:handle_system_msg(Request, From, Parent, ?MODULE, [], {Opts, State0}); Msg -> - error_logger:error_msg("~p: Tracer process received stray message ~9999p~n", - [?MODULE, Msg]), - tracer_loop(Parent, Fun, State0) + cowboy:log(warning, "~p: Tracer process received stray message ~9999p~n", + [?MODULE, Msg], Opts), + tracer_loop(Parent, Opts, State0) end. -spec tracer_terminate(_, _, _) -> no_return(). -tracer_terminate(Reason, Fun, State) -> +tracer_terminate(Reason, #{tracer_callback := Fun}, State) -> _ = Fun(terminate, State), exit(Reason). %% System callbacks. --spec system_continue(pid(), _, {fun(), any()}) -> no_return(). -system_continue(Parent, _, {Fun, State}) -> - tracer_loop(Parent, Fun, State). +-spec system_continue(pid(), _, {cowboy:opts(), any()}) -> no_return(). +system_continue(Parent, _, {Opts, State}) -> + tracer_loop(Parent, Opts, State). -spec system_terminate(any(), _, _, _) -> no_return(). -system_terminate(Reason, _, _, {Fun, State}) -> - tracer_terminate(Reason, Fun, State). +system_terminate(Reason, _, _, {Opts, State}) -> + tracer_terminate(Reason, Opts, State). -spec system_code_change(Misc, _, _, _) -> {ok, Misc} when Misc::any(). system_code_change(Misc, _, _, _) -> |