scoutapp / scout_apm_elixir

ScoutAPM Elixir Agent. Supports Phoenix and other frameworks.
https://scoutapm.com
Other
36 stars 20 forks source link

Ecto instrument raises Argument Error on rare occasions. #57

Closed cschneid closed 6 years ago

cschneid commented 6 years ago

A customer with a high throughput app sees an Argument Error in ecto_logger.ex about 30 times a day:

Full Backtrace
argument error
unknown  ? convert_time_unit/3
unknown:?:in `convert_time_unit/3'
ecto_logger.ex  85 query_time/1
lib/scout_apm/instruments/ecto_logger.ex:85:in `query_time/1'
ecto_logger.ex  29 record/1
lib/scout_apm/instruments/ecto_logger.ex:29:in `record/1'
ecto_logger.ex  21 log/1
lib/scout_apm/instruments/ecto_logger.ex:21:in `log/1'
db_connection.ex  1186 log/6
lib/db_connection.ex:1186:in `log/6'
db_connection.ex  643 execute/4
lib/db_connection.ex:643:in `execute/4'
connection.ex  98 execute/4
lib/ecto/adapters/postgres/connection.ex:98:in `execute/4'
sql.ex  256 sql_call/6
lib/ecto/adapters/sql.ex:256:in `sql_call/6'

Elixir's convert_time_unit/3 - https://github.com/elixir-lang/elixir/blob/v1.6.5/lib/elixir/lib/system.ex#L751

Erlang's convert_time_unit/3 - http://erlang.org/doc/man/erlang.html#convert_time_unit-3

I can reproduce the exception with any non-integer data type as the first argument, but positive, negative and zero all work:

iex(2)> System.convert_time_unit(0, :native, :milliseconds)
0
iex(3)> System.convert_time_unit(0.0, :native, :milliseconds)
** (ArgumentError) argument error
    :erlang.convert_time_unit(0.0, :native, :milli_seconds)
iex(3)> System.convert_time_unit(nil, :native, :milliseconds)
** (ArgumentError) argument error
    :erlang.convert_time_unit(nil, :native, :milli_seconds)
iex(3)> System.convert_time_unit("foo", :native, :milliseconds)
** (ArgumentError) argument error
    :erlang.convert_time_unit("foo", :native, :milli_seconds)
iex(4)> System.convert_time_unit(-500000000, :native, :milliseconds)
-500

The Ecto.LogEntry docs show the query_time field as being a required integer field. https://hexdocs.pm/ecto/Ecto.LogEntry.html so I'm not sure why that value would be missing, or wrong.

jonzlin95 commented 6 years ago

Elixir 1.6.4