Timing issue when testing LiveView with GenServer

Hi all,

I am working through the Pragmatic Programmer LiveView course, and in lesson 22 Testing Messages, we are testing a Sales Dashboard that receives sales data from another module. The test as given in the lesson worked fine, but in order to practice using GenServer and PubSub I created a SalesProducer module that periodically broadcasts sales data over PubSub, but to make the manual Refresh button work, I also implemented a GenServer callback and this is where I am getting a strange timing issue.

Here is the GenServer part of the SalesProducer module:

def make_stats() do
      new_orders: Enum.random(1..40),
      sales_amount: Enum.random(1..200),
      satisfaction: Enum.random(1..100)

  def handle_call(:get_stats, _from,  state) do
    {:reply, make_stats(), state}

Back in the LiveView, the Refresh button is implemented as:

 <button phx-click="refresh">
        <img src="images/refresh.svg">

The button event is handled like:

def handle_event("refresh", _, socket) do
    socket = assign_stats(socket)
    {:noreply, socket}

  defp assign_stats(socket) do
    stats = GenServer.call(LiveViewStudio.SalesProducer, :get_stats)
    IO.puts "assign_stats got "
    IO.inspect stats
      new_orders: stats.new_orders,
      sales_amount: stats.sales_amount,
      satisfaction: stats.satisfaction

This is where my code differs from the lesson in that I am making a GenServer call instead of one to a regular module, and this is where my test is failing. Here is the test code, and note the debug statement at the top:

test "refreshes when refresh button is pressed", %{conn: conn} do
    IO.puts "refreshes when refresh button is pressed"
    {:ok, view, _html} = live(conn, "/sales-dashboard")

    before_refresh = render(view)

    after_refresh =
      |> element("button", "Refresh")
      |> render_click()

    refute before_refresh =~ after_refresh

The test was failing because the before_refresh and after_refresh rendered views were exactly the same, so I started putting debug statements everywhere, and as soon as I put the one inside the test code that reprints the test description, the test passed:

15:37:39.813 [info]  Migrations already up
Sales producer starting
..assign_stats got
%{new_orders: 4, sales_amount: 104, satisfaction: 43}
assign_stats got
%{new_orders: 38, sales_amount: 200, satisfaction: 73}
.refreshes when refresh button is pressed
assign_stats got
%{new_orders: 32, sales_amount: 66, satisfaction: 55}
assign_stats got
%{new_orders: 1, sales_amount: 2, satisfaction: 29}
assign_stats got
%{new_orders: 14, sales_amount: 180, satisfaction: 26}

Finished in 0.9 seconds (0.6s async, 0.2s sync)
55 tests, 0 failures

If all I do is comment out that debug statement at the top of the test, it fails:

15:51:49.736 [info]  Migrations already up
Sales producer starting
..assign_stats got
%{new_orders: 39, sales_amount: 127, satisfaction: 48}
assign_stats got
%{new_orders: 31, sales_amount: 130, satisfaction: 35}
assign_stats got
%{new_orders: 38, sales_amount: 143, satisfaction: 13}
assign_stats got
%{new_orders: 40, sales_amount: 190, satisfaction: 74}
assign_stats got
%{new_orders: 16, sales_amount: 143, satisfaction: 99}

  1) test refreshes after tick (LiveViewStudioWeb.SalesDashboardLiveTest)
     Refute with =~ failed, both sides are exactly equal
     code: refute before_refresh =~ after_refresh
     left: "<div data-phx-main=\"true\" data-phx-session=\"SFMyNTY.g2gDaAJhBXQAAAAIZAACaWRtAAAAFHBoeC1Gc0VNS1R3cGtpakJHQVBCZAAMbGl2ZV9zZXNzaW9uaAJkAAdkZWZhdWx0bggAZ0LfhYiAvxZkAApwYXJlbnRfcGlkZAADbmlsZAAIcm9vdF9waWRkAANuaWxkAAlyb290X3ZpZXdkACtFbGl4aXIuTGl2ZVZpZXdTdHVkaW9XZWIuU2FsZXNEYXNoYm9hcmRMaXZlZAAGcm91dGVyZAAfRWxpeGlyLkxpdmVWaWV3U3R1ZGlvV2ViLlJvdXRlcmQAB3Nlc3Npb250AAAAAGQABHZpZXdkACtFbGl4aXIuTGl2ZVZpZXdTdHVkaW9XZWIuU2FsZXNEYXNoYm9hcmRMaXZlbgYASIcUwH0BYgABUYA.zy7wSfRN_3QmYukIYTrLXqjKY5v52VpK481Fo8Jo9F4\" data-phx-static=\"SFMyNTY.g2gDaAJhBXQAAAADZAAKYXNzaWduX25ld2pkAAVmbGFzaHQAAAAAZAACaWRtAAAAFHBoeC1Gc0VNS1R3cGtpakJHQVBCbgYAXIcUwH0BYgABUYA.s6AZpJXNjBmu1GqHZwrGK7GlsY2NkcEbZMzAv1FQEgs\" id=\"phx-FsEMKTwpkijBGAPB\"><main role=\"main\" class=\"container\"><p class=\"alert alert-info\" role=\"alert\" phx-click=\"lv:clear-flash\" phx-value-key=\"info\"></p><p class=\"alert alert-danger\" role=\"alert\" phx-click=\"lv:clear-flash\" phx-value-key=\"error\"></p><h1>Sales Dashboard</h1><div id=\"dashboard\"><div class=\"stats\"><div class=\"stat\"><span class=\"value\">\n        31\n      </span><span class=\"name\">\n        New Orders\n      </span></div><div class=\"stat\"><span class=\"value\">\n        $130\n      </span><span class=\"name\">\n        Sales Amount\n      </span></div><div class=\"stat\"><span class=\"value\">\n        35%\n      </span><span class=\"name\">\n        Satisfaction\n      </span></div></div><button phx-click=\"refresh\"><img src=\"images/refresh.svg\"/>\n    Refresh\n  </button></div></main></div>"
       test/live_view_studio_web/live/sales_dashboard_live_test.exs:26: (test)


Finished in 1.1 seconds (0.7s async, 0.4s sync)
55 tests, 1 failure

I get that tests run concurrently and all that, but I thought a GenServer.call was blocking, vs a cast, so how could an IO action before the call change things to the point where the test fails?

Thanks for any pointers