take over from elli main repo @ fb22a7422e86

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

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

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