Hi there,

I’m currently struggling with this bug, because i don’t have much logs and infos provided by my server. I have an endpoint called /stop (code sample provided below) in which i execute a lot of code before returning :ok . All this code is wrap in multiple functions and through multiple files and services.

Not far from the end of those functions, i’m writing to the database. I have 3 different inserts. But since a few days, i have this error : Postgrex.Protocol (#PID<0.375.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.543.0> exited showing up randomly in one of those 3 inserts. (It could be the first one, it could be in the middle of the second one, or the last one. And sometimes (rarely) it doesn’t even fail). The only thing i’ve been able to isolate as a “trigger” is when the inserted data is a little bigger. It has always worked before, and it also worked nicely when i’m trying to insert those same datas directly via iex.

On the Postgres side, i only have this log : LOG: unexpected EOF on client connection with an open transaction .

The controller code looks like this :

  def stop(conn, params) do
        case @influx_caller.end_connexion_performable?(params) do
          true ->
            handle_end_of_connexion(params)
            conn |> send_resp(:ok, [])

          false ->
            if @influx_caller.connexion_data_from(params["connexion_key"]) == %{} do
              update_connexion_with(:influx_empty, params, true)
            end

            conn |> send_resp(:forbidden, [])
        end
      end
    end
  end

The failure happens in the happy path (the true option of the case) in one of the files called by the handle_end_of_connexion function. For example in this query :

Ecto.Changeset.change(connexion, %{
        closed_at: Calculation.get_close_time(events),
      })
      |> Ecto.Changeset.put_assoc(:infos, MyApp.InfosGenerator.perform(obj, obj_type, twi, twl, events))
      |> MyApp.Repo.update

That exact same file with that exact same data can be called from another controller in my app (sort of admin panel), and it works just fine. So i think my problem is coming from the /stop endpoint.

Things i’ve tested so far :

• Checking my OTP version. It was 21.3 and i found a lot of reports talking about similar errors coming from it, so i updated it to 22.1.7
• Activating the show_sensitive_data_on_connection_error hoping it would add some logs to investigate, but no luck.
• Updating phoenix, plug_cowboy, postgrex, and ecto to the latest version.
• Adding http: [protocol_options: [idle_timeout: :infinity]], in my Mix.Config, since i’ve also read about a timeout from cowboy since it’s 2.0 version.

None of this works. (Of course, i also tried to log things everywhere, but everything is working just fine in local mode)

Any help or at least lead would be much appreciated. Thanks in advance !

[EDIT] This bug only happens in production and staging environment, but not locally. We figured that if we gave more memory to our containers, the error still show up, but less. We’re suspecting that the process gets killed by phoenix, but we can’t figure out why and when

[EDIT 2] Thanks to observer, i managed to collect those additional information :

• When this errors happens : Postgrex.Protocol (#PID<0.422.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.31212.0> exited, i have those lines popping in observer =>

11:06:52:783159 (<0.31212.0>) out {lists,reverse,1}
11:06:52:783212 (<0.31212.0>) in {lists,reverse,1}
11:06:52:783218 (<0.31212.0>) << {inet_reply,#Port<0.71>,ok}
11:06:52:783234 (<0.31212.0>) out {prim_inet,send_recv_reply,2}
11:06:52:783243 (<0.31212.0>) in {prim_inet,send_recv_reply,2}
11:06:52:783247 (<0.31212.0>) out {prim_inet,recv0,3}
11:06:52:797698 (<0.31209.0>) in {cowboy_http,loop,1}
11:06:52:797725 (<0.31209.0>) << {tcp_closed,#Port<0.140>}
11:06:52:797750 (<0.31209.0>) getting_unlinked #Port<0.140>
11:06:52:797786 (<0.31209.0>) out {cowboy_children,terminate_loop,2}
11:06:52:797794 (<0.31212.0>) in {prim_inet,recv0,3}
11:06:52:797800 (<0.31212.0>) exit shutdown
11:06:52:797820 (<0.31212.0>) out_exited 0
11:06:52:797905 (<0.31209.0>) in {cowboy_children,terminate_loop,2}
11:06:52:797911 (<0.31209.0>) getting_unlinked <0.31212.0>
11:06:52:797915 (<0.31209.0>) << {'EXIT',<0.31212.0>,shutdown}
11:06:52:797943 (<0.31209.0>) exit {shutdown,{socket_error,closed,'The socket has been closed.'}}
11:06:52:797951 (<0.31209.0>) out_exited 0

The process was spawn here :

11:06:52:304313 (<0.31209.0>) spawn <0.31212.0> as proc_lib:init_p(<0.31209.0>,[<0.447.0>,<0.446.0>,'Elixir.Tracking.Endpoint',<0.414.0>,<0.413.0>],cowboy_stream_h,request_process,[#{body_length => 136,cert => undefined,has_body => true, [etc...]

I really don’t understand what and why this process is closed and the link is lost