Nondeterministic behavior in Phoenix controller tests

[marick]

TL;DR: I have Phoenix controller tests that sometimes pass and sometimes fail. When they fail, an action that is supposed to be reached, because of an authentication token, instead redirects to /login. This only happens when two controller tests are running. It might be a timing issue, but slowing one of the controller's tests with :timer.sleep doesn't make the problem go away. (It does get less frequent, but it still happens even with a 30 second delay.)

I am an Elixir and Phoenix newbie, so it's probably something obvious. Using `:openmaize, "0.11.0" :phoenix, "1.0.4" with both Elixir 1.1.1 and 1.2.

---

In my Phoenix application, I'm using the tests here and in openmaize-phoenix as a model. I have two controllers. Their tests share this setup code:

  def authenticated() do 
    {:ok, user_token} = %{id: 2, login: "derp", role: "admin"} |> Token.generate_token({0, 86400})

    conn()
    |> put_req_cookie("access_token", user_token)
  end

(However, it doesn't matter if each of them has its own variant (with different login and role).)

The tests look like this and this:

  test "GET / when logged in", %{authenticated: conn}  do
    # :timer.sleep(30000)
    conn = get conn, "/"
    assert html_response(conn, 200)
  end

  test "GET / when logged in", %{authenticated: conn}  do
    conn = get conn, "/"
    assert html_response(conn, 200)
  end

The failures look like:

  1) test GET / when logged in (Critter4us.AdminControllerTest)
     test/controllers/admin_controller_test.exs:18
     ** (RuntimeError) expected response with status 200, got: 302
     stacktrace:
       (phoenix) lib/phoenix/test/conn_test.ex:327: Phoenix.ConnTest.response/2
       (phoenix) lib/phoenix/test/conn_test.ex:341: Phoenix.ConnTest.html_response/2
       test/controllers/admin_controller_test.exs:21

It can be either one that fails.

As I say, I expect this is a problem with my setup, but it might also be a real issue with openmaize.

[riverrun]

Thanks for reporting the issue. I think I need more information. Could you add IO.inspect result to the not logged in test (under the result line) and IO.inspect conn to the logged in test (under the conn = line), and let me know what you get.

[riverrun]

One extra comment: In the page_controller.ex file, I think the line:

plug :authorize, roles: ["superuser", "admin", "requester"]

should be:

plug :authorize, [roles: ["superuser", "admin", "requester"]] when action in [:index]

as the index page is the only one you want to protect.

[riverrun]

Just updated Openmaize, so run mix deps.update openmaize to get the latest version.

[marick]

