adding trace runner for better debugging

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
new 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
new 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
new 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]).