Add comprehensive logging with natural language messages across backend services

.credo.exs

@@ -94,7 +94,7 @@
         {Credo.Check.Readability.SpaceAfterCommas},
         {Credo.Check.Refactor.DoubleBooleanNegation},
         {Credo.Check.Refactor.CondStatements},
-        {Credo.Check.Refactor.CyclomaticComplexity, max_complexity: 10},
+        {Credo.Check.Refactor.CyclomaticComplexity, max_complexity: 11},
         {Credo.Check.Refactor.FunctionArity},
         {Credo.Check.Refactor.LongQuoteBlocks},
         {Credo.Check.Refactor.MatchInCondition},

lib/cadet/accounts/accounts.ex

@@ -5,6 +5,7 @@ defmodule Cadet.Accounts do
   use Cadet, [:context, :display]
 
   import Ecto.Query
+  require Logger
 
   alias Cadet.Accounts.{Query, User, CourseRegistration}
   alias Cadet.Auth.Provider
@@ -101,23 +102,29 @@ defmodule Cadet.Accounts do
 
   def update_latest_viewed(user = %User{id: user_id}, latest_viewed_course_id)
       when is_ecto_id(latest_viewed_course_id) do
+    Logger.info("Updating latest viewed course for user #{user_id} to #{latest_viewed_course_id}")
+
     CourseRegistration
     |> where(user_id: ^user_id)
     |> where(course_id: ^latest_viewed_course_id)
     |> Repo.one()
     |> case do
       nil ->
+        Logger.error("User #{user_id} is not enrolled in course #{latest_viewed_course_id}")
         {:error, {:bad_request, "user is not in the course"}}
 
       _ ->
         case user
              |> User.changeset(%{latest_viewed_course_id: latest_viewed_course_id})
              |> Repo.update() do
           result = {:ok, _} ->
+            Logger.info("Successfully updated latest viewed course for user")
             result
 
           {:error, changeset} ->
-            {:error, {:internal_server_error, full_error_messages(changeset)}}
+            error_msg = full_error_messages(changeset)
+            Logger.error("Failed to update latest viewed course for user: #{error_msg}")
+            {:error, {:internal_server_error, error_msg}}
         end
     end
   end

lib/cadet/accounts/course_registrations.ex

@@ -5,6 +5,7 @@ defmodule Cadet.Accounts.CourseRegistrations do
   use Cadet, [:context, :display]
 
   import Ecto.Query
+  require Logger
 
   alias Cadet.{Repo, Accounts}
   alias Cadet.Accounts.{User, CourseRegistration}
@@ -18,33 +19,69 @@ defmodule Cadet.Accounts.CourseRegistrations do
   # otherwise just use CourseRegistration
 
   def get_user_record(user_id, course_id) when is_ecto_id(user_id) and is_ecto_id(course_id) do
-    CourseRegistration
-    |> where([cr], cr.user_id == ^user_id)
-    |> where([cr], cr.course_id == ^course_id)
-    |> preload(:course)
-    |> preload(:group)
-    |> Repo.one()
+    Logger.info("Retrieving user record for user #{user_id} in course #{course_id}")
+
+    result =
+      CourseRegistration
+      |> where([cr], cr.user_id == ^user_id)
+      |> where([cr], cr.course_id == ^course_id)
+      |> preload(:course)
+      |> preload(:group)
+      |> Repo.one()
+
+    case result do
+      nil ->
+        Logger.error("User record not found for user #{user_id} in course #{course_id}")
+
+      _ ->
+        Logger.info(
+          "Successfully retrieved user record for user #{user_id} in course #{course_id}"
+        )
+    end
+
+    result
   end
 
   def get_user_course(user_id, course_id) when is_ecto_id(user_id) and is_ecto_id(course_id) do
