Fl4m3Ph03n1x

Fl4m3Ph03n1x

How to detect wich process is getting unexpected messages?

Background

We have an app the keeps running. This is a OTP application that has other OTP applications as dependencies. It uses GenServers and Supervisors as do many of its dependencies.

Problem

The app doesn’t crash, but it constantly prints the following error:

=ERROR REPORT==== 14-Jun-2019::14:31:35.089496 ===
Unexpected message: {#Ref<0.2607974300.3493068808.175359>,badarg}

Actions taken

To find out where the issue could be comming from we added the following code to every GenServer and Supervisor we could find (even going into the deps folders and adding it there as well):

  def handle_info(msg, state) do
    Logger.error("Unhandled message -> module: #{__MODULE__}, msg: #{inspect msg}, state: #{inspect state}")
    {:noreply, state}
  end

The idea here is to identify which module is having issues so we can fix it. However, nothing we do seems to be revealing the issue. The message keeps appearing.

Question

A few weeks ago @sasajuric posted a talk named The soul of erlang and elixir . The talk was interesting but what truly astonished me was the ease with which he could find critical pieces of code from just a pid or a reference.

I was wondering if someone could help me implement his strategies so we can find out where this error is coming from. This reference must be useful for something after all. I just don’t know how to use it.

Given this information, how can I find out which module has the failing code?

Most Liked

sasajuric

sasajuric

Author of Elixir In Action

Warning: what I’m about to show is not production safe! Try it out on local development or on some staging server.

You could use Erlang tracing to find out the processes sending and receiving these messages. Here’s a simple sketch using low-level Erlang tracing functions (code is copy-pastable to iex).

Suppose we have two following modules which are powering processes simulating your situation:

defmodule Receiver do
  use GenServer

  def start_link(_arg), do: GenServer.start_link(__MODULE__, nil, name: __MODULE__)
  def init(_arg), do: {:ok, nil}
end

defmodule Sender do
  use Task

  def start_link(_arg), do: Task.start_link(&loop/0)

  defp loop() do
    Process.sleep(2000)
    send(Process.whereis(Receiver), {make_ref(), :bad_arg})
    loop()
  end
end

You could add another process which traces {_, :badarg} messages sent from any process. Here’s a very simple version based on Erlang tracing BIFs:

defmodule Tracer do
  use GenServer

  def start_link(_arg), do: GenServer.start_link(__MODULE__, nil)

  def init(_) do
    :erlang.trace_pattern(:send, [{[:_, {:_, :bad_arg}], [], []}], [])
    :erlang.trace(:processes, true, [:send])
    {:ok, nil}
  end

  def handle_info({:trace, sender, :send, {_ref, :bad_arg}, receiver}, state) do
    IO.puts([
      "sender info:\n#{inspect(Process.info(sender), pretty: true)}\n\n",
      "receiver info:\n#{inspect(Process.info(receiver), pretty: true)}"
    ])

    {:noreply, state}
  end
end

Now we can start all these processes:

Supervisor.start_link(
  [Tracer, Sender, Receiver],
  strategy: :one_for_one
)

The output (snipped a bunch of noise):

19:19:27.949 [error] Receiver Receiver received unexpected message in handle_info/2: {#Reference<0.3363507600.1371275267.244393>, :bad_arg}

sender info:
[
  ...
  dictionary: [
    ...
    "$initial_call": {Sender, :"-start_link/1-fun-0-", 0},
    ...
  ],
  ...
]

receiver info:
[
  registered_name: Receiver,
  ...
  dictionary: [
    "$initial_call": {Receiver, :init, 1},
    ...
  ],
  ...
]

Depending on your particular situation, you might (but not necessarily will) be able to pinpoint the modules powering these processes. AFAIK, it’s not possible to get the stack trace, so you’ll need to analyze the code. But hopefully, the info above might help you track down the problematic process/module.

For production-safe tracing, check out recon_trace, and redbug (there’s also Elixir wrapper rexbug). You might also want to read this recent post on tracing in Elixir.

sasajuric

sasajuric

Author of Elixir In Action

In theory it should work, regardless of the supervision tree shape. You could try using :all instead of :processes. Another option is to trace receives, instead of sends. In that case you should replace :send with :receive. For more info, check out the docs of trace and trace_pattern.

You can try both approaches on my simple simulation, and once they work, you can move to do the same in your project.

Other than that, I don’t have much to advise ATM.

jweinkam

jweinkam

By using a custom formatter for Logger, I was able to determine that in my case this is getting logged by gun. After which I was able to find https://github.com/ninenines/gun/issues/193. I updated to Erlang 22.2.8 and now am no longer getting the Unexpected message.

peerreynders

peerreynders

I’d start looking at the logger and meta data configuration to capture additional information.


Before:

11:58:49.837 [error] Unexpected message: :ping

After:

config :logger, :console,
  format: "\n$time $metadata[$level] $levelpad$message\n",
  metadata: [:application, :module, :function, :pid, :registered_name, :file, :line]

2:03:19.400 application=demo module=Demo.Server function=handle_info/2 pid=<0.166.0> file=lib/demo/server.ex line=16 [error] Unexpected message: :ping

Not all loggers support this but it could be worthwhile retrofitting this.

Fl4m3Ph03n1x

Fl4m3Ph03n1x

First of all, thank you so much for your reply. It is always a huge pleasure reading your answers and comments as they are full of insight.

I did try out your Tracer module, but unfortunately it didn’t catch the culprit. Does the Tracer module need to be at the same level of the other process in the process tree for it to catch them?

For example, if I have the Tracer module in my app’s supervisor, and the error message is being received 10 levels down the process tree inside a process from a dependency, from another dependency, will Tracer be able to view it?

I am not versed in erlang nor in tracing tools at all, this is all new territory, so I apologize if my question is senseless.

I am also trying recon and I am reading the post on erlang solutions you suggested. Can’t wait to learn more!

Where Next?

Popular in Questions Top

JDanielMartinez
Hi! May someone helps me, please! I have two apps into an umbrella project: the first one is Database, which manages queries, and the se...
New
LegitStack
I’m hoping you guys can give me some general advice and perhaps code examples if you’re feeling up to it. I’m very interested in Elixir,...
New
sergio_101
I am VERY much an elixir newbie. I have taken one elixir course and one phoenix course on Udemy. During that course, I saw the instructor...
New
jononomo
I am trying to figure out how Mix knows whether the environment is test, dev, or prod -- where is this set? Thanks.
New
Kagamiiiii
Student &amp; New to elixir. Nice language. I want to convert a english character, e.g. “a”, which is stored in a variable, to it’s asci...
New
mgjohns61585
Could someone help me? I'm making my first elixir program, number guessing game. I can't figure out how to convert the user's guess from ...
New
Patoshizzle
After calling mix ecto.create I get this error: 17:00:32.162 [error] GenServer #PID&lt;0.412.0&gt; terminating ** (Postgrex.Error) FATAL...
New
Codball
Mix format works fine if run from the cmd. I’ve followed this to facilitate the implementation into VSC which involves downloading an ext...
New
9mm
I am constructing a JSON object (map) and I need to conditionally set a field. I’m trying to write proper elixir-way code… and I’m at a l...
New
lanycrost
Hi everyone! I need implement if…else if…else condition from my elixir code, and anymore of this control flow structures not work proper...
New

Other popular topics Top

bsollish-terakeet
Credo is smart enough to check for (something like) this: assert length(the_list) == 0 with this response: Checking if an enum is empt...
New
sergio_101
I am VERY much an elixir newbie. I have taken one elixir course and one phoenix course on Udemy. During that course, I saw the instructor...
New
grych
Hi folks, Few months ago I have announced the proof-of-concept of the library to manipulate the browsers DOM objects directly from Elixi...
639 49522 488
New
Jim
As a follow up to my earlier question: I have the code compiling and running but not getting a successful login from the rest server. ...
New
freewebwithme
Using vs code and installed ElixirLS: support and debugger. And I got an error popped up on start up says Failed to run ‘elixir’ comma...
New
minhajuddin
I have seen a lot of code which picks the first element from a list using Enum.at(0) instead of List.first. Is there a reason why people ...
New
ashish173
I am using Ecto timestamps with postgres, I can see the timestamps() use the :naive_dateime but for my use case I wanted to store the ti...
New
vonH
When I run the Plug and I recompile I wind up having to use Ctrl C to quit iex and start again. Witht the help of rlwrap I can use the cu...
New
stefanluptak
Hello everybody, usually, I use a 29" ultra-wide monitor for VSCode which can easily accomodate explorer (files panel) + file with code ...
New
lanycrost
Hi everyone! I need implement if…else if…else condition from my elixir code, and anymore of this control flow structures not work proper...
New

We're in Beta

About us Mission Statement