More logging

config/dev.exs

@@ -60,7 +60,9 @@ config :voomex, VoomexWeb.Endpoint,
     ]
   ]
 
-config :logger, :console, format: "$date $time $metadata[$level] $message\n"
+config :logger, :console,
+  format: "$date $time $metadata[$level] $message\n",
+  metadata: [:pid]
 
 # Set a higher stacktrace during development. Avoid configuring such
 # in production as building large stacktraces may be expensive.

config/releases.exs

@@ -90,8 +90,8 @@ config :voomex, Oban,
   queues: [to_smpp: 10, to_rapidsms: 10]
 
 config :logger, :console,
-  level: :info,
+  level: :debug,
   format: "$date $time $metadata[$level] $message\n",
-  metadata: [:request_id]
+  metadata: [:request_id, :pid]
 
 config :phoenix, :json_library, Jason

lib/voomex/smpp/connection.ex

@@ -37,11 +37,37 @@ defmodule Voomex.SMPP.Connection do
     {:via, Registry, {Voomex.SMPP.ConnectionRegistry, {mno, source_addr}}}
   end
 
+  def transport_name(connection) do
+    "#{connection.mno}_#{connection.source_addr}"
+  end
+
   def start_link(connection) do
     # Start the MNO connection (but don't bind yet)
-    SMPPEX.ESME.start_link(connection.host, connection.port, {__MODULE__, connection},
-      esme_opts: [enquire_link_limit: connection.enquire_link_limit]
-    )
+    # copy/paste SMPPEX.ESME.start_link in order to use our LogTransportSession instead of Session
+    mod_with_args = {__MODULE__, connection}
+    host = connection.host
+    port = connection.port
+    transport = :ranch_tcp
+    timeout = 5000
+    sock_opts = [:binary, {:packet, 0}, {:active, :once}]
+    esme_opts = [enquire_link_limit: connection.enquire_link_limit]
+
+    case transport.connect(SMPPEX.Compat.to_charlist(host), port, sock_opts, timeout) do
+      {:ok, socket} ->
+        session_opts = {Voomex.SMPP.LogTransportSession, [mod_with_args, esme_opts], :esme}
+
+        case SMPPEX.TransportSession.start_link(socket, transport, session_opts) do
+          {:ok, pid} ->
+            {:ok, pid}
+
+          {:error, _} = error ->
+            transport.close(socket)
+            error
+        end
+
+      {:error, _} = error ->
+        error
+    end
   end
 
   # GenServer implementation
@@ -81,34 +107,15 @@ defmodule Voomex.SMPP.Connection do
     }
 
     pdu = SMPPEX.Pdu.Factory.bind_transceiver(connection.system_id, connection.password, opts)
-    Logger.info("Outgoing bind_transceiver pdu: #{inspect(pdu)}")
 
     {:noreply, [pdu], state}
   end
 
-  @impl true
-  def handle_resp(pdu, _original_pdu, state) do
-    case SMPPEX.Pdu.command_name(pdu) do
-      :submit_sm_resp ->
-        Logger.info("MNO submit_sm_resp: #{inspect(pdu)}")
-        {:ok, state}
-
-      :bind_transceiver_resp ->
-        Logger.info("MNO bind_transceiver_resp: #{inspect(pdu)}")
-        {:ok, state}
-
-      _ ->
-        Logger.info("MNO other response received: #{inspect(pdu)}")
-        {:ok, state}
-    end
-  end
-
   @impl true
   def handle_pdu(pdu, state) do
     case SMPPEX.Pdu.command_name(pdu) do
       :deliver_sm ->
         :telemetry.execute([:voomex, :mno, :deliver_sm], %{count: 1}, state.connection)
-        Logger.info("SMPP incoming: #{inspect(pdu)}", type: :smpp)
         RapidSMS.send_to_rapidsms(pdu, state.connection.mno)
 
       _ ->
@@ -121,7 +128,6 @@ defmodule Voomex.SMPP.Connection do
   @impl true
   def handle_call({:submit_sm, dest_addr, message}, _from, state) do
     :telemetry.execute([:voomex, :mno, :submit_sm], %{count: 1}, state.connection)
-    Logger.info("SMPP outgoing: #{inspect(message)}", type: :smpp)
 
     # ref_num is a 2 byte number which must be the same for all parts of a split message
     ref_num = rem(state.ref_num + 1, 0xFF)

lib/voomex/smpp/logtransport.ex

