[TESTING] Europe to brazil problem

.github/workflows/loadtest-brazil-client-deploy.yml

@@ -8,6 +8,7 @@ on:
         options:
           - bot_manager
           - arena_load_test
+          - arena
         required: true
       target_server:
         type: choice
@@ -66,13 +67,15 @@ jobs:
           PHX_SERVER: ${{ vars.PHX_SERVER }}
           PHX_HOST: ${{ vars.LOADTEST_CLIENT_HOST }}
           PORT: ${{ vars.ARENA_PORT }}
+          BOT_MANAGER_HOST: ${{ vars.LOADTEST_CLIENT_HOST }}
           BOT_MANAGER_PORT: ${{ vars.BOT_MANAGER_PORT }}
           DATABASE_URL: ${{ secrets.DATABASE_URL }}
           SECRET_KEY_BASE: ${{ secrets.SECRET_KEY_BASE }}
           NEWRELIC_APP_NAME: ${{ vars.NEWRELIC_APP_NAME_LOADTEST }}
           NEWRELIC_KEY: ${{ secrets.NEWRELIC_KEY }}
           DBUS_SESSION_BUS_ADDRESS: ${{ vars.DBUS_SESSION_BUS_ADDRESS }}
           BRANCH_NAME: ${{ github.head_ref || github.ref_name }}
+          GATEWAY_URL: ${{ vars.GATEWAY_URL }}
         run: |
           set -ex
           ssh ${SSH_USERNAME}@${SSH_HOST} \
@@ -86,10 +89,12 @@ jobs:
                 PHX_SERVER=${PHX_SERVER} \
                 PHX_HOST=${PHX_HOST} \
                 PORT=${PORT} \
+                BOT_MANAGER_HOST=${BOT_MANAGER_HOST} \
                 BOT_MANAGER_PORT=${BOT_MANAGER_PORT} \
                 DATABASE_URL=${DATABASE_URL} \
                 SECRET_KEY_BASE=${SECRET_KEY_BASE} \
                 NEWRELIC_APP_NAME=${NEWRELIC_APP_NAME} \
                 NEWRELIC_KEY=${NEWRELIC_KEY} \
                 DBUS_SESSION_BUS_ADDRESS=${DBUS_SESSION_BUS_ADDRESS} \
+                GATEWAY_URL=${GATEWAY_URL} \
                 /home/${SSH_USERNAME}/deploy-script/deploy.sh

apps/arena/lib/arena/game_bounties_fetcher.ex

@@ -2,7 +2,7 @@ defmodule Arena.GameBountiesFetcher do
   @moduledoc false
   use GenServer
 
-  @update_interval_ms 30_000
+  @update_interval_ms 300_000
 
   # API
   def start_link(_) do

apps/arena/lib/arena/game_socket_handler.ex

@@ -58,6 +58,7 @@ defmodule Arena.GameSocketHandler do
 
     Process.send_after(self(), :send_ping, @ping_interval_ms)
 
+    Logger.info("Sending GameJoined")
     {:reply, {:binary, encoded_msg}, state}
   end
 
@@ -220,6 +221,7 @@ defmodule Arena.GameSocketHandler do
          %{block_movement: false} = state
        )
        when action in [:move] do
