1%%
2%% %CopyrightBegin%
3%%
4%% Copyright Ericsson AB 1999-2017. All Rights Reserved.
5%%
6%% Licensed under the Apache License, Version 2.0 (the "License");
7%% you may not use this file except in compliance with the License.
8%% You may obtain a copy of the License at
9%%
10%%     http://www.apache.org/licenses/LICENSE-2.0
11%%
12%% Unless required by applicable law or agreed to in writing, software
13%% distributed under the License is distributed on an "AS IS" BASIS,
14%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15%% See the License for the specific language governing permissions and
16%% limitations under the License.
17%%
18%% %CopyrightEnd%
19%%
20
21
22-module(trace_port_SUITE).
23
24-export([all/0, suite/0,
25	 call_trace/1,
26	 return_trace/1,
27	 send/1,
28	 receive_trace/1,
29	 receive_trace_non_scheduler/1,
30	 process_events/1,
31	 schedule/1,
32	 gc/1,
33	 default_tracer/1,
34	 tracer_port_crash/1]).
35
36-include_lib("common_test/include/ct.hrl").
37
38suite() ->
39    [{ct_hooks,[ts_install_cth]},
40     {timetrap, {minutes, 2}}].
41
42all() ->
43    [call_trace, return_trace, send, receive_trace,
44     receive_trace_non_scheduler,
45     process_events, schedule, gc,
46     default_tracer, tracer_port_crash].
47
48%% Test sending call trace messages to a port.
49call_trace(Config) when is_list(Config) ->
50    case test_server:is_native(?MODULE) orelse
51         test_server:is_native(lists) of
52        true ->
53            {skip,"Native code"};
54        false ->
55            start_tracer(Config),
56            Self = self(),
57            trace_func({lists,reverse,1}, []),
58            trace_pid(Self, true, [call]),
59            trace_info(Self, flags),
60            trace_info(Self, tracer),
61            [b,a] = lists:reverse([a,b]),
62            expect({trace,Self,call,{lists,reverse,[[a,b]]}}),
63
64            trace_pid(Self, true, [timestamp]),
65            trace_info(Self, flags),
66            Huge = huge_data(),
67            lists:reverse(Huge),
68            expect({trace_ts,Self,call,{lists,reverse,[Huge]},ts}),
69
70            trace_pid(Self, true, [arity]),
71            trace_info(Self, flags),
72            [y,x] = lists:reverse([x,y]),
73            expect({trace_ts,Self,call,{lists,reverse,1},ts}),
74
75            trace_pid(Self, false, [timestamp]),
76            trace_info(Self, flags),
77            [z,y,x] = lists:reverse([x,y,z]),
78            expect({trace,Self,call,{lists,reverse,1}}),
79
80            %% OTP-7399. Delayed sub-binary creation optimization.
81            trace_pid(Self, false, [arity]),
82            trace_info(Self, flags),
83            trace_func({?MODULE,bs_sum_c,2}, [], [local]),
84            26 = bs_sum_c(<<3:4,5:4,7:4,11:4>>, 0),
85            trace_func({?MODULE,bs_sum_c,2}, false, [local]),
86            expect({trace,Self,call,{?MODULE,bs_sum_c,[<<3:4,5:4,7:4,11:4>>,0]}}),
87            expect({trace,Self,call,{?MODULE,bs_sum_c,[<<5:4,7:4,11:4>>,3]}}),
88            expect({trace,Self,call,{?MODULE,bs_sum_c,[<<7:4,11:4>>,8]}}),
89            expect({trace,Self,call,{?MODULE,bs_sum_c,[<<11:4>>,15]}}),
90            expect({trace,Self,call,{?MODULE,bs_sum_c,[<<>>,26]}}),
91
92            trace_func({lists,reverse,1}, false),
93            ok
94    end.
95
96bs_sum_c(<<H:4,T/bits>>, Acc) -> bs_sum_c(T, H+Acc);
97bs_sum_c(<<>>, Acc) -> Acc.
98
99
100%% Test the new return trace.
101return_trace(Config) when is_list(Config) ->
102    case test_server:is_native(?MODULE) orelse
103         test_server:is_native(lists) of
104        true ->
105            {skip,"Native code"};
106        false ->
107            start_tracer(Config),
108            Self = self(),
109            MFA = {lists,reverse,1},
110
111            %% Plain (no timestamp, small data).
112
113            trace_func(MFA, [{['$1'],[],[{return_trace},
114                                         {message,false}]}]),
115            trace_pid(Self, true, [call]),
116            trace_info(Self, flags),
117            trace_info(Self, tracer),
118            trace_info(MFA, match_spec),
119            {traced,global} = trace_info(MFA, traced),
120            [b,a] = lists:reverse([a,b]),
121            expect({trace,Self,return_from,MFA,[b,a]}),
122
123            %% Timestamp, huge data.
124            trace_pid(Self, true, [timestamp]),
125            Result = lists:reverse(huge_data()),
126            expect({trace_ts,Self,return_from,MFA,Result,ts}),
127
128            %% Turn off trace.
129            trace_func(MFA, false),
130            trace_info(MFA, match_spec),
131            {traced,false} = trace_info(MFA, traced),
132            ok
133    end.
134
135%% Test sending send trace messages to a port.
136send(Config) when is_list(Config) ->
137    Tracer = start_tracer(Config),
138    Self = self(),
139    Sender = fun_spawn(fun sender/0),
140    trac(Sender, true, [send]),
141
142    %% Simple message, no timestamp.
143
144    Bin = list_to_binary(lists:seq(1, 10)),
145    Msg = {some_data,Bin},
146    Sender ! {send_please,self(),Msg},
147    receive Msg -> ok end,
148    expect({trace,Sender,send,Msg,Self}),
149
150    %% Timestamp.
151
152    BiggerMsg = {even_bigger,Msg},
153    trac(Sender, true, [send,timestamp]),
154    Sender ! {send_please,self(),BiggerMsg},
155    receive BiggerMsg -> ok end,
156    expect({trace_ts,Sender,send,BiggerMsg,Self,ts}),
157
158    %% Huge message.
159
160    HugeMsg = huge_data(),
161    Sender ! {send_please,self(),HugeMsg},
162    receive HugeMsg -> ok end,
163    expect({trace_ts,Sender,send,HugeMsg,Self,ts}),
164
165    %% Kill trace port and force a trace.  The emulator should not crasch.
166
167    unlink(Tracer),
168    exit(Tracer, kill),
169    erlang:yield(),				% Make sure that port gets killed.
170    Sender ! {send_please,Self,good_bye},
171    receive good_bye -> ok end,
172    ok.
173
174%% Test sending receive traces to a port.
175receive_trace(Config) when is_list(Config) ->
176    start_tracer(Config),
177    Receiver = fun_spawn(fun receiver/0),
178    trac(Receiver, true, ['receive']),
179
180    Receiver ! {hello,world},
181    expect({trace,Receiver,'receive',{hello,world}}),
182
183    trac(Receiver, true, ['receive',timestamp]),
184    Huge = {hello,huge_data()},
185    Receiver ! {hello,huge_data()},
186    expect({trace_ts,Receiver,'receive',Huge,ts}),
187    ok.
188
189%% Test sending receive traces to a port.
190receive_trace_non_scheduler(Config) when is_list(Config) ->
191    start_tracer(Config),
192    S = self(),
193    Receiver = spawn_link(
194                 fun() ->
195                         receive
196                             go ->
197                                 Ref = S ! erlang:trace_delivered(all),
198                                 receive {trace_delivered, Ref, all} -> ok end
199                         end
200                 end),
201    trac(Receiver, true, ['receive']),
202    Receiver ! go,
203    Ref = receive R -> R end,
204    expect({trace,Receiver,'receive',go}),
205    expect({trace,Receiver,'receive',{trace_delivered, all, Ref}}),
206
207    ok.
208
209%% Tests a few process events (like getting linked).
210process_events(Config) when is_list(Config) ->
211    start_tracer(Config),
212    Self = self(),
213    Receiver = fun_spawn(fun receiver/0),
214    trac(Receiver, true, [procs]),
215
216    unlink(Receiver),				%It is already linked.
217    expect({trace,Receiver,getting_unlinked,Self}),
218    link(Receiver),
219    expect({trace,Receiver,getting_linked,Self}),
220    trac(Receiver, true, [procs,timestamp]),
221    unlink(Receiver),
222    expect({trace_ts,Receiver,getting_unlinked,Self,ts}),
223    link(Receiver),
224    expect({trace_ts,Receiver,getting_linked,Self,ts}),
225
226    unlink(Receiver),
227    expect({trace_ts,Receiver,getting_unlinked,Self,ts}),
228    Huge = huge_data(),
229    exit(Receiver, Huge),
230    expect({trace_ts,Receiver,exit,Huge,ts}),
231
232    ok.
233
234%% Test sending scheduling events to a port.
235schedule(Config) when is_list(Config) ->
236    start_tracer(Config),
237    Receiver = fun_spawn(fun receiver/0),
238    trac(Receiver, true, [running]),
239
240    Receiver ! hi,
241    expect({trace,Receiver,in,{?MODULE,receiver,0}}),
242    expect({trace,Receiver,out,{?MODULE,receiver,0}}),
243
244    trac(Receiver, true, [running,timestamp]),
245
246    Receiver ! hi_again,
247    expect({trace_ts,Receiver,in,{?MODULE,receiver,0},ts}),
248    expect({trace_ts,Receiver,out,{?MODULE,receiver,0},ts}),
249
250    ok.
251
252%% Test sending garbage collection events to a port.
253gc(Config) when is_list(Config) ->
254    start_tracer(Config),
255    Garber = fun_spawn(fun garber/0, [{min_heap_size, 5000}]),
256    trac(Garber, true, [garbage_collection]),
257    trace_info(Garber, flags),
258
259    trace_info(Garber, flags),
260    Garber ! hi,
261    expect({trace,Garber,gc_major_start,info}),
262    expect({trace,Garber,gc_major_end,info}),
263
264    trac(Garber, true, [garbage_collection,timestamp]),
265    Garber ! hi,
266    expect({trace_ts,Garber,gc_major_start,info,ts}),
267    expect({trace_ts,Garber,gc_major_end,info,ts}),
268
269    ok.
270
271%% Test a port as default tracer.
272default_tracer(Config) when is_list(Config) ->
273    Tracer = start_tracer(Config),
274    TracerMonitor = erlang:monitor(process, Tracer),
275    Port = get(tracer_port),
276    %%
277    N = erlang:trace(all, true, [send, {tracer, Port}]),
278    {flags, [send]} = erlang:trace_info(self(), flags),
279    {tracer, Port} = erlang:trace_info(self(), tracer),
280    {flags, [send]} = erlang:trace_info(new, flags),
281    {tracer, Port} = erlang:trace_info(new, tracer),
282    G1 = fun_spawn(fun general/0),
283    {flags, [send]} = erlang:trace_info(G1, flags),
284    {tracer, Port} = erlang:trace_info(G1, tracer),
285    unlink(Tracer),
286    exit(Port, done),
287    receive
288        {'DOWN', TracerMonitor, process, Tracer, TracerExitReason} ->
289            done = TracerExitReason
290    end,
291    {flags, []} = erlang:trace_info(self(), flags),
292    {tracer, []} = erlang:trace_info(self(), tracer),
293    {flags, []} = erlang:trace_info(new, flags),
294    {tracer, []} = erlang:trace_info(new, tracer),
295    M = erlang:trace(all, false, [all]),
296    {flags, []} = erlang:trace_info(self(), flags),
297    {tracer, []} = erlang:trace_info(self(), tracer),
298    {flags, []} = erlang:trace_info(G1, flags),
299    {tracer, []} = erlang:trace_info(G1, tracer),
300    G1 ! {apply,{erlang,exit,[normal]}},
301    io:format("~p = ~p.~n", [M, N]),
302    M = N - 1, % G1 has been started, but Tracer and Port have died
303    ok.
304
305tracer_port_crash(Config) when is_list(Config) ->
306    case test_server:is_native(?MODULE) orelse
307         test_server:is_native(lists) of
308        true ->
309            {skip,"Native code"};
310        false ->
311            Tr = start_tracer(Config),
312            Port = get(tracer_port),
313            Tracee = spawn(fun () ->
314                                   register(trace_port_linker, self()),
315                                   link(Port),
316                                   receive go -> ok end,
317                                   lists:reverse([1,b,c]),
318                                   receive die -> ok end
319                           end),
320            Tr ! {unlink_tracer_port, self()},
321            receive {unlinked_tracer_port, Tr} -> ok end,
322            port_control(Port, $c, []), %% Make port commands crash tracer port...
323            trace_func({lists,reverse,1}, []),
324            trace_pid(Tracee, true, [call]),
325            trace_info(Tracee, flags),
326            trace_info(self(), tracer),
327            Tracee ! go,
328            receive after 1000 -> ok end,
329            case whereis(trace_port_linker) of
330                undefined ->
331                    ok;
332                Id ->
333                    %		    erts_debug:set_internal_state(available_internal_state, true),
334                    %		    erts_debug:set_internal_state(abort, {trace_port_linker, Id})
335                    ct:fail({trace_port_linker, Id})
336            end,
337            undefined = process_info(Tracee),
338            ok
339    end.
340
341%%% Help functions.
342
343huge_data() -> huge_data(16384).
344huge_data(0) -> [];
345huge_data(N) when N rem 2 == 0 ->
346    P = huge_data(N div 2),
347    [P|P];
348huge_data(N) ->
349    P = huge_data(N div 2),
350    [16#1234566,P|P].
351
352expect({trace_ts,E1,E2,info,ts}=Message) ->
353    receive
354        {trace_ts,E1,E2,_Info,_Ts}=MessageTs ->
355            ok = io:format("Expected and got ~p", [MessageTs]),
356            MessageTs;
357        Other ->
358            io:format("Expected ~p; got ~p", [Message,Other]),
359            ct:fail({unexpected,Other})
360    after 5000 ->
361              io:format("Expected ~p; got nothing", [Message]),
362              ct:fail(no_trace_message)
363    end;
364expect({trace,E1,E2,info}=Message) ->
365    receive
366        {trace,E1,E2,_Info}=MessageTs ->
367            ok = io:format("Expected and got ~p", [MessageTs]),
368            MessageTs;
369        Other ->
370            io:format("Expected ~p; got ~p", [Message,Other]),
371            ct:fail({unexpected,Other})
372    after 5000 ->
373              io:format("Expected ~p; got nothing", [Message]),
374              ct:fail(no_trace_message)
375    end;
376expect({trace_ts,E1,E2,E3,ts}=Message) ->
377    receive
378        {trace_ts,E1,E2,E3,_Ts}=MessageTs ->
379            ok = io:format("Expected and got ~p", [MessageTs]),
380            MessageTs;
381        Other ->
382            io:format("Expected ~p; got ~p", [Message,Other]),
383            ct:fail({unexpected,Other})
384    after 5000 ->
385              io:format("Expected ~p; got nothing", [Message]),
386              ct:fail(no_trace_message)
387    end;
388expect({trace_ts,E1,E2,E3,E4,ts}=Message) ->
389    receive
390        {trace_ts,E1,E2,E3,E4,_Ts}=MessageTs ->
391            ok = io:format("Expected and got ~p", [MessageTs]),
392            MessageTs;
393        Other ->
394            io:format("Expected ~p; got ~p", [Message,Other]),
395            ct:fail({unexpected,Other})
396    after 5000 ->
397              io:format("Expected ~p; got nothing", [Message]),
398              ct:fail(no_trace_message)
399    end;
400expect(Message) ->
401    receive
402        Message ->
403            ok = io:format("Expected and got ~p", [Message]),
404            Message;
405        Other ->
406            io:format("Expected ~p; got ~p", [Message,Other]),
407            ct:fail({unexpected,Other})
408    after 5000 ->
409              io:format("Expected ~p; got nothing", [Message]),
410              ct:fail(no_trace_message)
411    end.
412
413trac(What, On, Flags0) ->
414    Flags = [{tracer,get(tracer_port)}|Flags0],
415    get(tracer) ! {apply,self(),{erlang,trace,[What,On,Flags]}},
416    Res = receive
417              {apply_result,Result} -> Result
418          end,
419    ok = io:format("erlang:trace(~p, ~p, ~p) -> ~p",
420                   [What,On,Flags,Res]),
421    Res.
422
423trace_info(What, Key) ->
424    get(tracer) ! {apply,self(),{erlang,trace_info,[What,Key]}},
425    Res = receive
426              {apply_result,Result} -> Result
427          end,
428    ok = io:format("erlang:trace_info(~p, ~p) -> ~p",
429                   [What,Key,Res]),
430    Res.
431
432trace_func(MFA, MatchProg) ->
433    get(tracer) ! {apply,self(),{erlang,trace_pattern,[MFA,MatchProg]}},
434    Res = receive
435              {apply_result,Result} -> Result
436          end,
437    ok = io:format("erlang:trace_pattern(~p, ~p) -> ~p", [MFA,MatchProg,Res]),
438    Res.
439
440trace_func(MFA, MatchProg, Flags) ->
441    get(tracer) ! {apply,self(),{erlang,trace_pattern,[MFA,MatchProg,Flags]}},
442    Res = receive
443              {apply_result,Result} -> Result
444          end,
445    ok = io:format("erlang:trace_pattern(~p, ~p) -> ~p", [MFA,MatchProg,Res]),
446    Res.
447
448trace_pid(Pid, On, Flags0) ->
449    Flags = [{tracer,get(tracer_port)}|Flags0],
450    get(tracer) ! {apply,self(),{erlang,trace,[Pid,On,Flags]}},
451    Res = receive
452              {apply_result,Result} -> Result
453          end,
454    ok = io:format("erlang:trace(~p, ~p, ~p) -> ~p",
455                   [Pid,On,Flags,Res]),
456    Res.
457
458start_tracer(Config) ->
459    Path = proplists:get_value(data_dir, Config),
460    ok = load_driver(Path, echo_drv),
461    Self = self(),
462    put(tracer, fun_spawn(fun() -> tracer(Self) end)),
463    receive
464        {started,Port} ->
465            put(tracer_port, Port)
466    end,
467    get(tracer).
468
469load_driver(Dir, Driver) ->
470    case erl_ddll:load_driver(Dir, Driver) of
471        ok -> ok;
472        {error, Error} = Res ->
473            io:format("~s\n", [erl_ddll:format_error(Error)]),
474            Res
475    end.
476
477tracer(RelayTo) ->
478    Port = open_port({spawn,echo_drv}, [eof,binary]),
479    RelayTo ! {started,Port},
480    tracer_loop(RelayTo, Port).
481
482tracer_loop(RelayTo, Port) ->
483    receive
484        {apply,From,{M,F,A}} ->
485            From ! {apply_result,apply(M, F, A)},
486            tracer_loop(RelayTo, Port);
487        {Port,{data,Msg}} ->
488            RelayTo ! binary_to_term(Msg),
489            tracer_loop(RelayTo, Port);
490        {unlink_tracer_port, From} ->
491            unlink(Port),
492            From ! {unlinked_tracer_port, self()},
493            tracer_loop(RelayTo, Port);
494        Other ->
495            exit({bad_message,Other})
496    end.
497
498fun_spawn(Fun) ->
499    spawn_link(erlang, apply, [Fun,[]]).
500
501fun_spawn(Fun, Opts) ->
502    spawn_opt(erlang, apply, [Fun,[]], [link | Opts]).
503
504% flush() ->
505%     receive
506% 	X ->
507% 	    [X | flush()]
508%     after 2000 ->
509% 	    []
510%     end.
511
512
513%%% Models for various kinds of processes.
514
515%% Sends messages when ordered to.
516
517sender() ->
518    receive
519        {send_please, To, What} ->
520            To ! What,
521            sender()
522    end.
523
524%% Just consumes messages from its message queue.
525
526receiver() ->
527    receive
528        _Any -> receiver()
529    end.
530
531%% Does a garbage collection when it receives a message.
532
533garber() ->
534    receive
535        _Any ->
536            lists:seq(1, 100),
537            erlang:garbage_collect(),
538            garber()
539    end.
540
541%% All-purpose process
542
543general() ->
544    receive
545        {apply, {M, F, Args}} ->
546            erlang:apply(M, F, Args),
547            general();
548        {send, Dest, Msg} ->
549            Dest ! Msg,
550            general();
551        {call_f_1, Arg} ->
552            f(Arg),
553            general();
554        nop ->
555            general()
556    end.
557
558f(Arg) ->
559    Arg.
560