Unhandled StaleEntryError

[landongrindheim]

The develop branch had a StaleEntryError exception introduced recently. Tests pass, but the output below is observed.

The stack trace points to CodeCorps.Accounts.upload_github_photo_async/1. I hadn't seen until very recently. If this isn't an issue, please feel free to close this issue (and let me know how to resolve it on my end 😄 )

2017-10-08T19:08:53.717753Z [error] Task #PID<0.5247.0> started from #PID<0.5245.0> terminating
** (stop) exited in: GenServer.call(#PID<0.5246.0>, {:checkout, #Reference<0.3912897079.3947626497.211182>, true, 15000}, 5000)
    ** (EXIT) shutdown: "owner #PID<0.5245.0> exited with: shutdown"
    (db_connection) lib/db_connection/ownership/proxy.ex:32: DBConnection.Ownership.Proxy.checkout/2
    (db_connection) lib/db_connection.ex:920: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:742: DBConnection.run/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (ecto) lib/ecto/repo/schema.ex:136: Ecto.Repo.Schema.update!/4
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Function: #Function<6.37107395/0 in CodeCorps.Accounts.upload_github_photo_async/1>
    Args: []
2017-10-08T19:08:53.727984Z [error] Task #PID<0.5250.0> started from #PID<0.5245.0> terminating
** (DBConnection.OwnershipError) cannot find ownership process for #PID<0.5250.0>.

When using ownership, you must manage connections in one
of the four ways:

* By explicitly checking out a connection
* By explicitly allowing a spawned process
* By running the pool in shared mode
* By using :caller option with allowed process

The first two options require every new process to explicitly
check a connection out or be allowed by calling checkout or
allow respectively.

The third option requires a {:shared, pid} mode to be set.
If using shared mode in tests, make sure your tests are not
async.

The fourth option requires [caller: pid] to be used when
checking out a connection from the pool. The caller process
should already be allowed on a connection.

If you are reading this error, it means you have not done one
of the steps above or that the owner process has crashed.

    (db_connection) lib/db_connection.ex:926: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:742: DBConnection.run/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (ecto) lib/ecto/repo/schema.ex:136: Ecto.Repo.Schema.update!/4
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Function: #Function<6.37107395/0 in CodeCorps.Accounts.upload_github_photo_async/1>
    Args: []
2017-10-08T19:08:53.728153Z [error] Task #PID<0.5251.0> started from #PID<0.5245.0> terminating
** (Ecto.StaleEntryError) attempted to update a stale struct:

%CodeCorps.User{id: 552522, twitter: nil, email: "original@email.com", categories: #Ecto.Association.NotLoaded<association :categories is not loaded>, sign_up_context: "default", first_name: "First2491", github_app_installations: #Ecto.Association.NotLoaded<association :github_app_installations is not loaded>, user_roles: #Ecto.Association.NotLoaded<association :user_roles is not loaded>, github_app_installation: #Ecto.Association.NotLoaded<association :github_app_installation is not loaded>, encrypted_password: nil, password_confirmation: nil, stripe_platform_customer: #Ecto.Association.NotLoaded<association :stripe_platform_customer is not loaded>, website: nil, github_avatar_url: "https://github.com/images/error/octocat_happy.gif", username: "user3796", inserted_at: #DateTime<2017-10-08 19:08:53Z>, github_username: "octocat", last_name: nil, __meta__: #Ecto.Schema.Metadata<:loaded, "users">, updated_at: #DateTime<2017-10-08 19:08:53Z>, user_skills: #Ecto.Association.NotLoaded<association :user_skills is not loaded>, github_id: 1, password: nil, state_transition: nil, github_email: nil, admin: nil, roles: #Ecto.Association.NotLoaded<association :roles is not loaded>, state: "signed_up", default_color: nil, github_auth_token: "foo_auth_token", biography: nil, skills: #Ecto.Association.NotLoaded<association :skills is not loaded>, stripe_connect_subscriptions: #Ecto.Association.NotLoaded<association :stripe_connect_subscriptions is not loaded>, user_categories: #Ecto.Association.NotLoaded<association :user_categories is not loaded>, cloudinary_public_id: nil, project_users: #Ecto.Association.NotLoaded<association :project_users is not loaded>, type: "user", stripe_connect_customers: #Ecto.Association.NotLoaded<association :stripe_connect_customers is not loaded>, slugged_route: #Ecto.Association.NotLoaded<association :slugged_route is not loaded>, stripe_platform_card: #Ecto.Association.NotLoaded<association :stripe_platform_card is not loaded>}

    (ecto) lib/ecto/repo/schema.ex:549: Ecto.Repo.Schema.apply/4
    (ecto) lib/ecto/repo/schema.ex:289: anonymous fn/14 in Ecto.Repo.Schema.do_update/4
    (ecto) lib/ecto/repo/schema.ex:768: anonymous fn/3 in Ecto.Repo.Schema.wrap_in_transaction/6
    (ecto) lib/ecto/adapters/sql.ex:576: anonymous fn/3 in Ecto.Adapters.SQL.do_transaction/3
    (db_connection) lib/db_connection.ex:1275: DBConnection.transaction_run/4
    (db_connection) lib/db_connection.ex:1199: DBConnection.run_begin/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (ecto) lib/ecto/repo/schema.ex:136: Ecto.Repo.Schema.update!/4
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Function: #Function<6.37107395/0 in CodeCorps.Accounts.upload_github_photo_async/1>
    Args: []
2017-10-08T19:08:53.728369Z [error] Task #PID<0.5252.0> started from #PID<0.5245.0> terminating
** (Ecto.StaleEntryError) attempted to update a stale struct:

%CodeCorps.User{id: 552522, twitter: nil, email: "original@email.com", categories: #Ecto.Association.NotLoaded<association :categories is not loaded>, sign_up_context: "default", first_name: "First2491", github_app_installations: #Ecto.Association.NotLoaded<association :github_app_installations is not loaded>, user_roles: #Ecto.Association.NotLoaded<association :user_roles is not loaded>, github_app_installation: #Ecto.Association.NotLoaded<association :github_app_installation is not loaded>, encrypted_password: nil, password_confirmation: nil, stripe_platform_customer: #Ecto.Association.NotLoaded<association :stripe_platform_customer is not loaded>, website: nil, github_avatar_url: "https://github.com/images/error/octocat_happy.gif", username: "user3796", inserted_at: #DateTime<2017-10-08 19:08:53Z>, github_username: "octocat", last_name: nil, __meta__: #Ecto.Schema.Metadata<:loaded, "users">, updated_at: #DateTime<2017-10-08 19:08:53Z>, user_skills: #Ecto.Association.NotLoaded<association :user_skills is not loaded>, github_id: 1, password: nil, state_transition: nil, github_email: nil, admin: nil, roles: #Ecto.Association.NotLoaded<association :roles is not loaded>, state: "signed_up", default_color: nil, github_auth_token: "foo_auth_token", biography: nil, skills: #Ecto.Association.NotLoaded<association :skills is not loaded>, stripe_connect_subscriptions: #Ecto.Association.NotLoaded<association :stripe_connect_subscriptions is not loaded>, user_categories: #Ecto.Association.NotLoaded<association :user_categories is not loaded>, cloudinary_public_id: nil, project_users: #Ecto.Association.NotLoaded<association :project_users is not loaded>, type: "user", stripe_connect_customers: #Ecto.Association.NotLoaded<association :stripe_connect_customers is not loaded>, slugged_route: #Ecto.Association.NotLoaded<association :slugged_route is not loaded>, stripe_platform_card: #Ecto.Association.NotLoaded<association :stripe_platform_card is not loaded>}

    (ecto) lib/ecto/repo/schema.ex:549: Ecto.Repo.Schema.apply/4
    (ecto) lib/ecto/repo/schema.ex:289: anonymous fn/14 in Ecto.Repo.Schema.do_update/4
    (ecto) lib/ecto/repo/schema.ex:768: anonymous fn/3 in Ecto.Repo.Schema.wrap_in_transaction/6
    (ecto) lib/ecto/adapters/sql.ex:576: anonymous fn/3 in Ecto.Adapters.SQL.do_transaction/3
    (db_connection) lib/db_connection.ex:1275: DBConnection.transaction_run/4
    (db_connection) lib/db_connection.ex:1199: DBConnection.run_begin/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (ecto) lib/ecto/repo/schema.ex:136: Ecto.Repo.Schema.update!/4
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Function: #Function<6.37107395/0 in CodeCorps.Accounts.upload_github_photo_async/1>
    Args: []

[begedin]

@landongrindheim Thank you for confirming this isn't just happening for me. I've opened #1030 which tries to tackle the root cause - we need to write our "background processing" code better.

[begedin]

To clarify why this is actually happening, as the test executes, the background task we've created which uploads the user's avatar to cloudinary tries to update the user record after the database was already reset, meaning there is no record to update.

We use our wait_for_supervisor helper in other tests where we do background processing, but for some reason, the timing here is off so we're unable to use it in the same way reliably.

We will have to figure out a solution for this, but at the moment, I don't have the information I need.

[joshsmith]

This is happening again for some reason. Need to look into why (likely some tests that are missing async handling).

Running mix test --trace may help with this.

There may be a deeper fix we need to do, though.

[joshsmith]

CodeCorps.Sync.User.RecordLinkerTest
  * test link_to/2 for issues creates user if none is found by any other method (13.3ms)
  * test link_to/2 for issues returns error if multiple users by task association found (21.9ms)
  * test link_to/2 for comments creates user if none is by comment or id association (10.4ms)
  * test link_to/2 for comments if issue opened by bot, and no user by comment association, creates a bot user2017-10-22T21:28:17.645114Z [error] Postgrex.Protocol (#PID<0.2745.0>) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.7146.0> exited while client #PID<0.7148.0> is still running with: shutdown
  * test link_to/2 for comments if issue opened by bot, and no user by comment association, creates a bot user (36.7ms)
2017-10-22T21:28:17.665324Z [error] Postgrex.Protocol (#PID<0.2744.0>) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.7150.0> exited while client #PID<0.7152.0> is still running with: shutdown
  * test link_to/2 for comments finds user by comment association (38.8ms)
  * test link_to/2 for comments returns changeset if payload is somehow not as expected (14.3ms)
  * test link_to/2 for issues returns changeset if payload is somehow not as expected (9.7ms)
  * test link_to/2 for issues if issue opened by bot, and no user by task association, creates a bot user2017-10-22T21:28:17.740432Z [error] Postgrex.Protocol (#PID<0.2740.0>) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.7163.0> exited while client #PID<0.7165.0> is still running with: shutdown
  * test link_to/2 for issues if issue opened by bot, and no user by task association, creates a bot user (11.2ms)
  * test link_to/2 for issues returns user by github id if no user by task association found2017-10-22T21:28:17.751373Z [error] Task #PID<0.7165.0> started from #PID<0.7163.0> terminating
** (DBConnection.ConnectionError) tcp recv: closed
    (db_connection) lib/db_connection.ex:794: DBConnection.transaction/3
    (ecto) lib/ecto/repo/schema.ex:136: Ecto.Repo.Schema.update!/4
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Function: #Function<6.148594/0 in CodeCorps.Accounts.upload_github_photo_async/1>
    Args: []
  * test link_to/2 for issues returns user by github id if no user by task association found (23.0ms)
  * test link_to/2 for comments returns error if multiple users by comment association found (35.3ms)
  * test link_to/2 for comments finds user by github id if none is found by comment association (10.8ms)
  * test link_to/2 for issues if issue opened by bot, finds user by task association (20.3ms)
  * test link_to/2 for comments if comment created by bot, finds user by comment association (36.0ms)
  * test link_to/2 for issues finds user by task association (35.2ms)

[joshsmith]

Here's a possible solution to make our async tasks run synchronously: https://stackoverflow.com/a/39533505/373496

[landongrindheim]

@joshsmith That's an interesting approach. I assume this would slow down the test suite slightly, which may or may not be an issue.

I implemented the solution suggested on StackOverflow, and it's pretty simple and not difficult to reason about. But what about the other areas that are using Task.Supervisor? Should the same interface(?) functionality be implemented for the TestTaskSupervisor and those references replaced as well? Seems like it to me, but they're not problematic currently.

Coming from Ruby, my instinct is to want to know that the Task.Supervisor async functions are called. I don't know if that's a concern here or not.

[joshsmith]

@landongrindheim You can see in our test/support/github/success_api.ex that we've implemented a similar mock interface with an assert_received. We could do something similar here. That may be sufficient.

I'm curious to hear @begedin's thoughts on this, too.

[landongrindheim]

I've looked into this issue further and can say that I think my understanding earlier was off. I don't think creating a fake task supervisor for the test, at least the way I had done earlier, addresses the underlying issue.

[begedin]

The only thing that comes to mind for me is to rewrite the code to allow for a mock which fires of an async process in dev/prod, while just calling a send, so we can assert_received in test

We could do this by either

• wrapping the call that starts a background process via our supervisor into a module or
• replacing the minimal supervisor with a custom-defined one, which does the mocking internally

The first would be a simpler approach, the second would be more complex, but would allow for additional flexibility.

For example, if we end up testing code which launches multiple async processes, our mock custom supervisor could store a list of launched "processes", so we could assert on the contents of that list, even that they're placed in there in the correct order.

Either way, another thing we probably should do is rewrite our code that all calls sto start_child/2 are replaced with start_shild/4

This would allow for easier and more explicit testing in both implementations.

For example:

defmodule CodeCorps.GitHub.Webhook.Processor do
  def process_async(type, id, payload) do
    Task.Supervisor.start_child(:background_processor, fn -> process(type, id, payload) end)
  end

  defdelegate process(type, id, payload), to: Handler, as: :handle
end

can be rewritten as

defmodule CodeCorps.GitHub.Webhook.Processor do
  def process_async(type, id, payload) do
    Task.Supervisor.start_child(:background_processor, CodeCorps.GitHub.WebHook.Processor, :process, [type, id, payload])
  end

  defdelegate process(type, id, payload), to: Handler, as: :handle
end

We can then explicitly

assert_received {CodeCorps.GitHub.WebHook.Processor, :process, [type, id, payload]}

or with the second implementation we could (assuming quite a bit, here):

assert MockSupervisor.get_queue == [
  {CodeCorps.GitHub.WebHook.Processor, :process, [type, id, payload]}
]

[joshsmith]

We now have a mock that works roughly similar to the idea proposed by @begedin originally.