recon_trace:calls - no output on OTP26

[mkuratczyk]

When using recon_trace:calls, I don't get any (meaningful) output on OTP26. Empty lines are printed for every function call, but I can't see the actual trace output:

$ rebar3 shell
===> Verifying dependencies...
===> Analyzing applications...
===> Compiling recon
Erlang/OTP 26 [erts-14.0] [source] [64-bit] [smp:10:10] [ds:10:10:10] [async-threads:1] [jit] [dtrace]

Eshell V14.0 (press Ctrl+G to abort, type help(). for help)
1> recon_trace:calls({lists, seq, return_trace}, 10).
2
2> [lists:seq(1, X) || X <- [1, 2, 3]].
[[1],[1,2],[1,2,3]]






3>

On OTP25, everything works as expected:

1> recon_trace:calls({lists, seq, return_trace}, 10).
2
2> [lists:seq(1, X) || X <- [1, 2, 3]].

11:9:45.591208 <0.94.0> lists:seq(1, 1)
[[1],[1,2],[1,2,3]]

11:9:45.591826 <0.94.0> lists:seq/2 --> [1]

11:9:45.592098 <0.94.0> lists:seq(1, 2)

11:9:45.592347 <0.94.0> lists:seq/2 --> [1,2]

11:9:45.592612 <0.94.0> lists:seq(1, 3)

11:9:45.592785 <0.94.0> lists:seq/2 --> [1,2,3]

[ferd]

I'm a bit surprised yeah. This worked on OTP-26-RC3, and the full pattern still works outside of it on OTP-26 when using the matching function to make it work:

2> recon_trace:calls({lists, seq, return_trace}, 10).
2
3> lists:seq(1,10).
[1,2,3,4,5,6,7,8,9,10]


4> recon_trace:calls({lists, seq, fun(_) -> return_trace() end}, 10).
2
5> lists:seq(1,10).

13:9:53.284312 <0.164.0> lists:seq(1, 10)
[1,2,3,4,5,6,7,8,9,10]

13:9:53.284648 <0.164.0> lists:seq/2 --> [1,2,3,4,5,6,7,8,9,10]

The translation there is just a shortcut toward recon_trace:calls({lists, seq, [{'_', [], [{return_trace}]}]}, 10). and that's what no longer works.

I think this might be a break in Erlang/OTP itself, I'll see if I can follow up with folks from the OTP team.

[ferd]

Oh actually odd thing: they are fully equivalent. It's just the first call that fails:

1> recon_trace:calls({lists, seq, return_trace}, 10).
2
2> lists:seq(1,10).
[1,2,3,4,5,6,7,8,9,10]


3> lists:seq(1,10).

13:29:41.882057 <0.164.0> lists:seq(1, 10)
[1,2,3,4,5,6,7,8,9,10]

13:29:41.882527 <0.164.0> lists:seq/2 --> [1,2,3,4,5,6,7,8,9,10]

So the bug is really that the first invocation to a trace fails somehow.

[ferd]

Oh interesting, I decomposed the calls and it works fine with the built-in functions, so it is a recon bug. That's odd.

1> Tracer = spawn(fun F() -> receive X -> io:format("received ~p~n", [X]) end, F() end).
<0.166.0>
2> erlang:trace_pattern({lists, seq, '_'}, [{'_',[],[{return_trace}]}], [global]).
2
3> erlang:trace(all, true, [call, timestamp, {tracer,Tracer}, arity]).
90
4> lists:seq(1,10).
received {trace_ts,<0.164.0>,call,{lists,seq,2},{1685,22325,12420}}
[1,2,3,4,5,6,7,8,9,10]
received {trace_ts,<0.164.0>,return_from,
                   {lists,seq,2},
                   [1,2,3,4,5,6,7,8,9,10],
                   {1685,22325,12426}}

I'm now thinking this is a problem with the rebar3 shell -- there were a lot of changes around that, and the hack is on rebar3's side so I'll look into it.

