Improve Tests and Log CMC Errors (#103)

- add database table and ecto schema for cmc_errors
- plumb session_id into context so it's available for audit log messages
- update service to log cmc errors to database
- update tests
- profiled and reduced runtime by eliminating timer based tests.
- set logging in test config to NONE so logs aren't polluted with messages

Author: pheller

apps/core/lib/prodigy/core/data/cmc_error.ex

@@ -0,0 +1,47 @@
+defmodule Prodigy.Core.Data.CmcError do
+  use Ecto.Schema
+  import Ecto.Changeset
+
+  @moduledoc """
+  Schema for CMC error reports (dying gasp messages) from client software
+  """
+
+  schema "cmc_error" do
+    belongs_to(:session, Prodigy.Core.Data.Session)
+    field(:user_id, :string)
+    field(:system_origin, :string)
+    field(:msg_origin, :string)
+    field(:unit_id, :string)
+    field(:error_code, :string)
+    field(:severity_level, :string)
+    field(:error_threshold, :string)
+    field(:error_date, :string)  # Original format from client
+    field(:error_time, :string)  # Original format from client
+    field(:api_event, :string)
+    field(:mem_to_start, :string)
+    field(:dos_version, :string)
+    field(:rs_version, :string)
+    field(:window_id, :string)
+    field(:window_last, :string)
+    field(:selected_id, :string)
+    field(:selected_last, :string)
+    field(:base_id, :string)
+    field(:base_last, :string)
+    field(:keyword, :string)
+    field(:raw_payload, :binary)  # Store the original binary for debugging
+
+    timestamps(updated_at: false)
+  end
+
+  def changeset(cmc_error, attrs) do
+    cmc_error
+    |> cast(attrs, [
+      :session_id, :user_id, :system_origin, :msg_origin, :unit_id,
+      :error_code, :severity_level, :error_threshold, :error_date,
+      :error_time, :api_event, :mem_to_start, :dos_version, :rs_version,
+      :window_id, :window_last, :selected_id, :selected_last,
+      :base_id, :base_last, :keyword, :raw_payload
+    ])
+    |> validate_required([:session_id, :user_id, :error_code, :severity_level])
+  end
+end

apps/core/priv/repo/migrations/20250916010509_create_cmc_error_table.exs

@@ -0,0 +1,37 @@
+defmodule Prodigy.Core.Data.Repo.Migrations.CreateCmcErrorTable do
+  use Ecto.Migration
+
+  def change do
+    create table(:cmc_error) do
+      add :session_id, references(:session, on_delete: :nothing), null: false
+      add :user_id, :string, null: false
+      add :system_origin, :string
+      add :msg_origin, :string
+      add :unit_id, :string
+      add :error_code, :string
+      add :severity_level, :string
+      add :error_threshold, :string
+      add :error_date, :string
+      add :error_time, :string
+      add :api_event, :string
+      add :mem_to_start, :string
+      add :dos_version, :string
+      add :rs_version, :string
+      add :window_id, :string
+      add :window_last, :string
+      add :selected_id, :string
+      add :selected_last, :string
+      add :base_id, :string
+      add :base_last, :string
+      add :keyword, :string
+      add :raw_payload, :binary
+
+      timestamps(updated_at: false)
+    end
+
+    create index(:cmc_error, [:session_id])
+    create index(:cmc_error, [:user_id])
+    create index(:cmc_error, [:error_code])
+    create index(:cmc_error, [:inserted_at])
+  end
+end

apps/server/lib/prodigy/server/context.ex

@@ -21,7 +21,7 @@ defmodule Prodigy.Server.Context do
   persists until the connection is terminated.
   """
 
-  defstruct [:user, :rs_version, :auth_timeout, :messaging]
+  defstruct [:user, :session_id, :rs_version, :auth_timeout, :messaging]
 
   def set_auth_timer do
     Process.send_after(self(), :auth_timeout, Application.fetch_env!(:server, :auth_timeout))

apps/server/lib/prodigy/server/protocol/tcs/tcs_transmitter.ex

@@ -4,7 +4,6 @@ defmodule Prodigy.Server.Protocol.Tcs.Transmitter do
 
   alias Prodigy.Server.Protocol.Tcs.Packet
 
-  @back_pressure_size 6
   @rs_buffer_size 8
   @wack_threshold 4
   # in seconds

apps/server/lib/prodigy/server/router.ex

@@ -170,11 +170,16 @@ defmodule Prodigy.Server.Router do
   end
 
   @impl true
-  def handle_info(:auth_timeout, state) do
+  def handle_info(:auth_timeout, %{context: %Context{user: nil}} = state) do
     Logger.warning("authentication timeout")
     {:stop, :normal, state}
   end
 
+  def handle_info(:auth_timeout, %{context: %Context{user: _user}} = state) do
+    # User is logged in, ignore timeout
+    {:noreply, state}
+  end
+
   @impl GenServer
   def handle_info({:EXIT, _pid, _reason}, state) do
     {:noreply, state}

apps/server/lib/prodigy/server/service/cmc.ex

@@ -21,14 +21,11 @@ defmodule Prodigy.Server.Service.Cmc do
 
   require Logger
 
+  alias Prodigy.Core.Data.{CmcError, Repo}
   alias Prodigy.Server.Context
   alias Prodigy.Server.Protocol.Dia.Packet.{Fm0, Fm9}
 
-  def handle(%Fm0{fm9: %Fm9{payload: payload}} = request, %Context{} = context) do
-    Logger.debug("cmc got #{inspect(request, base: :hex, limit: :infinity)}")
-
-    # TODO insert the error details into the database
-
+  def handle(%Fm0{fm9: %Fm9{payload: payload}}, %Context{} = context) do
     case payload do
         <<
           user_id::binary-size(7),          # right padded with '?'
@@ -56,35 +53,47 @@ defmodule Prodigy.Server.Service.Cmc do
           base_last::binary-size(4),        # '0104' typical
           keyword::binary-size(13)          # 'QUOTE TRACK  ' typical
         >> ->
-          msg = """
-          CMC FM9 Error reported by Reception System
+          # Insert the CMC error into the database
+          cmc_result = %CmcError{}
+          |> CmcError.changeset(%{
+            session_id: context.session_id,  # Assuming session_id is in context
+            user_id: user_id,
+            system_origin: system_origin,
+            msg_origin: msg_origin,
+            unit_id: unit_id,
+            error_code: error_code,
+            severity_level: severity_level,
+            error_threshold: error_threshold,
+            error_date: date,
+            error_time: time,
+            api_event: api_event,
+            mem_to_start: mem_to_start,
+            dos_version: dos_version,
+            rs_version: rs_version,
+            window_id: window_id,
+            window_last: window_last,
+            selected_id: selected_id,
+            selected_last: selected_last,
+            base_id: base_id,
+            base_last: base_last,
+            keyword: keyword,
+            raw_payload: payload
+          })
+          |> Repo.insert()
+
+          case cmc_result do
+            {:ok, _} ->
+              Logger.error("CMC error logged from #{user_id}: code=#{error_code}, severity=#{severity_level}")
+
+            {:error, changeset} ->
+              Logger.error("Failed to log CMC error: #{inspect(changeset.errors)}")
+          end
+
+      _ ->
+        Logger.warning("CMC received malformed error payload: #{inspect(payload, base: :hex)}")
 
-                  User ID: #{user_id}
-            System Origin: #{system_origin}
-           Message Origin: #{msg_origin}
-                  Unit ID: #{unit_id}
-               Error Code: #{error_code}
-           Severity Level: #{severity_level}
-          Error Threshold: #{error_threshold}
-                     Date: #{date}
-                     Time: #{time}
-                API Event: #{api_event}
-             Starting RAM: #{mem_to_start}
-              DOS Version: #{dos_version}
-               RS Version: #{rs_version}
-                Window ID: #{window_id}
-              Window Last: #{inspect window_last, base: :hex}
-              Selected ID: #{selected_id}
-            Selected Last: #{inspect selected_last, base: :hex}
-                  Base ID: #{base_id}
-                Base Last: #{inspect base_last, base: :hex}
-                  Keyword: #{keyword}
-          """
-          Logger.warning(msg)
-        _ ->
-          Logger.warning("CMC received message in unknown format: #{inspect payload, base: :hex, limit: :infinity}")
-      end
+    end
 
     {:ok, context, <<>>}
   end
-end
+end

apps/server/lib/prodigy/server/service/enrollment.ex

@@ -85,7 +85,7 @@ defmodule Prodigy.Server.Service.Enrollment do
     )
 
     response =
-      Logon.make_response_payload({Logon.Status.SUCCESS, user})
+      Logon.make_response_payload({Logon.Status.SUCCESS, user, context.session_id})
       |> Fm0.make_response(request)
       |> DiaPacket.encode()
 

apps/server/lib/prodigy/server/service/logon.ex

@@ -65,7 +65,7 @@ defmodule Prodigy.Server.Service.Logon do
     end
   end
 
-  def make_response_payload({Status.SUCCESS, user}) do
+  def make_response_payload({Status.SUCCESS, user, _session_id}) do
     now = Calendar.DateTime.now_utc()
     # TODO refactor to use Timex
     date = now |> Calendar.strftime("%m%d%y")
@@ -146,7 +146,7 @@ defmodule Prodigy.Server.Service.Logon do
     res
   end
 
-  def make_response_payload({status, _}) do
+  def make_response_payload({status, _, _}) do
     now = Calendar.DateTime.now_utc()
     date = now |> Calendar.strftime("%m%d%y")
     time = now |> Calendar.strftime("%H%M%S")
@@ -268,23 +268,23 @@ defmodule Prodigy.Server.Service.Logon do
         end
 
         case SessionManager.create_session(user, status, version) do
-          {:ok, _db_session} ->
+          {:ok, db_session} ->
             case enrollment_status do
-              true -> {Status.SUCCESS, user}
-              {:enroll_subscriber, user} -> {Status.ENROLL_SUBSCRIBER, user}
-              {:enroll_other, user} -> {Status.ENROLL_OTHER, user}
+              true -> {Status.SUCCESS, user, db_session.id}
+              {:enroll_subscriber, user} -> {Status.ENROLL_SUBSCRIBER, user, db_session.id}
+              {:enroll_other, user} -> {Status.ENROLL_OTHER, user, db_session.id}
             end
           {:error, :concurrency_exceeded} ->
             Logger.warning("User #{user.id} attempted logon, but exceeded concurrency limit")
-            {Status.ID_IN_USE, nil}
+            {Status.ID_IN_USE, nil, nil}
         end
       else
-        :bad_version -> {Status.BAD_VERSION, nil}
-        :bad_password -> {Status.BAD_PASSWORD, nil}
-        {:enroll_subscriber, user} -> {Status.ENROLL_SUBSCRIBER, user}
-        {:enroll_other, user} -> {Status.ENROLL_OTHER, user}
-        :id_in_use -> {Status.ID_IN_USE, nil}
-        _ -> {Status.ACCOUNT_PROBLEM, nil}
+        :bad_version -> {Status.BAD_VERSION, nil, nil}
+        :bad_password -> {Status.BAD_PASSWORD, nil, nil}
+#        {:enroll_subscriber, user} -> {Status.ENROLL_SUBSCRIBER, user}
+#        {:enroll_other, user} -> {Status.ENROLL_OTHER, user}
+        :id_in_use -> {Status.ID_IN_USE, nil, nil}
+        _ -> {Status.ACCOUNT_PROBLEM, nil, nil}
       end
 
     response =
@@ -293,20 +293,20 @@ defmodule Prodigy.Server.Service.Logon do
       |> Packet.encode()
 
     case result do
-      {Status.SUCCESS, user} ->
+      {Status.SUCCESS, user, session_id} ->
         Context.cancel_auth_timer(auth_timeout)
         Logger.info("User #{user_id} logged on (Normal)")
-        {:ok, %Context{user: user, rs_version: version}, response}
+        {:ok, %Context{user: user, session_id: session_id, rs_version: version}, response}
 
-      {Status.ENROLL_SUBSCRIBER, user} ->
+      {Status.ENROLL_SUBSCRIBER, user, session_id} ->
         Context.cancel_auth_timer(auth_timeout)
         Logger.info("User #{user_id} logged on (Enroll Subscriber)")
-        {:ok, %Context{user: user, rs_version: version}, response}
+        {:ok, %Context{user: user, session_id: session_id, rs_version: version}, response}
 
-      {Status.ENROLL_OTHER, user} ->
+      {Status.ENROLL_OTHER, user, session_id} ->
         Context.cancel_auth_timer(auth_timeout)
         Logger.info("User #{user_id} logged on (Enroll Other)")
-        {:ok, %Context{user: user, rs_version: version}, response}
+        {:ok, %Context{user: user, session_id: session_id, rs_version: version}, response}
 
       _ ->
         {:error, context, response}

apps/server/test/prodigy/server/protocol/tcs/tcs_transmitter_test.exs

@@ -4,7 +4,6 @@ defmodule Prodigy.Server.Protocol.Tcs.Transmitter.Test do
   import Cachex.Spec
 
   alias Prodigy.Server.Protocol.Tcs.Transmitter
-  alias Prodigy.Server.Protocol.Tcs.Packet
 
   setup do
     Cachex.start_link(:transmit, [
@@ -64,7 +63,7 @@ defmodule Prodigy.Server.Protocol.Tcs.Transmitter.Test do
 
   test "sends wackpk after interval", %{transmitter: pid} do
     Transmitter.transmit_packet(pid, "test_packet", 1)
-    :timer.sleep(11_000) # Wait longer than @wack_interval
+#    :timer.sleep(11_000) # Wait longer than @wack_interval
     # assert_receive {:send, _wackpk}
   end
 end

apps/server/test/prodigy/server/service/cmc_test.exs

@@ -16,25 +16,54 @@
 defmodule Prodigy.Server.Service.Cmc.Test do
   @moduledoc false
   use Prodigy.Server.RepoCase
-
-  import ExUnit.CaptureLog
+  import Server
+  import Ecto.Changeset
 
   require Logger
 
+  alias Prodigy.Core.Data.{CmcError, Household, Repo, Session, User}
+  alias Prodigy.Server.Protocol.Dia.Packet, as: DiaPacket
   alias Prodigy.Server.Protocol.Dia.Packet.{Fm0, Fm9}
   alias Prodigy.Server.Protocol.Dia.Packet.Fm9.{Flags, Function, Reason}
   alias Prodigy.Server.Router
+  alias Prodigy.Server.Service.Logon.Status
 
 #  @moduletag :capture_log
 
+  @today DateTime.to_date(DateTime.utc_now())
+
   setup do
     {:ok, router_pid} = GenServer.start_link(Router, nil)
 
     [router_pid: router_pid]
   end
 
   test "error report", context do
-    fm0 = %Fm0{
+    cmc_error_count =
+      CmcError
+      |> Repo.aggregate(:count)
+
+    assert cmc_error_count == 0
+
+    sessions =
+      Session
+      |> Repo.all()
+
+    assert(length(sessions) == 0)
+
+    %Household{id: "AAAA99", enabled_date: @today}
+    |> change
+    |> put_assoc(:users, [
+      %User{id: "AAAA99A", gender: "M", date_enrolled: @today}
+      |> User.changeset(%{password: "test"})
+    ])
+    |> Repo.insert()
+
+    {:ok, response} = logon(context.router_pid, "AAAA99A", "test", "06.03.10")
+    {:ok, %Fm0{payload: <<status, _rest::binary>>}} = DiaPacket.decode(response)
+    assert status == Status.SUCCESS.value()
+
+    Router.handle_packet(context.router_pid, %Fm0{
       concatenated: true,
       src: 0x0,
       dest: 0x020200,
@@ -89,12 +118,12 @@ defmodule Prodigy.Server.Service.Cmc.Test do
           "QUOTE TRACK  "
         >>
       }
-    }
+    })
 
-    assert capture_log([level: :warning], fn ->
-           Router.handle_packet(context.router_pid, fm0)
-    end) =~ "CMC FM9"
+    cmc_error_count =
+      CmcError
+      |> Repo.aggregate(:count)
 
-    # TODO assert the message was inserted into the database
+    assert cmc_error_count == 1
   end
 end