@@ -0,0 +1,75 @@
+defmodule Voomex.SMPP.LogTransportSession do
+  @moduledoc """
+  Proxy implementation of TransportSession that adds logging at various steps, then
+  passes processing to SMPPEX.Session.
+  """
+
+  require Logger
+  @behaviour SMPPEX.TransportSession
+
+  alias Voomex.SMPP.{Connection, PDU}
+
+  @impl true
+  def init(socket, transport, opts), do: SMPPEX.Session.init(socket, transport, opts)
+
+  @impl true
+  def handle_pdu({:pdu, pdu} = pdu_parse_result, state) do
+    log("INCOMING: #{inspect(PDU.pdu_for_log(pdu))}", state)
+    SMPPEX.Session.handle_pdu(pdu_parse_result, state)
+  end
+
+  @impl true
+  def handle_pdu({:unparsed_pdu, raw_pdu, error} = pdu_parse_result, state) do
+    log("INCOMING unparsed handle_pdu: #{inspect(raw_pdu)} : #{inspect(error)}", state)
+    SMPPEX.Session.handle_pdu(pdu_parse_result, state)
+  end
+
+  @impl true
+  def handle_send_pdu_result(pdu, send_pdu_result, state) do
+    log("OUTGOING: #{inspect(PDU.pdu_for_log(pdu))}", state)
+    SMPPEX.Session.handle_send_pdu_result(pdu, send_pdu_result, state)
+  end
+
+  @impl true
+  def handle_call(request, from, state) do
+    log("handle_call: #{inspect(request)}", state)
+    SMPPEX.Session.handle_call(request, from, state)
+  end
+
+  @impl true
+  def handle_cast(request, state) do
+    log("handle_cast: #{inspect(request)}", state)
+    SMPPEX.Session.handle_cast(request, state)
+  end
+
+  @impl true
+  def handle_info(request, state), do: SMPPEX.Session.handle_info(request, state)
+
+  @impl true
+  def handle_socket_closed(state) do
+    log("SOCKET CLOSED", state)
+    SMPPEX.Session.handle_socket_closed(state)
+  end
+
+  @impl true
+  def handle_socket_error(error, state) do
+    log("SOCKET ERROR", state)
+    SMPPEX.Session.handle_socket_error(error, state)
+  end
+
+  @impl true
+  def terminate(reason, state) do
+    log("TERMINATE #{reason}", state)
+    SMPPEX.Session.terminate(reason, state)
+  end
+
+  @impl true
+  def code_change(old_vsn, state, extra) do
+    log("CODE_CHANGE", state)
+    SMPPEX.Session.code_change(old_vsn, state, extra)
+  end
+
+  defp log(message, state) do
+    Logger.info("#{Connection.transport_name(state.module_state.connection)} #{message}")
+  end
+end

lib/voomex/smpp/monitor.ex

@@ -10,7 +10,7 @@ defmodule Voomex.SMPP.Monitor do
 
   require Logger
 
-  alias Voomex.SMPP.TetherSupervisor
+  alias Voomex.SMPP.{Connection, TetherSupervisor}
 
   @connection_boot_delay 1_500
   @connection_retry_delay 10_000
@@ -66,12 +66,16 @@ defmodule Voomex.SMPP.Monitor do
     case TetherSupervisor.start_connection(connection) do
       {:ok, pid} ->
         Process.link(pid)
-        Logger.debug("Connected to MNO: #{connection.mno}", tag: :smpp)
+        Logger.debug("Connected to MNO: #{Connection.transport_name(connection)}", tag: :smpp)
 
         {:noreply, update_connection_pid(state, connection, pid)}
 
       {:error, error} ->
-        Logger.debug("Connection to MNO failed: #{inspect(error)}", tag: :smpp)
+        Logger.debug(
+          "Connection to MNO #{Connection.transport_name(connection)} failed: #{inspect(error)}",
+          tag: :smpp
+        )
+
         restart_connection(connection)
         {:noreply, state}
     end

lib/voomex/smpp/pdu.ex

@@ -43,4 +43,18 @@ defmodule Voomex.SMPP.PDU do
     |> SMPPEX.Pdu.set_mandatory_field(:service_type, connection.service_type)
     |> SMPPEX.Pdu.set_mandatory_field(:data_coding, connection.data_coding)
   end
+
+  @doc """
+  Return a pdu formatted for logging.
+
+  We change command_id and command_status from integers to their code names and then
+  drop the ref field, which we aren't using.
+  """
+  def pdu_for_log(pdu) do
+    pdu
+    |> Map.from_struct()
+    |> Map.put(:command_id, SMPPEX.Pdu.command_name(pdu))
+    |> Map.put(:command_status, SMPPEX.Pdu.Errors.format(pdu.command_status))
+    |> Map.drop([:ref])
+  end
 end

