Fail to execute Ecto.adapters.SQL.query!/4 when config :myapp, MyApp.Repo, :logger is set to [MyApp.Metrics.EctoInstrumenter, Ecto.LogEntry] in release mode.

[tatiesmars]

Recently we experience a strange issue after adding prometheus ecto to our phoenix app. Our migration script succeed in dev mode when developing locally, but once apply from a release app it will throw the error %ArgumentError{} when Ecto.adapters.SQL.query!/4 is run. We suppose the issue come from prometheus as when we remove the config line:

:myapp, MyApp.Repo, logger: [MyApp.Metrics.EctoInstrumenter, Ecto.LogEntry]

The migration succeed from the release app.

Here is the migration script that failed:

defmodule MyApp.Repo.Migrations.UserDeviceUserIdReference do
  use Ecto.Migration

  alias MyApp.Notification.UserDevice
  alias MyApp.Repo

  def change do
    create table(:user_devices_temp, primary_key: false) do
      add(:user_id, :uuid, primary_key: true)
      add(:device_token, :string)
      add(:device_type, :integer)
      add(:in_china, :boolean)
      add(:language, :string, default: "en")
      add(:type, :integer, default: 0)
      add(:timezone, :string, default: "Asia/Shanghai")

      timestamps()
    end

    flush()

    query = "INSERT INTO user_devices_temp
     SELECT CAST (ud.user_id as uuid), ud.device_token, ud.device_type, ud.in_china, ud.language, ud.type, ud.timezone, ud.updated_at, ud.inserted_at
     FROM user_devices ud
      INNER JOIN users u ON u.id = CAST (ud.user_id as uuid);"

    ##### LAST SEEN IO.inspect #####
    Ecto.Adapters.SQL.query!(MyApp.Repo, query, [])
    ##### EXPECTED IO.inspect #####

    flush()
  end
end

Here is the dockerfile for release:

FROM elixir:1.7-alpine

RUN apk add --update git

ENV HOME /app
RUN mkdir -p ${HOME}
WORKDIR ${HOME}
ENV MIX_ENV=prod REPLACE_OS_VARS=true

RUN mix local.hex --force
RUN mix local.rebar --force

# Cache elixir deps
COPY mix.exs mix.lock ./
RUN HEX_HTTP_CONCURRENCY=1 HEX_HTTP_TIMEOUT=120 mix deps.get
COPY config ./config
RUN mix deps.compile
COPY . .

RUN mix release --env=prod

FROM elixir:1.7-alpine
RUN apk add --update bash

ENV PORT=8080 MIX_ENV=prod REPLACE_OS_VARS=true SHELL=/bin/bash
EXPOSE 8080

ENV HOME /app
RUN mkdir -p ${HOME}
WORKDIR ${HOME}

COPY --from=0 ${HOME}/_build/prod/rel/myapp/releases/0.0.1/myapp.tar.gz .
RUN tar xfz myapp.tar.gz

CMD ["/app/bin/myapp", "boot"]

Boot command:

#!/bin/bash

$RELEASE_ROOT_DIR/bin/myapp migrate
$RELEASE_ROOT_DIR/bin/myapp foreground

Migrate command

#!/bin/bash

$RELEASE_ROOT_DIR/bin/myapp command Elixir.MyApp.ReleaseTasks seed

Release Task:

defmodule MyApp.ReleaseTasks do
  @start_apps [
    :crypto,
    :ssl,
    :postgrex,
    :ecto
  ]

  def myapp, do: Application.get_application(__MODULE__)

  def repos, do: Application.get_env(myapp(), :ecto_repos, [])

  def seed do
    me = :myapp

    IO.puts("Loading #{me}..")
    # Load the code for myapp, but don't start it
    Application.load(me)

    IO.puts("Starting dependencies..")
    # Start apps necessary for executing migrations
    Enum.each(@start_apps, &Application.ensure_all_started/1)

    # Start the Repo(s) for myapp
    IO.puts("Starting repos..")
    Enum.each(repos(), & &1.start_link(pool_size: 1))

    # Run migrations
    migrate()

    # Run seed script
    Enum.each(repos(), &run_seeds_for/1)

    # Signal shutdown
    IO.puts("Success!")
    :init.stop()
  end

  def migrate, do: Enum.each(repos(), &run_migrations_for/1)

  def priv_dir(app), do: "#{:code.priv_dir(app)}"

  defp run_migrations_for(repo) do
    try do
      app = Keyword.get(repo.config, :otp_app)
      IO.puts("Running migrations for #{app}")
      ########### THIS IS WHERE IT CRASH ###########
      Ecto.Migrator.run(repo, migrations_path(repo), :up, all: true)
    catch
      one, two ->
       ########### THIS IS WHERE THE ERROR IS CATCH ###########
        Process.sleep(5_000)
        IO.puts("Got one: #{inspect(one)}; Got two: #{inspect(two)}")
        IO.puts("Retry ... ")
        run_migrations_for(repo)
    end
  end

  def run_seeds_for(repo) do
    # Run the seed script if it exists
    seed_script = seeds_path(repo)

    if File.exists?(seed_script) do
      IO.puts("Running seed script..")
      Code.eval_file(seed_script)
    end
  end

  def migrations_path(repo), do: priv_path_for(repo, "migrations")

  def seeds_path(repo), do: priv_path_for(repo, "seeds.exs")

  def priv_path_for(repo, filename) do
    app = Keyword.get(repo.config, :otp_app)
    repo_underscore = repo |> Module.split() |> List.last() |> Macro.underscore()
    Path.join([priv_dir(app), repo_underscore, filename])
  end
end

Ecto config:

config :myapp, MyApp.Repo,
  adapter: Ecto.Adapters.Postgres,
  hostname: "${DB_HOSTNAME}",
  database: "${DB_NAME}",
  username: "${DB_USERNAME}",
  password: "${DB_PASSWORD}",
  pool_size: 20,
  loggers: [Myapp.Metrics.EctoInstrumenter, Ecto.LogEntry]

Our solution was to remove logger from the repo, apply migration and then re add the ecto logger, but it would be nice to find the root cause of this issue.

[deadtrickster]

Hi, do you have full stacktrace?

[tatiesmars]

@deadtrickster here you go

{"init terminating in do_boot",{#{'exception'=>true,'struct'=>'Elixir.ArgumentError',message=><<"argument error">>},[{ets,lookup,[prometheus_histogram_table,{default,ecto_db_query_duration_microseconds,[ok],1}],[]},{prometheus_histogram,observe,4,[{file,"src/metrics/prometheus_histogram.erl"},{line,196}]},{'Elixir.SelectChat.Metrics.EctoInstrumenter',log,1,[{file,"lib/select_chat/metrics/ecto_instrumenter.ex"},{line,2}]},{'Elixir.SelectChat.Repo','log',1,[{file,"lib/select_chat/repo.ex"},{line,2}]},{'Elixir.DBConnection',log,6,[{file,"lib/db_connection.ex"},{line,1186}]},{'Elixir.Ecto.Adapters.Postgres.Connection',prepare_execute,5,[{file,"lib/ecto/adapters/postgres/connection.ex"},{line,73}]},{'Elixir.Ecto.Adapters.SQL',sql_call,6,[{file,"lib/ecto/adapters/sql.ex"},{line,256}]},{'Elixir.Ecto.Adapters.SQL',execute_and_cache,7,[{file,"lib/ecto/adapters/sql.ex"},{line,426}]}]}}

[sulphur]

@tatiesmars Try adding :ecto_sql to application start list