[erlang-bugs] SSL choking on concurrent clients?

[Richard Carlsson]

Friday afternoon SSL fun: we're seeing long pauses where no client is 
getting any replies. See attached module. At first we thought it was a 
problem with lhttpc, but it turned out we could repeat the symptoms by 
making some simple concurrent ssl connections. (In our original case, 
the server was on another machine, and probably not using Erlang.)

    /Richard
-------------- next part --------------
%% NOTE: copy cert+key to current dir or modify CERTFILE and KEYFILE paths below
%%
%% First compile and start the server:
%%   erlc ssl_test.erl
%%   erl -sname server -s ssl_test server
%%
%% Then start a second shell in the same directory and run the client:
%%   erl -sname client -s ssl_test client_test -s init stop
%%
%% Look for messages like "didn't get anything for a while". Run the client
%% again a few times. Sometimes it works fine, and sometimes you get lots of
%% long pauses. Larger number of concurrent clients increase the probability
%% of pauses. Tested on R15, R16, and 17.0.

-define(CERTFILE, "cert.pem").
-define(KEYFILE,  "key.pem").
-define(CLIENTS, 30).

-module(ssl_test).

-export([ server/0
        , client_test/0
        ]).


server() ->
  ssl:start(),
  {ok, ListenSocket} = ssl:listen(9999,
                                  [{certfile, ?CERTFILE},
                                   {keyfile, ?KEYFILE},
                                   {reuseaddr, true}
                                  ]),
  server_loop(ListenSocket, 1).

server_loop(ListenSocket, N) ->
  {ok, Socket} = ssl:transport_accept(ListenSocket),
  ok = ssl:ssl_accept(Socket),
  error_logger:info_msg("~w accepted\n", [N]),
  ssl:send(Socket, <<N>>),
  ssl:close(Socket),
  error_logger:info_msg("~w closed\n", [N]),
  server_loop(ListenSocket, N + 1).


client_test() ->
  ssl:start(),
  Parent = self(),
  Pids = [spawn(fun() -> client(Parent) end) || _ <- lists:seq(1, ?CLIENTS)],
  collect(Pids).

collect(Pids) ->
  {T0, _} = statistics(wall_clock),
  collect(Pids, T0).

collect([], Time) ->
  T = element(1, statistics(wall_clock)) - Time,
  io:format("~w Test server got all replies\n", [T]);
collect(Pids, Time) ->
  receive
    {client_reply, Pid, Res} ->
      T = element(1, statistics(wall_clock)) - Time,
      io:format("~w Test server got reply from ~w: ~w\n", [T, Pid, Res]),
      collect(Pids -- [Pid], Time)
  after 1000 ->
      T = element(1, statistics(wall_clock)) - Time,
      io:format("~w Server didn't get anything for a while: ~w left\n",
                [T, length(Pids)]),
      collect(Pids, Time)
  end.


client(Parent) ->
  case ssl:connect("localhost", 9999,  [], infinity) of
    {ok, Socket} ->
      flush_until_closed(Socket),
      Parent ! {client_reply, self(), ok};
    Other ->
      error_logger:info_msg("Client ~w failed to connect: ~w\n",
                            [self(), Other]),
      flush_all(),
      Parent ! {client_reply, self(), error}
  end.

flush_until_closed(Socket) ->
  receive
    {ssl_closed, Socket} = X ->
      error_logger:info_msg("Client ~w got: ~w\n", [self(), X]);
    X ->
      error_logger:info_msg("Client ~w got: ~w\n", [self(), X]),
      flush_until_closed(Socket)
  end.

flush_all() ->
  receive
    X -> error_logger:info_msg("Client ~w got: ~w\n", [self(), X]),
         flush_all()
  after 0 -> ok
  end.