Tracing all calls to handle_info in all processes using recon_trace

Fl4m3Ph03n1x

Background

Our app is constantly printing an error message and we have no idea where it is coming from. My objective is to detect which process(es) is receiving the message so I can then trace it using Process.info via a remote shell and find out which module is causing the issue.

Objective

To achieve this, I am following a suggestion given in a previous discussion and I am trying to use recon.

The error message has the following format:

=ERROR REPORT==== 17-Jun-2019::09:29:22.694288 ===
Unexpected message: {#Ref<0.3271557848.1968439297.87877>,badarg}

After reading the documentation of recon_trace I concluded I needed to base my code on the following example, which traces all calls to handle_call for module Mod for all new processes, and those of an existing one registered with gproc:

recon_trace:calls({Mod,handle_call,3}, {10,100}, [{pid, [{via, gproc, Name}, new]}

In order to try the library I decided to go with a simpler approach and just trace 10 calls from anywhere to handle_info, but it errors out:

:recon_trace.calls({:_, handle_info, 2}, 10)
** (CompileError) iex:3: undefined function handle_info/0
    (stdlib) lists.erl:1354: :lists.mapfoldl/3
    (stdlib) lists.erl:1355: :lists.mapfoldl/3
    (stdlib) lists.erl:1354: :lists.mapfoldl/3

Question

I am connection to the application’s terminal via a remote shell and I am trying to run these commands there.
What am I doing wrong?

9 comments

#tracing

0 3011 9

2021-01-02 15:30:41 UTC

Showing Posts 1 to 9

Show Best Posts
Show All (oldest first)
Show All (newest first)

NobbZ

You probably want :handle_info. lower case identifiers are atoms in erlang syntax.

Post #1

Fl4m3Ph03n1x

Errors out with another error:

:recon_trace.calls({:_, :handle_info, 2}, 10)
** (ArgumentError) argument error
    :erlang.trace_pattern({:_, :handle_info, 2}, true, [:global])
    (recon) src/recon_trace.erl:425: :recon_trace."-trace_calls/3-lc$^0/1-0-"/2
    (recon) src/recon_trace.erl:426: :recon_trace.trace_calls/3
    (stdlib) erl_eval.erl:680: :erl_eval.do_apply/6
    (iex) lib/iex/evaluator.ex:257: IEx.Evaluator.handle_eval/5
    (iex) lib/iex/evaluator.ex:237: IEx.Evaluator.do_eval/3

Post #2

NobbZ

From recons documentation it seems to me, that the module isn’t allowed to be the wildcard matcher:

Module is any atom representing a module

Post #3

Fl4m3Ph03n1x

So, I can’t use recon_trace to check calls to handle_info coming from any processes?

How can I use the recon library to achieve my objective? (Is it possible to use it?)

Post #4

NobbZ

You could use :code.all_loaded/0 to get all loaded modules and iterate over them to check if they export handle_info/2 and set a trace programatically…

traces = :code.all_loaded()
|> Stream.filter(&:erlang.function_exported(&1, :handle_info, 2))
|> Enum.map(&{&1, :handle_info, 2})

:recon_trace.calls(traces, 10)

Of course this only works if you make sure to load all modules, eg. via starting a release.

Post #5

kip

ex_cldr Core Team

Deleted so the future historians will wonder what amazing insight should have been here

(but @NobbZ will know it was because made an totally incorrect statement)

Post #6

NobbZ

According to the documentation, that has nothing to do with preloading all modules:

[if the application] is started as permanent, […] the node will shut down if the application crashes permanently.

Post #7

Fl4m3Ph03n1x

Thank you everyone for your kind feedback. I have taken @NobbZ code and fixed it into the following (the original version was missing a map):


traces = 
  :code.all_loaded() 
  |> Stream.map(fn({module, _path}) -> module end) 
  |> Stream.filter(&:erlang.function_exported(&1, :handle_info, 2)) 
  |> Stream.map(&{&1, :handle_info, 2}) 
  |> Enum.map(&:recon_trace.calls(&1, 10))

This allows me to trace the 10 calls to all modules using handle_info.

Now, we can see the following output:

                                         
11:28:07.155854 <0.285.0> memsup:handle_info(time_to_collect, {state,{unix,linux},
       true,
       {2950590464,31605788672},
       {<0.6127.0>,10784136},
       false,60000,30000,0.8,0.05,<0.286.0>,undefined,undefined,[],[]})
                                          
11:28:07.156521 <0.285.0> memsup:handle_info({collected_sys,{2968354816,31605788672}}, {state,{unix,linux},
       true,
       {2950590464,31605788672},
       {<0.6127.0>,10784136},
       false,60000,30000,0.8,0.05,<0.286.0>,
       #Ref<0.960887702.3327131654.82864>,undefined,
       [reg],
       []})
                                          
11:29:07.190019 <0.285.0> memsup:handle_info(time_to_collect, {state,{unix,linux},
       true,
       {2968354816,31605788672},
       {<0.6127.0>,10787544},
       false,60000,30000,0.8,0.05,<0.286.0>,undefined,undefined,[],[]})
                                          
11:29:07.190603 <0.285.0> memsup:handle_info({collected_sys,{2987864064,31605788672}}, {state,{unix,linux},
       true,
       {2968354816,31605788672},
       {<0.6127.0>,10787544},
       false,60000,30000,0.8,0.05,<0.286.0>,
       #Ref<0.960887702.3327131656.11201>,undefined,
       [reg],
       []})

Which confirms this solution is working !

Post #8

ijunaidfarooq

this results into this..

iex(13)> traces = :code.all_loaded() |> Stream.map(fn({module, _path}) -> module end) |> Stream.filter(&:erlang.function_exported(&1, :handle_info, 2)) |> Stream.map(&{&1, :handle_info, 2}) |> Enum.map(&:recon_trace.calls(&1, 10)) |> Enum.to_list
[1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1,
 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, ...]
iex(14)>

how to see the trace?

Post #9

— All posts loaded —