diff --git a/README.md b/README.md new file mode 100644 index 0000000..d971e90 --- /dev/null +++ b/README.md @@ -0,0 +1,4 @@ +# Elli Access Log Middleware + +This is the new home of the `elli_access_log` middleware that used to be +bundled with [elli](https://github.com/knutin/elli). diff --git a/rebar b/rebar new file mode 100755 index 0000000..a753bf8 Binary files /dev/null and b/rebar differ diff --git a/src/elli_access_log.erl b/src/elli_access_log.erl new file mode 100644 index 0000000..c3e2702 --- /dev/null +++ b/src/elli_access_log.erl @@ -0,0 +1,111 @@ +%% @doc HTTP access and error log, sending to syslog over UDP +%% +%% Sends a simple log line for every request, even errors, to +%% syslog. The line includes the following timings, all specified in +%% wall-clock microseconds: +%% +%% RequestLine/Headers/Body/User/Response/Total +%% +%% * RequestLine: time between accept returning and complete receive +%% of the request line, ie. "GET /foo HTTP/1.1". If keep-alive is +%% used, this will be the time since the initial accept so it might +%% be very high. +%% +%% * Headers: Time to receive all headers +%% +%% * Body: Time to receive the entire body into memory, not including +%% any decoding +%% +%% * User: Time spent in the callback. If middleware is used, the +%% runtime of the middleware is included in this number +%% +%% * Response: Time taken to send the response to the client +%% +%% * Total: The time between the request line was received and the +%% response was sent. This is as close we can get to the actual time +%% of the request as seen by the user. + +-module(elli_access_log). +-behaviour(elli_handler). +-export([handle/2, handle_event/3]). + + +handle(_Req, _Args) -> + %% We are installed as a middleware, ignore everything. + ignore. + + +handle_event(request_complete, [Req, ResponseCode, _ResponseHeaders, + ResponseBody, Timings], Config) -> + + %% The Elli request process is done handling the request, so we + %% can afford to do some heavy lifting here. + + Accepted = proplists:get_value(accepted, Timings), + RequestStart = proplists:get_value(request_start, Timings), + HeadersEnd = proplists:get_value(headers_end, Timings), + BodyEnd = proplists:get_value(body_end, Timings), + UserStart = proplists:get_value(user_start, Timings), + UserEnd = proplists:get_value(user_end, Timings), + RequestEnd = proplists:get_value(request_end, Timings), + + TimeStr = io_lib:format("~w/~w/~w/~w/~w/~w", + [timer:now_diff(RequestStart, Accepted), + timer:now_diff(HeadersEnd, RequestStart), + timer:now_diff(BodyEnd, HeadersEnd), + timer:now_diff(UserEnd, UserStart), + timer:now_diff(RequestEnd, UserEnd), + timer:now_diff(RequestEnd, RequestStart)]), + + Msg = io_lib:format("~s ~s ~w ~w \"~s ~s\"", + [elli_request:peer(Req), + TimeStr, + ResponseCode, + iolist_size(ResponseBody), + elli_request:method(Req), + elli_request:raw_path(Req) + ]), + + elli_access_log_server:log(name(Config), Msg), + ok; + +handle_event(request_throw, [Req, Exception, Stack], _Config) -> + error_logger:error_msg("exception: ~p~nstack: ~p~nrequest: ~p~n", + [Exception, Stack, elli_request:to_proplist(Req)]), + ok; +handle_event(request_exit, [Req, Exit, Stack], _Config) -> + error_logger:error_msg("exit: ~p~nstack: ~p~nrequest: ~p~n", + [Exit, Stack, elli_request:to_proplist(Req)]), + ok; + +handle_event(request_error, [Req, Error, Stack], _Config) -> + error_logger:error_msg("error: ~p~nstack: ~p~nrequest: ~p~n", + [Error, Stack, elli_request:to_proplist(Req)]), + ok; + +handle_event(request_parse_error, [_Data], _Args) -> + ok; +handle_event(bad_request, _Data, _Args) -> + ok; + +handle_event(client_closed, [_When], _Config) -> + ok; +handle_event(client_timeout, [_When], _Config) -> + ok; + +handle_event(elli_startup, [], Config) -> + {ok, _} = elli_access_log_server:start_link(name(Config), facility(Config)), + + case whereis(name(Config)) of + undefined -> + {ok, _Pid} = syslog:start_link(name(Config), + proplists:get_value(ip, Config), + proplists:get_value(port, Config)), + ok; + Pid when is_pid(Pid) -> + ok + end. + + +name(Config) -> proplists:get_value(name, Config). +facility(Config) -> proplists:get_value(facility, Config, local0). diff --git a/src/elli_access_log_server.erl b/src/elli_access_log_server.erl new file mode 100644 index 0000000..43ad726 --- /dev/null +++ b/src/elli_access_log_server.erl @@ -0,0 +1,79 @@ +-module(elli_access_log_server). +-behaviour(gen_server). + +%% API +-export([start_link/2, log/2]). + +%% gen_server callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +-record(state, {name, facility}). + +%% +%% API +%% + +start_link(Name, Facility) -> + gen_server:start_link({local, Name}, ?MODULE, [Name, Facility], []). + +log(Name, Msg) -> + (catch ets:insert(Name, {erlang:now(), Msg})). + +%% +%% gen_server callbacks +%% + +init([Name, Facility]) -> + Name = ets:new(Name, [ordered_set, named_table, public, + {write_concurrency, true}]), + + erlang:send_after(1000, self(), flush), + {ok, #state{name = Name, facility = Facility}}. + + +handle_call(_Request, _From, State) -> + Reply = ok, + {reply, Reply, State}. + +handle_cast(_Msg, State) -> + {noreply, State}. + +handle_info(flush, State) -> + erlang:send_after(1000, self(), flush), + Opts = [{ident, node()}, + {facility, State#state.facility}], + SyslogMessages = lists:map(fun ({_Ts, Msg}) -> + {Msg, Opts} + end, flush(State#state.name)), + + syslog:multi_send(State#state.name, SyslogMessages), + {noreply, State}. + +terminate(_Reason, _State) -> + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + +%% +%% INTERNAL +%% + + +flush(Name) -> + flush_before(os:timestamp(), Name). + + +flush_before(Now, Name) -> + flush_before(Now, Name, ets:first(Name), []). + +flush_before(_Now, _Name, '$end_of_table', Acc) -> + Acc; +flush_before(Now, Name, Key, Acc) when Now >= Key -> + [Value] = ets:lookup(Name, Key), + true = ets:delete(Name, Key), + flush_before(Now, Name, ets:next(Name, Key), [Value | Acc]); +flush_before(_Now, _Name, _Key, Acc) -> + Acc. +