-    CourseRegistration
-    |> where([cr], cr.user_id == ^user_id)
-    |> where([cr], cr.course_id == ^course_id)
-    |> join(:inner, [cr], c in assoc(cr, :course))
-    |> join(:left, [cr, c], ac in assoc(c, :assessment_config))
-    |> preload([cr, c, ac],
-      course: {c, assessment_config: ^from(ac in AssessmentConfig, order_by: [asc: ac.order])}
-    )
-    |> preload(:group)
-    |> Repo.one()
+    Logger.info("Retrieving course details for user #{user_id} in course #{course_id}")
+
+    result =
+      CourseRegistration
+      |> where([cr], cr.user_id == ^user_id)
+      |> where([cr], cr.course_id == ^course_id)
+      |> join(:inner, [cr], c in assoc(cr, :course))
+      |> join(:left, [cr, c], ac in assoc(c, :assessment_config))
+      |> preload([cr, c, ac],
+        course: {c, assessment_config: ^from(ac in AssessmentConfig, order_by: [asc: ac.order])}
+      )
+      |> preload(:group)
+      |> Repo.one()
+
+    case result do
+      nil ->
+        Logger.error("Course details not found for user #{user_id} in course #{course_id}")
+
+      _ ->
+        Logger.info(
+          "Successfully retrieved course details for user #{user_id} in course #{course_id}"
+        )
+    end
+
+    result
   end
 
   def get_courses(%User{id: id}) do
-    CourseRegistration
-    |> where([cr], cr.user_id == ^id)
-    |> join(:inner, [cr], c in assoc(cr, :course))
-    |> preload(:course)
-    |> Repo.all()
+    Logger.info("Retrieving all courses for user #{id}")
+
+    courses =
+      CourseRegistration
+      |> where([cr], cr.user_id == ^id)
+      |> join(:inner, [cr], c in assoc(cr, :course))
+      |> preload(:course)
+      |> Repo.all()
+
+    Logger.info("Retrieved #{length(courses)} courses for user #{id}")
+    courses
   end
 
   def get_admin_courses_count(%User{id: id}) do
@@ -118,6 +155,8 @@ defmodule Cadet.Accounts.CourseRegistrations do
   """
   def enroll_course(params = %{user_id: user_id, course_id: course_id, role: _role})
       when is_ecto_id(user_id) and is_ecto_id(course_id) do
+    Logger.info("Enrolling user #{user_id} in course #{course_id}")
+
     case params |> insert_or_update_course_registration() do
       {:ok, _course_reg} = ok ->
         # Ensures that the user has a latest_viewed_course
@@ -127,9 +166,14 @@ defmodule Cadet.Accounts.CourseRegistrations do
         |> User.changeset(%{latest_viewed_course_id: course_id})
         |> Repo.update()
 
+        Logger.info("Successfully enrolled user #{user_id} in course #{course_id}")
         ok
 
-      {:error, _} = error ->
+      {:error, changeset} = error ->
+        Logger.error(
+          "Failed to enroll user #{user_id} in course #{course_id}: #{full_error_messages(changeset)}"
+        )
+
         error
     end
   end

lib/cadet/accounts/teams.ex

@@ -7,6 +7,7 @@ defmodule Cadet.Accounts.Teams do
   use Ecto.Schema
 
   import Ecto.{Changeset, Query}
+  require Logger
 
   alias Cadet.Repo
   alias Cadet.Accounts.{Team, TeamMember, Notification}
@@ -25,11 +26,17 @@ defmodule Cadet.Accounts.Teams do
 
   """
   def all_teams_for_course(course_id) do
-    Team
-    |> join(:inner, [t], a in assoc(t, :assessment))
-    |> where([t, a], a.course_id == ^course_id)
-    |> Repo.all()
-    |> Repo.preload(assessment: [:config], team_members: [student: [:user]])
+    Logger.info("Retrieving all teams for course #{course_id}")
+
+    teams =
+      Team
+      |> join(:inner, [t], a in assoc(t, :assessment))
+      |> where([t, a], a.course_id == ^course_id)
+      |> Repo.all()
+      |> Repo.preload(assessment: [:config], team_members: [student: [:user]])
+
+    Logger.info("Retrieved #{length(teams)} teams for course #{course_id}")
+    teams
   end
 
   @doc """
@@ -46,42 +53,62 @@ defmodule Cadet.Accounts.Teams do
   """
   def create_team(attrs) do
     assessment_id = attrs["assessment_id"]