lib/voomex/smpp/supervisor.ex

@@ -4,7 +4,7 @@ defmodule Voomex.SMPP.Supervisor do
   """
 
   use Supervisor
-  alias Voomex.SMPP.{Monitor, TetherSupervisor}
+  alias Voomex.SMPP.{Connection, Monitor, TetherSupervisor}
 
   @doc false
   def start_link(opts) do
@@ -18,10 +18,8 @@ defmodule Voomex.SMPP.Supervisor do
 
     children =
       Enum.map(connections, fn connection ->
-        transport_name = "#{connection.mno}_smpp_transport_#{connection.source_addr}"
-
         Supervisor.child_spec({TetherSupervisor, [name: TetherSupervisor.name(connection)]},
-          id: transport_name
+          id: Connection.transport_name(connection)
         )
       end)
 

lib/voomex/telemetry.ex

@@ -72,8 +72,7 @@ defmodule Voomex.Telemetry.Reporters do
 
   def handle_continue(:initialize, state) do
     reporters = [
-      Voomex.ObanReporter,
-      Voomex.SMPPEXReporter
+      Voomex.ObanReporter
     ]
 
     Enum.each(reporters, fn reporter ->

mix.exs

@@ -46,7 +46,7 @@ defmodule Voomex.MixProject do
       {:phoenix_pubsub, "~> 1.1"},
       {:plug_cowboy, "~> 2.0"},
       {:postgrex, ">= 0.0.0"},
-      {:smppex, github: "caktus/smppex", branch: "add-telemetry"},
+      {:smppex, "~> 2.0"},
       {:telemetry_poller, "~> 0.4"},
       {:telemetry_metrics, "~> 0.4"}
     ]

mix.lock

@@ -28,7 +28,7 @@
   "poolboy": {:hex, :poolboy, "1.5.2", "392b007a1693a64540cead79830443abf5762f5d30cf50bc95cb2c1aaafa006b", [:rebar3], [], "hexpm", "dad79704ce5440f3d5a3681c8590b9dc25d1a561e8f5a9c995281012860901e3"},
   "postgrex": {:hex, :postgrex, "0.15.3", "5806baa8a19a68c4d07c7a624ccdb9b57e89cbc573f1b98099e3741214746ae4", [:mix], [{:connection, "~> 1.0", [hex: :connection, repo: "hexpm", optional: false]}, {:db_connection, "~> 2.1", [hex: :db_connection, repo: "hexpm", optional: false]}, {:decimal, "~> 1.5", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}], "hexpm", "4737ce62a31747b4c63c12b20c62307e51bb4fcd730ca0c32c280991e0606c90"},
   "ranch": {:hex, :ranch, "1.7.1", "6b1fab51b49196860b733a49c07604465a47bdb78aa10c1c16a3d199f7f8c881", [:rebar3], [], "hexpm", "451d8527787df716d99dc36162fca05934915db0b6141bbdac2ea8d3c7afc7d7"},
-  "smppex": {:git, "https://github.com/caktus/smppex.git", "5eddf5089d483bc1d97a2f5503edb28b401c8e2c", [branch: "add-telemetry"]},
+  "smppex": {:hex, :smppex, "2.3.2", "49ee396ff8f9e6e36e0e839369372b7762df2d1a8e09da122d8e883e421cfd2c", [:mix], [{:ranch, "~> 1.3", [hex: :ranch, repo: "hexpm", optional: false]}], "hexpm", "d4a5624ee8f3861624fea3ebe7413370819b77ba1bca09f0dd8cb644aa8c72aa"},
   "telemetry": {:hex, :telemetry, "0.4.1", "ae2718484892448a24470e6aa341bc847c3277bfb8d4e9289f7474d752c09c7f", [:rebar3], [], "hexpm", "4738382e36a0a9a2b6e25d67c960e40e1a2c95560b9f936d8e29de8cd858480f"},
   "telemetry_metrics": {:hex, :telemetry_metrics, "0.4.2", "1de986fad9aa6bf81f8a33ddfd16e5d8ab0dec6272e624eb517c1a92a44d41a9", [:mix], [{:telemetry, "~> 0.4", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "e56ffed2dbe293ab6cf7c94980faeb368cb360662c1927f54fc634a4ca55362e"},
   "telemetry_poller": {:hex, :telemetry_poller, "0.5.0", "4770888ef85599ead39c7f51d6b4b62306e602d96c69b2625d54dea3d9a5204b", [:rebar3], [{:telemetry, "~> 0.4", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "69e4e8e65b0ae077c9e14cd5f42c7cc486de0e07ac6e3409e6f0e52699a7872c"},