Introduce undocumented option logger

This commit reworks the logging that Cowboy does via
error_logger to make the module that will do the actual
logging configurable.

The logger module interface must be the same as logger
and lager: a separate function per log level with the
same log levels they support.

The default behavior remains to call error_logger,
although some messages were downgraded to warnings
instead of errors. Since error_logger only supports
three different log levels, some messages may get
downgraded/upgraded depending on what the original
log level was to make them compatible with error_logger.

The {log, Level, Format, Args} command was also
added to stream handlers. Stream handlers should
use this command to log messages because it allows
writing a stream handler to intercept some of those
messages and extract information or block them as
necessary.

The logger option only applies to Cowboy itself,
not to the messages Ranch logs, so more work remains
to be done in that area.

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:
 

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).

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,26 +301,26 @@ 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} ->
 			Streams = lists:keyreplace(StreamID, #stream.id, Streams0,
 				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