chore: consolidate error/warning logging

lib/screens/audio.ex

@@ -1,7 +1,7 @@
 defmodule Screens.Audio do
   @moduledoc false
 
-  require Logger
+  alias Screens.Log
 
   @lexicon_names ["mbtalexicon"]
 
@@ -17,24 +17,8 @@ defmodule Screens.Audio do
         {:ok, audio_data}
 
       {:error, error} ->
-        report_error(ssml_string, error, log_meta)
+        Log.error("synthesize_ssml_failed", [error: error, string: ssml_string] ++ log_meta)
         :error
     end
   end
-
-  defp report_error(ssml_string, error, meta) do
-    Logger.error(
-      "synthesize_ssml_failed string=#{inspect(ssml_string)} error=#{inspect(error)}",
-      meta
-    )
-
-    _ =
-      if meta[:is_screen] do
-        Sentry.capture_message("synthesize_ssml_failed",
-          extra: Enum.into(meta, %{error: error, string: ssml_string})
-        )
-      end
-
-    nil
-  end
 end

lib/screens/cache/engine.ex

@@ -51,10 +51,4 @@ defmodule Screens.Cache.Engine do
   Returns the number of milliseconds to wait between each `update_table` call.
   """
   @callback update_interval_ms() :: non_neg_integer
-
-  @doc """
-  Returns the number of minutes to wait before changing the log level
-  for failed `update_table` calls from warning to error.
-  """
-  @callback update_failure_error_log_threshold_minutes() :: non_neg_integer
 end

lib/screens/cache/owner.ex

@@ -9,7 +9,7 @@ defmodule Screens.Cache.Owner do
   or what kinds of queries will be made against it.
   """
   alias Screens.Cache.Engine
-  require Logger
+  alias Screens.Log
 
   use GenServer
 
@@ -18,7 +18,6 @@ defmodule Screens.Cache.Owner do
           name: any(),
           update_table: (Engine.table_version() -> Engine.update_result()),
           update_interval_ms: non_neg_integer,
-          update_failure_error_log_threshold_minutes: non_neg_integer,
 
           ### Cache state
           table_version: Engine.table_version(),
@@ -27,12 +26,7 @@ defmodule Screens.Cache.Owner do
           status: :ok | :error
         }
 
-  @enforce_keys [
-    :name,
-    :update_table,
-    :update_interval_ms,
-    :update_failure_error_log_threshold_minutes
-  ]
+  @enforce_keys [:name, :update_table, :update_interval_ms]
   defstruct @enforce_keys ++ [table_version: nil, retry_count: 0, status: :error]
 
   ### Client
@@ -47,9 +41,7 @@ defmodule Screens.Cache.Owner do
     cache_opts = %{
       name: engine.name(),
       update_table: &engine.update_table/1,
-      update_interval_ms: engine.update_interval_ms(),
-      update_failure_error_log_threshold_minutes:
-        engine.update_failure_error_log_threshold_minutes()
+      update_interval_ms: engine.update_interval_ms()
     }
 
     GenServer.start_link(__MODULE__, cache_opts, gen_server_opts)
@@ -73,9 +65,7 @@ defmodule Screens.Cache.Owner do
     init_state = %__MODULE__{
       update_table: cache_opts.update_table,
       name: cache_opts.name,
-      update_interval_ms: cache_opts.update_interval_ms,
-      update_failure_error_log_threshold_minutes:
-        cache_opts.update_failure_error_log_threshold_minutes
+      update_interval_ms: cache_opts.update_interval_ms
     }
 
     state = do_update(init_state)
@@ -169,26 +159,12 @@ defmodule Screens.Cache.Owner do
   end
 
   defp error_state(%{status: :error} = state) do
-    _ = Logger.error("cache_init_error table_name=#{state.name}")
-
+    Log.error("cache_init_error", table_name: state.name)
     %{state | retry_count: state.retry_count + 1}
   end
 
   defp error_state(state) do
-    log_message = "cache_update_error table_name=#{state.name} retry_count=#{state.retry_count}"
-
-    if log_as_error?(state) do
-      Logger.error(log_message)
-    else
-      Logger.warning(log_message)
-    end
-
+    Log.error("cache_update_error", table_name: state.name, retry_count: state.retry_count)
     %{state | retry_count: state.retry_count + 1}
   end
-
-  defp log_as_error?(state) do
-    threshold_ms = state.update_failure_error_log_threshold_minutes * 60_000
-
-    state.retry_count * state.update_interval_ms >= threshold_ms
-  end
 end

lib/screens/config/cache/engine.ex

@@ -37,9 +37,6 @@ defmodule Screens.Config.Cache.Engine do
   @impl true
   def update_interval_ms, do: 5_000
 
