Losing conn.assigns in the middle of a test

Question

I struggle troubleshooting a failed test where conn.assigns are both part of the same test statement, but emptied in between two lines of the test.

I'm reading "Programming Phoenix", and reworking code to make it work with Phoenix 1.3. In 3 of the tests, the :current_user stored in conn.assigns is lost in the middle of the test, for example just in between a delete and a get in controller tests.

The code of the test is:

  describe "delete video" do
    setup [:login_user, :create_video]

    test "deletes chosen video", %{conn: conn, video: video} do
      conn = delete conn, video_path(conn, :delete, video)
      assert redirected_to(conn) == video_path(conn, :index)
      assert_error_sent 404, fn ->
        Logger.warn("Before get: #{inspect(conn.assigns)}")
        conn = get conn, video_path(conn, :show, video)
        Logger.warn("After get: #{inspect(conn.assigns)}")
        conn
      end
    end
  end

I added Logger.warn instructions to inspect the connection before and after the get request. In the "Before get:" log I still have a conn.assigns with :current_user key, but in the subsequent "After get" log, it's gone.

I initially thought my authentication mechanism was responsible for this, but I then created a Logging Plug to inspect the pipeline, and I can see that from the start of the pipeline for the call to get, the current_user is missing from assigns.

This is the test output showing the logging at start/end of pipeline as well as logs from test above.

ubuntu@ubuntu-xenial:~/rumbl$ MIX_ENV=test mix test test/rumbl_web/controllers/video_controller_test.exs:98
[info] Already up
Including tags: [line: "98"]
Excluding tags: [:test]

warning: module attribute @update_attrs was set but never used
  test/rumbl_web/controllers/video_controller_test.exs:10

