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

senggen
Erlang/OTP 25 [erts-13.2.2] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] 15:22:35.803 [error] gen_event {lager_file_backend...
New
srinivasu
How to handle excepions in elixir? Suppose i have A, B, C ,D, E modules. and each module has get() function. A.get() method will call th...
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
jerry
Good day to you all. I have been struggling to get a query involving like and ilike to work. Can anyone assist me on this, please? pro...
New
Werner
Hi, I’m using Ubuntu 18.04 and after updating to OTP-24.0 yesterday i have this warning when I run “mix local.hex”: 14:57:30.512 [warn] ...
New
myronmarston
The Elixir Typespec docs show the following syntax for keyword lists in typespecs: # ... | [key: type] # keyword lis...
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
chensan
I have a User schema with a :from_id field set to type :string: defmodule TweetBot.Repo.Migrations.CreateUsers do use Ecto.Migration ...
New
ovidiubadita
Hey all, I discovered Elixir and I love it. I always wanted to learn a functional programming and I intended to go for Haskell, but afte...
New
wernerlaude
In AR this is so simple @articles = current_user.articles How to do in Ecto? def index(conn, _params) do current_user = conn.assig...
New

Other popular topics Top

srinivasu
How to handle excepions in elixir? Suppose i have A, B, C ,D, E modules. and each module has get() function. A.get() method will call th...
New
Tee
can someone please explain to me how Enum.reduce works with maps
New
joaquinalcerro
Hi there, I am working with Ecto-Postgresql and I need to call all of the records from a specific table but the table has 40,000 record...
New
axelson
This post is a wiki (feel free to hit the edit button near the bottom right of this post to add your own changes!) This post collects co...
239 45766 226
New
lastday4you
I wanted to check elixir version in phoenix because i found that my elixir is 1.5 but when i use Enum.chunk_by it said the function is un...
New
chensan
I have a User schema with a :from_id field set to type :string: defmodule TweetBot.Repo.Migrations.CreateUsers do use Ecto.Migration ...
New
shahryarjb
Hello, I have map which I want to convert it to string like this: the map: %{last_name: "tavakkoli", name: "shahryar"} the string I ne...
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
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
lucidguppy
I have a super simple question about elixir - how would I take a file like this foo bar baz and output a new file that enumerates th...
New

We're in Beta

About us Mission Statement