+    Logger.info("Handling move")
     case message do
       %{action_type: {:move, %{direction: direction}}, timestamp: timestamp} ->
         GameUpdater.move(

apps/arena/lib/arena/game_updater.ex

@@ -4,6 +4,7 @@ defmodule Arena.GameUpdater do
   (player websocket).
   """
 
+  require Logger
   use GenServer
   alias Arena.Game.Obstacle
   alias Arena.GameBountiesFetcher
@@ -234,14 +235,22 @@ defmodule Arena.GameUpdater do
       # Obstacles
       |> handle_obstacles_transitions()
 
+    game_state =
+      if game_state.status != game_state.current_status do
+        put_in(game_state, [:current_status], game_state.status)
+        |> put_in([:print_state], true)
+      else
+        game_state
+        |> put_in([:print_state], false)
+      end
     broadcast_game_update(game_state)
     game_state = %{game_state | killfeed: [], damage_taken: %{}, damage_done: %{}}
 
     {:noreply, %{state | game_state: game_state}}
   end
 
   def handle_info(:selecting_bounty, state) do
-    Process.send_after(self(), :game_start, state.game_config.game.start_game_time_ms)
+    Process.send_after(self(), :game_start, 1000)
 
     {:noreply, put_in(state, [:game_state, :status], :SELECTING_BOUNTY)}
   end
@@ -626,6 +635,9 @@ defmodule Arena.GameUpdater do
   end
 
   defp broadcast_game_update(state) do
+    if state.print_state do
+      Logger.info("Game update #{state.status} #{state.server_timestamp}")
+    end
     encoded_state =
       GameEvent.encode(%GameEvent{
         event:
@@ -719,6 +731,7 @@ defmodule Arena.GameUpdater do
             config.game.bounty_pick_time_ms
       })
       |> Map.put(:status, :PREPARING)
+      |> Map.put(:current_status, nil)
       |> Map.put(
         :start_game_timestamp,
         initial_timestamp + config.game.start_game_time_ms + config.game.bounty_pick_time_ms

apps/arena/lib/arena/server_socket_handler.ex

@@ -0,0 +1,34 @@
+defmodule Arena.ServerSocketHandler do
+  @moduledoc """
+  Module that handles cowboy websocket requests
+  """
+  require Logger
+
+  @behaviour :cowboy_websocket
+
+  @impl true
+  def init(req, _opts) do
+    {:cowboy_websocket, req, %{}}
+  end
+
+  @impl true
+  def websocket_init(state) do
+    {:ok, state}
+  end
+
+  @impl true
+  def websocket_info(_any, state) do
+    {:ok, state}
+  end
+
+  @impl true
+  def websocket_handle({:text, msg}, state) do
+    handle_msg(Jason.decode!(msg), state)
+  end
+
+  defp handle_msg(%{"action" => "check_ping", "client_timestamp" => client_timestamp}, state) do
+    now = DateTime.utc_now() |> DateTime.to_unix()
+    Logger.info("Message received", %{server_timestamp: now, client_timestamp: client_timestamp})
+    {:reply, {:text, Jason.encode!(%{action: "response_ping", server_timestamp: now, client_timestamp: client_timestamp})}, state}
+  end
+end

apps/arena/lib/arena/tester.ex

@@ -0,0 +1,41 @@
+defmodule Tester do
+  @moduledoc """
+  GameClient socket handler.
+  It handles the communication with the server.
+  """
+
+  use WebSockex, restart: :transient
+  require Logger
+
+  def start_link() do
+    host = "arena-brazil-testing.curseofmirra.com"
+    ws_url = "wss://#{host}/testing"
+
+    WebSockex.start_link(ws_url, __MODULE__, %{})
+  end
+
+  def handle_connect(_, state) do
+    Logger.info("Game connected")
+    send(self(), :check_ping)
+    {:ok, state}
+  end
+
+  def handle_frame({:text, msg}, state) do
+    msg = Jason.decode!(msg, keys: :atoms)
+    metadata = Map.merge(msg, %{latency_ms: (msg.server_timestamp - msg.client_timestamp)})
+    Logger.info("Received frame", metadata)
+    {:ok, state}
+  end
+
+  def handle_info(:check_ping, state) do
+    now = DateTime.utc_now() |> DateTime.to_unix()
+    Logger.info("Sending check_ping", %{timestamp: now})
+    Process.send_after(self(), :check_ping, 30)
+    {:reply, {:text, Jason.encode!(%{"action" => "check_ping", "client_timestamp" => now})}, state}
+  end
+
+  def terminate(close_reason, _state) do
+    Logger.info("Socket closed: #{inspect(close_reason)}")
+    :ok
+  end
+end

apps/arena/mix.exs

@@ -52,6 +52,7 @@ defmodule Arena.MixProject do
       {:credo, "~> 1.7", only: [:dev, :test], runtime: false},
       {:plug_cowboy, "~> 2.5"},
       {:toxiproxy_ex, "~> 1.1.1"},
+      {:websockex, "~> 0.4.3"},
       {:joken, "~> 2.6"}
     ]
   end

apps/game_client/lib/game_client/game_test_handler.ex

@@ -0,0 +1,44 @@
+defmodule GameTestHandler do
+  @moduledoc """
+  GameClient socket handler.
+  It handles the communication with the server.
+  """
+
+  use WebSockex, restart: :transient
+  require Logger
+  alias Arena.Serialization
+
+  def start_link(gateway_jwt, player_id, game_id) do
+    ws_url = ws_url(gateway_jwt, player_id, game_id)
+
+    WebSockex.start_link(ws_url, __MODULE__, %{})
+  end
+
+  def handle_connect(_, state) do
+    Logger.info("Game connected")
+    {:ok, state}
+  end
+
+  def handle_frame({:binary, event}, state) do
+    decoded = Serialization.GameEvent.decode(event)
+    case decoded.event do
+      {:update, game_update} ->
+        Logger.info("Received update", %{server_timestamp: game_update.server_timestamp, status: game_update.status})
+        {:ok, state}
+      _ ->
+        {:ok, state}
+    end
+  end
+
+  def terminate(close_reason, _state) do
+    Logger.info("Game socket closed: #{inspect(close_reason)}")
+    :ok
+  end
+
+  defp ws_url(gateway_jwt, player_id, game_id) do
+    # FIX ME Remove hardcoded host
+    # host = "localhost:4000"
+    host = "arena-brazil-testing.curseofmirra.com"
+    "wss://#{host}/play/#{game_id}/#{player_id}?gateway_jwt=#{gateway_jwt}"
+  end
+end

apps/game_client/lib/game_client/test_handler.ex

@@ -0,0 +1,44 @@
+defmodule TestHandler do
+  @moduledoc """
+  GameClient socket handler.
+  It handles the communication with the server.
+  """
+
+  use WebSockex, restart: :transient
+  require Logger
+  alias Arena.Serialization
+
+  @gateway_jwt "eyJhbGciOiJFZDI1NTE5IiwidHlwIjoiSldUIn0.eyJkZXYiOiJhaUJWOTN1NkhBdmpJV3h2R2plQWlrTXVuM0xURVBwcmhMelFMb1VOR0ljPSIsImV4cCI6MTcyMTIxNDA0OSwiaWF0IjoxNzIxMjA2ODQ5LCJqdGkiOiIydmhmOTBsc3FoNmxhNzN1YXMwMDFnN2giLCJuYmYiOjE3MjEyMDY4NDksInN1YiI6IjU1MWJhNzMxLWU2YmUtNDgzNi1hNjk2LTQ5NzE1MDQyMDViMyJ9.dvm3I5PlEiEVIQCtn0C9q1WZVKWpugkuhoPexoNMKeaiGizrAGFP38pVJ-EzgMcLc7HihDUxJVZkYSUGT2xlAw"
+  @player_id "551ba731-e6be-4836-a696-4971504205b3"
+
+  def start_link() do
+    ws_url = ws_url(@gateway_jwt, @player_id)
+
+    WebSockex.start_link(ws_url, __MODULE__, %{})
+  end
+
+  def handle_frame({:binary, event}, state) do
+    decoded = Serialization.LobbyEvent.decode(event)
+    case decoded.event do
+      {:joined, _} ->
+        Logger.info("Joined lobby")
+        {:ok, state}
+      {:game, %{game_id: game_id}} ->
+        Logger.info("Moving to game")
+        GameTestHandler.start_link(@gateway_jwt, @player_id, game_id)
+        {:ok, state}
+    end
+  end
+
+  def terminate(close_reason, _state) do
+    Logger.info("Closing matchmaking socket: #{inspect(close_reason)}")
+    :ok
+  end
+
+  defp ws_url(gateway_jwt, player_id) do
+    # FIX ME Remove hardcoded host
+    # host = "localhost:4000"
+    host = "arena-brazil-testing.curseofmirra.com"
+    "wss://#{host}/join/#{player_id}/muflus/amin?gateway_jwt=#{gateway_jwt}"
+  end
+end

apps/game_client/mix.exs

@@ -57,7 +57,8 @@ defmodule GameClient.MixProject do
       {:credo, "~> 1.7", only: [:dev, :test], runtime: false},
       {:websockex, "~> 0.4.3"},
       {:exbase58, "~> 1.0.2"},
-      {:ueberauth_google, "~> 0.10"}
+      {:ueberauth_google, "~> 0.10"},
+      {:arena, in_umbrella: true}
     ]
   end
 

config/config.exs

@@ -29,8 +29,8 @@ import Config
 
 # Configures Elixir's Logger
 config :logger, :console,
-  format: "$time $metadata[$level] $message\n",
-  metadata: [:request_id]
+  format: "$time [$level] $message $metadata\n",
+  metadata: [:status, :action, :latency_ms, :server_timestamp, :client_timestamp]
 
 # Use Jason for JSON parsing in Phoenix
 config :phoenix, :json_library, Jason
@@ -87,6 +87,7 @@ config :joken,
 # Configures the endpoint
 dispatch = [
   _: [
+    {"/testing", Arena.ServerSocketHandler, []},
     {"/play/:game_id/:client_id", Arena.GameSocketHandler, []},
     {"/join/:client_id/:character_name/:player_name", Arena.SocketHandler, []},
     {"/quick_game/:client_id/:character_name/:player_name", Arena.QuickGameHandler, []},

config/dev.exs

@@ -5,7 +5,10 @@ import Config
 ##########################
 
 # Do not include metadata nor timestamps in development logs
-config :logger, :console, format: "[$level] $message\n"
+# config :logger, :console, format: "[$level] $message\n"
+# config :logger, :console,
+#   format: "$time [$level] $message $metadata\n",
+#   metadata: [:status, :action, :server_timestamp, :client_timestamp]
 
 # Set a higher stacktrace during development. Avoid configuring such
 # in production as building large stacktraces may be expensive.