recon
recon copied to clipboard
ferd
recon_trace:calls - no output on OTP26
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]
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.
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.
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.
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.
This was seen outside of Rebar first, in a RabbitMQ shell, for what it's worth.
Yeah for the time being I'll stop investigating here and track the OTP repo's bug, seems related.