[debug] QUERY OK db=1.2ms
begin []
[debug] QUERY OK db=2.7ms
INSERT INTO "users" ("name","password_hash","username","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5) RETURNING "id" ["Some User", "$2b$12$0VvTPna8JMdSXcbNz2uvwOdhYWF/3ibhQ.gntdXqsb8v1TSeCZ0.K", "max", {{2017, 9, 22}, {10, 56, 53, 527902}}, {{2017, 9, 22}, {10, 56, 53, 529912}}]
[debug] QUERY OK db=0.1ms
commit []
[debug] QUERY OK db=0.1ms
begin []
[debug] QUERY OK db=1.1ms
INSERT INTO "videos" ("description","title","url","user_id","inserted_at","updated_at") VALUES ($1,$2,$3,$4,$5,$6) RETURNING "id" ["some description", "some title", "some url", 351, {{2017, 9, 22}, {10, 56, 53, 544069}}, {{2017, 9, 22}, {10, 56, 53, 544075}}]
[debug] QUERY OK db=0.1ms
commit []
[info] DELETE /manage/videos/274
[warn] Start of pipeline: %{current_user: %RumblWeb.User{__meta__: #Ecto.Schema.Metadata<:loaded, "users">, id: 351, inserted_at: ~N[2017-09-22 10:56:53.527902], name: "Some User", password: "supersecret", password_hash: "$2b$12$0VvTPna8JMdSXcbNz2uvwOdhYWF/3ibhQ.gntdXqsb8v1TSeCZ0.K", updated_at: ~N[2017-09-22 10:56:53.529912], username: "max", videos: #Ecto.Association.NotLoaded<association :videos is not loaded>}}
[warn] End of pipeline: %{current_user: %RumblWeb.User{__meta__: #Ecto.Schema.Metadata<:loaded, "users">, id: 351, inserted_at: ~N[2017-09-22 10:56:53.527902], name: "Some User", password: "supersecret", password_hash: "$2b$12$0VvTPna8JMdSXcbNz2uvwOdhYWF/3ibhQ.gntdXqsb8v1TSeCZ0.K", updated_at: ~N[2017-09-22 10:56:53.529912], username: "max", videos: #Ecto.Association.NotLoaded<association :videos is not loaded>}}
[warn] Start of authenticate_user: %{current_user: %RumblWeb.User{__meta__: #Ecto.Schema.Metadata<:loaded, "users">, id: 351, inserted_at: ~N[2017-09-22 10:56:53.527902], name: "Some User", password: "supersecret", password_hash: "$2b$12$0VvTPna8JMdSXcbNz2uvwOdhYWF/3ibhQ.gntdXqsb8v1TSeCZ0.K", updated_at: ~N[2017-09-22 10:56:53.529912], username: "max", videos: #Ecto.Association.NotLoaded<association :videos is not loaded>}}
[debug] Processing with RumblWeb.VideoController.delete/2
  Parameters: %{"id" => "274"}
  Pipelines: [:browser, :authenticate_user]
[debug] QUERY OK source="videos" db=0.9ms
SELECT v0."id", v0."description", v0."title", v0."url", v0."user_id", v0."category_id", v0."inserted_at", v0."updated_at" FROM "videos" AS v0 WHERE (v0."user_id" = $1) AND (v0."id" = $2) [351, 274]
[debug] QUERY OK db=0.1ms
begin []
[debug] QUERY OK db=0.3ms
DELETE FROM "videos" WHERE "id" = $1 [274]
[debug] QUERY OK db=0.0ms
commit []
[info] Sent 302 in 46ms
[warn] Before get: %{current_user: %RumblWeb.User{__meta__: #Ecto.Schema.Metadata<:loaded, "users">, id: 351, inserted_at: ~N[2017-09-22 10:56:53.527902], name: "Some User", password: "supersecret", password_hash: "$2b$12$0VvTPna8JMdSXcbNz2uvwOdhYWF/3ibhQ.gntdXqsb8v1TSeCZ0.K", updated_at: ~N[2017-09-22 10:56:53.529912], username: "max", videos: #Ecto.Association.NotLoaded<association :videos is not loaded>}}
[info] GET /manage/videos/274
[warn] Start of pipeline: %{}
[warn] End of pipeline: %{current_user: nil}
[warn] Start of authenticate_user: %{current_user: nil}
[info] Sent 302 in 2ms
[warn] After get: %{current_user: nil}


  1) test delete video deletes chosen video (RumblWeb.VideoControllerTest)
     test/rumbl_web/controllers/video_controller_test.exs:98
     expected error to be sent as 404 status, but response sent 302 without error
     code: assert_error_sent 404, fn ->
     stacktrace:
       (phoenix) lib/phoenix/test/conn_test.ex:600: Phoenix.ConnTest.assert_error_sent/2
       test/rumbl_web/controllers/video_controller_test.exs:101: (test)



Finished in 0.6 seconds
8 tests, 1 failure, 7 skipped

Randomized with seed 982730

The authentication mechanism follows the book's advice, and passes authentication if there is a :current_user in conn.assigns. The setup login_user does just this, injecting a user in conn.assigns under :current_user key. In my test, and for whatever reason, as the conn.assigns is empty at some point in the get request, authentication fails, and the user is redirected to the home page.

I'm not sure how to troubleshoot what happens in between the delete statement and subsequent get. I looked at the pipeline, but as showing in log statements the conn.assigns is blanked before even entering the pipeline. I was expecting that conn would not change across the whole test statement, maybe that's a wrong assumption.

In reply to Dogbert's comment:

login_user function in the controller test:

  defp login_user(_) do
    user = insert_user(username: "max")
    conn = assign(build_conn(), :current_user, user)
    {:ok, conn: conn, user: user}
  end

call function in the auth controller:

  def call(conn, repo) do
    user_id = get_session(conn, :user_id)

    cond do
      user = conn.assigns[:current_user] ->
        conn
      user    = user_id && repo.get(RumblWeb.User, user_id) ->
        assign(conn, :current_user, user)
      true ->
        assign(conn, :current_user, nil)
    end
  end

Answer 1

This is caused by phoenix recycling, see (https://hexdocs.pm/phoenix/1.3.0/Phoenix.ConnTest.html#module-recycling)

Recycling

Browsers implement a storage by using cookies. When a cookie is set in the response, the browser stores it and sends it in the next request.

To emulate this behaviour, this module provides the idea of recycling. The recycle/1 function receives a connection and returns a new connection, similar to the one returned by conn/0 with all the response cookies from the previous connection defined as request headers. This is useful when testing multiple routes that require cookies or session to work.

Keep in mind Phoenix will automatically recycle the connection between dispatches. This usually works out well most times, but it may discard information if you are modifying the connection before the next dispatch:

# No recycling as the connection is fresh
conn = get build_conn(), "/"

# The connection is recycled, creating a new one behind the scenes
conn = post conn, "/login"

# We can also recycle manually in case we want custom headers
conn =
  conn
  |> recycle()
  |> put_req_header("x-special", "nice")

# No recycling as we did it explicitly
conn = delete conn, "/logout"

Recycling also recycles the “accept” header.

To preserve the assigns, you can manually recycle and assign between the calls to delete and get:

saved_assigns = conn.assigns
conn = 
  conn
  |> recycle()
  |> Map.put(:assigns, saved_assigns)