are you running pgbouncer or pgpool?
also try and bump log level in prod to :debug for a short while and get a better error trace..
outlog
chasers
sanswork
I’m seeing this exact same thing since switching to DO DBaaS. I haven’t had much time to investigate since as far as I can tell it isn’t actually impacting our service but happy to provide any additional data from another source that might help resolve this.
0
chasers
@sanswork yeah I was seeing it before moving to DO DBaaS … still seeing it there.
@outlog debug logs. Some duplicate queries I will take care of and cache but still nothing insightful.
03:57:00.467 [info] POST /api/logs
03:57:00.467 [info] Sent 403 in 134µs
03:57:00.467 [error] Postgrex.Protocol (#PID<0.1792.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.15429.0> exited
03:57:00.467 [debug] QUERY OK source="sources" db=0.9ms
SELECT s0."id", s0."name", s0."token", s0."public_token", s0."user_id", s0."overflow_source", s0."inserted_at", s0."updated_at" FROM "sources" AS s0 WHERE (s0."token" = $1) [<<250, 216, 124, 203, 137, 171, 76, 211, 131, 234, 81, 39, 84, 62, 128, 240>>]
03:57:00.472 [debug] QUERY OK source="sources" db=4.5ms
SELECT s0."id", s0."name", s0."token", s0."public_token", s0."user_id", s0."overflow_source", s0."inserted_at", s0."updated_at" FROM "sources" AS s0 WHERE (s0."token" = $1) [<<250, 216, 124, 203, 137, 171, 76, 211, 131, 234, 81, 39, 84, 62, 128, 240>>]
03:57:00.473 [debug] QUERY OK source="sources" db=1.1ms
SELECT s0."id", s0."name", s0."token", s0."public_token", s0."user_id", s0."overflow_source", s0."inserted_at", s0."updated_at" FROM "sources" AS s0 WHERE (s0."token" = $1) [<<250, 216, 124, 203, 137, 171, 76, 211, 131, 234, 81, 39, 84, 62, 128, 240>>]
03:57:00.475 [debug] QUERY OK source="rules" db=1.4ms
SELECT r0."id", r0."regex", r0."sink", r0."source_id" FROM "rules" AS r0 WHERE (r0."source_id" = $1) [142]
03:57:00.475 [info] Sent 200 in 10ms
03:57:00.496 [info] POST /api/logs
03:57:00.496 [info] Sent 403 in 180µs
03:57:00.496 [error] Postgrex.Protocol (#PID<0.1791.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.15435.0> exited
03:57:00.553 [info] POST /api/logs
03:57:00.556 [debug] QUERY OK source="sources" db=2.1ms
SELECT s0."id", s0."name", s0."token", s0."public_token", s0."user_id", s0."overflow_source", s0."inserted_at", s0."updated_at" FROM "sources" AS s0 WHERE (s0."token" = $1) [<<250, 216, 124, 203, 137, 171, 76, 211, 131, 234, 81, 39, 84, 62, 128, 240>>]
idk
0
chasers
outlog
sorry my bad on the debug level.. you need to enable :show_sensitive_data_on_connection_error to get better disconnect error messages, note the sensitive part.. db_connection/lib/db_connection.ex at master · elixir-ecto/db_connection · GitHub
nope you are fine
the exact same error? or similar?
yeah, seems like a general issue running up against pgbouncer (at least the DO one)
0
yurko
Weird that there is so little info in debug logs, but these might still be timeouts cause workers have to wait too long and increasing pool size would not help if your CPU can’t handle the load. To check it it’s true you can add timeout to your config, the default one is 15 seconds and you can set it to say 30:
config :app, App.Repo,
...
pool_size: ..,
timeout: 30000
The actual option is here Postgrex — Postgrex v0.22.2
If you have less such errors after changing the setting it would mean you actually short on CPU, but only sometimes. If it’s not about peak times but rather constant load is too high, the setting will do nothing but delay the errors. Anyway this might be a sign that you have to upgrade the droplet.
0
chasers
Well rewrote it … no db calls anymore. Previously:
20:01:39.968 [info] Sent 200 in 6ms
20:01:39.973 [info] POST /api/logs
20:01:39.974 [info] POST /api/logs
20:01:39.976 [info] POST /api/logs
20:01:39.977 [info] POST /api/logs
20:01:39.979 [info] POST /api/logs
20:01:39.981 [info] Sent 200 in 7ms
20:01:39.982 [info] Sent 200 in 7ms
20:01:39.983 [info] Sent 200 in 5ms
20:01:39.984 [info] Sent 200 in 7ms
Using my ETS cache:
20:05:50.294 [info] Sent 200 in 251µs
20:05:50.327 [info] POST /api/logs
20:05:50.327 [info] Sent 200 in 430µs
20:05:50.337 [info] POST /api/logs
20:05:50.337 [info] Sent 200 in 483µs
20:05:50.342 [info] POST /api/logs
20:05:50.343 [info] Sent 200 in 358µs
20:05:50.344 [info] POST /api/logs
20:05:50.344 [info] Sent 200 in 374µs
20:05:50.357 [info] POST /api/logs
I cut off that user from POSTing to us temporarily via an NGINX rule. Will reactivate them again soon to see but since we’re not making any db calls I’m certain I won’t see that message again. It was definitely only when they were hitting us and we were sending a 403 because they deleted the source they were actively logging to.
Another question … so implementing this cache … I’m assuming this is what Phoenix contexts are for? I started this app in Phoenix 1.3 so wasn’t familiar with contexts but now it would be nice if all my db calls were behind one module interface so I only had one place to update the cache when needed.
1
chasers
Holy hell okay if anyone cares this was the real fix for the original problem:
https://github.com/Logflare/logflare/commit/d22d07444a0a2800da7eea8de2201e003f058559
Basically I was using pipelineing in a plug module and was setting the response multiple times. Rewrote with plug builder so halt() is actually halting now. That was also one of the first things I wrote in Elixir / for this app so I’m sure that explains it haha.
9