pinterest / elixir-thrift

A Pure Elixir Thrift Implementation
https://hexdocs.pm/thrift/
Apache License 2.0
214 stars 44 forks source link

"Client exit" service test sometimes fails #411

Open thecodeboss opened 6 years ago

thecodeboss commented 6 years ago

I occasionally get the following error locally:

  1) test clients exit if they try to use a closed client (Thrift.Generator.ServiceTest)
     test/thrift/generator/service_test.exs:387
     ** (exit) exited in: :gen_server.call(#PID<0.1997.0>, {:call, "friend_ids_of", [<<10, 0, 1, 0, 0, 0, 0, 0, 0, 4, 210>> | <<0>>], []}, 5000)
         ** (EXIT) time out
     code: assert Client.friend_ids_of(client, 1234) == {:error, :closed}
     stacktrace:
       (stdlib) gen_server.erl:214: :gen_server.call/3
       (thrift) lib/thrift/binary/framed/client.ex:207: Thrift.Binary.Framed.Client.call/5
       test/thrift/generator/service_test.exs:392: (test)
thecodeboss commented 6 years ago

Similar test failure from a Travis build:

  1) test clients exit if the server dies handling a message (Thrift.Generator.ServiceTest)
     test/thrift/generator/service_test.exs:396
     No message matching {:EXIT, ^client, {:error, :closed}} after 100ms.
     The following variables were pinned:
       client = #PID<0.1744.0>
     Process mailbox:
       {:EXIT, #PID<0.1739.0>, :killed}
       {:EXIT, #PID<0.1744.0>, {:error, :econnreset}}
     code: assert_receive {:EXIT, ^client, {:error, :closed}}
     stacktrace:
       test/thrift/generator/service_test.exs:423: (test)
     The following output was logged:

     05:50:48.207 [error] Failed to connect to 127.0.0.1:36840 due to connection reset by peer

     05:50:48.226 [error] GenServer #PID<0.1740.0> terminating
     ** (stop) killed
     Last message: {:EXIT, #PID<0.1739.0>, :killed}
     State: {:state, {#PID<0.1740.0>, :ranch_listener_sup}, :rest_for_one, [{:child, #PID<0.1742.0>, :ranch_acceptors_sup, {:ranch_acceptors_sup, :start_link, [Thrift.Generator.ServiceTest.ServerSpy, :ranch_tcp]}, :permanent, :infinity, :supervisor, [:ranch_acceptors_sup]}, {:child, #PID<0.1741.0>, :ranch_conns_sup, {:ranch_conns_sup, :start_link, [Thrift.Generator.ServiceTest.ServerSpy, :ranch_tcp, Thrift.Binary.Framed.ProtocolHandler]}, :permanent, :infinity, :supervisor, [:ranch_conns_sup]}], :undefined, 1, 5, [], 0, :ranch_listener_sup, {Thrift.Generator.ServiceTest.ServerSpy, :ranch_tcp, Thrift.Binary.Framed.ProtocolHandler}}

     05:50:48.230 [error] GenServer #PID<0.1744.0> terminating
     ** (stop) {:error, :econnreset}
     Last message: nil
     State: %Thrift.Binary.Framed.Client.State{host: '127.0.0.1', port: 36840, seq_id: 0, sock: nil, ssl_enabled: false, ssl_opts: [], tcp_opts: [], timeout: 5000}
childxr commented 6 years ago

I observed similar when using interactive shell

iex(2)> alias Calculator.Generated.Service.Binary.Framed.Client
Calculator.Generated.Service.Binary.Framed.Client
iex(3)> {:ok, client} = Client.start_link("localhost", 9090, [])
{:ok, #PID<0.238.0>}
iex(4)> {:ok, result} = Client.add(client, 10, 20)
{:ok, 30}
iex(5)> {:ok, result} = Client.add(client, 10, 20)
iex(4)>
23:14:32.826 [error] Connection closed
** (MatchError) no match of right hand side value: {:error, :closed}
    (stdlib) erl_eval.erl:450: :erl_eval.expr/5
    (iex) lib/iex/evaluator.ex:249: IEx.Evaluator.handle_eval/5
    (iex) lib/iex/evaluator.ex:229: IEx.Evaluator.do_eval/3
    (iex) lib/iex/evaluator.ex:207: IEx.Evaluator.eval/3
    (iex) lib/iex/evaluator.ex:94: IEx.Evaluator.loop/1
    (iex) lib/iex/evaluator.ex:24: IEx.Evaluator.init/4
iex(5)>
23:14:32.826 [error] GenServer #PID<0.238.0> terminating
** (stop) {:error, :closed}
Last message (from #PID<0.203.0>): {:call, "add", [<<10, 0, 1, 0, 0, 0, 0, 0, 0, 0, 10>>, <<10, 0, 2, 0, 0, 0, 0, 0, 0, 0, 20>> | <<0>>], []}
State: nil
Client #PID<0.203.0> is alive

    (stdlib) gen.erl:169: :gen.do_call/4
    (stdlib) gen_server.erl:219: :gen_server.call/3
    (thrift) lib/thrift/binary/framed/client.ex:207: Thrift.Binary.Framed.Client.call/5
    (stdlib) erl_eval.erl:677: :erl_eval.do_apply/6
    (stdlib) erl_eval.erl:446: :erl_eval.expr/5
    (elixir) src/elixir.erl:265: :elixir.eval_forms/4
    (iex) lib/iex/evaluator.ex:249: IEx.Evaluator.handle_eval/5
    (iex) lib/iex/evaluator.ex:229: IEx.Evaluator.do_eval/3
** (EXIT from #PID<0.203.0>) shell process exited with reason: {:error, :closed}

Interactive Elixir (1.7.3) - press Ctrl+C to exit (type h() ENTER for help)

Seems like the connection get closed after sometime like 30 sec ~ 1 min. Anyone knows why?