Friday, December 29, 2006

How to tell what's going on

In my last two posts (Cohatoe example walkthrough, part I and part II) I have explained the basics of how to contribute some Haskell code in an Eclipse plugin so that it can be called from the Java code in that Eclipse plugin (and other Eclipse plugins that depend on it). If you have experimented a little with this, then you might have encountered situations in which something went wrong and you could not immediately see what - so what can you do for diagnostics?

One helpful instrument is Eclipse's built-in tracing. It is not a full-fledged logging framework, but it can come in helpful. For Cohatoe, I have implemented tracing for the inits and all calls to the Cohatoe server singleton. The server singleton basically manages all registered Haskell functions and delegates calls to them to the native object code. If you switch on the tracing for the Cohatoe server, you will be able to detect problems of three different sorts:

  • declaration problems in the plugin manifest file, plugin.xml (e.g. you have a typo in the declaration of your object files)
  • initialization problems that occcur when the server is started
  • problems during calls to the native code (e.g. load errors that occured when object code could not be loaded or exceptions on the Haskell side, like calls to the Prelude.error function)
Especially the latter sort of problem is still very much work in progress. In later versions of Cohatoe, exceptions that are fired on the Haskell side will be transferred to the Java side and re-raised there, where the caller to the evaluate() method on the server singleton will be responsible for handling them. (Of course, it is even better the Haskell code would already handle them itself :-). But that mechanism is not yet in place as of Cohatoe 0.1, therefore you will only see problems on the Haskell side when you switch on tracing.

And here's how you do it: Assuming that you have an Eclipse plugin project, and you have at least once run it as an Eclipse application from the Run or Debug menu, then you have a so-called launch configuration for that launch. Whether tracing is enabled is a property of that launch configuration, and you can switch it on or off on the launch configuration dialog. Select Run > Run ... from the main menu. On the dialog that appears, select the Eclipse application launch configuration for your launch. Here is how the dialog looks like in my examples workspace:

Switch to the Tracing tab. Here you can see the tracing options from all plugins which support tracing. In order to enable a particular tracing option, you have first to globally enable the tracing functionality - that's the Enable tracing for the selected plugins checkbox right on top of the Tracing tab. Then you must select the plugins themselves, in our case that is the Cohatoe server plugin, which appears in the list with its plugin id, namely: de.leiffrenzel.cohatoe.server.core. Finally, check the particular tracing option that you want to enable - this is logs in our case, which is the only option that Cohatoe currently provides.

Note that it is not enough to just check the option, you must also check the plugin! If you check the option and not the plugin, you won't see anything. This is how the tab should look like now:

When you run your launch configuration now and (in the second Eclipse instance that was fired up) trigger some action that calls a Haskell function, you will see some output in the console that obviously came from the Cohatoe server. Here is what I got:
[Cohatoe Server] No entry 'inexistent.obj' in bundle 'de.leiffrenzel.cohatoe.server.core.test'.
[Cohatoe Server] Initializing server.
[Cohatoe Server] Setting port to 36522
[Cohatoe Server] Setting executable to C:\workspaces\cohatoe\de.leiffrenzel.cohatoe.server.core.win32.win32.x86\server\haskellserver.exe
[Cohatoe Server] Evaluating de.leiffrenzel.cohatoe.example.core.functions.IHelloFunction
[Cohatoe Server] C:\workspaces\cohatoe\de.leiffrenzel.cohatoe.example\os\win32\x86\obj\Hello.o
[Cohatoe Server] > Server process ready
[Cohatoe Server] Response was: Hi, thanks for saying 'Hi Haskell!' to me.§
Now what does all this tell us?

The first line in this tracing output complains about a non-existing object file. This comes from the initialization phase of the Cohatoe server. The server, in that phase, reads all extensions to the haskellFunctions extension point. In these extensions, the object code for the Haskell functions is declared, and the server needs to locate the object files so that it knows (on the Haskell side of things) where to get them. The line in our trace states that one object file, named 'inexistent.obj', was not actually found, and that this file was declared by the bundle (for which read 'Eclipse plugin') with the id de.leiffrenzel.cohatoe.server.core.test. In this case, that's fine, because that plugin is the one which contains my unit tests for Cohatoe, and the object file declaration declared deliberately a non-existing object file (because I wanted to test the behaviour of the server in such a case). But if you see such a line in the trace, that indicates that you have either forgotten to provide an object file, or you have mistyped its declaration in the plugin.xml.

The next 3 lines tell us a bit about the proceedings inside Cohatoe. The server singleton starts its init routine, determines a free port on the local host, and then fires up a native executable in an external process which listens on that port. That executable knows how to load and execute Haskell functions from object code (using hs-plugins), and is the Haskell side of the Cohatoe server. I will add details about all this in some later posts.

After these inits, we see now the tracing output for all the calls to Haskell functions. You see the fully qualified name of a Java interface and the file name of an object file. Cohatoe uses Java interfaces as keys for Haskell functions, namely the interfaces that have been declared together with the object code in the plugin.xml. You can think of these Java interfaces as the placeholders or representatives of your Haskell functions in the Eclipse-plugin world. For every Haskell function that is called, you will see the interface name, object file name, and the response from the Haskell side in the trace.

You will have noticed that there was another line in between these function call tracing outputs: "> Server process ready". The '>' character in front of a tracing line indicates that this line comes from the standard output or standard error stream of the native server process. In this case, that's only a friendly message that the server is ready. (It is read asynchronously with low priority on the Java side, and therefore appears sometimes a little later in the trace.) But if, for some reason, your Haskell code causes the server process to write to the error stream, you'll see that output here.

Finally, when you shut down your debugging Eclipse, you will see some more output:
[Cohatoe Server] Disposing server.
[Cohatoe Server] Finished out and err of the server process.
which obviously informs us about the cleanups which go on at that time.

1 comment:

Leif Frenzel said...

I have noticed that the tracing output that I have quoted doesn't fit on the page and half of it is not visible. But it is there nonetheless - if you select and copy it to the clipboard, you get the full text.

Sorry about that. In my future posts I will try and work around that problem.