Ecto creates unhelpful query error logs

Questions / Help
, , ,
1

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.

2

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)
3

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?

4

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
5

Try in production mode.

6

This is with debug_errors: false.

1 Like
7

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.

8

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