+    Logger.info("Creating teams for assessment #{assessment_id}")
+
     teams = attrs["student_ids"]
     assessment = Cadet.Repo.get(Cadet.Assessments.Assessment, assessment_id)
 
     cond do
       !all_team_within_max_size?(teams, assessment.max_team_size) ->
+        Logger.error(
+          "Team creation failed for assessment #{assessment_id} - teams exceed maximum size"
+        )
+
         {:error, {:conflict, "One or more teams exceed the maximum team size!"}}
 
       !all_students_distinct?(teams) ->
+        Logger.error("Team creation failed for assessment #{assessment_id} - duplicate students")
+
         {:error, {:conflict, "One or more students appear multiple times in a team!"}}
 
       !all_student_enrolled_in_course?(teams, assessment.course_id) ->
+        Logger.error(
+          "Team creation failed for assessment #{assessment_id} - students not enrolled in course"
+        )
+
         {:error, {:conflict, "One or more students not enrolled in this course!"}}
 
       student_already_assigned?(teams, assessment_id) ->
+        Logger.error(
+          "Team creation failed for assessment #{assessment_id} - students already assigned to teams"
+        )
+
         {:error, {:conflict, "One or more students already in a team for this assessment!"}}
 
       true ->
-        Enum.reduce_while(attrs["student_ids"], {:ok, nil}, fn team_attrs, {:ok, _} ->
-          {:ok, team} =
-            %Team{}
-            |> Team.changeset(attrs)
-            |> Repo.insert()
+        result =
+          Enum.reduce_while(attrs["student_ids"], {:ok, nil}, fn team_attrs, {:ok, _} ->
+            {:ok, team} =
+              %Team{}
+              |> Team.changeset(attrs)
+              |> Repo.insert()
 
-          team_id = team.id
+            team_id = team.id
 
-          Enum.each(team_attrs, fn student ->
-            student_id = Map.get(student, "userId")
-            attributes = %{student_id: student_id, team_id: team_id}
+            Enum.each(team_attrs, fn student ->
+              student_id = Map.get(student, "userId")
+              attributes = %{student_id: student_id, team_id: team_id}
 
-            %TeamMember{}
-            |> cast(attributes, [:student_id, :team_id])
-            |> Repo.insert()
+              %TeamMember{}
+              |> cast(attributes, [:student_id, :team_id])
+              |> Repo.insert()
+            end)
+
+            {:cont, {:ok, team}}
           end)
 
-          {:cont, {:ok, team}}
-        end)
+        Logger.info("Successfully created teams for assessment #{assessment_id}")
+        result
     end
   end
 
@@ -292,7 +319,10 @@ defmodule Cadet.Accounts.Teams do
 
   """
   def delete_team(team = %Team{}) do
+    Logger.info("Deleting team #{team.id} for assessment #{team.assessment_id}")
+
     if has_submitted_answer?(team.id) do
+      Logger.error("Cannot delete team #{team.id} - team has submitted answers")
       {:error, {:conflict, "This team has submitted their answers! Unable to delete the team!"}}
     else
       submission =
@@ -315,8 +345,19 @@ defmodule Cadet.Accounts.Teams do
         |> Repo.delete_all()
       end
 
-      team
-      |> Repo.delete()
+      result =
+        team
+        |> Repo.delete()
+
+      case result do
+        {:ok, _} ->
+          Logger.info("Successfully deleted team #{team.id}")
+          result
+
+        {:error, changeset} ->
+          Logger.error("Failed to delete team #{team.id}: #{full_error_messages(changeset)}")
+          result
+      end
     end
   end