|
|
# Debugging AmbientTalk using Causeway
|
|
|
|
|
|
# Introduction
|
|
|
|
|
|
As of r1666 the trunk version of AmbientTalk has support for generating a trace log of sent and received asynchronous messages between objects. This trace log can then be used for e.g. analysis or debugging. AmbientTalk's trace log format is based on that of [Waterken](http://waterken.sourceforge.net/debug) and can be visualized in the [Causeway](http://www.erights.org/elang/tools/causeway) distributed debugger. This is a tremendously useful utility for analyzing a message-based distributed application.
|
|
|
|
|
|
# What is Causeway?
|
|
|
|
|
|
Causeway is a "post-mortem" distributed debugger. It works based on log files that are generated by an application as it executes. The log files basically contain events of interest (such as sent and received messages between actors), and Causeway provides you with a UI in which you can easily browse those events. See the following youtube movie for an overview:
|
|
|
|
|
|
<wiki:video url="http://www.youtube.com/watch?v=QeqcGa7HlBk"/>
|
|
|
|
|
|
Need more detail? Read the [tech report](http://www.hpl.hp.com/techreports/2009/HPL-2009-78.html) (also useful if you want to know more about how Causeway works).
|
|
|
|
|
|
# How do I enable tracing in AmbientTalk?
|
|
|
|
|
|
Tracing is supported by the `/.at.support.tracer` module. To load the module, execute:
|
|
|
|
|
|
```
|
|
|
def Tracer := /.at.support.tracer("actorName", "/tmp");
|
|
|
```
|
|
|
|
|
|
Note that the `tracer` module is actually a function. To instantiate the module, you call the function, passing it a human-readable name describing the actor you will be tracing, and a directory path to where the log file should be saved. In this case, a log file `/tmp/actorName.json` will be created.
|
|
|
|
|
|
Importing the tracer does not automatically activate it. To activate, invoke `Tracer.traceOn()`. To deactivate, invoke `Tracer.traceoff()`. To stop tracing and close the logfile, invoke `Tracer.close()`.
|
|
|
|
|
|
Sometimes, you may only want to trace part of your application. In that case, the following `trace:` construct exported by the module is useful:
|
|
|
```
|
|
|
Tracer.trace: {
|
|
|
...
|
|
|
}
|
|
|
```
|
|
|
|
|
|
The `trace:` construct activates tracing only during the execution of the block. If the block returns a future, tracing is only deactivated *when the future becomes resolved* (this is similar to the behaviour of AmbientTalk's [dynamic variables](https://gitlab.soft.vub.ac.be/ambienttalk/atlib/blob/master/at/lang/dynvars.at)). The `trace:` construct is most useful for scoping asynchronously sent messages. Unless the closure passed to `trace:` returns a future, `trace:` is not useful for tracing asynchronously received messages of objects. If, while executing the closure, a message M is sent asynchronously, and then the closure returns (without returning a future), tracing will have been disabled by the time the reply to M arrives. AmbientTalk's event loop model only dispatches received messages to their recipient objects when the runtime stack is empty.
|
|
|
|
|
|
An easy way to enable continuous actor tracing in a new actor from the moment it is created can be achieved by executing:
|
|
|
```
|
|
|
def Tracer := /.at.support.tracer("actorName", path).traceOn();
|
|
|
...
|
|
|
}
|
|
|
```
|
|
|
|
|
|
Finally, trace events can be emitted explicitly by invoking the appropriate methods on the `Tracer`. The best use case for this is the generation of `comment` events. To generate a `comment`, invoke `Tracer.comment("any text")`.
|
|
|
|
|
|
The tracer module traces an entire actor and can only be activated once per actor. If the tracer module is loaded multiple times with the same actor name, the first call will activate the module and all calls will return the same module object. If the tracer module is already activated and it is called with a different actor name, an IllegalOperation exception will be raised.
|
|
|
|
|
|
For a concrete use of the tracer, have a look at the example in the next section.
|
|
|
|
|
|
For more information about the tracer, it is best to look at its [implementation](https://gitlab.soft.vub.ac.be/ambienttalk/atlib/blob/master/at/support/tracer.at) in `atlib/at/support/tracer.at`
|
|
|
It's worth noting that the tracer is built completely on top of AmbientTalk's reflective actor API. The interpreter itself was not modified to enable tracing (it was modified to enable tracking line and column info of source code, and a logfile writer was added that outputs the log in JSON format).
|
|
|
|
|
|
# An example
|
|
|
|
|
|
Consider a shopping application that needs to process purchase orders. Before the shop can acknowledge the order, it must verify three things: 1) whether the requested items are still in stock, 2) whether the customer has provided valid payment information and 3) whether a shipper is available to ship the order in time. The above example is available as a [demo](https://gitlab.soft.vub.ac.be/ambienttalk/atlib/blob/master/demo/purchase_example.at) in AmbientTalk. Let's review the code. In total, four different actors are created. The first one is the "buyer" process, which must process order purchases:
|
|
|
|
|
|
```
|
|
|
def home := jlobby.java.lang.System.getProperty("user.home");
|
|
|
|
|
|
// buyer process
|
|
|
def buyerP := actor: {
|
|
|
def T := /.at.support.tracer("buyer", home).traceOn();
|
|
|
|
|
|
[def go(inventory, creditBureau, shipper) {
|
|
|
def teller := makeAsyncAnd(3, object: {
|
|
|
def run(answer) {
|
|
|
system.println("Got answer: " + answer);
|
|
|
T.close(); // stop tracing
|
|
|
}
|
|
|
});
|
|
|
|
|
|
inventory<-partInStock("partNo", teller);
|
|
|
creditBureau<-checkCredit("name", teller);
|
|
|
shipper<-canDeliver("profile", teller);
|
|
|
};
|
|
|
|
|
|
};
|
|
|
```
|
|
|
|
|
|
First, notice that tracing was enabled for this actor as indicated previously. Second, the buyer process responds to a message named `go` that, given references to the appropriate (remote) objects, sends out the appropriate messages to inventory, creditBureau and shipper objects. Dummy arguments are provided. To keep this example simple, we don't make use of futures. Instead, the buyer makes use of an "AsyncAnd" abstraction. An AsyncAnd object is created by invoking `makeAsyncAnd(n, callback)` where `n` is a number indicating how many affirmative replies the AsyncAnd object should receive before it invokes `callback<-run(true)`.The `callback` is an object that responds to the message `run(boolean)`. If the "AsyncAnd" receives a negative reply, it will immediately invoke `callback<-run(false)`. Here is the code for `makeAsyncAnd`:
|
|
|
|
|
|
```
|
|
|
def makeAsyncAnd(numExpected, callback) {
|
|
|
if: (numExpected < 1) then: {
|
|
|
callback<-run(true);
|
|
|
object: { def run(answer) { } };
|
|
|
} else: {
|
|
|
object: {
|
|
|
def run(answer) {
|
|
|
if: (callback != nil) then: {
|
|
|
if: answer then: {
|
|
|
numExpected := numExpected - 1;
|
|
|
if: (numExpected <= 0) then: {
|
|
|
T.comment("happened: all true");
|
|
|
callback<-run(true);
|
|
|
callback := nil;
|
|
|
} else: {
|
|
|
T.comment("leadsto: all true");
|
|
|
}
|
|
|
} else: {
|
|
|
T.comment("found a false");
|
|
|
callback<-run(false);
|
|
|
callback := nil;
|
|
|
}
|
|
|
}
|
|
|
}
|
|
|
}
|
|
|
}
|
|
|
};
|
|
|
```
|
|
|
|
|
|
Notice the two calls to `T.comment` in the above code. `T.comment(string)` logs any string for inspection in Causeway. However, the format used in these comments, namely "happened: event" and "leadsto: event" have a special meaning for Causeway. A "leadsto: event" comment emitted by a method as a result of receiving a message `m` indicates that reception of the message `m` leads to a certain "event". Eventually, when the "event" happens, this is logged using the "happened: event" comment. Causeway will visually indicate the causal relationship that exists between the "leadsto: event" and the "happened: event" messages. Note that the event logged by those messages should be unique. If two "happened: X" strings are generated within the same application, Causeway will raise an "Happening conflict warning" message.
|
|
|
|
|
|
The rest of the example simply consists of the defintion of a number of ancillary processes (modelled as actors) that respond to the different messages. For simplicity, all three processes simply send an affirmative reply to the "AsyncAnd" callback.
|
|
|
|
|
|
```
|
|
|
// product process
|
|
|
def productP := actor: {
|
|
|
def T := /.at.support.tracer("product", home).traceOn();
|
|
|
|
|
|
def partInStock(partNo, teller) {
|
|
|
teller<-run(true); T.close();
|
|
|
};
|
|
|
};
|
|
|
|
|
|
// accounts process
|
|
|
def accountP := actor: {
|
|
|
def T := /.at.support.tracer("account", home).traceOn();
|
|
|
|
|
|
def checkCredit(name, teller) {
|
|
|
teller<-run(true); T.close();
|
|
|
};
|
|
|
};
|
|
|
|
|
|
// shipper process
|
|
|
def shipperP := actor: {
|
|
|
def T := /.at.support.tracer("shipper", home).traceOn();
|
|
|
|
|
|
def canDeliver(profile, teller) {
|
|
|
teller<-run(true); T.close();
|
|
|
};
|
|
|
};
|
|
|
```
|
|
|
|
|
|
Since no further messages need to be traced in these processes once they sent their reply, they close their trace log by invoking `T.close()`.
|
|
|
|
|
|
Finally, the example is put in motion by sending the `go` message to the buyer process:
|
|
|
|
|
|
```
|
|
|
buyerP<-go(productP, accountP, shipperP);
|
|
|
```
|
|
|
|
|
|
Running this example should print the following to the console:
|
|
|
`> Got answer: true`
|
|
|
As a side-effect of running the example, you should see the files `buyer.json`, `product.json`, `account.json` and `shipper.json` in your home directory. To inspect the trace logs, launch Causeway:
|
|
|
|
|
|
```
|
|
|
rune -J-Xmx128m -J-Xss128m causeway.e-swt ~/*.json
|
|
|
```
|
|
|
|
|
|
Which should show you something similar to:
|
|
|
![trace_example_overview](trace_example_overview.jpg)
|
|
|
|
|
|
The upper right pane shows the "message order tree", which depicts the causality between sent and received messages as a tree. Received messages are always "caused by" the equivalent sent messages. The notation `[buyer,0](...])` means that this message was either sent or received by the "buyer" process in "turn" 0. For sent messages, the line of code shown is the actual message send, for received messages, the line of code shown is that of the method definition triggered by the received message:
|
|
|
|
|
|
![trace_example_message_order_tree](trace_example_message_order_tree.jpg)
|
|
|
|
|
|
Notice the little "=>" arrows next to the `[def run(answer)` messages. Clicking on any of the messages tagged by the "=>" arrow immediately makes the selection jump to the last of these. The "=>" arrows denote that these messages lead to a certain other message. In other words, they visually represent the "leadsto:" and "happened:" events from the example.
|
|
|
|
|
|
The upper right pane allows you to select a logged actor (note that each actor gets assigned its own color). In the screenshot below, I selected the "product" actor. It shows that the "product" actor received one message named `partInStock` and, in response to receiving that message, it sent another message `teller<-run(true)` to the `AsyncAnd` teller:
|
|
|
|
|
|
![trace_example_stack](trace_example_stack.jpg)
|
|
|
|
|
|
If you select any of the sent or received messages of an actor, the bottom right panel shows the corresponding "stack explorer". The stack explorer shows the stack trace of the selected actor at the time the selected message was sent. It also shows the stack trace of the sender actor at the time it sent the message that caused the selected message to execute, and so on. So in the above stack trace, we can see that computation was started by the `go` message, which caused the buyer actor to send the "partInStock" message to the product actor. In response to receiving this message, the product actor sent the `run` message to the `teller`.
|
|
|
|
|
|
Also take some time to explore some of Causeway's options. One useful option for bigger examples is filtering: select `Tools` then `Set Filter Options`. It will show you a list of all the traced source files. You can deselect some source files, which will hide all the messages sent by or received from code in those source files.
|
|
|
|
|
|
# Great! Now how do I install Causeway?
|
|
|
|
|
|
Causeway is written in the [http://www.erights.org E](buyer,3]) programming language. To run Causeway, you will need to [download and install E](http://www.erights.org/download/index.html) or, to get the latest version, simply execute:
|
|
|
|
|
|
```
|
|
|
svn co svn://svn.synchrona.org/erights/e/trunk e
|
|
|
```
|
|
|
|
|
|
Then, `cd e/src` and `make` to build the E interpreter. This should create an `../export/dist` directory in which you can find a `README.txt` file with further instructions on how to get E up and running. In principle, it suffices to do:
|
|
|
```
|
|
|
cp rune-template.txt rune
|
|
|
cp eprops-template.txt eprops.txt
|
|
|
chmod a+x rune
|
|
|
```
|
|
|
|
|
|
Then open rune and eprops.txt and modify the necessary ${{...}} variables to refer to the right directories.
|
|
|
For example, in rune, ${{e.home}} should be replaced by the directory in which "rune" lives (between quotes) and ${{e.javacmd}} should be replaced by "java" as shown below:
|
|
|
|
|
|
```
|
|
|
EHOME="/Users/me/e/export/dist"
|
|
|
JCMD="java"
|
|
|
```
|
|
|
|
|
|
Causeway is available under `export/dist/scripts/causeway.e-swt`
|
|
|
To run it, it's best to add the `export/dist` directory to your `$PATH`, allowing you to run `rune` (E's command-line interpreter). Then start causeway as follows:
|
|
|
```
|
|
|
rune causeway.e-swt logfile1.json logfile2.json ...
|
|
|
```
|
|
|
|
|
|
As Causeway requires a lot of memory, try the following if you run out of stack/heap space:
|
|
|
```
|
|
|
rune -J-Xmx128m -J-Xss128m causeway.e-swt logfile1.json logfile2.json ...
|
|
|
```
|
|
|
|
|
|
If your tracelogs contain relative paths to the traced source files (e.g. "at/demo/foo.at"), you can tell Causeway how to resolve those relative paths into absolute paths (e.g. "/Users/me/ambienttalk/at/demo/foo.at") by passing a "base" path, as follows:
|
|
|
```
|
|
|
rune -Dsrc="/Users/me/ambienttalk/" causeway.e-swt ...
|
|
|
```
|
|
|
|
|
|
Finally, if you encounter problems and think causeway may be misinterpreting some of the events, passing the following flag will show an additional panel indicating the JSON source of a parsed event:
|
|
|
```
|
|
|
rune -J-Xmx128m -J-Xss128m -Dcauseway_debug=true causeway.e-swt logfile1.json logfile2.json ...
|
|
|
```
|
|
|
|
|
|
Causeway uses SWT to render its GUI. SWT is a Java widget toolkit that is platform-independent but that uses native widgets to render the GUI. Normally, E should include a version of the SWT GUI library that should work under all major OSes.
|
|
|
|
|
|
## Support for futures and custom logging
|
|
|
|
|
|
As of r1781 the tracer supports logging of futures and when:becomes:-observers. The future-based version of the above "purchase example" can be found [here](https://gitlab.soft.vub.ac.be/ambienttalk/atlib/blob/master/demo/purchase_example_futures.at).
|
|
|
|
|
|
One important limitation of logging of future-based messages is the following: futures attached to asynchronous messages are implicitly resolved by the return value of the method that they trigger. However, it is very difficult for the implementation to determine the AST of the expression that 'generated' the return value. When clicking on a `#resolved` event, Causeway will highlight the first expression in the body of the method whose return value resolved the future. It is up to the programmer to figure out what the return value of the method body was.
|
|
|
|
|
|
The tracing module exports a number of type tags that can be used to do custom logging of events. For example, to disable logging of an async message:
|
|
|
```
|
|
|
o<-msg(args)@TraceModule.NoTrace
|
|
|
```
|
|
|
|
|
|
Messages can also be annotated with custom logging behavior, as follows:
|
|
|
|
|
|
```
|
|
|
o<-msg(args)@TraceModule.TraceAs(isolate:{
|
|
|
def traceReceived(rcvr, msg, log) { ... };
|
|
|
def traceSent(rcvr, msg, log) { ... };
|
|
|
});
|
|
|
```
|
|
|
|
|
|
However, this is an expert feature and should be used only on special "meta-messages" that should not end up in a Causeway trace log as regular "application level" messages.
|
|
|
|
|
|
# Known issues
|
|
|
|
|
|
1. Causeway (or more generally any E program using SWT) does not run out of the box on Mac OS X 10.6 (Snow Leopard). To get it running, edit the `rune` script to add the `-d32` flag to the JVM. More details [here](http://wiki.erights.org/wiki/SWT).
|
|
|
1. On Mac OS X, quitting Causeway via Command+Q closes the GUI, but does not close the application itself. Quitting Causeway using its File > Exit menu uption does work properly.
|
|
|
1. Sometimes highlighted line number in the source code panel is off by 1 line.
|
|
|
1. If you were tracing an AmbientTalk application that crashed or otherwise terminated early/abnormally, the tracer may not have had a chance to properly close the tracelog file. In this case, if you load the file in Causeway, it will tell you that the file has a "syntax error". In principle, it suffices to add a closing "]" to the JSON tracelog file in order to make the file readable to Causeway.
|
|
|
|
|
|
## TODO
|
|
|
|
|
|
1. proper support for other `when*` observers, e.g. whendisconnected, whendiscovered, ...
|
|
|
1. Currently, the log files generated by AmbientTalk contain absolute paths to the "source" location of the traced source files. These should be turned into paths relative to the AmbientTalk object path. This would enable log-files to become more machine-independent. The relative paths can be turned back into absolute paths by passing the `-Dsrc="some-absolute-base-path"` flag to Causeway. However, for this to be convenient, Causeway should support multiple absolute base paths. |