[erlang-bugs] httpc memory leak with stand_alone profile and persistent HTTP connections.

[Ruan Jonker]

Hi,

I've discovered a memory leak in httpc, which occurs when you are using
httpc with a stand_alone profile and using persistent http connections in
R16B03-1.

After some investigation, it turns out that the issue has been around since
R14B04 (maybe even before), but it has been hidden by another bug which was
fixed somewhere in R15.

Synopsis:
--------------

1. Start a stand_alone profile.
2. Establish a persistent http connection to a server that is never
recycled.
3. In a continuous loop, keep on submitting requests on the same persistent
connection at an interval less than keep_alive_timeout (default is 2
minutes), i.e. the tcp connection is kept alive (assuming the server does
not kill the tcp connection).
4. The ETS table used by the httpc_manager to keep track of requests per
httpc_handler process (PROFILENAME__handler_db) grows without ever being
cleaned up, even though the httpc_handler sends "request_done"
notifications (gen_server:cast) for each completed request, back to the
httpc_manager.
5. Either kill the server endpoint or stop submitting requests for longer
than keep_alive_timeout,  so that the tcp connection in 2. can be recycled,
either way, the httpc_manager process will get an 'EXIT' / 'DOWN'
notification, and THEN ONLY it will clean the PROFILENAME__handler_db ETStable.

Code to reproduce (incl. workaround) in R16B03-1:
-------------------------------------------------------------------------
-module(reproduce_httpc_stand_alone_memory_leak_r16b03_1).

-export([go/0]).

go() ->

    application:start(inets),

    TcpPort = 20031,
    NumClientRequests = 5,

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
%Start a httpc server
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
    NotifyReadyPid = self(),
    ServerPid = spawn(fun() -> server_listen(NotifyReadyPid, TcpPort) end),
    receive listening -> ok end,
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
%Start the httpc stand_alone profile
    {ok, ProfilePid} = inets:start(httpc, [{profile, my_profile}],
stand_alone),
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
%First run without workaround
    io:format("whereis(stand_alone_my_profile) => ~p~n", [whereis
(stand_alone_my_profile)]),
    ClientPid = start_the_client(ProfilePid, TcpPort, NumClientRequests),
    monitor(process, ClientPid),
    receive {'DOWN', _, _, ClientPid, _} -> ok end,
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%


%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
%HttpClient connection will recycle
%after 1000ms of inactivity, which will trigger the
%cleanup of the ETS table
    timer:sleep(1100),  0 = ets:info(stand_alone_my_profile__handler_db,
size),
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
%Implement workaround
    io:format("now for the workaround... register(~p,~p)
~n",[stand_alone_my_profile, ProfilePid]),
    register(stand_alone_my_profile, ProfilePid),
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
%Second run with workaround
    io:format("whereis(stand_alone_my_profile) => ~p~n", [whereis
(stand_alone_my_profile)]),
    ClientPid2 = start_the_client(ProfilePid, TcpPort, NumClientRequests),
    monitor(process, ClientPid2),
    receive {'DOWN', _, _, ClientPid2, _} -> ok end,
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

    init:stop().


%HttpServer
server_listen(NotifyReadyPid, Port) ->
    {ok, LS} = gen_tcp:listen(Port, [{ip, {127,0,0,1}}, binary]),
    NotifyReadyPid ! listening,
    server_accept(LS).

server_accept(LS) ->
    {ok, AS} = gen_tcp:accept(LS),
    ok = inet:setopts(AS, [{packet, http}, {active, false}]),
    WPid = spawn(fun() -> receive gogogo -> ok end,  server_worker(AS) end),
    ok = gen_tcp:controlling_process(AS, WPid),
    WPid ! gogogo,
    server_accept(LS).

server_worker(AS) ->
    case recv_to_http_eoh(AS) of
    ok ->
        Rsp = <<"HTTP/1.1 200 OK\r\nContent-Length: 2\r\nContent-Type:
text/html\r\n\r\nOK">>,
        ok = gen_tcp:send(AS, Rsp),
        server_worker(AS);
    closed ->
        ok
    end.

recv_to_http_eoh(AS) ->
    case gen_tcp:recv(AS, 0) of
    {ok, http_eoh} ->
        ok;
    {error, closed} ->
        closed;
    {ok, _Packet} ->
        recv_to_http_eoh(AS)
    end.

%HttpClient
start_the_client(ProfilePid, TcpPort, NumRequests) ->
    ok = httpc:set_options([{max_sessions, 1}, {max_pipeline_length, 0},
{pipeline_timeout, 0}, {max_keep_alive_length, 1}, {keep_alive_timeout,
1000}], ProfilePid),
    Url = "http://localhost:"++integer_to_list(TcpPort)++"/temp",
    spawn(fun() -> worker_thread(Url, ProfilePid, NumRequests) end).

worker_thread(Url, ProfilePid, 0) ->
    io:format("ets:info(stand_alone_my_profile__handler_db, info) => ~p~n",
[ets:info(stand_alone_my_profile__handler_db, size)]);
worker_thread(Url, ProfilePid, NumRequests) when NumRequests > 0 ->
    {ok, {200, <<"OK">>}} = httpc:request(get, {Url, []}, [],
[{body_format, binary}, {full_result, false}], ProfilePid),
    io:format("client ~p request completed.~n", [self()]),
    io:format("ets:info(stand_alone_my_profile__handler_db, info) => ~p~n",
[ets:info(stand_alone_my_profile__handler_db, size)]),
    worker_thread(Url, ProfilePid, NumRequests - 1).

%EOF

>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>


Proposed patch:
------------------------

On file : otp_src_R16B03-1/lib/inets/src/http_client/httpc_manager.erl(didn't
have the R17 src)

82a83
>     Server       = {local, ProfileName},
86c87
<     gen_server:start_link(?MODULE, Args, Opts);
---
>     gen_server:start_link(Server, ?MODULE, Args, Opts);


Other notes:
------------------

The reason why this issue never surfaced in R14B04, is because of the
kepos specified when creating the __handler_db ETS table :

In file otp_src_R14B04/lib/inets/src/http_client/httpc_manager.erl:

You have :
-record(handler_info,
    {
      id,      % Id of the request:          request_id()
      starter, % Pid of the handler starter process (temp): pid()
      handler, % Pid of the handler process: pid()
      from,    % From for the request:  from()
      state    % State of the handler: initiating | started | operational |
canceled
     }).

and in do_init/2 :

ets:new(HandlerDbName,
        [protected, set, named_table, {keypos, #handler_info.id}]),

#handler_info.id maps to element at position 2 in the tuple (element 1 is
the record name),
which means the httpc_handler Pid
is used as key for adding new entries to __handler_db, instead of the
reference generated for each new request (see lines 656 and 716 in same
file).
The net effect being that the __handler_db table being "cleaned" by
overriding any
existing request entry to a given httpc_handler pid.

In later versions (R15 and up), the ETS table is created with :
ets:new(HandlerDbName, [protected, set, named_table, {keypos, 1}])

which results in the reference associated with each request being used for
creating new entries in the relevant __handler_db table, causing the memory
leak.

--END--

-- 
Ruan Jonker
South Africa
+27824619036
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-bugs/attachments/20140324/9ef4f3b6/attachment.htm>