Ecto race conditions question

[Louis Simoneau]

Hi all,

Just trying out Ecto in a new project, and noticed something unexpected when testing an update method on my model.

The test for update fails intermittently, which I can only presume is due to a race condition between the update and the get, but I'm unsure why that would be, since I didn't think these functions would be operating asynchronously.

Can someone explain why this is happening? I tried to look for a way to get Ecto to log out the SQL it was executing, but couldn't find anything.

Any help would be appreciated.

Here's my test:

  test "updating an existing post" do
    {:ok, post} = Post.create
    Post.update(post, "I went to the park")
    post = Repo.get(Post, post.id)
    assert post.text == "I went to the park"
  end

This is the code for the model:

defmodule MyApp.Models.Post do
  use Ecto.Model
  alias MyApp.Repo
  alias MyApp.Models.Post

  schema "posts" do
    field :text, :string
    field :created_at, :datetime
    field :updated_at, :datetime
  end

  def create(text \\ "") do
    now = Ecto.DateTime.from_erl(:calendar.universal_time)
    post = %Post{created_at: now, updated_at: now, text: text}
    {:ok, Repo.insert(post)}
  end

  def update(post, text) do
    post = %{post | text: text}
    Repo.update(post)
  end
end

With the following test:

[José Valim]

This may be possible if we are sending casts to the connection handler. Any ideas Eric?

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Lead Developer

--
You received this message because you are subscribed to the Google Groups "elixir-lang-talk" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elixir-lang-ta...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Louis Simoneau]

AFAICT from a code search on GitHub, nothing in either Ecto or Postgrex seems to be doing a cast (except for worker monitoring and unmonitoring).

Is there a way of getting Ecto to output the SQL it's running? Maybe then it would be possible to see if queries are being handled out of sequence.

[José Valim]

Could it be that we are checking different workers from the pool and it is causing race conditions between workers? Maybe we should try to use the same worker once one is checked out in that process?

For logging, check this out: https://github.com/elixir-lang/ecto/blob/master/lib/ecto/repo.ex#L342

But keep in mind that you can have race conditions between sending data to logger too, so the log messages may not necessarily confirm or deny the query race condition.

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Lead Developer

[Louis Simoneau]

I figured it out, it's not a race. I was putting sleeps in the test and it wasn't making any difference, so ruled that out. Then I remembered I was using this transactional test helper copied from hex-web:

  setup do
    Postgres.begin_test_transaction(HexWeb.Repo)
    on_exit fn ->
      Postgres.rollback_test_transaction(HexWeb.Repo)
    end
  end

I imagine either Ecto or Postgres is using a pool of connections, and the subsequent queries are being handled by different connections (which can't see the data because the transaction hasn't committed yet.)

Removing that helper makes it pass every time, but I'll look into ensuring that only a single connection is used in the test environment instead.

Sorry for the false alarm!

[Alex Shneyderman]

you can probably set up postgres to do it (this will probably be a nice option to have on postgrex)

http://stackoverflow.com/questions/722221/how-to-log-postgres-sql-queries 

[José Valim]

Ah, you need to set the pool size to 1 when using such helpers.

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Lead Developer

[Eric Meadows-Jönsson]

We explain how to setup your repository for testing in the docs for test transactions: http://elixir-lang.org/docs/ecto/Ecto.Adapter.TestTransactions.html

Eric Meadows-Jönsson