diff options
author | Ulf Wiger <ulf@feuerlabs.com> | 2016-03-15 14:51:50 -0700 |
---|---|---|
committer | Ulf Wiger <ulf@feuerlabs.com> | 2016-03-15 14:51:50 -0700 |
commit | d1670d49c7c45dbbe7e23daa1bf02d1e39a75c2e (patch) | |
tree | 1c555e44555df7f85139fe2289b7d70a476727d2 | |
parent | 23b36f7a70d5fbc1f4261bad8cb49d266c40debd (diff) | |
download | rvi_core-d1670d49c7c45dbbe7e23daa1bf02d1e39a75c2e.tar.gz |
adding trace runner for better debugging
-rw-r--r-- | components/service_edge/src/service_edge_rpc.erl | 32 | ||||
-rw-r--r-- | deps/trace_runner/.gitignore | 10 | ||||
-rw-r--r-- | deps/trace_runner/LICENSE | 373 | ||||
-rw-r--r-- | deps/trace_runner/Makefile | 9 | ||||
-rw-r--r-- | deps/trace_runner/README.md | 120 | ||||
-rw-r--r-- | deps/trace_runner/doc/images/ttb-log-snap-1.png | bin | 0 -> 15391 bytes | |||
-rw-r--r-- | deps/trace_runner/doc/images/ttb-log-snap-2.png | bin | 0 -> 98930 bytes | |||
-rw-r--r-- | deps/trace_runner/doc/images/ttb-log-snap.png | bin | 0 -> 83352 bytes | |||
-rw-r--r-- | deps/trace_runner/include/trace_runner.hrl | 29 | ||||
-rw-r--r-- | deps/trace_runner/src/tr_ttb.erl | 213 | ||||
-rw-r--r-- | deps/trace_runner/src/trace_runner.app.src | 22 | ||||
-rw-r--r-- | rebar.config | 3 | ||||
-rw-r--r-- | test/rvi_core_SUITE.erl | 57 |
13 files changed, 852 insertions, 16 deletions
diff --git a/components/service_edge/src/service_edge_rpc.erl b/components/service_edge/src/service_edge_rpc.erl index bee503e..4a61088 100644 --- a/components/service_edge/src/service_edge_rpc.erl +++ b/components/service_edge/src/service_edge_rpc.erl @@ -39,13 +39,15 @@ -export([service_available/3, service_unavailable/3]). - +-export([record_fields/1]). %%-include_lib("lhttpc/include/lhttpc.hrl"). -include_lib("lager/include/log.hrl"). -include_lib("rvi_common/include/rvi_common.hrl"). +-include_lib("trace_runner/include/trace_runner.hrl"). + -define(SERVER, ?MODULE). @@ -62,7 +64,10 @@ url = undefined %% URL where the service can be reached. }). - +record_fields(service_entry) -> record_info(fields, service_entry); +record_fields(st ) -> record_info(fields, st); +record_fields(component_spec) -> record_info(fields, component_spec); +record_fields(_) -> no. start_link() -> gen_server:start_link({local, ?SERVER}, ?MODULE, [], []). @@ -180,6 +185,7 @@ start_websocket() -> %% Invoked by service_discovery to announce service availability %% Must be handled either as a JSON-RPC call or a gen_server call. service_available(CompSpec, SvcName, DataLinkModule) -> + ?event({service_available, SvcName}), rvi_common:notification(service_edge, ?MODULE, service_available, [{ service, SvcName }, @@ -187,12 +193,14 @@ service_available(CompSpec, SvcName, DataLinkModule) -> service_unavailable(CompSpec, SvcName, DataLinkModule) -> + ?event({service_unavailable, SvcName}), rvi_common:notification(service_edge, ?MODULE, service_unavailable, [{ service, SvcName }, { data_link_module, DataLinkModule }], CompSpec). handle_remote_message(CompSpec, Conn, SvcName, Timeout, Params) -> + ?event({handle_remote_message, [Conn, SvcName, Timeout, Params]}), {IP, Port} = Conn, rvi_common:notification(service_edge, ?MODULE, handle_remote_message, @@ -207,6 +215,7 @@ handle_remote_message(CompSpec, Conn, SvcName, Timeout, Params) -> %% A message originated from a locally connected service %% has timed out handle_local_timeout(CompSpec, SvcName, TransID) -> + ?event({handle_local_timeout, [SvcName, TransID]}), rvi_common:notification(service_edge, ?SERVER, handle_local_timeout, [ { service, SvcName}, { transaction_id, TransID} ], @@ -220,6 +229,7 @@ handle_websocket(WSock, Mesg, Arg) -> ?debug("Failed decode of ~p: ~p", [Mesg, E0]), Mesg end, + ?event({handle_websocket, Decoded}), ?debug("Decoded Mesg = ~p", [Decoded]), { ok, Method } = rvi_common:get_json_element(["method"], Mesg), { ok, Params0 } = rvi_common:get_json_element(["params"], Mesg), @@ -248,6 +258,7 @@ handle_ws_json_rpc(WSock, <<"message">>, Params, _Arg ) -> { ok, Timeout } = rvi_common:get_json_element(["timeout"], Params), { ok, Parameters } = rvi_common:get_json_element(["parameters"], Params), SvcName = iolist_to_binary(SvcName0), + ?event({message, ws, [SvcName, Timeout, Parameters]}), ?debug("WS Parameters: ~p", [Parameters]), %% Parameters = parse_ws_params(Parameters0), LogId = log_id_json_tail(Params ++ Parameters), @@ -270,6 +281,7 @@ handle_ws_json_rpc(WSock, <<"message">>, Params, _Arg ) -> handle_ws_json_rpc(WSock, <<"register_service">>, Params,_Arg ) -> { ok, SvcName } = rvi_common:get_json_element(["service_name"], Params), + ?event({register_service, ws, SvcName}), ?debug("service_edge_rpc:websocket_register(~p) service: ~p", [ WSock, SvcName ]), [ok, FullSvcName ] = gen_server:call(?SERVER, { rvi, @@ -283,6 +295,7 @@ handle_ws_json_rpc(WSock, <<"register_service">>, Params,_Arg ) -> handle_ws_json_rpc(WSock, <<"unregister_service">>, Params, _Arg ) -> { ok, SvcName } = rvi_common:get_json_element(["service_name"], Params), + ?event({unregister_service, ws, SvcName}), ?debug("service_edge_rpc:websocket_unregister(~p) service: ~p", [ WSock, SvcName ]), gen_server:call(?SERVER, { rvi, unregister_local_service, [ SvcName ]}), { ok, [ { status, rvi_common:json_rpc_status(ok)} ]}; @@ -310,6 +323,7 @@ handle_ws_json_rpc(_Ws , <<"get_available_services">>, _Params, _Arg ) -> %% handle_rpc(<<"register_service">>, Args) -> {ok, SvcName} = rvi_common:get_json_element([<<"service">>], Args), + ?event({register_service, json_rpc, SvcName}), {ok, URL} = rvi_common:get_json_element([<<"network_address">>], Args), [ok, FullSvcName ] = gen_server:call(?SERVER, { rvi, register_local_service, @@ -323,6 +337,7 @@ handle_rpc(<<"register_service">>, Args) -> handle_rpc(<<"unregister_service">>, Args) -> {ok, SvcName} = rvi_common:get_json_element(["service"], Args), + ?event({unregister_service, json_rpc, SvcName}), gen_server:call(?SERVER, { rvi, unregister_local_service, [ SvcName]}), {ok, [ { status, rvi_common:json_rpc_status(ok) }, { method, <<"unregister_service">>} @@ -341,6 +356,7 @@ handle_rpc(<<"message">>, Args) -> {ok, SvcName} = rvi_common:get_json_element(["service_name"], Args), {ok, Timeout} = rvi_common:get_json_element(["timeout"], Args), {ok, Parameters} = rvi_common:get_json_element(["parameters"], Args), + ?event({message, json_rpc, [SvcName, Timeout, Parameters]}), LogId = log_id_json_tail(Args ++ Parameters), [ Res, TID ] = gen_server:call(?SERVER, { rvi, handle_local_message, [ SvcName, Timeout, Parameters | LogId]}), @@ -364,7 +380,7 @@ handle_notification(<<"service_available">>, Args) -> [ SvcName, DataLinkModule ]}), ok; -handle_notification("service_unavailable", Args) -> +handle_notification(<<"service_unavailable">>, Args) -> {ok, SvcName} = rvi_common:get_json_element(["service"], Args), {ok, DataLinkModule} = rvi_common:get_json_element(["data_link_module"], Args), ?debug("service_edge:service_unavailable(): service: ~p", [ SvcName]), @@ -514,6 +530,7 @@ handle_cast({rvi, handle_remote_message, Timeout, Parameters ] }, #st{cs = CS} = St) -> + ?event({handle_remote_message, [IP, Port, SvcName, Timeout]}, St), spawn(fun() -> handle_remote_message_( IP, Port, SvcName, Timeout, Parameters, CS) @@ -629,9 +646,10 @@ do_handle_local_message_([SvcName, TimeoutArg, Parameters | _Tail], CS) -> LookupRes = ets:lookup(?SERVICE_TABLE, SvcName), ?debug("Service LookupRes = ~p", [LookupRes]), case LookupRes of - [ #service_entry { url = URL } ] -> %% SvcName is local. Forward message + [ #service_entry { url = URL } = E ] -> %% SvcName is local. Forward message ?debug("service_edge_rpc:local_msg(): Service is local. Forwarding."), log("dispatch to ~s", [URL], CS), + ?event({matching_service_entry, E}), Res = forward_message_to_local_service(URL, SvcName, Parameters, @@ -743,7 +761,8 @@ forward_message_to_local_service(URL,SvcName, Parameters, CompSpec) -> SvcName, CompSpec) catch Tag:Err -> - ?debug("Caught ~p:~p", [Tag,Err]) + ?error("Caught ~p:~p~n~p", + [Tag,Err,erlang:get_stacktrace()]) end end), timer:sleep(500), @@ -831,3 +850,6 @@ log_id_json_tail(Args) -> {error, _} -> [] end. + +event(_, _, _) -> + ok. diff --git a/deps/trace_runner/.gitignore b/deps/trace_runner/.gitignore new file mode 100644 index 0000000..8e46d5a --- /dev/null +++ b/deps/trace_runner/.gitignore @@ -0,0 +1,10 @@ +.eunit +deps +*.o +*.beam +*.plt +erl_crash.dump +ebin +rel/example_project +.concrete/DEV_MODE +.rebar diff --git a/deps/trace_runner/LICENSE b/deps/trace_runner/LICENSE new file mode 100644 index 0000000..a612ad9 --- /dev/null +++ b/deps/trace_runner/LICENSE @@ -0,0 +1,373 @@ +Mozilla Public License Version 2.0 +================================== + +1. Definitions +-------------- + +1.1. "Contributor" + means each individual or legal entity that creates, contributes to + the creation of, or owns Covered Software. + +1.2. "Contributor Version" + means the combination of the Contributions of others (if any) used + by a Contributor and that particular Contributor's Contribution. + +1.3. "Contribution" + means Covered Software of a particular Contributor. + +1.4. "Covered Software" + means Source Code Form to which the initial Contributor has attached + the notice in Exhibit A, the Executable Form of such Source Code + Form, and Modifications of such Source Code Form, in each case + including portions thereof. + +1.5. "Incompatible With Secondary Licenses" + means + + (a) that the initial Contributor has attached the notice described + in Exhibit B to the Covered Software; or + + (b) that the Covered Software was made available under the terms of + version 1.1 or earlier of the License, but not also under the + terms of a Secondary License. + +1.6. "Executable Form" + means any form of the work other than Source Code Form. + +1.7. "Larger Work" + means a work that combines Covered Software with other material, in + a separate file or files, that is not Covered Software. + +1.8. "License" + means this document. + +1.9. "Licensable" + means having the right to grant, to the maximum extent possible, + whether at the time of the initial grant or subsequently, any and + all of the rights conveyed by this License. + +1.10. "Modifications" + means any of the following: + + (a) any file in Source Code Form that results from an addition to, + deletion from, or modification of the contents of Covered + Software; or + + (b) any new file in Source Code Form that contains any Covered + Software. + +1.11. "Patent Claims" of a Contributor + means any patent claim(s), including without limitation, method, + process, and apparatus claims, in any patent Licensable by such + Contributor that would be infringed, but for the grant of the + License, by the making, using, selling, offering for sale, having + made, import, or transfer of either its Contributions or its + Contributor Version. + +1.12. "Secondary License" + means either the GNU General Public License, Version 2.0, the GNU + Lesser General Public License, Version 2.1, the GNU Affero General + Public License, Version 3.0, or any later versions of those + licenses. + +1.13. "Source Code Form" + means the form of the work preferred for making modifications. + +1.14. "You" (or "Your") + means an individual or a legal entity exercising rights under this + License. For legal entities, "You" includes any entity that + controls, is controlled by, or is under common control with You. For + purposes of this definition, "control" means (a) the power, direct + or indirect, to cause the direction or management of such entity, + whether by contract or otherwise, or (b) ownership of more than + fifty percent (50%) of the outstanding shares or beneficial + ownership of such entity. + +2. License Grants and Conditions +-------------------------------- + +2.1. Grants + +Each Contributor hereby grants You a world-wide, royalty-free, +non-exclusive license: + +(a) under intellectual property rights (other than patent or trademark) + Licensable by such Contributor to use, reproduce, make available, + modify, display, perform, distribute, and otherwise exploit its + Contributions, either on an unmodified basis, with Modifications, or + as part of a Larger Work; and + +(b) under Patent Claims of such Contributor to make, use, sell, offer + for sale, have made, import, and otherwise transfer either its + Contributions or its Contributor Version. + +2.2. Effective Date + +The licenses granted in Section 2.1 with respect to any Contribution +become effective for each Contribution on the date the Contributor first +distributes such Contribution. + +2.3. Limitations on Grant Scope + +The licenses granted in this Section 2 are the only rights granted under +this License. No additional rights or licenses will be implied from the +distribution or licensing of Covered Software under this License. +Notwithstanding Section 2.1(b) above, no patent license is granted by a +Contributor: + +(a) for any code that a Contributor has removed from Covered Software; + or + +(b) for infringements caused by: (i) Your and any other third party's + modifications of Covered Software, or (ii) the combination of its + Contributions with other software (except as part of its Contributor + Version); or + +(c) under Patent Claims infringed by Covered Software in the absence of + its Contributions. + +This License does not grant any rights in the trademarks, service marks, +or logos of any Contributor (except as may be necessary to comply with +the notice requirements in Section 3.4). + +2.4. Subsequent Licenses + +No Contributor makes additional grants as a result of Your choice to +distribute the Covered Software under a subsequent version of this +License (see Section 10.2) or under the terms of a Secondary License (if +permitted under the terms of Section 3.3). + +2.5. Representation + +Each Contributor represents that the Contributor believes its +Contributions are its original creation(s) or it has sufficient rights +to grant the rights to its Contributions conveyed by this License. + +2.6. Fair Use + +This License is not intended to limit any rights You have under +applicable copyright doctrines of fair use, fair dealing, or other +equivalents. + +2.7. Conditions + +Sections 3.1, 3.2, 3.3, and 3.4 are conditions of the licenses granted +in Section 2.1. + +3. Responsibilities +------------------- + +3.1. Distribution of Source Form + +All distribution of Covered Software in Source Code Form, including any +Modifications that You create or to which You contribute, must be under +the terms of this License. You must inform recipients that the Source +Code Form of the Covered Software is governed by the terms of this +License, and how they can obtain a copy of this License. You may not +attempt to alter or restrict the recipients' rights in the Source Code +Form. + +3.2. Distribution of Executable Form + +If You distribute Covered Software in Executable Form then: + +(a) such Covered Software must also be made available in Source Code + Form, as described in Section 3.1, and You must inform recipients of + the Executable Form how they can obtain a copy of such Source Code + Form by reasonable means in a timely manner, at a charge no more + than the cost of distribution to the recipient; and + +(b) You may distribute such Executable Form under the terms of this + License, or sublicense it under different terms, provided that the + license for the Executable Form does not attempt to limit or alter + the recipients' rights in the Source Code Form under this License. + +3.3. Distribution of a Larger Work + +You may create and distribute a Larger Work under terms of Your choice, +provided that You also comply with the requirements of this License for +the Covered Software. If the Larger Work is a combination of Covered +Software with a work governed by one or more Secondary Licenses, and the +Covered Software is not Incompatible With Secondary Licenses, this +License permits You to additionally distribute such Covered Software +under the terms of such Secondary License(s), so that the recipient of +the Larger Work may, at their option, further distribute the Covered +Software under the terms of either this License or such Secondary +License(s). + +3.4. Notices + +You may not remove or alter the substance of any license notices +(including copyright notices, patent notices, disclaimers of warranty, +or limitations of liability) contained within the Source Code Form of +the Covered Software, except that You may alter any license notices to +the extent required to remedy known factual inaccuracies. + +3.5. Application of Additional Terms + +You may choose to offer, and to charge a fee for, warranty, support, +indemnity or liability obligations to one or more recipients of Covered +Software. However, You may do so only on Your own behalf, and not on +behalf of any Contributor. You must make it absolutely clear that any +such warranty, support, indemnity, or liability obligation is offered by +You alone, and You hereby agree to indemnify every Contributor for any +liability incurred by such Contributor as a result of warranty, support, +indemnity or liability terms You offer. You may include additional +disclaimers of warranty and limitations of liability specific to any +jurisdiction. + +4. Inability to Comply Due to Statute or Regulation +--------------------------------------------------- + +If it is impossible for You to comply with any of the terms of this +License with respect to some or all of the Covered Software due to +statute, judicial order, or regulation then You must: (a) comply with +the terms of this License to the maximum extent possible; and (b) +describe the limitations and the code they affect. Such description must +be placed in a text file included with all distributions of the Covered +Software under this License. Except to the extent prohibited by statute +or regulation, such description must be sufficiently detailed for a +recipient of ordinary skill to be able to understand it. + +5. Termination +-------------- + +5.1. The rights granted under this License will terminate automatically +if You fail to comply with any of its terms. However, if You become +compliant, then the rights granted under this License from a particular +Contributor are reinstated (a) provisionally, unless and until such +Contributor explicitly and finally terminates Your grants, and (b) on an +ongoing basis, if such Contributor fails to notify You of the +non-compliance by some reasonable means prior to 60 days after You have +come back into compliance. Moreover, Your grants from a particular +Contributor are reinstated on an ongoing basis if such Contributor +notifies You of the non-compliance by some reasonable means, this is the +first time You have received notice of non-compliance with this License +from such Contributor, and You become compliant prior to 30 days after +Your receipt of the notice. + +5.2. If You initiate litigation against any entity by asserting a patent +infringement claim (excluding declaratory judgment actions, +counter-claims, and cross-claims) alleging that a Contributor Version +directly or indirectly infringes any patent, then the rights granted to +You by any and all Contributors for the Covered Software under Section +2.1 of this License shall terminate. + +5.3. In the event of termination under Sections 5.1 or 5.2 above, all +end user license agreements (excluding distributors and resellers) which +have been validly granted by You or Your distributors under this License +prior to termination shall survive termination. + +************************************************************************ +* * +* 6. Disclaimer of Warranty * +* ------------------------- * +* * +* Covered Software is provided under this License on an "as is" * +* basis, without warranty of any kind, either expressed, implied, or * +* statutory, including, without limitation, warranties that the * +* Covered Software is free of defects, merchantable, fit for a * +* particular purpose or non-infringing. The entire risk as to the * +* quality and performance of the Covered Software is with You. * +* Should any Covered Software prove defective in any respect, You * +* (not any Contributor) assume the cost of any necessary servicing, * +* repair, or correction. This disclaimer of warranty constitutes an * +* essential part of this License. No use of any Covered Software is * +* authorized under this License except under this disclaimer. * +* * +************************************************************************ + +************************************************************************ +* * +* 7. Limitation of Liability * +* -------------------------- * +* * +* Under no circumstances and under no legal theory, whether tort * +* (including negligence), contract, or otherwise, shall any * +* Contributor, or anyone who distributes Covered Software as * +* permitted above, be liable to You for any direct, indirect, * +* special, incidental, or consequential damages of any character * +* including, without limitation, damages for lost profits, loss of * +* goodwill, work stoppage, computer failure or malfunction, or any * +* and all other commercial damages or losses, even if such party * +* shall have been informed of the possibility of such damages. This * +* limitation of liability shall not apply to liability for death or * +* personal injury resulting from such party's negligence to the * +* extent applicable law prohibits such limitation. Some * +* jurisdictions do not allow the exclusion or limitation of * +* incidental or consequential damages, so this exclusion and * +* limitation may not apply to You. * +* * +************************************************************************ + +8. Litigation +------------- + +Any litigation relating to this License may be brought only in the +courts of a jurisdiction where the defendant maintains its principal +place of business and such litigation shall be governed by laws of that +jurisdiction, without reference to its conflict-of-law provisions. +Nothing in this Section shall prevent a party's ability to bring +cross-claims or counter-claims. + +9. Miscellaneous +---------------- + +This License represents the complete agreement concerning the subject +matter hereof. If any provision of this License is held to be +unenforceable, such provision shall be reformed only to the extent +necessary to make it enforceable. Any law or regulation which provides +that the language of a contract shall be construed against the drafter +shall not be used to construe this License against a Contributor. + +10. Versions of the License +--------------------------- + +10.1. New Versions + +Mozilla Foundation is the license steward. Except as provided in Section +10.3, no one other than the license steward has the right to modify or +publish new versions of this License. Each version will be given a +distinguishing version number. + +10.2. Effect of New Versions + +You may distribute the Covered Software under the terms of the version +of the License under which You originally received the Covered Software, +or under the terms of any subsequent version published by the license +steward. + +10.3. Modified Versions + +If you create software not governed by this License, and you want to +create a new license for such software, you may create and use a +modified version of this License if you rename the license and remove +any references to the name of the license steward (except to note that +such modified license differs from this License). + +10.4. Distributing Source Code Form that is Incompatible With Secondary +Licenses + +If You choose to distribute Source Code Form that is Incompatible With +Secondary Licenses under the terms of this version of the License, the +notice described in Exhibit B of this License must be attached. + +Exhibit A - Source Code Form License Notice +------------------------------------------- + + This Source Code Form is subject to the terms of the Mozilla Public + License, v. 2.0. If a copy of the MPL was not distributed with this + file, You can obtain one at http://mozilla.org/MPL/2.0/. + +If it is not possible or desirable to put the notice in a particular +file, then You may include the notice in a location (such as a LICENSE +file in a relevant directory) where a recipient would be likely to look +for such a notice. + +You may add additional accurate notices of copyright ownership. + +Exhibit B - "Incompatible With Secondary Licenses" Notice +--------------------------------------------------------- + + This Source Code Form is "Incompatible With Secondary Licenses", as + defined by the Mozilla Public License, v. 2.0. diff --git a/deps/trace_runner/Makefile b/deps/trace_runner/Makefile new file mode 100644 index 0000000..a0c2cba --- /dev/null +++ b/deps/trace_runner/Makefile @@ -0,0 +1,9 @@ +.PHONY: all clean compile + +all: compile + +compile: + rebar compile + +clean: + rebar clean diff --git a/deps/trace_runner/README.md b/deps/trace_runner/README.md new file mode 100644 index 0000000..51b9141 --- /dev/null +++ b/deps/trace_runner/README.md @@ -0,0 +1,120 @@ +# trace_runner +A wrapper for tracing test runs using TTB. + +This component is based on [locks_ttb](https://github.com/uwiger/locks/blob/master/src/locks_ttb.erl), whose main purpose was to be used in complicated +multi-node test cases: a wrapper around the test case sets up a multi-node +trace using ttb; if the test case succeeds, the traces are discarded, but +if it fails, the logs are fetched, merged and formatted for 'easy' viewing. + +The idea is complemented with the notion of using an `event()` function, +whose only purpose is to be traced. This can serve as extremely lightweight +runtime debugging statements. Since the `event()` function only returns +`ok`, the whole operation is cheaper than any runtime test for debug level +could be. the `include/trace_runner.hrl` include file defines `?event` +macros that can be used, including one that tests whether the `event()` +function is traced, before evaluating the argument expression. This can +be used to 'pretty-print' the arguments to the `event()` function without +incurring overhead when not tracing (obviously there is *some* overhead in +checking the trace status). + +Example (from https://github.com/PDXOstc/rvi_core, although at the time of writing, the trace_runner support hasn't yet been merged) + +First, we create a callback module for the `tr_ttb` behavior, which +lets us specify trace patterns and trace flags. + +```erlang +patterns() -> + [{authorize_rpc , event, 3, []}, + {service_edge_rpc , event, 3, []}, + {service_discovery_rpc, event, 3, []}, + {dlink_tcp_rpc , event, 3, []}, + {connection , event, 3, []}, + {dlink_tls_rpc , event, 3, []}, + {dlink_tls_conn , event, 3, []}, + {dlink_bt_rpc , event, 3, []}, + {bt_connection , event, 3, []}, + {dlink_sms_rpc , event, 3, []}, + {schedule_rpc , event, 3, []}, + {proto_json_rpc , event, 3, []}, + {proto_msgpack_rpc , event, 3, []}, + {rvi_common , event, 3, []}, + {?MODULE , event, 3, []} + | tr_ttb:default_patterns()]. + +flags() -> + {all, call}. +``` + +Then, we instrument our test suite(s): + +```erlang +t_multicall_sota_service(Config) -> + with_trace(fun t_multicall_sota_service_/1, Config, + "t_multicall_sota_service"). + +t_multicall_sota_service_(_Config) -> + %% the actual test case + Data = <<"abc">>, + ... +``` + +In the wrapper, we determine which nodes to include in the trace, +give the trace a name, then call the test case within a try ... catch. +If the test succeeds, we call `stop_nofetch()`, discarding the trace, +otherwise, we fetch the trace logs and merge them, pretty-printing +the result. + +```erlang +with_trace(F, Config, File) -> + Nodes = [N || {N,_} <- get_nodes()], + rvi_ttb:on_nodes([node()|Nodes], File), + try F(Config) + catch + error:R -> + Stack = erlang:get_stacktrace(), + ttb_stop(), + ct:log("Error ~p; Stack = ~p", [R, Stack]), + erlang:error(R); + exit:R -> + ttb_stop(), + exit(R) + end, + rvi_ttb:stop_nofetch(), + ok. + +ttb_stop() -> + Dir = rvi_ttb:stop(), + Out = filename:join(filename:dirname(Dir), + filename:basename(Dir) ++ ".txt"), + rvi_ttb:format(Dir, Out), + ct:log("Formatted trace log in ~s~n", [Out]). +``` + +On test failure, this would result in the following output in the CT log: + +<img src="doc/images/ttb-log-snap-1.png" alt="trace log snapshot 2" style="width:800"> + +The formatted text log has an emacs erlang-mode header, so is best +viewed in emacs. + +<img src="doc/images/ttb-log-snap.png" alt="trace log snapshot" style="width:800"> + +Note that the log formatter prefixes each message with the relative time +(in ms) since the start of the trace, the name of the node where the +trace event originated and the module/line of the traced call. +It also tries to pretty-print records, looking for a +`record_fields(RecName)` callback in the module named in the call trace. + +<img src="doc/images/ttb-log-snap-2.png" alt="trace log snapshot 2" style="width:800"> + +A `record_fields/1` function might look like this: + +```erlang +record_fields(service_entry) -> record_info(fields, service_entry); +record_fields(st ) -> record_info(fields, st); +record_fields(component_spec) -> record_info(fields, component_spec); +record_fields(_) -> no. +``` + +In the future, more log formatting options may be added. +Pull requests are welcome. diff --git a/deps/trace_runner/doc/images/ttb-log-snap-1.png b/deps/trace_runner/doc/images/ttb-log-snap-1.png Binary files differnew file mode 100644 index 0000000..e279ec4 --- /dev/null +++ b/deps/trace_runner/doc/images/ttb-log-snap-1.png diff --git a/deps/trace_runner/doc/images/ttb-log-snap-2.png b/deps/trace_runner/doc/images/ttb-log-snap-2.png Binary files differnew file mode 100644 index 0000000..75d502b --- /dev/null +++ b/deps/trace_runner/doc/images/ttb-log-snap-2.png diff --git a/deps/trace_runner/doc/images/ttb-log-snap.png b/deps/trace_runner/doc/images/ttb-log-snap.png Binary files differnew file mode 100644 index 0000000..75cee87 --- /dev/null +++ b/deps/trace_runner/doc/images/ttb-log-snap.png diff --git a/deps/trace_runner/include/trace_runner.hrl b/deps/trace_runner/include/trace_runner.hrl new file mode 100644 index 0000000..353c258 --- /dev/null +++ b/deps/trace_runner/include/trace_runner.hrl @@ -0,0 +1,29 @@ +%% -*- mode: erlang; indent-tabs-mode: nil; -*- +%%---- BEGIN COPYRIGHT ------------------------------------------------------- +%% +%% Copyright (C) 2016 Ulf Wiger. All rights reserved. +%% +%% This Source Code Form is subject to the terms of the Mozilla Public +%% License, v. 2.0. If a copy of the MPL was not distributed with this +%% file, You can obtain one at http://mozilla.org/MPL/2.0/. +%% +%%---- END COPYRIGHT --------------------------------------------------------- + +-ifndef(event). + +-define(costly_event(E), + case erlang:trace_info({MODULE,event,3}, traced) of + {_, false} -> ok; + _ -> event(?LINE, E, none) + end). + +-define(costly_event(E, S), + case erlang:trace_info({MODULE,event,3}, traced) of + {_, false} -> ok; + _ -> event(?LINE, E, S) + end). + +-define(event(E), event(?LINE, E, none)). +-define(event(E, S), event(?LINE, E, S)). + +-endif. % ?event() diff --git a/deps/trace_runner/src/tr_ttb.erl b/deps/trace_runner/src/tr_ttb.erl new file mode 100644 index 0000000..339b28f --- /dev/null +++ b/deps/trace_runner/src/tr_ttb.erl @@ -0,0 +1,213 @@ +%% -*- mode: erlang; indent-tabs-mode: nil; -*- +%%---- BEGIN COPYRIGHT ------------------------------------------------------- +%% +%% Copyright (C) 2016 Ulf Wiger. All rights reserved. +%% +%% This Source Code Form is subject to the terms of the Mozilla Public +%% License, v. 2.0. If a copy of the MPL was not distributed with this +%% file, You can obtain one at http://mozilla.org/MPL/2.0/. +%% +%%---- END COPYRIGHT --------------------------------------------------------- +-module(tr_ttb). + +-export([ event/1 ]). + +-export([ + on_nodes/2, + on_nodes/3, + on_nodes/4, + default_patterns/0, + default_flags/0, + stop/0, + stop_nofetch/0, + format/1, + format/2, + format_opts/0, + format_opts/1, + handler/4, + pp/3, + record_print_fun/1 + ]). + +-type trace_pat() :: any(). +-type pattern() :: {module(), atom(), arity(), trace_pat()}. + +-callback flags() -> [{atom(), any()}]. +-callback patterns() -> [pattern()]. + + +%% This function is also traced. Can be used to insert markers in the trace +%% log. +event(E) -> + event(?LINE, E, none). + +event(_, _, _) -> + ok. + +on_nodes(Ns, File) -> + on_nodes(Ns, default_patterns(), default_flags(), [{file, File}]). + +on_nodes(Ns, File, Mod) -> + on_nodes(Ns, + cb(Mod, patterns, [], default_patterns()), + cb(Mod, flags, [], default_flags()), + [{mod, Mod}, {file, File}]). + +on_nodes(Ns, Patterns, Flags, Opts) -> + ttb:start_trace(Ns, Patterns, Flags, lists:keydelete(mod, 1, Opts)). + +default_patterns() -> + [{?MODULE , event, 3, []}]. + +default_flags() -> + {all, call}. + +stop() -> + {stopped, Dir} = ttb:stop([return_fetch_dir]), + Dir. + +stop_nofetch() -> + ttb:stop([nofetch]). + +format(Dir) -> + format(Dir, standard_io). + +format(Dir, OutFile) -> + ttb:format(Dir, format_opts(OutFile)). + +format_opts() -> + format_opts(standard_io). + +format_opts(OutFile) -> + [{out, OutFile}, {handler, {fun handler/4, {0,0}}}]. + +handler(Fd, Trace, _, {Tp,Diff} = Acc) -> + if Acc == {0,0} -> + io:fwrite(Fd, "%% -*- erlang -*-~n", []); + true -> ok + end, + case Trace of + {trace_ts,{_, _, Node}, + call, + {Mod, event, [Line, Evt, State]}, TS} when is_integer(Line) -> + Tdiff = tdiff(TS, Tp), + Diff1 = Diff + Tdiff, + print(Fd, Node, Mod, Line, Evt, State, Diff1), + case get_pids({Evt, State}) of + [] -> ok; + Pids -> + io:fwrite(Fd, " Nodes = ~p~n", [Pids]) + end, + {TS, Diff1}; + _ -> + io:fwrite(Fd, "~p~n", [Trace]), + {Tp, Diff} + end. + +-define(CHAR_MAX, 60). + +print(Fd, N, Mod, L, E, St, T) -> + Tstr = io_lib:fwrite("~w", [T]), + Indent = iolist_size(Tstr) + 3, + Head = io_lib:fwrite(" - ~w|~w/~w: ", [N, Mod, L]), + EvtCol = iolist_size(Head) + 1, + EvtCs = pp(E, EvtCol, Mod), + io:requests(Fd, [{put_chars, unicode, [Tstr, Head, EvtCs]}, nl + | print_tail(St, Mod, Indent)]). + +print_tail(none, _, _Col) -> []; +print_tail(St, Mod, Col) -> + Cs = pp(St, Col+1, Mod), + [{put_chars, unicode, [lists:duplicate(Col,$\s), Cs]}, nl]. + +pp(Term, Col, Mod) -> + io_lib_pretty:print(pp_term(Term), + [{column, Col}, + {line_length, 80}, + {depth, -1}, + {max_chars, ?CHAR_MAX}, + {record_print_fun, record_print_fun(Mod)}]). + +pp_term(D) when element(1,D) == dict -> + try {'$dict', dict:to_list(D)} + catch + error:_ -> + list_to_tuple([pp_term(T) || T <- tuple_to_list(D)]) + end; +pp_term(T) when is_tuple(T) -> + list_to_tuple([pp_term(Trm) || Trm <- tuple_to_list(T)]); +pp_term(L) when is_list(L) -> + [pp_term(T) || T <- L]; +pp_term(T) -> + T. + +tdiff(_, 0) -> 0; +tdiff(TS, T0) -> + %% time difference in milliseconds + timer:now_diff(TS, T0) div 1000. + +record_print_fun(Mod) -> + fun(Tag, NoFields) -> + try Mod:record_fields(Tag) of + Fields when is_list(Fields) -> + case length(Fields) of + NoFields -> Fields; + _ -> no + end; + no -> no + catch + _:_ -> + no + end + end. + +get_pids(Term) -> + Pids = dict:to_list(get_pids(Term, dict:new())), + [{node_prefix(P), N} || {N, P} <- Pids]. + +get_pids(T, Acc) when is_tuple(T) -> + get_pids(tuple_to_list(T), Acc); +get_pids(L, Acc) when is_list(L) -> + get_pids_(L, Acc); +get_pids(P, Acc) when is_pid(P) -> + try ets:lookup(ttb, P) of + [{_, _, Node}] -> + dict:store(Node, P, Acc); + _ -> + Acc + catch + error:_ -> Acc + end; +get_pids(_, Acc) -> + Acc. + +get_pids_([H|T], Acc) -> + get_pids_(T, get_pids(H, Acc)); +get_pids_(_, Acc) -> + Acc. + + +node_prefix(P) -> + case re:run(pid_to_list(P), "[^<\\.]+", [{capture,first,list}]) of + {match, [Pfx]} -> + Pfx; + _ -> + P + end. + +cb(Mod, F, Args, Default) -> + ensure_loaded(Mod), + case erlang:function_exported(Mod, F, length(Args)) of + true -> + apply(Mod, F, Args); + false -> + Default + end. + +ensure_loaded(Mod) -> + case code:ensure_loaded(Mod) of + {module, _} -> + true; + {error, _} -> + false + end. diff --git a/deps/trace_runner/src/trace_runner.app.src b/deps/trace_runner/src/trace_runner.app.src new file mode 100644 index 0000000..0454c1f --- /dev/null +++ b/deps/trace_runner/src/trace_runner.app.src @@ -0,0 +1,22 @@ +%% -*- mode: erlang; indent-tabs-mode: nil; -*- +%%---- BEGIN COPYRIGHT ------------------------------------------------------- +%% +%% Copyright (C) 2016 Ulf Wiger. All rights reserved. +%% +%% This Source Code Form is subject to the terms of the Mozilla Public +%% License, v. 2.0. If a copy of the MPL was not distributed with this +%% file, You can obtain one at http://mozilla.org/MPL/2.0/. +%% +%%---- END COPYRIGHT --------------------------------------------------------- +{application, trace_runner, + [ + {description, "A wrapper for tracing test runs using TTB"}, + {vsn, "1"}, + {registered, []}, + {applications, [ + kernel, + stdlib, + observer + ]}, + {env, []} + ]}. diff --git a/rebar.config b/rebar.config index 09ea971..6533c9e 100644 --- a/rebar.config +++ b/rebar.config @@ -45,7 +45,8 @@ {base64url, ".*", {git, "git://github.com/dvv/base64url.git", "HEAD"}}, {msgpack, ".*", {git, "git://github.com/msgpack/msgpack-erlang.git", "HEAD"}}, {exec, ".*", {git, "git://github.com/saleyn/erlexec.git", "HEAD"}}, - {gproc, ".*", {git, "git://github.com/uwiger/gproc.git", "HEAD"}} + {gproc, ".*", {git, "git://github.com/uwiger/gproc.git", "HEAD"}}, + {trace_runner, ".*", {git, "git://github.com/uwiger/trace_runner.git", "HEAD"}} ]}. {xref_checks, diff --git a/test/rvi_core_SUITE.erl b/test/rvi_core_SUITE.erl index b563755..93b518c 100644 --- a/test/rvi_core_SUITE.erl +++ b/test/rvi_core_SUITE.erl @@ -317,7 +317,11 @@ t_register_sota_service(_Config) -> t_call_sota_service(_Config) -> call_sota_service_(sota_client, sota_bin()). -t_multicall_sota_service(_Config) -> +t_multicall_sota_service(Config) -> + with_trace(fun t_multicall_sota_service_/1, Config, + "t_multicall_sota_service"). + +t_multicall_sota_service_(_Config) -> Data = <<"abc">>, Pids = [spawn_monitor(fun() -> exit({ok, call_sota_service_(N, Data)}) @@ -546,13 +550,17 @@ join_stdout_msgs_rev(L) -> spawn_cmd(Cmd0) -> Cmd = binary_to_list(iolist_to_binary(Cmd0)), Me = self(), - Pid = spawn(fun() -> - Res = exec:run(Cmd, [stdin, stdout, stderr]), - ct:log("~s ->~n~p~n", [Cmd, Res]), - Me ! {self(), ok}, - cmd_loop() - end), + {Pid, Ref} = + spawn_monitor(fun() -> + Res = exec:run(Cmd, [stdin, stdout, stderr]), + ct:log("~s ->~n~p~n", [Cmd, Res]), + Me ! {self(), ok}, + cmd_loop() + end), receive + {'DOWN', Ref, _, _, Reason} -> + error({spawn_cmd, [{cmd, Cmd}, + {error, Reason}]}); {Pid, ok} -> Pid end. @@ -644,7 +652,7 @@ generate_cred(sample, KeyDir, CredDir, _Config) -> " --stop='", Stop, "'" " --root_key=", root_keys(), "/root_key.pem" " --receive='jlr.com/vin/abc/unlock jlr.com/vin/abc/lock'" - " --invoke='jlr.com/backend/set_state'" + " --invoke='jlr.com/vin/abc/lock jlr.com/backend/set_state'" " --jwt_out=", CredDir, "/lock_cred.jwt" " --cred_out=", KeyDir, "/lock_cred.json"]), ok; @@ -677,7 +685,7 @@ generate_sota_cred(sample, KeyDir, CredDir, _Config) -> " --stop='", Stop, "'" " --root_key=", root_keys(), "/root_key.pem" " --receive='jlr.com/vin/abc/store'" - " --invoke='jlr.com/backend/set_state'" + " --invoke='jlr.com/vin/abc/sota jlr.com/backend/set_state'" " --jwt_out=", CredDir, "/sota_cred.jwt" " --cred_out=", KeyDir, "/sota_cred.json"]), ok; @@ -858,12 +866,16 @@ save_ospid(Node) -> %% lookup({Node, pid}). stop_nodes() -> - Nodes = ets:select(?DATA, [{ {{'$1',pid},'$2'}, [], [{{'$1','$2'}}] }]), + Nodes = get_nodes(), ct:log("Stopping, Nodes = ~p~n", [Nodes]), rpc:multicall([N || {N,_} <- Nodes], init, stop, []), [verify_killed(cmd_(["kill -9 ", P], [])) || {_,P} <- Nodes], [delete_node(N) || {N,_} <- Nodes]. +get_nodes() -> + ets:select(?DATA, [{ {{'$1',pid},'$2'}, [], [{{'$1','$2'}}] }]). + + stop_services() -> Services = ets:select(?DATA, [{ {{service,'_'},'_'}, [], ['$_'] }, @@ -948,3 +960,28 @@ log_is_empty(Log, F, Name) -> ct:log("~s: Cannot read log ~s (~p)", [Name, Log, Reason]), false end. + + +with_trace(F, Config, File) -> + Nodes = [N || {N,_} <- get_nodes()], + rvi_ttb:on_nodes([node()|Nodes], File), + try F(Config) + catch + error:R -> + Stack = erlang:get_stacktrace(), + ttb_stop(), + ct:log("Error ~p; Stack = ~p", [R, Stack]), + erlang:error(R); + exit:R -> + ttb_stop(), + exit(R) + end, + rvi_ttb:stop_nofetch(), + ok. + +ttb_stop() -> + Dir = rvi_ttb:stop(), + Out = filename:join(filename:dirname(Dir), + filename:basename(Dir) ++ ".txt"), + rvi_ttb:format(Dir, Out), + ct:log("Formatted trace log in ~s~n", [Out]). |