How to test DB insert failure without printing the error to test output

I have some tests (pretty sure these were originally generated by phx.gen.auth) which attempt to violate DB constraints and assert that an error is raised. The tests pass, but they display all the errors in the test output. I’m wondering if this is working as intended, or if there is a better way to run the test.

Here is one test:

test "validates email uniqueness" do
  %{email: email} = user_fixture()
  attrs = %{username: "tester", password: "test1234", email: email}
  {:error, changeset} = Accounts.register_user(attrs)
  assert "has already been taken" in errors_on(changeset).email
end

which results in

2021-04-21 12:45:24.569 CDT [14410] ERROR:  duplicate key value violates unique constraint "users_email_index"
2021-04-21 12:45:24.569 CDT [14410] DETAIL:  Key (email)=(user-576460752303389599@example.com) already exists.
2021-04-21 12:45:24.569 CDT [14410] STATEMENT:  INSERT INTO "users" ("email","hashed_password","username","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5) RETURNING "id"

being shown in the test output.

There is another test which uses a different approach - assert_raise/2 - which seems like it would do exactly what I want:

test "generates a token", %{user: user} do
  token = Accounts.generate_user_session_token(user)
  assert user_token = Repo.get_by(UserToken, token: token)
  assert user_token.context == "session"

  # Creating the same token for another user should fail
  assert_raise Ecto.ConstraintError, fn ->
    Repo.insert!(%UserToken{
      token: user_token.token,
      user_id: user_fixture().id,
      context: "session"
    })
  end
end

but the result is basically the same:

2021-04-21 12:45:24.496 CDT [14408] ERROR:  duplicate key value violates unique constraint "users_tokens_context_token_index"
2021-04-21 12:45:24.496 CDT [14408] DETAIL:  Key (context, token)=(session, \x8a965dd47a14cbaf5e3befdffdae91a0834e63acc0785ed7363e8cdeddb01daf) already exists.
2021-04-21 12:45:24.496 CDT [14408] STATEMENT:  INSERT INTO "users_tokens" ("context","token","user_id","inserted_at") VALUES ($1,$2,$3,$4) RETURNING "id"

Is there a better way to handle these error-case tests which will result in “clean” output, or should I just not worry about it since the tests are passing?

FWIW, this format of log messages appears to originate from libpq - I’m not sure if even ExUnit.CaptureLog.capture_log would catch them.

2 Likes

If you have a constraint violation you expect, you should use the Ecto.Changeset — Ecto v3.6.1 or Ecto.Changeset — Ecto v3.6.1 helpers so that Ecto turns those errors into values on the changeset instead of raising.

The function Accounts.register_user/1 which is called in the first test, is defined as

def register_user(attrs) do
  %User{}
  |> User.registration_changeset(attrs)
  |> Repo.insert()
end

User.registration_changeset/3 is

def registration_changeset(user, attrs, opts \\ []) do
  user
  |> cast(attrs, [:email, :password, :username, :post_count, :timezone, :title])
  |> validate_email()
  |> validate_password(opts)
  |> validate_username()
end

and validate_email/1 is

defp validate_email(changeset) do
  changeset
  |> validate_required([:email])
  |> validate_format(:email, ~r/^[^\s]+@[^\s]+$/, message: "must have the @ sign and no spaces")
  |> validate_length(:email, max: 160)
  |> unique_constraint(:email)
end

So at the end of the pipeline before Repo.insert/2, we are passing through unique_constraint/3 referencing :email, but still the DB outputs the error.

Also note that the first test is passing with assert ... in errors_on(changeset).email so we are getting the error assigned properly to the changeset.

I recently ran into this same problem, leading to this github thread - Unexpected logging when running tests · Issue #2978 · elixir-ecto/ecto · GitHub

The reason for the terminal output is I had run pg_ctl in the terminal, then used that same terminal window to run my tests. Switching to a new terminal window stopped the output from printing.

2 Likes