Intermittent ServerError

[ukazap]

Elixir/OTP version: 1.14.3/24

Toxyproxy version: 2.5.0

Got the following error intermittently:

     test/integration/fill_stream_test.exs:98
     ** (ToxiproxyEx.ServerError) Could not fetch proxies.
     code: for product_symbol <- product_symbols do
     stacktrace:
       (toxiproxy_ex 1.1.0) lib/toxiproxy_ex.ex:162: ToxiproxyEx.all!/0
       (toxiproxy_ex 1.1.0) lib/toxiproxy_ex.ex:118: ToxiproxyEx.get!/1
       test/integration/fill_stream_test.exs:149: anonymous fn/4 in FillStreamTest."test FillStream behaviour correctly starts the supervision tree and process the stream"/1
       (elixir 1.14.3) lib/enum.ex:2468: Enum."-reduce/3-lists^foldl/2-0-"/3
       test/integration/fill_stream_test.exs:144: (test)

Sometimes it's "Could not fetch proxies", another time it's "Could not disable proxy".

Sample:

https://gist.github.com/ukazap/ed7fc6f598abee0e0d14c6ac1796b87e#file-fill_stream_test-exs-L33 https://gist.github.com/ukazap/ed7fc6f598abee0e0d14c6ac1796b87e#file-fill_stream_test-exs-L41 https://gist.github.com/ukazap/ed7fc6f598abee0e0d14c6ac1796b87e#file-fill_stream_test-exs-L147

[Jcambass]

Hi @ukazap 👋🏻

Are you able to provide a minimum reproducible example?

I see that you proposed to change the used HTTP client. I'm not against that but I'd like the better understand this issue you're seeing. We might wanna add more logging first to understand the error you're seeing.

[ukazap]

Hi @Jcambass, you're right, sorry I was in a hurry so it was a guesswork on my part without looking for the root cause. I will get back with more details and log.

[ukazap]

It appears that client() |> Tesla.get("/proxies") returns {:error, :unknown}.

Upon inspecting the Tesla library (mainly putting countless IO.inspects and Kernel.dbgs), I found that there's a stray message being received by this function in the Mint adapter https://github.com/elixir-tesla/tesla/blob/v1.3.3/lib/tesla/adapter/mint.ex#L314

simulating kafka down for 5 seconds
[lib/tesla/adapter/mint.ex:316: Tesla.Adapter.Mint.receive_message/2]
message #=> {:all_done, "OWA_RZZ"}

[lib/tesla/adapter/mint.ex:317: Tesla.Adapter.Mint.receive_message/2]
HTTP.stream(conn, message) #=> :unknown

[lib/tesla/adapter/mint.ex:295: Tesla.Adapter.Mint.receive_packet/4]
receive_message(conn, opts) #=> :unknown

[lib/toxiproxy_ex/client.ex:17: ToxiproxyEx.Client.list_proxies/0]
client() #=> %Tesla.Client{
  fun: nil,
  pre: [
    {Tesla.Middleware.BaseUrl, :call, ["http://toxiproxy:8474"]},
    {Tesla.Middleware.JSON, :call, [[]]}
  ],
  post: [],
  adapter: {Tesla.Adapter.Mint, :call, [[]]}
}
|> Tesla.get("/proxies") #=> {:error, :unknown}

{:all_done, "OWA_RZZ"} is a message that I sent in my test script, not sure why it ended up there, could the :active mode to blame?

Before that message was sent, the request works flawlessly:

[lib/tesla/adapter/mint.ex:316: Tesla.Adapter.Mint.receive_message/2]
message #=> {:tcp, #Port<0.14>,
 "HTTP/1.1 200 OK\r\nContent-Type: application/json\r\nX-Toxiproxy-Request-Id: cj7p71egn34c738anrq0\r\nDate: Sun, 06 Aug 2023 12:35:17 GMT\r\nContent-Length: 114\r\n\r\n{\"kafka\":{\"name\":\"kafka\",\"listen\":\"[::]:9092\",\"upstream\":\"redpanda:29092\",\"enabled\":true,\"Logger\":{},\"toxics\":[]}}"}

