Ecto creates unhelpful query error logs

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:

Repo.one from u in Sensetra.Model.User, where: u.id == "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: u0.id == "thisisntvalid",
  select: u0

Or

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

MyTable
|> 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

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

    conn
  end

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.

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