Ecto creates unhelpful query error logs

My application, when encountering a database-related error, logs it as follows:

19:30:04.994 request_id=F4COjwtYrfbnTSkAABcx [debug] QUERY ERROR source="table_xyz" db=0.0ms queue=18.5ms idle=287.9ms SELECT ... FROM ... WHERE ... [1]
19:30:04.994 request_id=F4COjwtYrfbnTSkAABcx [info] Sent 500 in 81ms
19:30:04.994 request_id=F4COjwtYrfbnTSkAABcx [debug] Converted error Postgrex.Error to 500 response

This is eminently unhelpful – for one, this shouldn’t be debug level, but more importantly, it doesn’t show any information about the error itself that would allow me to fix it.

As far as I know, my logger configuration is limited to

config :logger, :console,
  format: "$time $metadata[$level] $message\n",
  metadata: [:request_id]

I’m not sure what else I may have misconfigured to cause this problem, and would be grateful for any ideas where to look next.

Hey @skosch can you show the code that causes this error? This is definitely less information than I normally see if my ecto queries have an error, I’m used to seeing something like: from u in Sensetra.Model.User, where: == "thisisntvalid"
** (Ecto.QueryError) iex:2: value `"thisisntvalid"` cannot be dumped to type :id. Or the value is incompatible or it must be interpolated (using ^) so it may be cast accordingly in query:

from u0 in Sensetra.Model.User,
  where: == "thisisntvalid",
  select: u0


Repo.query!("select 1 + 'foo'", [])
** (Postgrex.Error) ERROR 22P02 (invalid_text_representation) invalid input syntax for type integer: "foo"

    query: select 1 + 'foo'
    (ecto_sql 3.10.1) lib/ecto/adapters/sql.ex:913: Ecto.Adapters.SQL.raise_sql_call_error/1
    iex:2: (file)

Hi Ben, in this particular case it was due to some_column missing in Postgres, so any query including it, like

|> where([m], m.some_column == ^some_value)
|> App.Repo.all

would fail with the error shown above.

Do you know what log level your warnings show up at?

That error raises an Ecto.QueryError for me not a Postgrex.Error, what version of ecto / postgrex are you on?

To test this I created this function in my controller and then added a route to it.

  def fail(conn, _params) do
    import Ecto.Query
    alias Sensetra.Repo

    |> where(does_not_exist: "foo")
    |> Repo.all()


When I went to /fail I get this error at log_level: :info.

09:08:39.939 request_id=F4DIU0mXfz3qFAEAAPqG [info] GET /fail
09:08:39.965 request_id=F4DIU0mXfz3qFAEAAPqG [info] Sent 500 in 31ms
09:08:39.968 [error] #PID<0.6302.0> running Phoenix.Endpoint.SyncCodeReloadPlug (connection #PID<0.6301.0>, stream id 1) terminated
Server: localhost:4000 (http)
Request: GET /fail
** (exit) an exception was raised:
    ** (Ecto.QueryError) lib/sensetra/web/controllers/health_controller.ex:21: field `does_not_exist` in `where` does not exist in schema Sensetra.Model.User in query:

from u0 in Sensetra.Model.User,
  where: u0.does_not_exist == "foo",
  select: u0

        (elixir 1.14.3) lib/enum.ex:1780: Enum."-map_reduce/3-lists^mapfoldl/2-0-"/3
        (elixir 1.14.3) lib/enum.ex:1780: Enum."-map_reduce/3-lists^mapfoldl/2-0-"/3
        (elixir 1.14.3) lib/enum.ex:2468: Enum."-reduce/3-lists^foldl/2-0-"/3
        (elixir 1.14.3) lib/enum.ex:2468: Enum."-reduce/3-lists^foldl/2-0-"/3
        (ecto 3.10.3) lib/ecto/repo/queryable.ex:211: Ecto.Repo.Queryable.execute/4
        (ecto 3.10.3) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
        (sensetra 1.0.0) lib/sensetra/web/controllers/health_controller.ex:22

Try in production mode.

This is with debug_errors: false.

1 Like

I think you’ll get Ecto.QueryError is the field is missing from your schema and Postgrex.Error if it’s in your schema but not in your database table.

Thank you both, this is very helpful as it’s helped me narrow the issue down a bit. Specifically, Postgrex.Error messages aren’t printed to the tmp/log/erlang.log.N files (haven’t yet tried with Ecto.QueryErrors)

When I try to query the missing column manually inside of the bin/app remote shell, I do get the error printed to my console:

** (Postgrex.Error) ERROR 42703 (undefined_column) column c0.missing_column does not exist                                                                                                     
    query: SELECT ... FROM ... WHERE ...
    hint: Perhaps you meant to reference the column ...                                                                                                    
    (ecto_sql 3.10.2) lib/ecto/adapters/sql.ex:1047: Ecto.Adapters.SQL.raise_sql_call_error/1                                                                                              
    (ecto_sql 3.10.2) lib/ecto/adapters/sql.ex:945: Ecto.Adapters.SQL.execute/6                                                                                                            
    (ecto 3.10.3) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4                                                                                                            
    (ecto 3.10.3) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3                                                                                                                 
    iex:3: (file)                                                                                                                                                                          
16:39:25.739 [debug] QUERY ERROR ...

But when I hit the same by making an actual request to the app that indirectly hits a resolver function trying to access that column, all I see in tmp/log/erlang.log.1 is the unhelpful

16:39:53.436 request_id=F4Eibp9VbPR3sHQAAAWB [debug] QUERY ERROR ...
16:39:53.436 request_id=F4Eibp9VbPR3sHQAAAWB [info] Sent 500 in 53ms
16:39:53.437 request_id=F4Eibp9VbPR3sHQAAAWB [debug] Converted error Postgrex.Error to 500 response