[lib/tesla/adapter/mint.ex:317: Tesla.Adapter.Mint.receive_message/2]
HTTP.stream(conn, message) #=> {:ok,
 %Mint.HTTP1{
   host: "toxiproxy",
   port: 8474,
   request: nil,
   streaming_request: nil,
   socket: #Port<0.14>,
   transport: Mint.Core.Transport.TCP,
   mode: :active,
   scheme_as_string: "http",
   requests: {[], []},
   state: :open,
   buffer: "",
   proxy_headers: [],
   private: %{},
   log: false
 },
 [
   {:status, #Reference<0.785926400.3127640068.68267>, 200},
   {:headers, #Reference<0.785926400.3127640068.68267>,
    [
      {"content-type", "application/json"},
      {"x-toxiproxy-request-id", "cj7p71egn34c738anrq0"},
      {"date", "Sun, 06 Aug 2023 12:35:17 GMT"},
      {"content-length", "114"}
    ]},
   {:data, #Reference<0.785926400.3127640068.68267>,
    "{\"kafka\":{\"name\":\"kafka\",\"listen\":\"[::]:9092\",\"upstream\":\"redpanda:29092\",\"enabled\":true,\"Logger\":{},\"toxics\":[]}}"},
   {:done, #Reference<0.785926400.3127640068.68267>}
 ]}

[lib/tesla/adapter/mint.ex:295: Tesla.Adapter.Mint.receive_packet/4]
receive_message(conn, opts) #=> {:ok,
 %Mint.HTTP1{
   host: "toxiproxy",
   port: 8474,
   request: nil,
   streaming_request: nil,
   socket: #Port<0.14>,
   transport: Mint.Core.Transport.TCP,
   mode: :active,
   scheme_as_string: "http",
   requests: {[], []},
   state: :open,
   buffer: "",
   proxy_headers: [],
   private: %{},
   log: false
 },
 [
   {:status, #Reference<0.785926400.3127640068.68267>, 200},
   {:headers, #Reference<0.785926400.3127640068.68267>,
    [
      {"content-type", "application/json"},
      {"x-toxiproxy-request-id", "cj7p71egn34c738anrq0"},
      {"date", "Sun, 06 Aug 2023 12:35:17 GMT"},
      {"content-length", "114"}
    ]},
   {:data, #Reference<0.785926400.3127640068.68267>,
    "{\"kafka\":{\"name\":\"kafka\",\"listen\":\"[::]:9092\",\"upstream\":\"redpanda:29092\",\"enabled\":true,\"Logger\":{},\"toxics\":[]}}"},
   {:done, #Reference<0.785926400.3127640068.68267>}
 ]}

[lib/toxiproxy_ex/client.ex:17: ToxiproxyEx.Client.list_proxies/0]
client() #=> %Tesla.Client{
  fun: nil,
  pre: [
    {Tesla.Middleware.BaseUrl, :call, ["http://toxiproxy:8474"]},
    {Tesla.Middleware.JSON, :call, [[]]}
  ],
  post: [],
  adapter: {Tesla.Adapter.Mint, :call, [[]]}
}
|> Tesla.get("/proxies") #=> {:ok,
 %Tesla.Env{
   method: :get,
   url: "http://toxiproxy:8474/proxies",
   query: [],
   headers: [
     {"content-type", "application/json"},
     {"x-toxiproxy-request-id", "cj7p71egn34c738anrq0"},
     {"date", "Sun, 06 Aug 2023 12:35:17 GMT"},
     {"content-length", "114"}
   ],
   body: %{
     "kafka" => %{
       "Logger" => %{},
       "enabled" => true,
       "listen" => "[::]:9092",
       "name" => "kafka",
       "toxics" => [],
       "upstream" => "redpanda:29092"
     }
   },
   status: 200,
   opts: [],
   __module__: Tesla,
   __client__: %Tesla.Client{
     fun: nil,
     pre: [
       {Tesla.Middleware.BaseUrl, :call, ["http://toxiproxy:8474"]},
       {Tesla.Middleware.JSON, :call, [[]]}
     ],
     post: [],
     adapter: {Tesla.Adapter.Mint, :call, [[]]}
   }
 }}

[ukazap]

@Jcambass

It's a bug in Tesla that they have already fixed @ version >= 1.4 https://github.com/elixir-tesla/tesla/commit/d118d980301aced0473432449098b31601a9e85c

Should we update the dependency?

[ukazap]

I closed my MR #8.

[Jcambass]

Thanks for looking into this @ukazap ❤️ Sounds like upgrading Tesla indeed is the best thing to do. I'll take care of that 👍🏻

[Jcambass]

Fixed in toxiproxy_ex 1.1.1.

[ukazap]

Awesome! thanks, @Jcambass.