Postgrex Client Exited Help

chasers

Any insight would be appreciated here…

I’m getting this message in my logs and can’t quite figure it out:

Postgrex.Protocol (pid<>) disconnected: ** (DBConnection.ConnectionError) client pid<> exited

I’ve been working on a centralized logging service https://logflare.app. It’s really easy to start using if you’re on Cloudflare because we have a Cloudflare app. Recently been getting some larger sites signing up.

This weekend we got another big one playing with it. CPU was high and ram started climbing. Looking at the logs I see that message.

At that point everything was on a $40 a month Digital Ocean box (which is awesome because we are handling a lot of requests, sometime sites are sending upwards of 1000 requests a second). No downtime at all and no bad response codes. Ecto seems to just be reissuing the query or something if it exits.

My first try at alleviating this was to move Postgres to it’s own instance. I did that … still seeing errors. Doesn’t seem to be Postgres struggling. Upped the Ecto pool count, and enabled pooling on Postgres. No difference there.

Then I started caching API keys in ETS. Which is also awesome because it was super easy. A little lighter load on Postgres but still I get those errors in the logs.

Not quite sure where to go from here. The way I see it I can:
a) Cache more stuff in ETS.
b) Upgrade the box.
c) Remove Nginx as maybe there is some contention there (currently limiting Nginx to 2 workers and it’s a 4 core box).

Although I’m still kind of just throwing darts here. Is something in my code killing the client? Is whatever making that call finishing before the query returns and causing the exit?

I need to figure out how to run observer remotely. Maybe that will shed some light on things. I’m assuming the ram issue is logger filling up with error messages.

Another fun side effect is that mix edeliver restart production just hangs. No idea why that is either.

Code is all up at: GitHub - Logflare/logflare: Never get surprised by a logging bill again. Centralized structured logging for Cloudflare, Vercel, Elixir and Javascript. · GitHub

19 comments

#troubleshooting

2 5141 19

2019-03-19 22:16:45 UTC

Showing Posts 1 to 10

Show Best Posts
Show All (oldest first)
Show All (newest first)

engineeringdept

You’re not running on Erlang/OTP 21.3 are you? I got bitten by this bug, when connecting to Postgres over SSL.

Post #1

outlog

yeah, this(similar error output)was also in an earlier OTP (20).. so make sure to bump to latest patch version - and avoid 21.3

Post #2

chasers

Running OTP 21 will by a different patch version

Post #3

outlog

what version are you on now?

Post #4

chasers

Did sudo apt-get upgrade esl-erlang=1:21.2.7-1 and still seeing this issue.

Upgrade looks like it went fine. Killed and restarted the app. Maybe recompile?

Post #5

chasers

And come to think of it … it was happening before when Postgres was on the same server and I wasn’t connecting over ssl.

Post #6

outlog

can you post a bit more of the error log eg. is an timeout?

would assume you need to do a new release to pick it up - also update your build server..

also mix.hex outdated has latest postgrex/ecto etc?

EDIT: also what OTP version did you have on it?

Post #7

chasers

Logs just look a lot like this:

21:37:30.862 [info] POST /api/logs
21:37:30.862 [info] Sent 403 in 228µs
21:37:30.862 [error] Postgrex.Protocol (#PID<0.1817.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.8124.20> exited
21:37:30.874 [info] Sent 200 in 42ms
21:37:30.877 [info] POST /api/logs
21:37:30.878 [info] Sent 200 in 27ms
21:37:30.878 [info] POST /api/logs
21:37:30.878 [info] Sent 403 in 158µs
21:37:30.878 [error] Postgrex.Protocol (#PID<0.1816.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.8480.20> exited
21:37:30.881 [info] POST /api/logs
21:37:30.885 [info] Sent 200 in 32ms
21:37:30.886 [info] Sent 200 in 29ms
21:37:30.886 [info] Sent 200 in 28ms
21:37:30.892 [info] POST /api/logs
21:37:30.892 [info] Sent 403 in 224µs
21:37:30.892 [error] Postgrex.Protocol (#PID<0.1802.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.32377.19> exited
21:37:30.894 [info] Sent 200 in 12ms
21:37:30.895 [info] Sent 200 in 17ms
21:37:30.897 [info] POST /api/logs
21:37:30.897 [info] Sent 403 in 288µs
21:37:30.898 [error] Postgrex.Protocol (#PID<0.1869.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.7904.20> exited

deps are:

defp deps do
    [
      {:phoenix, "~> 1.4.0"},
      {:phoenix_pubsub, "~> 1.0"},
      {:phoenix_ecto, "~> 4.0"},
      {:ecto_sql, "~> 3.0.5"},
      {:postgrex, ">= 0.0.0"},
      {:phoenix_html, "~> 2.10"},
      {:phoenix_live_reload, "~> 1.0", only: :dev},
      {:gettext, "~> 0.11"},
      {:plug_cowboy, "~> 2.0"},
      {:ueberauth_github, "~> 0.7"},
      {:plug, "~> 1.7"},
      {:jason, "~> 1.0"},
      {:distillery, "~> 2.0"},
      {:edeliver, ">= 1.6.0"},
      {:httpoison, "~> 1.4"},
      {:phoenix_oauth2_provider,
       github: "danschultzer/phoenix_oauth2_provider", branch: "phoenix-1-4"},
      {:poison, "~> 3.1"},
      {:ueberauth_google, "~> 0.8"}
    ]
  end

Build server is currently the same as prod.

Post #8

outlog

Those logs are missing key information… but I will go ahead and assume those are timeouts..

I assume “POST /api/logs” to be a flaming hot path and from a quick look you have 5-7 db queries going on that is way much for a hot path (starting with a plug assigning user which seems not needed)

increase the ecto :timeout

consider using Repo.checkout to bundle them into one, but perhaps better to use Cachex and avoid the db calls.

they look like somewhat stable repo.get/repo.all - so wrap those calls with Cachex - add appropriate cachex update/delete calls where needed elsewhere to bust/update the cache.

consider instrumentation like GitHub - deadtrickster/prometheus-ecto: Prometheus.io collector for Elixir.Ecto · GitHub or similar

Post #9