Difficulty to understand GenServer error message triggered by reply

Questions / Help
1

I accidentally called GenServer.reply(from, :ok) twice so I got the following error message in my logs. For me the message is rather cryptic. What in the message could point me to the fact that i called reply twice?

00:47:16.704 [error] [message: {#Reference<0.4144651693.395575298.249020>, :ok}, module: SCs, name: #PID<0.196.0>]

2

I cannot reproduce that:

defmodule Foo do
  use GenServer

  def init(_), do: {:ok, []}

  def handle_call(msg, from, state) do
    IO.inspect(msg, label: __MODULE__)
    GenServer.reply(from, :ok)
    GenServer.reply(from, :ok)
    {:noreply, state}
  end
end

{:ok, pid} = GenServer.start_link(Foo, [])

IO.inspect GenServer.call(pid, :test)

Output

Elixir.Foo: :test
:ok

Edit, you probably run it from other GenServer that has handle_info created that will log error on unknown message. Check that.

1 Like
3

I think thatā€™s the default GenServer logger.

defmodule Foo do
  use GenServer
  def init(_), do: {:ok, nil}
  def handle_call({:call, pid}, _from, _) do
    GenServer.call(pid, :foo)
    {:reply, :ok, nil}
  end
end

defmodule Bar do
  use GenServer
  def init(_), do: {:ok, nil}
  def handle_call(call, from, _) do
    call |> IO.inspect(label: "14")
    GenServer.reply(from, :ok)
    GenServer.reply(from, :ok)
    {:noreply, nil}
  end
end

iex(4)> {:ok, foo} = GenServer.start_link(Foo, nil)
{:ok, #PID<0.145.0>}
iex(5)> {:ok, bar} = GenServer.start_link(Bar, nil)
{:ok, #PID<0.147.0>}
iex(6)> GenServer.call(foo, {:call, bar})
14: :foo
:ok
iex(7)> 
10:50:28.689 [error] [message: {#Reference<0.2646108517.405536772.190147>, :ok}, module: Foo, name: #PID<0.145.0>]
1 Like
4

Your example is good. But how could I either learn to read the message? Or how could I replace the logger?

5

so hereā€™s how to read that error:

if you see {#Referenceā€¦, } that is the signature of a gen_server call reply. the module: ā€¦ is the module of the genserver that received the stray reply. Unfortunately, the source gen_server cannot be easily known, so I would say the best you can do is look at and try to figure out what could have emitted that. In the case of :ok, you might have to look in a lot of places, ha.

you do NOT want to replace the logger for stray messages. i have pushed code to prod that I was able to debug because these errors showed up in my monitoring months later (it wasnā€™t diminishing the user experience in a knowable way, but it was nice to be able to sleep sounder at night)

4 Likes
6

Actually I didnā€™t aimed to silence it, but rather modify it for my needs of understanding. :slight_smile:

7

ah. In that case I recommend this:

defmodule SCs do

   # ... SCs code

  def handle_info(msg, state) do
    msg |> IO.inspect(label: "message")
    state |> IO.inspect(label: "state")
    {:noreply, state}
  end
end
2 Likes
8

It seems like bug in the GenServer error message handling, or in Elixir error handler. I will need to dig it more to check what os the source of the problem.

9

I have created issue with that problem:

And already provided PR that solves it in this particular case (but it also revealed bigger problem there):

1 Like