The problem seems to that sometimes current_user is not set. Here's a snippet from a successful case:

 assigns: %{current_user: %{id: 2, login: "derp", role: "admin"},

The failure case gives this:

 assigns: %{current_user: nil},

There are other differences, but I guess they're because one's a 302 and ones a 200. In any case:

The success case (200 result)

{adapter: {Plug.Adapters.Test.Conn, :...},
 assigns: %{current_user: %{id: 2, login: "derp", role: "admin"},
   layout: {Critter4us.LayoutView, "app.html"}},
 before_send: [#Function<1.134203335/1 in Plug.CSRFProtection.call/2>,
  #Function<6.132079527/1 in Phoenix.Controller.fetch_flash/2>,
  #Function<1.10057843/1 in Plug.Session.before_send/2>,
  #Function<1.127722499/1 in Plug.Logger.call/2>], body_params: %{},
 cookies: %{"access_token" => "eyJ0eXAiOiJKV1QiLCJraWQiOiIxIiwiYWxnIjoiSFM1MTIifQ.eyJyb2xlIjoiYWRtaW4iLCJuYmYiOjE0NTIyODY2MzczNDQsImxvZ2luIjoiZGVycCIsImlkIjoyLCJleHAiOjE0NTc0NzA2MzczNDR9.qZY-CW7YKuU4m0vSuJVsFYfEIzmK6xcnojPLLpz39K6bpO6CR1NjJulyx-du24IpK5GfAwK1xszcn6BtUiSiwQ"},
 halted: false, host: "www.example.com", method: "GET", owner: #PID<0.267.0>,
 params: %{}, path_info: [], peer: {{127, 0, 0, 1}, 111317}, port: 80,
 private: %{Critter4us.Router => {[], %{}}, :phoenix_action => :index,
   :phoenix_controller => Critter4us.PageController,
   :phoenix_endpoint => Critter4us.Endpoint, :phoenix_flash => %{},
   :phoenix_format => "html", :phoenix_layout => {Critter4us.LayoutView, :app},
   :phoenix_pipelines => [:browser], :phoenix_recycled => false,
   :phoenix_route => #Function<5.117644131/1 in Critter4us.Router.match/4>,
   :phoenix_router => Critter4us.Router, :phoenix_template => "index.html",
   :phoenix_view => Critter4us.PageView, :plug_session => %{},
   :plug_session_fetch => :done, :plug_skip_csrf_protection => true},
 query_params: %{}, query_string: "", remote_ip: {127, 0, 0, 1},
 req_cookies: %{"access_token" => "eyJ0eXAiOiJKV1QiLCJraWQiOiIxIiwiYWxnIjoiSFM1MTIifQ.eyJyb2xlIjoiYWRtaW4iLCJuYmYiOjE0NTIyODY2MzczNDQsImxvZ2luIjoiZGVycCIsImlkIjoyLCJleHAiOjE0NTc0NzA2MzczNDR9.qZY-CW7YKuU4m0vSuJVsFYfEIzmK6xcnojPLLpz39K6bpO6CR1NjJulyx-du24IpK5GfAwK1xszcn6BtUiSiwQ"},
 req_headers: [{"cookie",
   "access_token=eyJ0eXAiOiJKV1QiLCJraWQiOiIxIiwiYWxnIjoiSFM1MTIifQ.eyJyb2xlIjoiYWRtaW4iLCJuYmYiOjE0NTIyODY2MzczNDQsImxvZ2luIjoiZGVycCIsImlkIjoyLCJleHAiOjE0NTc0NzA2MzczNDR9.qZY-CW7YKuU4m0vSuJVsFYfEIzmK6xcnojPLLpz39K6bpO6CR1NjJulyx-du24IpK5GfAwK1xszcn6BtUiSiwQ"}],
 request_path: "/",
 resp_body: "<!DOCTYPE html>\n<html lang=\"en\">\n  <head>\n    <meta charset=\"utf-8\">\n    <meta http-equiv=\"X-UA-Compatible\" content=\"IE=edge\">\n    <meta name=\"viewport\" content=\"width=device-width, initial-scale=1\">\n    <meta name=\"description\" content=\"\">\n    <meta name=\"author\" content=\"\">\n\n    <title>Critter4Us</title>\n    <link rel=\"stylesheet\" href=\"/css/app.css?vsn=19EC856\">\n  </head>\n\n  <body>\n    <div class=\"container\" role=\"main\">\n      <div class=\"header\">\n        <ul class=\"nav nav-pills pull-right\">\n          <li><a href=\"/\">Home</a></li>\n          <li><a href=\"/admin\">Admin</a></li>\n          \n            <li><a href=\"/logout\">Logout</a></li>\n          \n        </ul>\n      </div>\n\n      <p class=\"alert alert-info\" role=\"alert\"></p>\n      <p class=\"alert alert-danger\" role=\"alert\"></p>\n\n      <div class=\"jumbotron\">\n</div>\n\n\n\n    </div> <!-- /container -->\n    <script src=\"/js/app.js?vsn=616B091\"></script>\n  </body>\n</html>\n",
 resp_cookies: %{},
 resp_headers: [{"content-type", "text/html; charset=utf-8"},
  {"cache-control", "max-age=0, private, must-revalidate"},
  {"x-request-id", "ujeqna0s6u5t7tki06dcsu6dac0m0gtv"},
  {"x-frame-options", "SAMEORIGIN"}, {"x-xss-protection", "1; mode=block"},
  {"x-content-type-options", "nosniff"}], scheme: :http, script_name: [],
 secret_key_base: "r2P74BRX1ZmeCnWdQE/mugP9BXO2KkmM8rP6YbQ5VRnnybwiEayg9Is9HGpCNERo",
 state: :sent, status: 200}

The failure case:

%Plug.Conn{adapter: {Plug.Adapters.Test.Conn, :...},
 assigns: %{current_user: nil},
 before_send: [#Function<1.134203335/1 in Plug.CSRFProtection.call/2>,
  #Function<6.132079527/1 in Phoenix.Controller.fetch_flash/2>,
  #Function<1.10057843/1 in Plug.Session.before_send/2>,
  #Function<1.127722499/1 in Plug.Logger.call/2>], body_params: %{},
 cookies: %{"access_token" => "eyJ0eXAiOiJKV1QiLCJraWQiOiIxIiwiYWxnIjoiSFM1MTIifQ.eyJyb2xlIjoiYWRtaW4iLCJuYmYiOjE0NTIyODY2MDMzOTcsImxvZ2luIjoiZGVycCIsImlkIjoyLCJleHAiOjE0NTc0NzA2MDMzOTd9.hPYE_96bkPCCGsZJ8wKTe6wmcfigBoWZTF7xx5t3pw4ZIgCB9E3zdc5dKi26lGGqY77aZdJ5RBmd-VOdHDW-Eg"},
 halted: false, host: "www.example.com", method: "GET", owner: #PID<0.267.0>,
 params: %{}, path_info: [], peer: {{127, 0, 0, 1}, 111317}, port: 80,
 private: %{Critter4us.Router => {[], %{}}, :phoenix_action => :index,
   :phoenix_controller => Critter4us.PageController,
   :phoenix_endpoint => Critter4us.Endpoint, :phoenix_flash => %{},
   :phoenix_format => "html", :phoenix_layout => {Critter4us.LayoutView, :app},
   :phoenix_pipelines => [:browser], :phoenix_recycled => false,
   :phoenix_route => #Function<5.117644131/1 in Critter4us.Router.match/4>,
   :phoenix_router => Critter4us.Router, :phoenix_view => Critter4us.PageView,
   :plug_session => %{}, :plug_session_fetch => :done,
   :plug_skip_csrf_protection => true}, query_params: %{}, query_string: "",
 remote_ip: {127, 0, 0, 1},
 req_cookies: %{"access_token" => "eyJ0eXAiOiJKV1QiLCJraWQiOiIxIiwiYWxnIjoiSFM1MTIifQ.eyJyb2xlIjoiYWRtaW4iLCJuYmYiOjE0NTIyODY2MDMzOTcsImxvZ2luIjoiZGVycCIsImlkIjoyLCJleHAiOjE0NTc0NzA2MDMzOTd9.hPYE_96bkPCCGsZJ8wKTe6wmcfigBoWZTF7xx5t3pw4ZIgCB9E3zdc5dKi26lGGqY77aZdJ5RBmd-VOdHDW-Eg"},
 req_headers: [{"cookie",
   "access_token=eyJ0eXAiOiJKV1QiLCJraWQiOiIxIiwiYWxnIjoiSFM1MTIifQ.eyJyb2xlIjoiYWRtaW4iLCJuYmYiOjE0NTIyODY2MDMzOTcsImxvZ2luIjoiZGVycCIsImlkIjoyLCJleHAiOjE0NTc0NzA2MDMzOTd9.hPYE_96bkPCCGsZJ8wKTe6wmcfigBoWZTF7xx5t3pw4ZIgCB9E3zdc5dKi26lGGqY77aZdJ5RBmd-VOdHDW-Eg"}],
 request_path: "/",
 resp_body: "<html><body>You are being <a href=\"/login\">redirected</a>.</body></html>",
 resp_cookies: %{},
 resp_headers: [{"content-type", "text/html; charset=utf-8"},
  {"cache-control", "max-age=0, private, must-revalidate"},
  {"x-request-id", "efkeq2q80p688avq1nuoaf0u3ltpo380"},
  {"x-frame-options", "SAMEORIGIN"}, {"x-xss-protection", "1; mode=block"},
  {"x-content-type-options", "nosniff"}, {"location", "/login"}], scheme: :http,
 script_name: [],
 secret_key_base: "r2P74BRX1ZmeCnWdQE/mugP9BXO2KkmM8rP6YbQ5VRnnybwiEayg9Is9HGpCNERo",
 state: :sent, status: 302}

[marick]

I've never seen theGET / when not logged in redirects" test produce different results in the success and failure cases. Here's an example:

{adapter: {Plug.Adapters.Test.Conn, :...},
 assigns: %{current_user: nil},
 before_send: [#Function<1.134203335/1 in Plug.CSRFProtection.call/2>,
  #Function<6.132079527/1 in Phoenix.Controller.fetch_flash/2>,
  #Function<1.10057843/1 in Plug.Session.before_send/2>,
  #Function<1.127722499/1 in Plug.Logger.call/2>], body_params: %{},
 cookies: %{"_critter4us_key" => "g3QAAAABbQAAAA1waG9lbml4X2ZsYXNodAAAAAFtAAAABWVycm9ybQAAACdZb3UgaGF2ZSB0byBiZSBsb2dnZWQgaW4gdG8gdmlldyAvYWRtaW4=--MQKMWVuQ64ZO3Fw8x6NUKtXm5BA="},
 halted: true, host: "www.example.com", method: "GET", owner: #PID<0.266.0>,
 params: %{}, path_info: ["admin"], peer: {{127, 0, 0, 1}, 111317}, port: 80,
 private: %{Critter4us.Router => {[], %{}}, :phoenix_action => :index,
   :phoenix_controller => Critter4us.AdminController,
   :phoenix_endpoint => Critter4us.Endpoint,
   :phoenix_flash => %{"error" => "You have to be logged in to view /admin"},
   :phoenix_format => "html", :phoenix_layout => {Critter4us.LayoutView, :app},
   :phoenix_pipelines => [:browser], :phoenix_recycled => false,
   :phoenix_route => #Function<4.117644131/1 in Critter4us.Router.match/4>,
   :phoenix_router => Critter4us.Router, :phoenix_view => Critter4us.AdminView,
   :plug_session => %{"phoenix_flash" => %{"error" => "You have to be logged in to view /admin"}},
   :plug_session_fetch => :done, :plug_session_info => :write,
   :plug_skip_csrf_protection => true}, query_params: %{}, query_string: "",
 remote_ip: {127, 0, 0, 1}, req_cookies: %{}, req_headers: [],
 request_path: "/admin", resp_body: "",
 resp_cookies: %{"_critter4us_key" => %{value: "g3QAAAABbQAAAA1waG9lbml4X2ZsYXNodAAAAAFtAAAABWVycm9ybQAAACdZb3UgaGF2ZSB0byBiZSBsb2dnZWQgaW4gdG8gdmlldyAvYWRtaW4=--MQKMWVuQ64ZO3Fw8x6NUKtXm5BA="}},
 resp_headers: [{"set-cookie",
   "_critter4us_key=g3QAAAABbQAAAA1waG9lbml4X2ZsYXNodAAAAAFtAAAABWVycm9ybQAAACdZb3UgaGF2ZSB0byBiZSBsb2dnZWQgaW4gdG8gdmlldyAvYWRtaW4=--MQKMWVuQ64ZO3Fw8x6NUKtXm5BA=; path=/; HttpOnly"},
  {"content-type", "text/html; charset=utf-8"}, {"location", "/login"},
  {"cache-control", "max-age=0, private, must-revalidate"},
  {"x-request-id", "oti6gqrs8c96fgtouej7la4oh9eegq37"},
  {"x-frame-options", "SAMEORIGIN"}, {"x-xss-protection", "1; mode=block"},
  {"x-content-type-options", "nosniff"}], scheme: :http, script_name: [],
 secret_key_base: "r2P74BRX1ZmeCnWdQE/mugP9BXO2KkmM8rP6YbQ5VRnnybwiEayg9Is9HGpCNERo",
 state: :sent, status: 302}

[marick]

I've noticed an interesting thing. When I put a slight delay in the construction of the token, the problem seems to go away:

  def authenticated() do 
    {:ok, user_token} = %{id: 2, login: "derp", role: "admin"} |> Token.generate_token({0, 86400})

    result = conn()
    |> put_req_cookie("access_token", user_token)

    :timer.sleep(1)
    result
  end

That makes me suspect this in token/verify.ex:

  defp check_nbf({:ok, %{nbf: nbf} = payload}) do
    nbf < current_time && {:ok, Map.delete(payload, :nbf)} || {:error, "The token cannot be used yet."}
  end

... although I expect any sleep does a thread switch, so I suppose it could also be a concurrency issue. Remember that failures go away if I remove one of the two controller's "GET / when logged in", %{authenticated: conn} test. (I just reconfirmed that.)

[riverrun]

OK. Thanks for your input. I might add a small leeway for the nbf check. Hopefully, that'll solve it. I'll let you know when it's ready.

[riverrun]

I've just updated to version 0.12. I've added a leeway to the nbf check, and hopefully that will solve this issue. There are three changes that will affect you:

1. redirect_pages now has a value for "logout" (and no value for nil), which is for where you want to be redirected on logout. You will need to change it to "/login".
2. generate_token now takes three arguments - the second argument will be :login in your example.

3. I've remove unique_id from the config. You now need to call it with Openmaize.Login:

   plug Openmaize.Login, [unique_id: :login] when action in [:login_user]

I've also just updated the example site.

[marick]

Works. Thanks.