[ferd]

Here's the diff I ran:

diff --git a/src/recon_trace.erl b/src/recon_trace.erl
index 975f536..2d78009 100644
--- a/src/recon_trace.erl
+++ b/src/recon_trace.erl
@@ -354,6 +354,7 @@ count_tracer(0) ->
 count_tracer(N) ->
     receive
         Msg ->
+            io:format(standard_error, "tracer received ~p~n", [Msg]),
             recon_trace_formatter ! Msg,
             count_tracer(N-1)
     end.
@@ -393,6 +394,7 @@ formatter(Tracer, IOServer, FormatterFun) ->
         {'EXIT', Tracer, Reason} ->
             exit(Reason);
         TraceMsg ->
+            io:format(standard_error, "~n Fake: ~p~n", [FormatterFun(TraceMsg)]),
             io:format(IOServer, FormatterFun(TraceMsg), []),
             formatter(Tracer, IOServer, FormatterFun)
     end.

And how I invoke it:

→ rebar3 shell
===> Verifying dependencies...
===> Analyzing applications...
===> Compiling recon
Erlang/OTP 26 [erts-14.0] [source] [64-bit] [smp:2:2] [ds:2:2:10] [async-threads:1] [jit:ns]

Eshell V14.0 (press Ctrl+G to abort, type help(). for help)
1> recon_trace:calls({lists, seq, [{'_',[],[{return_trace}]}]}, 10).
2
2> lists:seq(1,9).
tracer received {trace,<0.171.0>,call,{lists,seq,[1,9]}}
tracer received {trace,<0.171.0>,return_from,
                       {lists,seq,2},
                       [1,2,3,4,5,6,7,8,9]}
[1,2,3,4,5,6,7,8,9]
3>
 Fake: [10,"14",58,"54",58,48,57,46,49,51,55,50,51,51,32,"<0.171.0>",32,
        "lists",58,"seq",
        [40,[["1"],", ",["9"]],41],
        10]

3>
 Fake: [10,"14",58,"54",58,48,57,46,49,53,49,49,57,54,32,"<0.171.0>",32,
        "lists",58,"seq",47,"2",32,45,45,62,32,
        [[91,
          ["1",44,"2",44,"3",44,"4",44,"5",44,"6",44,"7",44,"8",44,"9"],
          93]],
        10]
3> lists:seq(1,10).tracer received {trace,<0.171.0>,call,{lists,seq,[1,10]}}
tracer received {trace,<0.171.0>,return_from,
                       {lists,seq,2},
                       [1,2,3,4,5,6,7,8,9,10]}

 Fake: [10,"14",58,"54",58,49,50,46,52,54,57,53,54,51,32,"<0.171.0>",32,
        "lists",58,"seq",
        [40,[["1"],", ",["10"]],41],
        10]


14:54:12.469850 <0.171.0> lists:seq(1, 10)
[1,2,3,4,5,6,7,8,9,10]
 Fake: [10,"14",58,"54",58,49,50,46,52,55,48,51,53,52,32,"<0.171.0>",32,
        "lists",58,"seq",47,"2",32,45,45,62,32,
        [[91,
          ["1",44,"2",44,"3",44,"4",44,"5",44,"6",44,"7",44,"8",44,"9",44,
           "10"],
          93]],
        10]


14:54:12.470583 <0.171.0> lists:seq/2 --> [1,2,3,4,5,6,7,8,9,10]

Beats me why, but the second loop invocation works and gets the data out, but the first batch of call never does (even though it works with standard_error)

It's like until that formatter loop returns once, everything is hung.

[ferd]

Might be related to erlang/otp#7263

[lhoguin]

This was seen outside of Rebar first, in a RabbitMQ shell, for what it's worth.

[ferd]

Yeah for the time being I'll stop investigating here and track the OTP repo's bug, seems related.