Merge pull request #20 from deadtrickster/request_start_timing_fix

Request start timing fix. closes #19
elli-lib · Nov 27, 2016 · cb55269 · cb55269
2 parents 7b1336e + 02aed60
commit cb55269
Show file tree

Hide file tree

Showing 3 changed files with 91 additions and 19 deletions.
diff --git a/rebar.config b/rebar.config
@@ -11,6 +11,9 @@
       ]},
       {doclet, edown_doclet}
     ]}
+  ]},
+  {test, [
+    {deps,      [{hackney, "1.6.3"}]}
   ]}
 ]}.
 

diff --git a/src/elli_http.erl b/src/elli_http.erl
@@ -70,7 +70,7 @@ keepalive_loop(Socket, Options, Callback) ->
 keepalive_loop(Socket, NumRequests, Buffer, Options, Callback) ->
     case ?MODULE:handle_request(Socket, Buffer, Options, Callback) of
         {keep_alive, NewBuffer} ->
-            ?MODULE:keepalive_loop(Socket, NumRequests,
+            ?MODULE:keepalive_loop(Socket, NumRequests + 1,
                                    NewBuffer, Options, Callback);
         {close, _} ->
             elli_tcp:close(Socket),
@@ -87,7 +87,6 @@ keepalive_loop(Socket, NumRequests, Buffer, Options, Callback) ->
       Callback  :: elli_handler:callback(),
       ConnToken :: {'keep_alive' | 'close', binary()}.
 handle_request(S, PrevB, Opts, {Mod, Args} = Callback) ->
-    t(request_start),
     {Method, RawPath, V, B0} = get_request(S, PrevB, Opts, Callback),
     t(headers_start),
     {RequestHeaders, B1} = get_headers(S, V, B0, Opts, Callback),
@@ -404,23 +403,17 @@ send_chunk(Socket, Data) ->
 %%
 
 %% @doc Retrieve the request line.
-get_request(Socket, Buffer, Options, {Mod, Args} = Callback) ->
+get_request(Socket, <<>>, Options, Callback) ->
+    NewBuffer = recv_request(Socket, <<>>, Options, Callback),
+    get_request(Socket, NewBuffer, Options, Callback);
+get_request(Socket, Buffer, Options, Callback) ->
+    t(request_start),
+    get_request_(Socket, Buffer, Options, Callback).
+
+get_request_(Socket, Buffer, Options, {Mod, Args} = Callback) ->
     case erlang:decode_packet(http_bin, Buffer, []) of
         {more, _} ->
-            case elli_tcp:recv(Socket, 0, request_timeout(Options)) of
-                {ok, Data} ->
-                    NewBuffer = <<Buffer/binary, Data/binary>>,
-                    get_request(Socket, NewBuffer, Options, Callback);
-                {error, timeout} ->
-                    handle_event(Mod, request_timeout, [], Args),
-                    elli_tcp:close(Socket),
-                    exit(normal);
-                {error, Closed} when Closed =:= closed orelse
-                                     Closed =:= enotconn ->
-                    handle_event(Mod, request_closed, [], Args),
-                    elli_tcp:close(Socket),
-                    exit(normal)
-            end;
+            recv_request(Socket, Buffer, Options, Callback);
         {ok, {http_request, Method, RawPath, Version}, Rest} ->
             {Method, RawPath, Version, Rest};
         {ok, {http_error, _}, _} ->
@@ -433,6 +426,21 @@ get_request(Socket, Buffer, Options, {Mod, Args} = Callback) ->
             exit(normal)
     end.
 
+recv_request(Socket, Buffer, Options, {Mod, Args} = _Callback) ->
+    case elli_tcp:recv(Socket, 0, request_timeout(Options)) of
+        {ok, Data} ->
+            <<Buffer/binary, Data/binary>>;
+        {error, timeout} ->
+            handle_event(Mod, request_timeout, [], Args),
+            elli_tcp:close(Socket),
+            exit(normal);
+        {error, Closed} when Closed =:= closed orelse
+                             Closed =:= enotconn ->
+            handle_event(Mod, request_closed, [], Args),
+            elli_tcp:close(Socket),
+            exit(normal)
+    end.
+
 -spec get_headers(Socket, V, Buffer, Opts, Callback) -> Headers when
       Socket   :: elli_tcp:socket(),
       V        :: version(),

diff --git a/test/elli_tests.erl b/test/elli_tests.erl
@@ -7,8 +7,8 @@
 -define(I2L(I), integer_to_list(I)).
 -define(README, "README.md").
 -define(VTB(T1, T2, LB, UB),
-        time_diff_to_micro_seconds(T1, T2) > LB andalso
-        time_diff_to_micro_seconds(T1, T2) < UB).
+        time_diff_to_micro_seconds(T1, T2) >= LB andalso
+        time_diff_to_micro_seconds(T1, T2) =< UB).
 
 time_diff_to_micro_seconds(T1, T2) ->
     erlang:convert_time_unit(
@@ -23,6 +23,7 @@ elli_test_() ->
      [{foreach,
        fun init_stats/0, fun clear_stats/1,
        [?_test(hello_world()),
+        ?_test(keep_alive_timings()),
         ?_test(not_found()),
         ?_test(crash()),
         ?_test(invalid_return()),
@@ -72,6 +73,7 @@ setup() ->
     application:start(crypto),
     application:start(public_key),
     application:start(ssl),
+    hackney:start(),
     inets:start(),
 
     Config = [
@@ -167,6 +169,65 @@ hello_world() ->
     ?assertMatch(true,
                  ?VTB(send_start, send_end, 1, 200)).
 
+
+keep_alive_timings() ->
+
+    Transport = hackney_tcp,
+    Host = <<"localhost">>,
+    Port = 3001,
+    Options = [],
+    {ok, ConnRef} = hackney:connect(Transport, Host, Port, Options),
+
+    ReqBody = <<>>,
+    ReqHeaders = [],
+    ReqPath = <<"/hello/world">>,
+    ReqMethod = get,
+    Req = {ReqMethod, ReqPath, ReqHeaders, ReqBody},
+
+    {ok, Status, Headers, HCRef} = hackney:send_request(ConnRef, Req),
+    keep_alive_timings(Status, Headers, HCRef),
+
+    %% pause between keep-alive requests,
+    %% request_start is a timestamp of
+    %% the first bytes of the second request
+    timer:sleep(1000),
+
+    {ok, Status, Headers, HCRef} = hackney:send_request(ConnRef, Req),
+    keep_alive_timings(Status, Headers, HCRef),
+
+    hackney:close(ConnRef).
+
+keep_alive_timings(Status, Headers, HCRef) ->
+    ?assertMatch(200, Status),
+    ?assertMatch([{<<"Connection">>,<<"Keep-Alive">>},
+                  {<<"Content-Length">>,<<"12">>}], Headers),
+    ?assertMatch({ok, <<"Hello World!">>}, hackney:body(HCRef)),
+    %% sizes
+    ?assertMatch(63, get_size_value(resp_headers)),
+    ?assertMatch(12, get_size_value(resp_body)),
+    %% timings
+    ?assertNotMatch(undefined, get_timing_value(request_start)),
+    ?assertNotMatch(undefined, get_timing_value(headers_start)),
+    ?assertNotMatch(undefined, get_timing_value(headers_end)),
+    ?assertNotMatch(undefined, get_timing_value(body_start)),
+    ?assertNotMatch(undefined, get_timing_value(body_end)),
+    ?assertNotMatch(undefined, get_timing_value(user_start)),
+    ?assertNotMatch(undefined, get_timing_value(user_end)),
+    ?assertNotMatch(undefined, get_timing_value(send_start)),
+    ?assertNotMatch(undefined, get_timing_value(send_end)),
+    ?assertNotMatch(undefined, get_timing_value(request_end)),
+    %% check timings
+    ?assertMatch(true,
+                 ?VTB(request_start, request_end, 1000000, 1200000)),
+    ?assertMatch(true,
+                 ?VTB(headers_start, headers_end, 1, 100)),
+    ?assertMatch(true,
+                 ?VTB(body_start, body_end, 1, 100)),
+    ?assertMatch(true,
+                 ?VTB(user_start, user_end, 1000000, 1200000)),
+    ?assertMatch(true,
+                 ?VTB(send_start, send_end, 1, 200)).
+
 not_found() ->
     {ok, Response} = httpc:request("http://localhost:3001/foobarbaz"),
     ?assertMatch(404, status(Response)),