Phoenix API Using Absinthe - Issue Sending Back Mutation Data to Frontend After Deploying

tnederlof · May 16, 2020, 1:30am

I am struggling to figure out how to go about getting to the bottom of the following issue. Any pointers even if total guesses would be greatly appreciated.

I have a Phoenix app using Ecto/Postgres and Absinthe for Graphql. My front end can send queries and mutations no problem when both the front and backend are on my local dev machine. I have tried deploying the front and backend using render.com (which is amazing so far). The issue I am running into is as soon as I send a mutation the DB actions succeed (I can see the correct rows being written to my database), however my front end never receives data back (I get an Internal Server Error). When I look in the logs of my server I see the following…

May 15 09:26:36 PM  01:26:36.296 request_id=Fg9d3MbmOxvBr94AAAPi [info] POST /api
May 15 09:26:51 PM  01:26:51.536 [error] Postgrex.Protocol (#PID<0.3631.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4107.0> timed out because it queued and checked out the connection for longer than 15000ms
May 15 09:26:51 PM  
May 15 09:26:51 PM  #PID<0.4107.0> was at location:
May 15 09:26:51 PM  
May 15 09:26:51 PM      (stdlib) gen.erl:167: :gen.do_call/4
May 15 09:26:51 PM      (stdlib) gen_statem.erl:623: :gen_statem.call_dirty/4
May 15 09:26:51 PM      (ssl) ssl_connection.erl:2525: :ssl_connection.call/2
May 15 09:26:51 PM      (postgrex) lib/postgrex/protocol.ex:2879: Postgrex.Protocol.rows_recv/5
May 15 09:26:51 PM      (postgrex) lib/postgrex/protocol.ex:1898: Postgrex.Protocol.recv_execute/5
May 15 09:26:51 PM      (postgrex) lib/postgrex/protocol.ex:1772: Postgrex.Protocol.bind_execute/4
May 15 09:26:51 PM      (db_connection) lib/db_connection/holder.ex:316: DBConnection.Holder.holder_apply/4
May 15 09:26:51 PM      (db_connection) lib/db_connection.ex:1255: DBConnection.run_execute/5
May 15 09:26:51 PM  
May 15 09:26:51 PM  01:26:51.538 [error] Task #PID<0.4107.0> started from #PID<0.4105.0> terminating
May 15 09:26:51 PM  ** (DBConnection.ConnectionError) ssl recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)
May 15 09:26:51 PM      (ecto_sql) lib/ecto/adapters/sql.ex:593: Ecto.Adapters.SQL.raise_sql_call_error/1
May 15 09:26:51 PM      (ecto_sql) lib/ecto/adapters/sql.ex:526: Ecto.Adapters.SQL.execute/5
May 15 09:26:51 PM      (ecto) lib/ecto/repo/queryable.ex:192: Ecto.Repo.Queryable.execute/4
May 15 09:26:51 PM      (ecto) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
May 15 09:26:51 PM      (elixir) lib/enum.ex:1336: Enum."-map/2-lists^map/1-0-"/2
May 15 09:26:51 PM  Function: &:erlang.apply/2
May 15 09:26:51 PM      Args: [#Function<10.44016962/1 in Dataloader.Source.Dataloader.Ecto.run_batches/1>, [{{:assoc, Weatherscout.Weather.Station, #PID<0.4087.0>, :observations, Weatherscout.Weather.Observation, %{}}, #MapSet<[{["USC00043113"], %Weatherscout.Weather.Station{__meta__: #Ecto.Schema.Metadata<:loaded, "stations">, elevation: 106.7, gsnflag: false, hcnflag: false, id: "USC00043113", inserted_at: ~U[2020-05-14 00:00:00Z], latitude: 38.7, locations: #Ecto.Association.NotLoaded<association :locations is not loaded>, longitude: -121.1667, name: "FOLSOM DAM", observations: #Ecto.Association.NotLoaded<association :observations is not loaded>, post_office: "Folsom", state: "CA", updated_at: ~U[2020-05-14 00:00:00Z], wmoid: nil, zipcode: "95630"}}]>}]]
May 15 09:26:51 PM  01:26:51.540 request_id=Fg9d3MbmOxvBr94AAAPi [info] Sent 500 in 15244ms
May 15 09:26:51 PM  01:26:51.540 request_id=Fg9d3MbmOxvBr94AAAPi [info] Converted error Dataloader.GetError to 500 response
May 15 09:26:51 PM  01:26:51.544 [error] #PID<0.4087.0> running WeatherscoutWeb.Endpoint (connection #PID<0.4086.0>, stream id 1) terminated
May 15 09:26:51 PM  Server: XXXXXXXXXXXXXXX.com:80 (http)
May 15 09:26:51 PM  Request: POST /api
May 15 09:26:51 PM  ** (exit) an exception was raised:
May 15 09:26:51 PM      ** (Dataloader.GetError) {%DBConnection.ConnectionError{message: "ssl recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)", severity: :error}, [{Ecto.Adapters.SQL, :raise_sql_call_error, 1, [file: 'lib/ecto/adapters/sql.ex', line: 593]}, {Ecto.Adapters.SQL, :execute, 5, [file: 'lib/ecto/adapters/sql.ex', line: 526]}, {Ecto.Repo.Queryable, :execute, 4, [file: 'lib/ecto/repo/queryable.ex', line: 192]}, {Ecto.Repo.Queryable, :all, 3, [file: 'lib/ecto/repo/queryable.ex', line: 17]}, {Enum, :"-map/2-lists^map/1-0-", 2, [file: 'lib/enum.ex', line: 1336]}]}
May 15 09:26:51 PM          (dataloader) lib/dataloader.ex:198: Dataloader.do_get/2
May 15 09:26:51 PM          (absinthe) lib/absinthe/resolution/helpers.ex:257: anonymous fn/5 in Absinthe.Resolution.Helpers.do_dataloader/6
May 15 09:26:51 PM          (absinthe) lib/absinthe/middleware/dataloader.ex:33: Absinthe.Middleware.Dataloader.get_result/2
May 15 09:26:51 PM          (absinthe) lib/absinthe/phase/document/execution/resolution.ex:209: Absinthe.Phase.Document.Execution.Resolution.reduce_resolution/1
May 15 09:26:51 PM          (absinthe) lib/absinthe/phase/document/execution/resolution.ex:168: Absinthe.Phase.Document.Execution.Resolution.do_resolve_field/4
May 15 09:26:51 PM          (absinthe) lib/absinthe/phase/document/execution/resolution.ex:98: Absinthe.Phase.Document.Execution.Resolution.walk_results/6
May 15 09:26:51 PM          (absinthe) lib/absinthe/phase/document/execution/resolution.ex:77: Absinthe.Phase.Document.Execution.Resolution.walk_result/5
May 15 09:26:51 PM          (absinthe) lib/absinthe/phase/document/execution/resolution.ex:98: Absinthe.Phase.Document.Execution.Resolution.walk_results/6

dimitarvp · May 16, 2020, 6:28am

There’s no way for us to know with only a log but I’d guess your backend is spawning a new process somewhere and is processing a long DB query. You could add logging statements in the body of your mutating function and take it from there.

tnederlof · May 16, 2020, 11:58am

Thank you. Yes, I am trying to narrow it down so then perhaps I can post the relevant parts. I put some logging into the mutation function in questions and everything looks fine, it inserts into the database and after when I look at the data it looks fine (which it returns). Since the error comes after all of that (after the function in my context), where is the next place I should be looking?

dimitarvp · May 16, 2020, 5:56pm

Do you have some sort of background workers in your app?

tnederlof · May 17, 2020, 12:03am

No it’s just a pretty standard Phoenix API only app using ecto and Postgres. Considering everything works locally and that’s all http I’m wondering if it’s an issue with my deployment setup and https. It’s odd though because the request makes it, data written to database, queries data succeeds, it just never makes it back out to the front end.

dimitarvp · May 17, 2020, 2:09pm

Sounds like a firewall problem, maybe? Not an expert in that though. What’s your setup? AWS?

tnederlof · May 18, 2020, 2:02am

I am using render.com. I messed around with my own droplets and trying to deploy but quickly got lost in the sea of tutorials out of data/to many config options distillery, etc. Render.com is the first method I got up and running, its just this weird connection issue I am having.

tnederlof · May 18, 2020, 1:43pm

I did some more testing with IO.inspect and I can see the data being successfully returned from the resolver function. Does anyone else know where else I can look from the output of resolver function to where it gets sent back out to the requesting front end post request?