-  @impl true
-  def update_failure_error_log_threshold_minutes, do: 2
-
   @spec config_to_table_entries(Config.t(), DateTime.t() | nil) :: Cache.table_contents()
   defp config_to_table_entries(config, last_deploy_timestamp) do
     screen_entries =

lib/screens/departures/departure.ex

@@ -1,8 +1,7 @@
 defmodule Screens.Departures.Departure do
   @moduledoc false
 
-  require Logger
-
+  alias Screens.Log
   alias Screens.Predictions.Prediction
   alias Screens.Schedules.Schedule
   alias Screens.Trips.Trip
@@ -410,8 +409,10 @@ defmodule Screens.Departures.Departure do
       expected_route_ids = ["64", "120"]
 
       if length(route_ids) > 1 and !Enum.member?(expected_route_ids, route_id) do
-        Logger.warning(
-          "log_unexpected_groups found #{length(route_ids)} predictions on trip #{trip_id} for route #{Enum.at(route_ids, 0)}"
+        Log.warning("log_unexpected_groups",
+          predictions: length(route_ids),
+          route: Enum.at(route_ids, 0),
+          trip: trip_id
         )
       end
     end)

lib/screens/log.ex

@@ -0,0 +1,20 @@
+defmodule Screens.Log do
+  @moduledoc "Conveniences for logging to Splunk and Sentry."
+
+  require Logger
+
+  def error(tag, data \\ []), do: log(:error, tag, data)
+  def warning(tag, data \\ []), do: log(:warning, tag, data)
+
+  @spec log(:error | :warning, String.t(), Enumerable.t({String.Chars.t(), term()})) :: :ok
+  defp log(level, tag, data) do
+    Logger.log(
+      level,
+      tag <> " " <> Enum.map_join(data, " ", fn {key, value} -> "#{key}=#{inspect(value)}" end)
+    )
+
+    _ = Sentry.capture_message(tag, extra: Map.new(data), level: level, result: :none)
+
+    :ok
+  end
+end

lib/screens/route_patterns/route_direction_stops.ex

@@ -1,18 +1,13 @@
 defmodule Screens.RoutePatterns.RouteDirectionStops do
   @moduledoc false
 
-  require Logger
+  alias Screens.Log
 
   def parse_result(%{"data" => data, "included" => included}, route_id) do
     included_data = parse_included_data(included)
     parse_data(data, included_data, route_id)
   end
 
-  def parse_result(_, _) do
-    Logger.warning("Unrecognized format of route_pattern data.")
-    :error
-  end
-
   defp parse_included_data(data) do
     data
     |> Enum.map(fn item ->
@@ -62,17 +57,16 @@ defmodule Screens.RoutePatterns.RouteDirectionStops do
          },
          included_data
        ) do
-    # The only way this function output an empty array is if the trip data has an empty stop list
-    # This happens occasionally in dev-green
     parsed =
       included_data
       |> Map.get({"trip", trip_id})
       |> Enum.map(fn stop_id -> Map.get(included_data, {"stop", stop_id}) end)
 
     case parsed do
-      # If `trip` is present, but the stop array is empty, there's a problem with the trip in the API
       [] ->
-        Logger.warning("Trip data doesn't contain stop ids. trip_id: #{trip_id}")
+        # Happens sometimes in API dev (only?). If a trip has no stops, there is something wrong
+        # with the data.
+        Log.warning("route_pattern_empty_stops", trip_id: trip_id)
         :error
 
       _ ->

lib/screens/screens_by_alert/memcache.ex

