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

Can you post the code for `login_user`? This might be related to this question: https://stackoverflow.com/q/42347723/320615. — Dogbert, Sep 22 '17 at 11:21
I added the login_user function, as well as the call function from my Auth controller. Unless I'm missing something the "cond" should make sure I don't overwrite my assigns if :current_user is set. — Olivier Boudry, Sep 22 '17 at 11:30
Add another check after `user = insert_user(username: "max")` - do you really have a user here, or just a `nil`? — denis.peplin, Sep 22 '17 at 11:35

score 9 · Accepted Answer · edited Jun 20 '20 at 09:12

9

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)

edited Jun 20 '20 at 09:12

Community

1
1

answered Sep 22 '17 at 11:38

Mike Buhot

4,790
20
31

Mike, is there any way this recycling can be prevented ? Or is the concept of putting the :current_user in the conn.assigns no longer valid ? This was a small cheat proposed by "Programming Phoenix 1.0" to make testing easier. Shall I revert to doing a proper authentication first or is there a way to keep the trick and bypass recycling ? – Olivier Boudry Sep 22 '17 at 11:45
1

Recycling was the problem. This got me crazy for days, I now have Logger statements all around my code and an ugly recycling block that I need to put into a function for easier reuse. But I learned something and my tests pass. Thank you very much for your help ! – Olivier Boudry Sep 22 '17 at 12:27
Is this really still the best option? Seems so gross. It's like a smell, but testing a controller with Auth isn't a smell.. – Jono Jun 07 '18 at 21:32
1

I don't think you want `|> Map.put(&1, :assigns, ...` in the last code block. With the |> conn will be passed as the first arg, so is should be `|> Map.put(:assigns, ...` – WillW Aug 30 '18 at 11:24
Thanks @WillW, now fixed. – Mike Buhot Sep 01 '18 at 12:00
`conn = conn |> recycle() |> Map.put(:assigns, conn.assigns)` is enough. – Sam Chen Nov 26 '18 at 12:53

Losing conn.assigns in the middle of a test

1 Answers1

Recycling