Issue with Genserver state on first call

So I’m not sure this is an issue with genserver itself, the channel communication, or the way I’ve got the JS hooked up. The architecture is as:

  • User loads the page, JS imports happen, a VueJS component is instantiated, on the mount trigger for the component the user connects to a general channel for this “duel”. The response from joining includes the state of the game, which is used to populate the VueJS component and a another call to join a user particular channel is made.

The problem I’m running into is that, if I have the game going and state has been altered, and then I refresh the page, the state I’m being served is stale on the first connection. If I then take an action the update broadcast actually shows the correct state (and updates the vuejs component accordingly). My question is why is the gen state serving a stale state on the beginning and then serving the correct one afterwards?

The code is as follows:

#js side

imports {.... }

export default class View extends Shared {
  ...
  Vue.component('Game', Game)
    new Vue({
      el: 'main',
      data() {
        return {
          ...
        }
      },
      mounted() {
        this.channel = socket.channel("duel:"+window.gameId, {token: window.userToken});
        this.channel.join()
          .receive("ok", response => {
            this.user_id = response.user_id;
            ...
           joinUserChannel(this, response.user_id);
    }
  }
}

#channel side

def join("duel:" <> id, payload, socket) do
    case authorized?(payload, socket, id) do
      {:ok, socket} ->
        stats = Monitor.game_stats(id) |> Processor.clean_stats(socket.assigns.current_user)
        {:ok, %{user_id: socket.assigns.current_user, game: stats}, socket}
      {:error, _} ->
        {:error}
    end
  end

 def handle_in("pass", %{"game_id" => game_id}, socket) do
    IO.puts("handle in pass")
    stats = Monitor.game_stats(game_id) |> Processor.pass(socket.assigns.current_user)
    |> broadcast_this
    {:noreply, socket}
 end

#monitor

defmodule AetherWars.Duels.Monitor do
  @moduledoc """
  Keeps and serves Game State
  """
  use GenServer
  alias AetherWars.Duels.Processor
  alias AetherWars.Games
  ...
  def start_link(game_id) do
    IO.puts("Monitor start_link -> game #{game_id}")
    GenServer.start_link(__MODULE__, game_id, name: ref(game_id))
  end

  def init(game_id) do
    IO.puts("Initializing Game #{game_id}")
    game = Games |> Games.players |> AetherWars.Repo.get(game_id)
    case game.game do
      nil ->
        IO.puts("Initializing Game #{game_id} - doesn't exist")
        state = Processor.create(game)
        changeset = Ecto.Changeset.change game, game: state
        AetherWars.Repo.update changeset
        {:ok, state}
      game ->
        IO.puts("Initializing Game #{game_id} - exists")
        state = game
        {:ok, state}
    end
  end

def game_stats(game_id) do
    IO.puts("game_stats game: #{game_id}")
    try_call game_id, {:game_stats}
end

...

def handle_call({:game_stats}, _from, state) do
    IO.puts("handle_call game_stats")
    {:reply, state, state}
end

defp try_call(game_id, call_function) do
    case GenServer.whereis(ref(game_id)) do
      nil ->
        IO.puts("try_call whereis nil")
        case create(game_id) do
          {:ok, pid} ->
            GenServer.call(pid, {:game_stats})
          _ ->
            {:error}
        end
      pid ->
        IO.puts("try_call whereis not nil match")
        IO.inspect(pid)
        GenServer.call(pid, call_function)
    end
 end

So what I’m not understanding is why the first call to Monitor.game_stats(game_id) on the join seems to return a stale state but as soon as I make any other action that triggers the same Monitor.game_stats the returned state is actually the updated version?

Am I missing something obvious? I could make it ask explicitly for the game state after joining once again, but shouldn’t it be serving the correct state right away? The only difference when making the call is that it then broadcasts them to the particular channel of the user, but the data is loaded into the vuecomponent the same way (and indeed on the join it’s loading data, but just as if the state was the init state).

(do channels cache their response? because then a refresh of the page could mean the cached response was being served over the channel? it doesn’t seem to make sense though…)

Thanks

What’s in create(game_id)?

btw, there is no need to wrap atoms in tuples. It seems to me that

:game_stats
# and
:error

is a bit cleaner than

{:game_stats}
# and
{:error}

I agree, leftovers not yet cleaned up.

def create(game_id) do
    IO.puts("Monitor create")
    case GenServer.whereis(ref(game_id)) do
      nil ->
        IO.puts("Game #{game_id} whereis nil")
        Supervisor.start_child(AetherWars.Duels.Supervisor, [game_id])
      pid ->
        pid
    end
  end

It’s this

In case this helps:

defmodule AetherWars.Duels.Supervisor do
  use Supervisor
  alias AetherWars.Games
  alias AetherWars.Repo

  def start_link do
    IO.puts("start_link Supervisor")
    Supervisor.start_link(__MODULE__, :ok, name: __MODULE__)
  end

  def init(:ok) do
    IO.puts("init Supervisor")
    #open_games = Games |> Games.list_running_games |> Repo.all
    #children = for id <- open_games, do: worker(AetherWars.Duels.Monitor, id, restart: :transient)
    children = [
      worker(AetherWars.Duels.Monitor, [], restart: :transient)
    ]

    supervise(children, strategy: :simple_one_for_one)
  end
end

And the start_link from the genserver:

def start_link(game_id) do
    IO.puts("Monitor start_link -> game #{game_id}")
    GenServer.start_link(__MODULE__, game_id, name: ref(game_id))
  end

(and for the lolz your message pops up as “idiot blablabl” and I was like, wow this guy starts a bit harsh)

I think I’m doing something wrong on the initialisation because I get two processes when I inspect with the observer.

But what is weird is that, when I join the channel, it fetches one process

[info] JOIN duel:5 to AetherWars.DuelChannel
  Transport:  Phoenix.Transports.WebSocket
  Parameters: %{"token" => "SFMyNTY.g3QAAAACZAAEZGF0YWEBZAAGc2lnbmVkbgYAmQzhr14B.G8MUIXpafUb-PkZeU-eT2r_tfL7WPooGCgc3cNaFjwo"}
[debug] QUERY OK source="games" db=21.3ms
SELECT g0."id", g0."player_1", g0."player_2", g0."status", g0."game", g0."start_time", g0."end_time", g0."public", g0."password", g0."winner", g0."inserted_at", g0."updated_at" FROM "games" AS g0 WHERE (g0."id" = $1) [5]
game_stats game: 5
try_call whereis not nil match
#PID<0.447.0>
handle_call game_stats

When I inspect that on observer it has the initialised state of a game that has just started.

But when I call an action or something it gives me the actual updated process:

[info] JOIN user:1 to AetherWars.UserChannel
  Transport:  Phoenix.Transports.WebSocket
  Parameters: %{"token" => "SFMyNTY.g3QAAAACZAAEZGF0YWEBZAAGc2lnbmVkbgYAmQzhr14B.G8MUIXpafUb-PkZeU-eT2r_tfL7WPooGCgc3cNaFjwo"}
[info] Replied user:1 :ok
game_stats game: 5
try_call whereis not nil match
#PID<0.452.0>

So I’m probably doing something wrong with how I’m initialising the Supervisor and the child processes?
But they’re being called by the same ref id?

Sorry, got busy for a moment.

Can you put some IO.inspect or Logger.debug around the values returned in channel’s join (especially stats) and compare them with what you get in the client?

do channels cache their response?

No, I don’t think they do.

But they’re being called by the same ref id?

Can you show the code for AetherWars.Duels.Monitor.ref(game_id)?

With :simple_one_for_one strategy it might be a good idea to use Registry and keep track of the child processes there. Note that atoms from ref(game_id) won’t be garbage collected.

Then your start_link would look like this

GenServer.start_link(__MODULE__, game_id, name: {:via, Registry, {Registry.Duels, game_id}})

Can’t see the reason for duplicated processes though …

So basically I patched a bunch of articles and the documentation to get to this point, so it can be obviously wrong:

defp ref(game_id) do
    {:global, {:game, game_id}}
 end

What I had understood was that :game was gonna be a atom but not game_id (if it’s so then I should really change that).

What’s been tripping me up is that it basically does this (I’m passing it all from the init console output), you can see that first it initiates a Genserver for game 5, but then when the second user joins the game, it creates another one because it can’t seem to find an existing reference - perhaps this is an issue of being too concurrent?? shouldn’t be right?

Micaels-MacBook-Pro:aetherwars mnussbaumer$ iex -S mix phoenix.server
Erlang/OTP 20 [erts-9.0] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:10] [hipe] [kernel-poll:false] [dtrace]

[info] Running AetherWars.Endpoint with Cowboy using http://localhost:4000
start_link Supervisor
init Supervisor
[debug] QUERY OK source="games" db=2.4ms
SELECT g0."id", g0."player_1", g0."player_2", g0."public", g0."status", u1."username", u2."username" FROM "games" AS g0 LEFT OUTER JOIN "users" AS u1 ON u1."id" = g0."player_1" LEFT OUTER JOIN "users" AS u2 ON u2."id" = g0."player_2" WHERE (g0."winner" IS NULL) ORDER BY g0."inserted_at" DESC []
Interactive Elixir (1.5.0) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> 23 Sep 23:33:37 - info: compiling
23 Sep 23:33:37 - info: compiled 22 files into 2 files, copied 56 in 4.2 sec
23 Sep 23:33:37 - info: [copycat] copied 6 files
[info] JOIN duel:5 to AetherWars.DuelChannel
  Transport:  Phoenix.Transports.WebSocket
  Parameters: %{"token" => "SFMyNTY.g3QAAAACZAAEZGF0YWEBZAAGc2lnbmVkbgYAh2rcsF4B.2GH65pUQ83IyQKylV1nCcjXj7q4dL_0Tz9vDjK58WOA"}
[debug] QUERY OK source="games" db=5.3ms decode=2.8ms
SELECT g0."id", g0."player_1", g0."player_2", g0."status", g0."game", g0."start_time", g0."end_time", g0."public", g0."password", g0."winner", g0."inserted_at", g0."updated_at" FROM "games" AS g0 WHERE (g0."id" = $1) [5]
game_stats game: 5
try_call whereis nil
Monitor create
Game 5 whereis nil
Monitor start_link -> game 5
Initializing Game 5
[debug] QUERY OK source="games" db=3.0ms
SELECT g0."id", g0."player_1", g0."player_2", g0."status", g0."game", g0."start_time", g0."end_time", g0."public", g0."password", g0."winner", g0."inserted_at", g0."updated_at" FROM "games" AS g0 WHERE (g0."id" = $1) [5]
[debug] QUERY OK source="users" db=1.1ms queue=0.1ms
SELECT u0."id", u0."email", u0."password_hash", u0."temp_password", u0."username", u0."first_name", u0."last_name", u0."verified", u0."locked", u0."subscribed", u0."subscribed_until", u0."last_login", u0."user_data", u0."avatar", u0."verification_token", u0."inserted_at", u0."updated_at", u0."id" FROM "users" AS u0 WHERE (u0."id" = $1) [1]
[debug] QUERY OK source="users" db=1.8ms queue=0.1ms
SELECT u0."id", u0."email", u0."password_hash", u0."temp_password", u0."username", u0."first_name", u0."last_name", u0."verified", u0."locked", u0."subscribed", u0."subscribed_until", u0."last_login", u0."user_data", u0."avatar", u0."verification_token", u0."inserted_at", u0."updated_at", u0."id" FROM "users" AS u0 WHERE (u0."id" = $1) [23]
Initializing Game 5 - exists
#PID<0.436.0>
handle_call game_stats
[info] Replied duel:5 :ok
[info] JOIN user:1 to AetherWars.UserChannel
  Transport:  Phoenix.Transports.WebSocket
  Parameters: %{"token" => "SFMyNTY.g3QAAAACZAAEZGF0YWEBZAAGc2lnbmVkbgYAh2rcsF4B.2GH65pUQ83IyQKylV1nCcjXj7q4dL_0Tz9vDjK58WOA"}
[info] Replied user:1 :ok
[debug] Duplicate channel join for topic "user:1" in AetherWars.UserSocket. Closing existing channel for new join.
[info] JOIN user:1 to AetherWars.UserChannel
  Transport:  Phoenix.Transports.WebSocket
  Parameters: %{"token" => "SFMyNTY.g3QAAAACZAAEZGF0YWEBZAAGc2lnbmVkbgYAh2rcsF4B.2GH65pUQ83IyQKylV1nCcjXj7q4dL_0Tz9vDjK58WOA"}
[info] Replied user:1 :ok
[info] JOIN duel:5 to AetherWars.DuelChannel
  Transport:  Phoenix.Transports.WebSocket
  Parameters: %{"token" => "SFMyNTY.g3QAAAACZAAEZGF0YWEXZAAGc2lnbmVkbgYAH37asF4B.3hK57gThspX69IKe1-GQuWD7qvgO7mDqpg0aUnahDw8"}
[debug] QUERY OK source="games" db=3.2ms
SELECT g0."id", g0."player_1", g0."player_2", g0."status", g0."game", g0."start_time", g0."end_time", g0."public", g0."password", g0."winner", g0."inserted_at", g0."updated_at" FROM "games" AS g0 WHERE (g0."id" = $1) [5]
game_stats game: 5
try_call whereis not nil match
#PID<0.436.0>
handle_call game_stats
[info] Replied duel:5 :ok
[info] JOIN user:23 to AetherWars.UserChannel
  Transport:  Phoenix.Transports.WebSocket
  Parameters: %{"token" => "SFMyNTY.g3QAAAACZAAEZGF0YWEXZAAGc2lnbmVkbgYAH37asF4B.3hK57gThspX69IKe1-GQuWD7qvgO7mDqpg0aUnahDw8"}
[info] Replied user:23 :ok
[debug] Duplicate channel join for topic "user:23" in AetherWars.UserSocket. Closing existing channel for new join.
[info] JOIN user:23 to AetherWars.UserChannel
  Transport:  Phoenix.Transports.WebSocket
  Parameters: %{"token" => "SFMyNTY.g3QAAAACZAAEZGF0YWEXZAAGc2lnbmVkbgYAH37asF4B.3hK57gThspX69IKe1-GQuWD7qvgO7mDqpg0aUnahDw8"}
[info] Replied user:23 :ok
handle in cast
game_stats game: 5
try_call whereis nil
Monitor create
Game 5 whereis nil
Monitor start_link -> game 5
Initializing Game 5
[debug] QUERY OK source="games" db=4.0ms queue=0.1ms
SELECT g0."id", g0."player_1", g0."player_2", g0."status", g0."game", g0."start_time", g0."end_time", g0."public", g0."password", g0."winner", g0."inserted_at", g0."updated_at" FROM "games" AS g0 WHERE (g0."id" = $1) [5]
[debug] QUERY OK source="users" db=2.2ms queue=0.2ms
SELECT u0."id", u0."email", u0."password_hash", u0."temp_password", u0."username", u0."first_name", u0."last_name", u0."verified", u0."locked", u0."subscribed", u0."subscribed_until", u0."last_login", u0."user_data", u0."avatar", u0."verification_token", u0."inserted_at", u0."updated_at", u0."id" FROM "users" AS u0 WHERE (u0."id" = $1) [1]
[debug] QUERY OK source="users" db=2.4ms queue=0.1ms
SELECT u0."id", u0."email", u0."password_hash", u0."temp_password", u0."username", u0."first_name", u0."last_name", u0."verified", u0."locked", u0."subscribed", u0."subscribed_until", u0."last_login", u0."user_data", u0."avatar", u0."verification_token", u0."inserted_at", u0."updated_at", u0."id" FROM "users" AS u0 WHERE (u0."id" = $1) [23]
Initializing Game 5 - exists
#PID<0.447.0>
handle_call game_stats
inside cast - Player: player_1 Opponent: player_2
inside cast_stack - Player: player_1 Opponent: player_2 Card: %{"card" => true, "element" => %{"cmc" => 0, "cost" => "0", "flavour" => "The Sea is calm just as many times as it is in powerful turmoil", "image" => "http://d1cn0kki1do5l.cloudfront.net/water-flux.jpg", "name" => "Water Flux", "quantity" => 5, "rules" => %{}, "slug" => "water_flux", "stats" => "", "text" => [], "type" => "æther flux"}, "to_cast" => "play"}
nil
inside empty cast stack
inside cast_card
inside play æther flux
flux available %{"cmc" => 0, "cost" => "0", "flavour" => "The Sea is calm just as many times as it is in powerful turmoil", "image" => "http://d1cn0kki1do5l.cloudfront.net/water-flux.jpg", "name" => "Water Flux", "quantity" => 5, "rules" => %{}, "slug" => "water_flux", "stats" => "", "text" => [], "type" => "æther flux"}
"player_1"
try_call whereis not nil match
#PID<0.447.0>

But as soon as I do anything that requires interacting with the Genserver (pass, cast, etc), it correctly references the last pid. By what I read I was thinking that whenever you have a global ref if you try to duplicate one of them is terminated by default?

What’s weirder is that on joining, given a ref for game 5, it fetches the first initiated process, and then when calling other stuff it fetches the second process. Multiple refreshes don’t create additional processes, so I think I’m missing something on the instantiation of the child processes?

Thanks for looking into it - it’s not crucial right now - but I would like to understand what I’m doing wrong.

Oh - you know what was the problem? When the id was being taken from the channel topic with <> it’s a string, but when being sent through the channel as a message parameter, I was sending it as an integer.
I noticed it by using IO.inspect instead of IO.puts on the id’s - and there they were, “5” and 5… so there goes the mystery. Thanks for looking at it, the fact you mentioned they would be :atoms made me look again and find this :wink:

2 Likes