@@ -26,11 +26,11 @@ defmodule Screens.ScreensByAlert.Memcache do
   }
   ```
   """
+
+  alias Screens.Log
   alias Screens.ScreensByAlert.Memcache.TaskSupervisor
   alias Screens.Util
 
-  require Logger
-
   @behaviour Screens.ScreensByAlert.Behaviour
 
   @server __MODULE__.Server
@@ -83,7 +83,7 @@ defmodule Screens.ScreensByAlert.Memcache do
         Map.merge(default_map, found_items)
 
       {:error, message} ->
-        Logger.warning("[get_screens_by_alert memcache error] message=\"#{message}\"")
+        log_warning(message, :get_screens_by_alert)
         # Should we return an error tuple instead of the default map?
         default_map
     end
@@ -100,26 +100,20 @@ defmodule Screens.ScreensByAlert.Memcache do
         Map.merge(default_map, found_items)
 
       {:error, message} ->
-        Logger.warning("[get_screens_last_updated memcache error] message=\"#{message}\"")
+        log_warning(message, :get_screens_last_updated)
         # Should we return an error tuple instead of the default map?
         default_map
     end
   end
 
   defp update_screens_last_updated_key(screen_id, now) do
-    set_result =
-      Memcache.set(@server, last_updated_key(screen_id), now, ttl: @screens_last_updated_ttl)
+    case Memcache.set(@server, last_updated_key(screen_id), now, ttl: @screens_last_updated_ttl) do
+      {:error, message} ->
+        log_warning(message, :update_screens_last_updated_key, screen_id: screen_id)
 
-    _ =
-      case set_result do
-        {:error, message} ->
-          Logger.warning(
-            "[put_data screens_last_updated memcache error] screen_id=#{screen_id} message=#{message}"
-          )
-
-        _ ->
-          :ok
-      end
+      _ ->
+        :ok
+    end
   end
 
   # Creates or updates the cache item for the given alert ID with the given screen ID, retrying until success.
@@ -141,9 +135,7 @@ defmodule Screens.ScreensByAlert.Memcache do
 
     case cas_result do
       {:error, message} ->
-        Logger.warning(
-          "[put_data screens_by_alert memcache error] alert_id=#{alert_id} screen_id=#{screen_id} message=#{message}"
-        )
+        log_warning(message, :update_alert_key, alert_id: alert_id, screen_id: screen_id)
 
       _ ->
         :ok
@@ -185,4 +177,8 @@ defmodule Screens.ScreensByAlert.Memcache do
 
   defp key_to_id(@screens_by_alert_key_prefix <> alert_id), do: alert_id
   defp key_to_id(@screens_last_updated_key_prefix <> screen_id), do: screen_id
+
+  defp log_warning(message, source, extra \\ []) do
+    Log.warning("memcache_error", [message: message, source: source] ++ extra)
+  end
 end

lib/screens/signs_ui_config/cache/engine.ex

@@ -23,7 +23,4 @@ defmodule Screens.SignsUiConfig.Cache.Engine do
 
   @impl true
   def update_interval_ms, do: 60_000
-
-  @impl true
-  def update_failure_error_log_threshold_minutes, do: 2
 end

lib/screens/v2/candidate_generator/dup/alerts.ex

@@ -5,6 +5,7 @@ defmodule Screens.V2.CandidateGenerator.Dup.Alerts do
 
   alias Screens.Alerts.Alert
   alias Screens.LocationContext
+  alias Screens.Log
   alias Screens.Routes.Route
   alias Screens.Stops.Stop
   alias Screens.V2.LocalizedAlert
@@ -159,14 +160,13 @@ defmodule Screens.V2.CandidateGenerator.Dup.Alerts do
       alert.effect in [:shuttle, :suspension] and
         Enum.any?(alert.informed_entities, &(&1.direction_id in 0..1))
 
-    _ =
-      if directional do
-        Sentry.capture_message(
-          "DUP logic encountered a directional shuttle or suspension alert. Discarding.",
-          level: "warning",
-          extra: %{alert_id: alert.id, alert_effect: alert.effect}
-        )
-      end
+    if directional do
+      Log.warning(
+        "dup_discarding_directional_alert",
+        alert_id: alert.id,
+        alert_effect: alert.effect
+      )
+    end
 
     directional
   end

lib/screens/v2/candidate_generator/dup/departures.ex

@@ -4,6 +4,7 @@ defmodule Screens.V2.CandidateGenerator.Dup.Departures do
   require Logger
 
   alias Screens.Alerts.Alert
+  alias Screens.Log
   alias Screens.Routes.Route
   alias Screens.Util
   alias Screens.V2.CandidateGenerator.Widgets
@@ -534,11 +535,12 @@ defmodule Screens.V2.CandidateGenerator.Dup.Departures do
          _first_schedule_tomorrow,
          route_id,
          direction_id,
-         now
+         _now
        )
        when is_nil(first_schedule_today) or is_nil(last_schedule_today) do
-    Logger.info(
-      "[get_overnight_schedules_for_section] No schedules for today found. route_id=#{route_id} direction_id=#{direction_id} now=#{now}"
+    Log.warning("dup_overnight_no_first_last_schedule",
+      route_id: route_id,
+      direction_id: direction_id
     )
 
     nil
@@ -577,8 +579,9 @@ defmodule Screens.V2.CandidateGenerator.Dup.Departures do
        ) do
     cond do
       DateTime.compare(now, first_schedule_tomorrow.departure_time) == :gt ->
-        Logger.warning(
-          "[get_overnight_schedules_for_section] now is after first_schedule_tomorrow. route_id=#{route_id} direction_id=#{direction_id} now=#{now}"
+        Log.warning("dup_overnight_after_first_schedule",
+          route_id: route_id,
+          direction_id: direction_id
         )
 
         nil