Ensure error logs are always printed

.formatter.exs

@@ -5,7 +5,8 @@ locals_without_parens =
     def_options: 1,
     def_clock: 1,
     def_type_from_list: 1,
-    assert_receive_message: 3
+    assert_receive_message: 3,
+    wrap_with_try: 1
   ]
 
 [

lib/membrane/core/bin.ex

@@ -19,6 +19,7 @@ defmodule Membrane.Core.Bin do
 
   alias Membrane.ResourceGuard
 
+  require Membrane.Core.Macros, as: Macros
   require Membrane.Core.Message
   require Membrane.Core.Telemetry
   require Membrane.Logger
@@ -79,6 +80,12 @@ defmodule Membrane.Core.Bin do
 
   @impl GenServer
   def init(options) do
+    Macros.log_on_error do
+      do_init(options)
+    end
+  end
+
+  defp do_init(options) do
     Process.link(options.parent_supervisor)
     %{name: name, module: module} = options
 
@@ -144,13 +151,17 @@ defmodule Membrane.Core.Bin do
 
   @impl GenServer
   def handle_continue(:setup, state) do
-    state = Parent.LifecycleController.handle_setup(state)
-    {:noreply, state}
+    Macros.log_on_error do
+      state = Parent.LifecycleController.handle_setup(state)
+      {:noreply, state}
+    end
   end
 
   @impl GenServer
   def handle_info(message, state) do
-    do_handle_info(message, state)
+    Macros.log_on_error do
+      do_handle_info(message, state)
+    end
   end
 
   @compile {:inline, do_handle_info: 2}
@@ -162,7 +173,6 @@ defmodule Membrane.Core.Bin do
 
   defp do_handle_info(Message.new(:parent_notification, notification), state) do
     state = Child.LifecycleController.handle_parent_notification(notification, state)
-
     {:noreply, state}
   end
 
@@ -251,22 +261,26 @@ defmodule Membrane.Core.Bin do
   end
 
   @impl GenServer
-  def handle_call(
-        Message.new(:handle_link, [direction, this, other, params]),
-        _from,
-        state
-      ) do
+  def handle_call(request, from, state) do
+    Macros.log_on_error do
+      do_handle_call(request, from, state)
+    end
+  end
+
+  defp do_handle_call(
+         Message.new(:handle_link, [direction, this, other, params]),
+         _from,
+         state
+       ) do
     {reply, state} = PadController.handle_link(direction, this, other, params, state)
     {:reply, reply, state}
   end
 
-  @impl GenServer
-  def handle_call(Message.new(:get_clock), _from, state) do
+  defp do_handle_call(Message.new(:get_clock), _from, state) do
     {:reply, state.synchronization.clock, state}
   end
 
-  @impl GenServer
-  def handle_call(Message.new(:get_child_pid, child_name), _from, state) do
+  defp do_handle_call(Message.new(:get_child_pid, child_name), _from, state) do
     reply =
       with %State{children: %{^child_name => %{pid: child_pid}}} <- state do
         {:ok, child_pid}

lib/membrane/core/callback_handler.ex

@@ -185,8 +185,6 @@ defmodule Membrane.Core.CallbackHandler do
           Error handling actions returned by callback #{inspect(state.module)}.#{callback}
           """)
 
-          log_debug_orginal_error(actions, e, __STACKTRACE__)
-
           reraise e, __STACKTRACE__
       end
 
@@ -197,32 +195,14 @@ defmodule Membrane.Core.CallbackHandler do
         rescue
           e ->
             Membrane.Logger.error("""
-            Error handling action #{inspect(action)} returned by callback #{inspect(state.module)}.#{callback}
+            Error handling action returned by callback #{inspect(state.module)}.#{callback}.
+            Action: #{inspect(action, pretty: true)}
             """)
 
-            log_debug_orginal_error(action, e, __STACKTRACE__)
-
             reraise e, __STACKTRACE__
         end
       end)
 
     handler_module.handle_end_of_actions(state)
   end
-
-  # We log it, because sometimes, for some reason, crashing process doesn't cause
-  # printing error logs on stderr, so this debug log allows us to get some info
-  # about what happened in case of process crash
-  defp log_debug_orginal_error(action_or_actions, error, stacktrace) do
-    action_or_actions =
-      if(is_list(action_or_actions), do: "actions ", else: "action ") <>
-        inspect(action_or_actions, limit: :infinity)
-
-    Membrane.Logger.debug("""
-    Error while handling #{action_or_actions}
-
-    Orginal error:
-    #{inspect(error, pretty: true, limit: :infinity)}
-    #{Exception.format_stacktrace(stacktrace)}
-    """)
-  end
 end

lib/membrane/core/element.ex

@@ -35,6 +35,7 @@ defmodule Membrane.Core.Element do
 
   alias Membrane.Core.{SubprocessSupervisor, TimerController}
 
+  require Membrane.Core.Macros, as: Macros
   require Membrane.Core.Message, as: Message
   require Membrane.Core.Stalker, as: Stalker
   require Membrane.Core.Telemetry, as: Telemetry
@@ -94,6 +95,12 @@ defmodule Membrane.Core.Element do
 
   @impl GenServer
   def init(options) do
+    Macros.log_on_error do
+      do_init(options)
+    end
+  end
+
+  defp do_init(options) do
     Process.link(options.parent_supervisor)
 
     observability_config = %{
@@ -155,38 +162,42 @@ defmodule Membrane.Core.Element do
 
   @impl GenServer
   def handle_continue(:setup, state) do
-    state = LifecycleController.handle_setup(state)
-    {:noreply, state}
+    Macros.log_on_error do
+      state = LifecycleController.handle_setup(state)
+      {:noreply, state}
+    end
   end
 
   @impl GenServer
-  def handle_call(Message.new(:get_clock), _from, state) do
+  def handle_call(request, from, state) do
+    Macros.log_on_error do
+      do_handle_call(request, from, state)
+    end
+  end
+
+  defp do_handle_call(Message.new(:get_clock), _from, state) do
     {:reply, state.synchronization.clock, state}
   end
 
-  @impl GenServer
-  def handle_call(
-        Message.new(:handle_link, [direction, this, other, params]),
-        _from,
-        state
-      ) do
+  defp do_handle_call(
+         Message.new(:handle_link, [direction, this, other, params]),
+         _from,
+         state
+       ) do
     {reply, state} = PadController.handle_link(direction, this, other, params, state)
     {:reply, reply, state}
   end
 
-  @impl GenServer
-  def handle_call(Message.new(:set_stream_sync, sync), _from, state) do
+  defp do_handle_call(Message.new(:set_stream_sync, sync), _from, state) do
     state = put_in(state.synchronization.stream_sync, sync)
     {:reply, :ok, state}
   end
 
-  @impl GenServer
-  def handle_call(Message.new(:get_child_pid, _child_name), _from, state) do
+  defp do_handle_call(Message.new(:get_child_pid, _child_name), _from, state) do
     {:reply, {:error, :element_cannot_have_children}, state}
   end
 
-  @impl GenServer
-  def handle_call(message, {pid, _tag}, _state) do
+  defp do_handle_call(message, {pid, _tag}, _state) do
     raise Membrane.ElementError,
           "Received invalid message #{inspect(message)} from #{inspect(pid)}"
   end
@@ -198,7 +209,9 @@ defmodule Membrane.Core.Element do
       :erlang.process_info(self(), :message_queue_len) |> elem(1)
     )
 
-    do_handle_info(message, state)
+    Macros.log_on_error do
+      do_handle_info(message, state)
+    end
   end
 
   @compile {:inline, do_handle_info: 2}

lib/membrane/core/macros.ex

@@ -0,0 +1,24 @@
+defmodule Membrane.Core.Macros do
+  @moduledoc false
+
+  # For some reason GenServer processes sometimes don't print logs about crash, so
+  # we add this macro, to ensure that error logs wil be always logged
+  defmacro log_on_error(do: code) do
+    quote do
+      try do
+        unquote(code)
+      rescue
+        e ->
+          require Membrane.Logger
+
+          Membrane.Logger.error("""
+          Error occured in Membrane Component:
+          #{inspect(e, pretty: true, limit: :infinity)}
+          #{Exception.format_stacktrace(__STACKTRACE__)}
+          """)
+
+          reraise e, __STACKTRACE__
+      end
+    end
+  end
+end